Nservicebus: ExpiredTimeoutsPoller exception rolls over into not executing task

[janpieterz]

We've had an endpoint that was alive skip 1 of the scheduled tasks indefinitely (until restart) because (presumably) the below exception. This is the only exception in the logs, though given that it is a timeout exception it might have hit other parts of the endpoint too. Software version is NSB 6.0.0.

2016-12-24 12:49:10 (NServiceBus.DefaultScheduler) [Information] Start executing scheduled task named '"Heartbeat"'.
2016-12-24 12:49:10 (NServiceBus.DefaultScheduler) [Information] Start executing scheduled task named '"RunSiteSynchronisation"'.
2016-12-24 12:49:10 (NServiceBus.DefaultScheduler) [Information] Scheduled task '"Heartbeat"' run for 00:00:00.0001337
2016-12-24 12:49:10 (NServiceBus.DefaultScheduler) [Information] Scheduled task '"RunSiteSynchronisation"' run for 00:00:00.0001377
2016-12-24 12:50:45 (NServiceBus.ExpiredTimeoutsPoller) [Warning] Failed to fetch timeouts from the timeout storage
System.Exception: Failed to send message to [transport].[Server.TimeoutsDispatcher] ---> System.Data.SqlClient.SqlException: Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception: The wait operation timed out
   --- End of inner exception stack trace ---
   at System.Data.SqlClient.SqlCommand.EndExecuteNonQueryAsync(IAsyncResult asyncResult)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.Transport.SQLServer.TableBasedQueue.<SendRawMessage>d__9.MoveNext() in C:\Build\src\NServiceBus.SqlServer\Queuing\TableBasedQueue.cs:line 91
   --- End of inner exception stack trace ---
   at NServiceBus.Transport.SQLServer.TableBasedQueue.ThrowFailedToSendException(Exception ex) in C:\Build\src\NServiceBus.SqlServer\Queuing\TableBasedQueue.cs:line 128
   at NServiceBus.Transport.SQLServer.TableBasedQueue.<SendRawMessage>d__9.MoveNext() in C:\Build\src\NServiceBus.SqlServer\Queuing\TableBasedQueue.cs:line 101
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.Transport.SQLServer.TableBasedQueueDispatcher.<Send>d__6.MoveNext() in C:\Build\src\NServiceBus.SqlServer\Sending\TableBasedQueueDispatcher.cs:line 96
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.Transport.SQLServer.TableBasedQueueDispatcher.<DispatchOperationsWithNewConnectionAndTransaction>d__4.MoveNext() in C:\Build\src\NServiceBus.SqlServer\Sending\TableBasedQueueDispatcher.cs:line 56
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.Transport.SQLServer.TableBasedQueueDispatcher.<DispatchAsNonIsolated>d__3.MoveNext() in C:\Build\src\NServiceBus.SqlServer\Sending\TableBasedQueueDispatcher.cs:line 42
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.Transport.SQLServer.MessageDispatcher.<Dispatch>d__1.MoveNext() in C:\Build\src\NServiceBus.SqlServer\Sending\MessageDispatcher.cs:line 21
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
   at NServiceBus.ExpiredTimeoutsPoller.<SpinOnce>d__11.MoveNext() in C:\Build\src\NServiceBus.Core\DelayedDelivery\TimeoutManager\ExpiredTimeoutsPoller.cs:line 117
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.ExpiredTimeoutsPoller.<InnerPoll>d__10.MoveNext() in C:\Build\src\NServiceBus.Core\DelayedDelivery\TimeoutManager\ExpiredTimeoutsPoller.cs:line 85
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at NServiceBus.ExpiredTimeoutsPoller.<Poll>d__9.MoveNext() in C:\Build\src\NServiceBus.Core\DelayedDelivery\TimeoutManager\ExpiredTimeoutsPoller.cs:line 67
2016-12-24 12:50:45 (NServiceBus.RepeatedFailuresOverTimeCircuitBreaker) [Warning] The circuit breaker for "TimeoutStorageConnectivity" is now in the armed state
2016-12-24 12:50:46 (NServiceBus.RepeatedFailuresOverTimeCircuitBreaker) [Information] The circuit breaker for "TimeoutStorageConnectivity" is now disarmed
2016-12-24 12:50:47 (NServiceBus.DefaultScheduler) [Information] Start executing scheduled task named '"Heartbeat"'.
2016-12-24 12:50:47 (NServiceBus.DefaultScheduler) [Information] Scheduled task '"Heartbeat"' run for 00:00:00.0001450
2016-12-24 12:51:48 (NServiceBus.DefaultScheduler) [Information] Start executing scheduled task named '"Heartbeat"'.
2016-12-24 12:51:48 (NServiceBus.DefaultScheduler) [Information] Scheduled task '"Heartbeat"' run for 00:00:00.0001413

[SzymonPobiega]

Hi @janpieterz

Can you provide us with more logs round this place? Also, what kind of persistence do you use? Ideally can you provide the code that configures the EncpointConfiguration.

[janpieterz]

Updated above post with some more logs (after this it just keeps repeating those Heartbeat lines).
The RunSiteSynchronisation task is the one that did not resume.
We're using the NHibernate persistence (version 7.0.0), the endpoint is a self hosted endpoint.
Endpoint config as below:

var endpointConfiguration = new EndpointConfiguration(Constants.EndpointName);
 endpointConfiguration.UseContainer<AutofacBuilder>(customizations: customizations =>
{
    customizations.ExistingLifetimeScope(lifetimeScope);
});

string sqlConnectionString = ConfigurationManager.ConnectionStrings["SqlConnection"].ConnectionString;
endpointConfiguration.UsePersistence<NHibernatePersistence>()
    .UseConfiguration(new NHibernate.Cfg.Configuration()
    {
        Properties =
        {
            ["default_schema"] = "persistence",
            ["connection.connection_string"] = sqlConnectionString,
            ["dialect"] = "NHibernate.Dialect.MsSql2012Dialect"
        }
    });
endpointConfiguration.SendFailedMessagesTo("error");
endpointConfiguration.DisableFeature<Audit>();
endpointConfiguration.UseTransport<SqlServerTransport>()
    .ConnectionString(connectionString: sqlConnectionString)
    .DefaultSchema("transport")
    .Transactions(TransportTransactionMode.SendsAtomicWithReceive);
endpointConfiguration.EnableInstallers();

//https://github.com/Particular/NServiceBus/issues/4089
endpointConfiguration.LimitMessageProcessingConcurrencyTo(2);
endpointConfiguration.DefineCriticalErrorAction(OnCriticalError);
string license = ConfigurationManager.AppSettings["NServiceBusLicense"];
endpointConfiguration.License(DecodeUrlString(license));
var conventionsBuilder = endpointConfiguration.Conventions();
conventionsBuilder.DefiningCommandsAs(t => t.Namespace != null && t.Namespace.StartsWith("Intreba.") && t.Namespace.EndsWith("Commands"));
conventionsBuilder.DefiningEventsAs(t => t.Namespace != null && t.Namespace.StartsWith("Intreba.") && t.Namespace.EndsWith("Events"));
conventionsBuilder.DefiningMessagesAs(t => t.Namespace != null && t.Namespace.StartsWith("Intreba.") && t.Namespace.EndsWith("RequestResponse"));

endpointConfiguration.ExcludeAssemblies(
//Long list of unrelated assemblies
);

return endpointConfiguration;

[SzymonPobiega]

@janpieterz the problem you experienced is due to a combination of a bug in the NServiceBus core (which I described in the issue itself) and a failure to forward-port an issue already found and fixed in NHibernate persistence 6.2.7.

We're working on NHibernate 7.1.1 that will bring that fix back again. TL;DR the fix is whenever a timeout is missed for any reason, it will be picked up by a cleaning process then catches all due and missed timeouts. That process runs, by default, every 2 minutes.

[SzymonPobiega]

@Particular/nservicebus-maintainers I've updated the issue description. Please run it through your triage process.

[janpieterz]

@SzymonPobiega Am I correct in reading your edits that if I'd change to the Transaction Scope it would not occur? Would that mean both 'failures' that you describe?

I went for the Sends Atomic with Receive because of the prevention of the ghost messages, but depending on how I read the TransactionScope document, these would be prevented there too.

Thanks for your effort in helping to diagnose and pinpoint this!

[timbussmann]

when using TransactionScope transaction mode, we ensure that there are no duplicate timeout messages. We can't guarantee the same when using lower modes (e.g. SendsAtomicWithReceive). The issue found by @SzymonPobiega related to the core is independent of the choosen transaction mode to my understanding (maybe Szymon can confirm this assumption).

[SzymonPobiega]

@timbussmann yeah, you're right. The issue is not dependent on the transaction mode.

@janpieterz TransactionScope mode has stonger guarantees than SendsAtomocWithReceive. Not only it prevents ghost messages but also allows you to hook to the receive transaction and modify data (assuming data store supports ambient transactions via TransactionScope) in sync with receiving a message.

[timbussmann]

@janpieterz for better clarity I raised a dedicated issue for the core related bug found by @SzymonPobiega instead of tracking it directly in this issue (so we don't have to modify your issue description). There has also been an NHibernate hotfix which should ensure that no timeouts skipped for a longer period of time, so upgrading to the latest NH release should hopefully resolve your issue.

[andreasohlund]

@janpieterz are you ok with us closing this isssue? (saw your thumbs up on Tims comment above)

[janpieterz]

@andreasohlund I believe so, thanks guys!