Background worker unexpectedly shutdown when sentry server is down, does not recover

[phillipcaofph]

Package

Sentry

.NET Flavor

.NET

.NET Version

7.0.306

OS

Any (not platform specific)

SDK Version

4.2.1

Self-Hosted Sentry Version

24.2.0

Steps to Reproduce

1. Sentry server is down
2. Sentry events are sent

Expected Result

Events are dropped and background worker continues working.

Actual Result

After being stuck for about 2min, waiting for envelope to be sent, background working thinks the Shutdown token was triggered and exits.

It appears that an OperationCanceledException can be thrown within SendEnvelopeAsync and the background worker will misinterpret that as a shutdown, causing it to stop processing events.

01:19:32.883 [DBG] [Sentry.ISentryClient] Attempting to finish Transaction a5b7cdcda27d2365.
01:19:32.884 [DBG] [Sentry.ISentryClient] Finished Transaction a5b7cdcda27d2365.
01:19:32.884 [INF] [Sentry.ISentryClient] Capturing transaction.
01:19:32.884 [DBG] [Sentry.ISentryClient] Enqueuing envelope e211bab4febb4047abdf430d60539028
01:19:32.884 [INF] [Sentry.ISentryClient] Envelope queued up: 'e211bab4febb4047abdf430d60539028'
01:19:32.886 [DBG] [Sentry.ISentryClient] HttpTransport: Attached client report to envelope e211bab4febb4047abdf430d60539028.
01:19:32.892 [DBG] [Sentry.ISentryClient] SentryPropagator.Extract
01:19:32.892 [DBG] [Sentry.ISentryClient] Baggage
01:19:32.892 [DBG] [Sentry.ISentryClient] No SentryTraceHeader present in carrier
01:19:32.892 [DBG] [Sentry.ISentryClient] SentryPropagator.Inject
01:19:32.892 [DBG] [Sentry.ISentryClient] Envelope handed off to transport (event ID: 'e211bab4febb4047abdf430d60539028'). 1 items in queue.

01:19:32.900 [ERR] [Sentry.ISentryClient] Error while processing envelope (event ID: 'e211bab4febb4047abdf430d60539028'). 1 items in queue.
System.Net.Http.HttpRequestException: Connection refused (sentry:443)
 ---> System.Net.Sockets.SocketException (111): Connection refused
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
   at System.Net.Sockets.Socket.<ConnectAsync>g__WaitForConnectWithCancellation|281_0(AwaitableSocketAsyncEventArgs saea, ValueTask connectTask, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectToTcpHostAsync(String host, Int32 port, HttpRequestMessage initialRequest, Boolean async, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpConnectionPool.ConnectToTcpHostAsync(String host, Int32 port, HttpRequestMessage initialRequest, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.AddHttp11ConnectionAsync(QueueItem queueItem)
   at System.Threading.Tasks.TaskCompletionSourceWithCancellation`1.WaitWithCancellationAsync(CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.HttpConnectionWaiter`1.WaitForConnectionAsync(Boolean async, CancellationToken requestCancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsyncCore(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at System.Net.Http.DecompressionHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
   at Sentry.Internal.Http.GzipBufferedRequestBodyHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at Sentry.Internal.Http.RetryAfterHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
   at Sentry.Internal.Http.HttpTransport.SendEnvelopeAsync(Envelope envelope, CancellationToken cancellationToken)
   at Sentry.Internal.BackgroundWorker.DoWorkAsync()
01:19:32.905 [DBG] [Sentry.ISentryClient] De-queueing event e211bab4febb4047abdf430d60539028
01:19:42.882 [DBG] [Sentry.ISentryClient] Attempting to finish Transaction d3ec612a867a5f49.
01:19:42.882 [DBG] [Sentry.ISentryClient] Finished Transaction d3ec612a867a5f49.
01:19:42.882 [INF] [Sentry.ISentryClient] Capturing transaction.
01:19:42.883 [DBG] [Sentry.ISentryClient] Enqueuing envelope 3c815543be064dfb945ef56203be6f47
01:19:42.883 [INF] [Sentry.ISentryClient] Envelope queued up: '3c815543be064dfb945ef56203be6f47'
01:19:42.883 [DBG] [Sentry.ISentryClient] SentryPropagator.Extract
01:19:42.883 [DBG] [Sentry.ISentryClient] Baggage
01:19:42.883 [DBG] [Sentry.ISentryClient] No SentryTraceHeader present in carrier
01:19:42.883 [DBG] [Sentry.ISentryClient] SentryPropagator.Inject
01:19:42.883 [DBG] [Sentry.ISentryClient] Envelope handed off to transport (event ID: '3c815543be064dfb945ef56203be6f47'). 1 items in queue.
01:19:52.883 [DBG] [Sentry.ISentryClient] Attempting to finish Transaction 30d34cd79a897f55.
01:19:52.883 [DBG] [Sentry.ISentryClient] Finished Transaction 30d34cd79a897f55.
01:19:52.883 [INF] [Sentry.ISentryClient] Capturing transaction.
01:19:52.883 [DBG] [Sentry.ISentryClient] Enqueuing envelope 36d1dc981ff64430aed7657963e5459f
01:19:52.883 [INF] [Sentry.ISentryClient] Envelope queued up: '36d1dc981ff64430aed7657963e5459f'
01:20:02.886 [DBG] [Sentry.ISentryClient] Attempting to finish Transaction 71a71394edbb9681.
01:20:02.886 [DBG] [Sentry.ISentryClient] Finished Transaction 71a71394edbb9681.
01:20:02.886 [INF] [Sentry.ISentryClient] Capturing transaction.
01:20:02.886 [DBG] [Sentry.ISentryClient] Enqueuing envelope f4f2def1ac964a67a35b0b7783be9a93
01:20:02.886 [INF] [Sentry.ISentryClient] Envelope queued up: 'f4f2def1ac964a67a35b0b7783be9a93'
01:20:12.884 [DBG] [Sentry.ISentryClient] Attempting to finish Transaction 399604c5b673d21d.
01:20:12.885 [DBG] [Sentry.ISentryClient] Finished Transaction 399604c5b673d21d.
01:20:12.885 [INF] [Sentry.ISentryClient] Capturing transaction.
01:20:12.885 [DBG] [Sentry.ISentryClient] Enqueuing envelope bf0185d77c984cddaed3f9ab66eb1e7f
01:20:12.885 [INF] [Sentry.ISentryClient] Envelope queued up: 'bf0185d77c984cddaed3f9ab66eb1e7f'
01:20:22.883 [DBG] [Sentry.ISentryClient] Attempting to finish Transaction 7bab88d23a46aca.
01:20:22.883 [DBG] [Sentry.ISentryClient] Finished Transaction 7bab88d23a46aca.
01:20:22.883 [INF] [Sentry.ISentryClient] Capturing transaction.
01:20:22.883 [DBG] [Sentry.ISentryClient] Enqueuing envelope 2ae0550dfdcd4af6a5fe4a81aefc04d3
01:20:22.883 [INF] [Sentry.ISentryClient] Envelope queued up: '2ae0550dfdcd4af6a5fe4a81aefc04d3'
01:20:32.884 [DBG] [Sentry.ISentryClient] Attempting to finish Transaction 8563018e2a04ce21.
01:20:32.884 [DBG] [Sentry.ISentryClient] Finished Transaction 8563018e2a04ce21.
01:20:32.884 [INF] [Sentry.ISentryClient] Capturing transaction.
01:20:32.884 [DBG] [Sentry.ISentryClient] Enqueuing envelope 271996f2b2e74996a3f826b40dcf2f6b
01:20:32.884 [INF] [Sentry.ISentryClient] Envelope queued up: '271996f2b2e74996a3f826b40dcf2f6b'
01:20:42.886 [DBG] [Sentry.ISentryClient] Attempting to finish Transaction 5e3fef0fc0f536b8.
01:20:42.886 [DBG] [Sentry.ISentryClient] Finished Transaction 5e3fef0fc0f536b8.
01:20:42.886 [INF] [Sentry.ISentryClient] Capturing transaction.
01:20:42.886 [DBG] [Sentry.ISentryClient] Enqueuing envelope 36d77649878c46cda1e6cb1834151d94
01:20:42.886 [INF] [Sentry.ISentryClient] Envelope queued up: '36d77649878c46cda1e6cb1834151d94'
01:20:52.884 [DBG] [Sentry.ISentryClient] Attempting to finish Transaction 92866433c3c6e08b.
01:20:52.884 [DBG] [Sentry.ISentryClient] Finished Transaction 92866433c3c6e08b.
01:20:52.884 [INF] [Sentry.ISentryClient] Capturing transaction.
01:20:52.884 [DBG] [Sentry.ISentryClient] Enqueuing envelope 5b64fbcd7b2d40b3b222be4531486246
01:20:52.884 [INF] [Sentry.ISentryClient] Envelope queued up: '5b64fbcd7b2d40b3b222be4531486246'
01:21:02.885 [DBG] [Sentry.ISentryClient] Attempting to finish Transaction c27a90447e8b5ef7.
01:21:02.885 [DBG] [Sentry.ISentryClient] Finished Transaction c27a90447e8b5ef7.
01:21:02.885 [INF] [Sentry.ISentryClient] Capturing transaction.
01:21:02.885 [DBG] [Sentry.ISentryClient] Enqueuing envelope 00e6abc0b6ae463d8e71499b0f11f729
01:21:02.885 [INF] [Sentry.ISentryClient] Envelope queued up: '00e6abc0b6ae463d8e71499b0f11f729'
01:21:12.885 [DBG] [Sentry.ISentryClient] Attempting to finish Transaction 1ac8f0f15d8306b0.
01:21:12.885 [DBG] [Sentry.ISentryClient] Finished Transaction 1ac8f0f15d8306b0.
01:21:12.885 [INF] [Sentry.ISentryClient] Capturing transaction.
01:21:12.885 [DBG] [Sentry.ISentryClient] Enqueuing envelope fde46560ee1a4d8ba0bbe0dba872a43b
01:21:12.885 [INF] [Sentry.ISentryClient] Envelope queued up: 'fde46560ee1a4d8ba0bbe0dba872a43b'
01:21:22.885 [DBG] [Sentry.ISentryClient] Attempting to finish Transaction 9fbbe86f8b998ae6.
01:21:22.885 [DBG] [Sentry.ISentryClient] Finished Transaction 9fbbe86f8b998ae6.
01:21:22.885 [INF] [Sentry.ISentryClient] Capturing transaction.
01:21:22.885 [DBG] [Sentry.ISentryClient] Enqueuing envelope ed65b7b8bad04da2ae5a0ffb2e073787
01:21:22.885 [INF] [Sentry.ISentryClient] Envelope queued up: 'ed65b7b8bad04da2ae5a0ffb2e073787'

01:21:22.886 [INF] [Sentry.ISentryClient] Shutdown token triggered. Time to exit. 11 items in queue.

[bitsandfoxes]

Thanks for raising this! That doesn't sound right but it sounds fairly straight forward to reproduce.

[phillipcaofph]

On further research, it looks like the dotnet HTTP client in dotnet core and NET5+ will throw TaskCanceledException if on timeout, which inherits from OperationCanceledException. This explains why this could be happening.

I've created #3284 as a potential fix

[bitsandfoxes]

That's a great catch! Thanks for contributing!