Log fills up when recoverability policy fails

antmeehan · January 31, 2025, 5:38am

We’ve hit an issue in NServiceBus 8.1.6 where I log file fills up with theses errors continuously:

2025-01-31 10:23:59,892 [37] FATAL NServiceBus - Failed to execute recoverability policy for message with native ID: `fade6432-f177-4546-b67a-f9941bce78dc\-1672808665`
System.ArgumentNullException: Value cannot be null.
Parameter name: address
   at NServiceBus.Transport.Msmq.MsmqAddress.Parse(String address) in /_/src/NServiceBus.Transport.Msmq/MsmqAddress.cs:line 22
   at NServiceBus.Transport.Msmq.MsmqMessageDispatcher.SendToDelayedDeliveryQueue(TransportTransaction transaction, UnicastTransportOperation transportOperation) in /_/src/NServiceBus.Transport.Msmq/MsmqMessageDispatcher.cs:line 106
   at NServiceBus.Transport.Msmq.MsmqMessageDispatcher.Dispatch(TransportOperations outgoingMessages, TransportTransaction transaction, CancellationToken cancellationToken) in /_/src/NServiceBus.Transport.Msmq/MsmqMessageDispatcher.cs:line 38
   at (ArrayClosure , IDispatchContext )
   at NServiceBus.RoutingToDispatchConnector.Invoke(IRoutingContext context, Func`2 stage) in /_/src/NServiceBus.Core/Pipeline/Outgoing/RoutingToDispatchConnector.cs:line 51
   at NServiceBus.AttachSenderRelatedInfoOnMessageBehavior.Invoke(IRoutingContext context, Func`2 next) in /_/src/NServiceBus.Core/Pipeline/Outgoing/AttachSenderRelatedInfoOnMessageBehavior.cs:line 43
   at NServiceBus.RecoverabilityRoutingConnector.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Recoverability/RecoverabilityRoutingConnector.cs:line 28
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.RecoverabilityPipelineExecutor`1.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Recoverability/RecoverabilityPipelineExecutor.cs:line 54
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at NServiceBus.RecoverabilityPipelineExecutor`1.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Recoverability/RecoverabilityPipelineExecutor.cs:line 54
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.Transport.Msmq.ReceiveStrategy.<HandleError>d__8.MoveNext() in /_/src/NServiceBus.Transport.Msmq/ReceiveStrategy.cs:line 121
2025-01-31 10:23:59,892 [28] WARN  NServiceBus.DelayedRetry - Delayed Retry will reschedule message '55cfb5ee-b032-4bc2-bba8-b27600278801' after a delay of 00:00:10 because of an exception:
System.ArgumentException: An item with the same key has already been added.
   at System.ThrowHelper.ThrowArgumentException(ExceptionResource resource)
   at System.Collections.Generic.Dictionary`2.Insert(TKey key, TValue value, Boolean add)
   at System.Linq.Enumerable.ToDictionary[TSource,TKey,TElement](IEnumerable`1 source, Func`2 keySelector, Func`2 elementSelector, IEqualityComparer`1 comparer)
   at Cbh.Movements.Engine.Host.Services.GetSiteDescriptionsLookupQuery.<Query>d__2.MoveNext() in C:\agent\_work\13\s\src\Cbh.Movements.Engine.Host\Services\GetSiteDescriptionsLookupQuery.cs:line 19
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Cbh.Movements.Engine.Host.MessageHandlers.NetworkNotificationSentHandler.<Handle>d__5.MoveNext() in C:\agent\_work\13\s\src\Cbh.Movements.Engine.Host\MessageHandlers\NetworkNotificationSentHandler.cs:line 21
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.InvokeHandlerTerminator.<Terminate>d__1.MoveNext() in /_/src/NServiceBus.Core/Pipeline/Incoming/InvokeHandlerTerminator.cs:line 52
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at NServiceBus.LoadHandlersConnector.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Pipeline/Incoming/LoadHandlersConnector.cs:line 42
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at NServiceBus.DeserializeMessageConnector.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Pipeline/Incoming/DeserializeMessageConnector.cs:line 32
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at ReceivePerformanceDiagnosticsBehavior.<Invoke>d__0.MoveNext() in /_/src/NServiceBus.Metrics/ProbeBuilders/ReceivePerformanceDiagnosticsBehavior.cs:line 23
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.SubscriptionReceiverBehavior.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Routing/MessageDrivenSubscriptions/SubscriptionReceiverBehavior.cs:line 29
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.InvokeAuditPipelineBehavior.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Audit/InvokeAuditPipelineBehavior.cs:line 21
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.ProcessingStatisticsBehavior.<Invoke>d__0.MoveNext() in /_/src/NServiceBus.Core/Performance/Statistics/ProcessingStatisticsBehavior.cs:line 25
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.TransportReceiveToPhysicalMessageConnector.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Pipeline/Incoming/TransportReceiveToPhysicalMessageConnector.cs:line 37
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.RetryAcknowledgementBehavior.<Invoke>d__2.MoveNext() in /_/src/NServiceBus.Core/ServicePlatform/Retries/RetryAcknowledgementBehavior.cs:line 27
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.MainPipelineExecutor.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Pipeline/MainPipelineExecutor.cs:line 64
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at NServiceBus.MainPipelineExecutor.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Pipeline/MainPipelineExecutor.cs:line 68
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.Transport.Msmq.ReceiveStrategy.<TryProcessMessage>d__7.MoveNext() in /_/src/NServiceBus.Transport.Msmq/ReceiveStrategy.cs:line 112
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.Transport.Msmq.ReceiveOnlyNativeTransactionStrategy.<ProcessMessage>d__2.MoveNext() in /_/src/NServiceBus.Transport.Msmq/ReceiveOnlyNativeTransactionStrategy.cs:line 93
2025-01-31 10:23:59,892 [28] FATAL NServiceBus - Failed to execute recoverability policy for message with native ID: `fade6432-f177-4546-b67a-f9941bce78dc\-1672808665`
System.ArgumentNullException: Value cannot be null.
Parameter name: address
   at NServiceBus.Transport.Msmq.MsmqAddress.Parse(String address) in /_/src/NServiceBus.Transport.Msmq/MsmqAddress.cs:line 22
   at NServiceBus.Transport.Msmq.MsmqMessageDispatcher.SendToDelayedDeliveryQueue(TransportTransaction transaction, UnicastTransportOperation transportOperation) in /_/src/NServiceBus.Transport.Msmq/MsmqMessageDispatcher.cs:line 106
   at NServiceBus.Transport.Msmq.MsmqMessageDispatcher.Dispatch(TransportOperations outgoingMessages, TransportTransaction transaction, CancellationToken cancellationToken) in /_/src/NServiceBus.Transport.Msmq/MsmqMessageDispatcher.cs:line 38
   at (ArrayClosure , IDispatchContext )
   at NServiceBus.RoutingToDispatchConnector.Invoke(IRoutingContext context, Func`2 stage) in /_/src/NServiceBus.Core/Pipeline/Outgoing/RoutingToDispatchConnector.cs:line 51
   at NServiceBus.AttachSenderRelatedInfoOnMessageBehavior.Invoke(IRoutingContext context, Func`2 next) in /_/src/NServiceBus.Core/Pipeline/Outgoing/AttachSenderRelatedInfoOnMessageBehavior.cs:line 43
   at NServiceBus.RecoverabilityRoutingConnector.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Recoverability/RecoverabilityRoutingConnector.cs:line 28
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.RecoverabilityPipelineExecutor`1.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Recoverability/RecoverabilityPipelineExecutor.cs:line 54
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at NServiceBus.RecoverabilityPipelineExecutor`1.<Invoke>d__1.MoveNext() in /_/src/NServiceBus.Core/Recoverability/RecoverabilityPipelineExecutor.cs:line 54
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.Transport.Msmq.ReceiveStrategy.<HandleError>d__8.MoveNext() in /_/src/NServiceBus.Transport.Msmq/ReceiveStrategy.cs:line 121

Our message handler is failing, but then the recoverability fails (haven’t got to the bottom of that yet) and it looks like the message is tried again continuously. This written 20Gb of log files in a few hours.

We’ll obviously sort out why the recoverability error is occurring, but I’ve seen in lots of other places in NServiceBus a circuit breaker is used to avoid these scenarios of endless logging.

Thoughts?

andreasohlund · January 31, 2025, 8:29am

Hi!

We would need to know more details about versions, startup diagnostics etc so I recommend that you open a support case with us to enable you to share more details.

We’ll make sure to report back here once we have found the cause of the issue.

Hope this makes sense.

Cheers,

Andreas

antmeehan · February 3, 2025, 1:34am

Hi Andreas,

I’ve created a minimal repo here - GitHub - antmeehan/NServiceBus-MSMQ-EndlessLogging.

If you don’t disable delayed retries you get in the endless logging loop.

endpointConfiguration.Recoverability()
            .Delayed(settings => settings.NumberOfRetries(0));

Of course you don’t discover this until your first failure during message handling

Thanks,

Ant.

andreasohlund · February 3, 2025, 8:31am

Excellent reproduction

You are hitting this issue Missing DelayedDelivery configuration causes ArgumentNullException exceptions at runtime · Issue #541 · Particular/NServiceBus.Transport.Msmq · GitHub

To make this work you need to configure delayed delivery for the transport

Let me know if that fixes the problem?

Cheers,

Andreas

antmeehan · February 3, 2025, 8:47am

Hi Andreas,

Yes setting the delayed delivery retries to 0 fixes the problem, but we only found out about the issue once our log files were at 20Gb and counting

Would be great for it to hit a circuit breaker so we don’t run out of disk space.

Many thanks,

Ant.