Messages go into infinite immediate retries in case there are a lot of messages (over 100) with persistent issue while processing.

[bonieckimarcin]

Describe the bug

Description

We have encountered a problem with infinite loop in immediate retries in case there is a lot of messages in queue one next to each other (during tests it was between 100 and 1000), which have persistent issue while processing. After a configured number of immediate retires (2 for proceeded test) all messages go to first delayed retry. Next after configured delay messges are going back to processing. At this moment they undergo infinite immediate retries and never go to delayed retry again. We have noticed that this problem occurs when LimitMessageProcessingConcurrencyTo is set to more than 1.

Expected behavior

Messages go through immediate, then delayed retries and finally will land in the error queue.

Actual behavior

Messages after first iteration of immediate retries go to first delayed retry. After that they undergo infinite immediate retries.

Versions

Affected package:

• NServiceBus.RabbitMQ 7.0.2, 7.0.3, 7.0.4, 7.0.5

Tested with:

• NServiceBus 7.8.2
• .net Framework 4.7.2 and .net6
• RabbitMQ Server 3.10.20

Steps to reproduce

1. Create a classic queue endpoint in .net Framework 4.7.2 or .net6 which will handle one type of message
2. Use delayed message infrastructure v2
3. Set following endpoint parameters:

• Number of immediate retries: 2
• Number of delayed retries: 10
• Delayed retry time increase: 60s
• LimitMessageProcessingConcurrencyTo: 3
• Outbox enabled
• TransportTransaction: ReceiveOnly
• PrefetchMultiplier:10

4. In message handler throw an exception to simulate permament processing problem
5. Keep endpoint stopped
6. Add more than 100 messages to the queue
7. Start endpoint
8. Observe endpoint log

Relevant log output

2023-06-13 00:00:18,437 [282] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:00:18,445 [282] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:00:19,022 [193] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:00:19,037 [193] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:00:19,584 [278] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:00:19,591 [278] WARN  NServiceBus.RecoverabilityExecutor - Delayed Retry will reschedule message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' after a delay of 00:01:00 because of an exception:
2023-06-13 00:01:25,815 [261] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:25,826 [261] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:26,136 [252] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:26,148 [252] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:26,420 [242] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:26,430 [242] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:26,628 [242] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:26,634 [242] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:26,842 [256] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:26,847 [256] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:27,050 [276] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:27,058 [276] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:27,311 [276] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:27,318 [276] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:27,561 [276] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:27,568 [276] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:27,734 [274] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:27,744 [274] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:27,935 [274] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:27,953 [274] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:28,154 [238] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:28,159 [238] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:28,323 [256] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:28,333 [256] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:28,475 [196] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:28,483 [196] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
2023-06-13 00:01:28,756 [258] INFO  TransportMutator - incoming msg id: '2eedbb99-fdae-482d-a17f-b01f016aa0ee'
2023-06-13 00:01:28,763 [258] INFO  NServiceBus.RecoverabilityExecutor - Immediate Retry is going to retry message '2eedbb99-fdae-482d-a17f-b01f016aa0ee' because of an exception:
and on ...

Additional Information

Workarounds

• Turn off immediate retries or
• Set LimitMessageProcessingConcurrencyTo: 1