search

Particular / NServiceBus.RavenDB

https://docs.particular.net/nservicebus/ravendb/
Other
11 stars 17 forks source link

GetCleanupChunk blocks TimeoutManager #380

Closed timbussmann closed 4 years ago

timbussmann commented 6 years ago

I've noticed that the delayed delivery acceptance tests randomly fail when running them locally. I noticed this during switching over to the acceptance testing transport, but according to @mauroservienti it is also reproducible when using MSMQ transport.

The tests fail with a timeout, never delivering the delayed message. By adding some more logging, I was able to pinpoint the issue down to GetCleanupChunk which sometimes blocks when called initially, causing the timeout query to never complete.

Here's the full Debug level log from such a failing test:

System.TimeoutException : The maximum time limit for this test(90s) has been reached
----------------------------------------------------------------------------

   bei NServiceBus.AcceptanceTesting.Support.ScenarioRunner.<PerformScenarios>d__2.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei NServiceBus.AcceptanceTesting.Support.ScenarioRunner.<PerformScenarios>d__2.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei System.Runtime.CompilerServices.ConfiguredTaskAwaitable.ConfiguredTaskAwaiter.GetResult()
   bei NServiceBus.AcceptanceTesting.Support.ScenarioRunner.<PerformTestRun>d__1.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei NServiceBus.AcceptanceTesting.ScenarioWithContext`1.<Run>d__2.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   bei NServiceBus.AcceptanceTests.DelayedDelivery.When_deferring_to_non_local.<Message_should_be_received>d__0.MoveNext() in C:\Users\Tim\.nuget\packages\nservicebus.acceptancetests.sources\7.1.0-acceptance-test-0001\contentFiles\cs\any\NSB.AcceptanceTests\DelayedDelivery\When_deferring_to_non_local.cs:Zeile 19.
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei NUnit.Framework.Internal.AsyncInvocationRegion.AsyncTaskInvocationRegion.WaitForPendingOperationsToComplete(Object invocationResult)
   bei NUnit.Framework.Internal.Commands.TestMethodCommand.RunAsyncTestMethod(TestExecutionContext context)

current context: NServiceBus.AcceptanceTests.DelayedDelivery.When_deferring_to_non_local+Context
Started test @ 12/18/2017 16:41:05
Created '358f3e6a-7425-47fb-b185-08962aedcd3f' database
Created '91ac3bed-60a7-4bd3-af9e-d172d0c660ab' database
Stopping endpoint: DeferringToNonLocal.Endpoint
Stopping endpoint: DeferringToNonLocal.Receiver
Endpoint: DeferringToNonLocal.Receiver stopped (00:00:00.0007389s)
Endpoint: DeferringToNonLocal.Endpoint stopped (00:00:11.0058840s)
Finished test @ 12/18/2017 16:42:47
Deleted '358f3e6a-7425-47fb-b185-08962aedcd3f' database
Deleted '91ac3bed-60a7-4bd3-af9e-d172d0c660ab' database
------------------------------------------------------
Test summary:

Using settings:

Endpoints:
     - DeferringToNonLocal.Endpoint
     - DeferringToNonLocal.Receiver
Test failed: System.TimeoutException: The maximum time limit for this test(90s) has been reached
----------------------------------------------------------------------------

   bei NServiceBus.AcceptanceTesting.Support.ScenarioRunner.<PerformScenarios>d__2.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei NServiceBus.AcceptanceTesting.Support.ScenarioRunner.<PerformScenarios>d__2.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei System.Runtime.CompilerServices.ConfiguredTaskAwaitable.ConfiguredTaskAwaiter.GetResult()
   bei NServiceBus.AcceptanceTesting.Support.ScenarioRunner.<PerformTestRun>d__1.MoveNext()

Context:
WasCalled = False
SentAt = 18.12.2017 15:41:06
ReceivedAt = 01.01.0001 00:00:00
TestRunId = 7f8f9f8d-a3a9-4cef-8459-60c4ac4a54f0
EndpointsStarted = True
HasNativePubSubSupport = False
LogLevel = Debug
Total time for testrun: 00:01:41.6878330
Log entries (log level: Debug):
------------------------------------------------------
16:41:05 Debug DeferringToNonLocal.Endpoint: Activating persistence 'RavenDBPersistence' to provide storage for 'NServiceBus.StorageType+GatewayDeduplication' storage.
16:41:05 Debug DeferringToNonLocal.Endpoint: Activating persistence 'RavenDBPersistence' to provide storage for 'NServiceBus.StorageType+Timeouts' storage.
16:41:05 Debug DeferringToNonLocal.Endpoint: Activating persistence 'RavenDBPersistence' to provide storage for 'NServiceBus.StorageType+Sagas' storage.
16:41:05 Debug DeferringToNonLocal.Endpoint: Activating persistence 'RavenDBPersistence' to provide storage for 'NServiceBus.StorageType+Subscriptions' storage.
16:41:05 Debug DeferringToNonLocal.Endpoint: Activating persistence 'RavenDBPersistence' to provide storage for 'NServiceBus.StorageType+Outbox' storage.
16:41:05 Debug DeferringToNonLocal.Endpoint: Error queue retrieved from code configuration via 'EndpointConfiguration.SendFailedMessagesTo()'.
16:41:05 Debug DeferringToNonLocal.Endpoint: Error queue retrieved from code configuration via 'EndpointConfiguration.SendFailedMessagesTo()'.
16:41:05 Debug DeferringToNonLocal.Endpoint: Initializing type: NServiceBus.AcceptanceTests.DelayedDelivery.When_deferring_to_non_local+MyMessage, NServiceBus.RavenDB.AcceptanceTests, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
16:41:05 Debug DeferringToNonLocal.Endpoint: Number of messages found: 1
16:41:05 Debug DeferringToNonLocal.Endpoint: Message definitions: 
NServiceBus.AcceptanceTests.DelayedDelivery.When_deferring_to_non_local+MyMessage
16:41:05 Debug DeferringToNonLocal.Endpoint: Looking for license in the following locations:
License not found in C:\Projects\NServiceBus.RavenDB\src\NServiceBus.RavenDB.AcceptanceTests\bin\Debug\net452\license.xml
License found in C:\Users\Tim\AppData\Local\ParticularSoftware\license.xml
License not found in C:\ProgramData\ParticularSoftware\license.xml
License found in HKEY_CURRENT_USER\SOFTWARE\ParticularSoftware
License not found in HKEY_LOCAL_MACHINE\SOFTWARE\ParticularSoftware
License not found in app config 'NServiceBus/License' setting
License file not found in path supplied by app config 'NServiceBus/LicensePath' setting. Value was ''
Selected active license from C:\Users\Tim\AppData\Local\ParticularSoftware\license.xml
License Expiration: 2020-01-01

16:41:05 Debug DeferringToNonLocal.Endpoint: Associated 'NServiceBus.ScheduledTask' message with 'NServiceBus.ScheduledTaskMessageHandler' handler.
16:41:05 Debug DeferringToNonLocal.Endpoint: Error queue retrieved from code configuration via 'EndpointConfiguration.SendFailedMessagesTo()'.
16:41:06 Debug DeferringToNonLocal.Receiver: Activating persistence 'RavenDBPersistence' to provide storage for 'NServiceBus.StorageType+GatewayDeduplication' storage.
16:41:06 Debug DeferringToNonLocal.Receiver: Activating persistence 'RavenDBPersistence' to provide storage for 'NServiceBus.StorageType+Timeouts' storage.
16:41:06 Debug DeferringToNonLocal.Receiver: Activating persistence 'RavenDBPersistence' to provide storage for 'NServiceBus.StorageType+Sagas' storage.
16:41:06 Debug DeferringToNonLocal.Receiver: Activating persistence 'RavenDBPersistence' to provide storage for 'NServiceBus.StorageType+Subscriptions' storage.
16:41:06 Debug DeferringToNonLocal.Receiver: Activating persistence 'RavenDBPersistence' to provide storage for 'NServiceBus.StorageType+Outbox' storage.
16:41:06 Debug DeferringToNonLocal.Receiver: Error queue retrieved from code configuration via 'EndpointConfiguration.SendFailedMessagesTo()'.
16:41:06 Debug DeferringToNonLocal.Receiver: Error queue retrieved from code configuration via 'EndpointConfiguration.SendFailedMessagesTo()'.
16:41:06 Debug DeferringToNonLocal.Receiver: Initializing type: NServiceBus.AcceptanceTests.DelayedDelivery.When_deferring_to_non_local+MyMessage, NServiceBus.RavenDB.AcceptanceTests, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
16:41:06 Debug DeferringToNonLocal.Receiver: Number of messages found: 1
16:41:06 Debug DeferringToNonLocal.Receiver: Message definitions: 
NServiceBus.AcceptanceTests.DelayedDelivery.When_deferring_to_non_local+MyMessage
16:41:06 Debug DeferringToNonLocal.Receiver: Looking for license in the following locations:
License not found in C:\Projects\NServiceBus.RavenDB\src\NServiceBus.RavenDB.AcceptanceTests\bin\Debug\net452\license.xml
License found in C:\Users\Tim\AppData\Local\ParticularSoftware\license.xml
License not found in C:\ProgramData\ParticularSoftware\license.xml
License found in HKEY_CURRENT_USER\SOFTWARE\ParticularSoftware
License not found in HKEY_LOCAL_MACHINE\SOFTWARE\ParticularSoftware
License not found in app config 'NServiceBus/License' setting
License file not found in path supplied by app config 'NServiceBus/LicensePath' setting. Value was ''
Selected active license from C:\Users\Tim\AppData\Local\ParticularSoftware\license.xml
License Expiration: 2020-01-01

16:41:06 Debug DeferringToNonLocal.Receiver: Associated 'NServiceBus.ScheduledTask' message with 'NServiceBus.ScheduledTaskMessageHandler' handler.
16:41:06 Debug DeferringToNonLocal.Receiver: Associated 'NServiceBus.AcceptanceTests.DelayedDelivery.When_deferring_to_non_local+MyMessage' message with 'NServiceBus.AcceptanceTests.DelayedDelivery.When_deferring_to_non_local+Receiver+MyMessageHandler' handler.
16:41:06 Debug DeferringToNonLocal.Receiver: Error queue retrieved from code configuration via 'EndpointConfiguration.SendFailedMessagesTo()'.
16:41:06 Debug DeferringToNonLocal.Endpoint: Polling for timeouts at 18.12.2017 15:41:06.
16:41:06 Debug DeferringToNonLocal.Endpoint: Calling GetCleanupChunk
16:41:06 Debug DeferringToNonLocal.Endpoint: Receiver Main is starting, listening to queue DeferringToNonLocal.Endpoint.
16:41:06 Debug DeferringToNonLocal.Endpoint: Receiver Timeout Message Processor is starting, listening to queue DeferringToNonLocal.Endpoint-Timeouts.
16:41:06 Debug DeferringToNonLocal.Endpoint: Started polling for new messages in c:\temp\0-1285\DeferringToNonLocal.Endpoint
16:41:06 Debug DeferringToNonLocal.Endpoint: Receiver Timeout Dispatcher Processor is starting, listening to queue DeferringToNonLocal.Endpoint-TimeoutsDispatcher.
16:41:06 Debug DeferringToNonLocal.Endpoint: Started polling for new messages in c:\temp\0-1285\DeferringToNonLocal.Endpoint-Timeouts
16:41:06 Debug DeferringToNonLocal.Endpoint: Started polling for new messages in c:\temp\0-1285\DeferringToNonLocal.Endpoint-TimeoutsDispatcher
16:41:06 Debug DeferringToNonLocal.Receiver: Receiver Main is starting, listening to queue DeferringToNonLocal.Receiver.
16:41:06 Debug DeferringToNonLocal.Receiver: Started polling for new messages in c:\temp\0-1285\DeferringToNonLocal.Receiver
16:41:06 Debug DeferringToNonLocal.Endpoint: Serializing message 'NServiceBus.AcceptanceTests.DelayedDelivery.When_deferring_to_non_local+MyMessage, NServiceBus.RavenDB.AcceptanceTests, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null' with id '1e850c93-8a2d-4948-b9de-a84d01027b4c', ToString() of the message yields: NServiceBus.AcceptanceTests.DelayedDelivery.When_deferring_to_non_local+MyMessage 

16:41:06 Debug DeferringToNonLocal.Endpoint: Destination: DeferringToNonLocal.Endpoint-Timeouts
Message headers:
NServiceBus.MessageId:1e850c93-8a2d-4948-b9de-a84d01027b4c, NServiceBus.MessageIntent:Send, NServiceBus.ConversationId:9b449891-ce2d-4db7-874e-a84d01027b4d, NServiceBus.CorrelationId:1e850c93-8a2d-4948-b9de-a84d01027b4c, NServiceBus.OriginatingMachine:TIM-MBP, NServiceBus.OriginatingEndpoint:DeferringToNonLocal.Endpoint, $.diagnostics.originating.hostid:7884a76059d53e9ebae1dd64d75ada91, NServiceBus.ReplyToAddress:DeferringToNonLocal.Endpoint, NServiceBus.ContentType:text/xml, NServiceBus.EnclosedMessageTypes:NServiceBus.AcceptanceTests.DelayedDelivery.When_deferring_to_non_local+MyMessage, NServiceBus.RavenDB.AcceptanceTests, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null, NServiceBus.Version:7.1.0, NServiceBus.TimeSent:2017-12-18 15:41:06:171172 Z, NServiceBus.Timeout.RouteExpiredTimeoutTo:DeferringToNonLocal.Receiver, NServiceBus.Timeout.Expire:2017-12-18 15:41:08:171172 Z
16:41:06 Debug DeferringToNonLocal.Endpoint: Completing processing for c:\temp\0-1285\DeferringToNonLocal.Endpoint-Timeouts\24a1de16-a4bc-4aaa-9875-8e3ffeff8645.metadata.txt(c:\temp\0-1285\DeferringToNonLocal.Endpoint-Timeouts\.pending\6ebea2ae-bcd2-4f28-86ef-60effc216224\24a1de16-a4bc-4aaa-9875-8e3ffeff8645.metadata.txt), exception (if any): 
16:42:36 Info DeferringToNonLocal.Endpoint: Initiating shutdown.
16:42:36 Debug DeferringToNonLocal.Endpoint: Stopping Main receiver
16:42:36 Info DeferringToNonLocal.Receiver: Initiating shutdown.
16:42:36 Debug DeferringToNonLocal.Receiver: Stopping Main receiver
16:42:36 Debug DeferringToNonLocal.Receiver: Stopped Main receiver
16:42:36 Debug DeferringToNonLocal.Endpoint: Stopped Main receiver
16:42:36 Debug DeferringToNonLocal.Endpoint: Stopping Timeout Message Processor receiver
16:42:36 Info DeferringToNonLocal.Receiver: Shutdown complete.
16:42:36 Debug DeferringToNonLocal.Endpoint: Stopped Timeout Message Processor receiver
16:42:36 Debug DeferringToNonLocal.Endpoint: Stopping Timeout Dispatcher Processor receiver
16:42:36 Debug DeferringToNonLocal.Endpoint: Stopped Timeout Dispatcher Processor receiver
16:42:46 Warn DeferringToNonLocal.Endpoint: Failed to fetch timeouts from the timeout storage Raven.Abstractions.Connection.ErrorResponseException: Eine Aufgabe wurde abgebrochen. ---> System.Threading.Tasks.TaskCanceledException: Eine Aufgabe wurde abgebrochen.
   bei System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei Raven.Client.Connection.Implementation.HttpJsonRequest.<>c__DisplayClass36_0.<<SendRequestInternal>b__0>d.MoveNext()
   --- Ende der internen Ausnahmestapelüberwachung ---
   bei Raven.Client.Connection.Implementation.HttpJsonRequest.<>c__DisplayClass36_0.<<SendRequestInternal>b__0>d.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei Raven.Client.Connection.Implementation.HttpJsonRequest.<RunWithAuthRetry>d__38`1.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei Raven.Client.Connection.Implementation.HttpJsonRequest.<ReadResponseJsonAsync>d__35.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei Raven.Client.Connection.Async.AsyncServerClient.<QueryAsyncAsGet>d__103.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei Raven.Client.Connection.ReplicationInformerBase`1.<TryOperationAsync>d__34`1.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei Raven.Client.Connection.ReplicationInformerBase`1.<ExecuteWithReplicationAsync>d__33`1.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei Raven.Client.Connection.Async.AsyncServerClient.<ExecuteWithReplication>d__172`1.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei Raven.Client.Document.AbstractDocumentQuery`2.<ExecuteActualQueryAsync>d__176.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei Raven.Client.Document.AsyncDocumentQuery`1.<InitAsync>d__120.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei Raven.Client.Document.AsyncDocumentQuery`1.<ToListAsync>d__110.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   bei NServiceBus.Persistence.RavenDB.QueryTimeouts.<GetCleanupChunk>d__13.MoveNext() in C:\Projects\NServiceBus.RavenDB\src\NServiceBus.RavenDB\Timeouts\QueryTimeouts.cs:Zeile 152.
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   bei NServiceBus.Persistence.RavenDB.QueryTimeouts.<GetNextChunk>d__12.MoveNext() in C:\Projects\NServiceBus.RavenDB\src\NServiceBus.RavenDB\Timeouts\QueryTimeouts.cs:Zeile 73.
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   bei NServiceBus.ExpiredTimeoutsPoller.<SpinOnce>d__11.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei System.Runtime.CompilerServices.ConfiguredTaskAwaitable.ConfiguredTaskAwaiter.GetResult()
   bei NServiceBus.ExpiredTimeoutsPoller.<InnerPoll>d__10.MoveNext()
--- Ende der Stapelüberwachung vom vorhergehenden Ort, an dem die Ausnahme ausgelöst wurde ---
   bei System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   bei System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   bei System.Runtime.CompilerServices.ConfiguredTaskAwaitable.ConfiguredTaskAwaiter.GetResult()
   bei NServiceBus.ExpiredTimeoutsPoller.<Poll>d__9.MoveNext()
16:42:46 Warn DeferringToNonLocal.Endpoint: The circuit breaker for TimeoutStorageConnectivity is now in the armed state
16:42:47 Info DeferringToNonLocal.Endpoint: Shutdown complete.

notice the part around:

16:41:06 Debug DeferringToNonLocal.Endpoint: Polling for timeouts at 18.12.2017 15:41:06.
16:41:06 Debug DeferringToNonLocal.Endpoint: Calling GetCleanupChunk

The later entry is an additional log statement I added. There is another log statement which is added once GetCleanupChunk is done. It doesn't show up in the log file on failed tests.

timbussmann commented 6 years ago

ping @Particular/ravendb-persistence-maintainers

mauroservienti commented 6 years ago

What’s interesting is that the failure occurs locally only, and not on TC

danielmarbach commented 4 years ago

I ran the test over a dozen of times on my machine using the latest versions and I did not run into any issues. While walking through the timeout query code I saw though that every query that we issue can effectively run up to the query timeout that is defined on the database or server which by default is 300 seconds

image

https://ravendb.net/docs/article-page/4.2/csharp/server/configuration/database-configuration

Every query in the timeout seam including the GetNextChunk could theoretically take up to 300 seconds and therefore hang/block for that specific amount of time. But like I said I wasn't able to reproduce it.

We are closing this for now. Should it come up again we have the necessary breadcrumbs here to further investigate.