SocketException in BatchedSeqSink.EmitBatchAsync after upgrade to .Net 8 and Serilog 3.1.1/Serilog.Sinks.Seq 6.0.0

[plj6502]

Hi,
After upgrading to .Net 8 and Serilog 3.1.1/Serilog.Sinks.Seq 6.0.0 we are now getting SocketException from a timer triggered background thread. See entire stacktrace below. Any way to solve this ?

System.AggregateException: A Task's exception(s) were not observed either by Waiting on the Task or accessing its Exception property. As a result, the unobserved exception was rethrown by the finalizer thread. (Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host..)
---> System.IO.IOException: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host..
---> System.Net.Sockets.SocketException (10054): An existing connection was forcibly closed by the remote host.
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.CreateException(SocketError error, Boolean forAsyncThrow)
at System.Net.Sockets.NetworkStream.ReadAsync(Memory1 buffer, CancellationToken cancellationToken) at System.Net.Http.HttpConnection.PrepareForReuse(Boolean async) at System.Net.Http.HttpConnectionPool.TryGetPooledHttp11Connection(HttpRequestMessage request, Boolean async, HttpConnection& connection, HttpConnectionWaiter1& waiter)
at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at System.Net.Http.HttpConnectionPool.SendAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
at System.Net.Http.HttpConnectionPoolManager.SendAsyncCore(HttpRequestMessage request, Uri proxyUri, Boolean async, Boolean doRequestAuth, Boolean isProxyConnect, CancellationToken cancellationToken)
at System.Net.Http.HttpConnectionPoolManager.SendAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
at System.Net.Http.HttpMessageHandlerStage.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
at System.Net.Http.SocketsHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
at System.Net.Http.HttpClient.g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at System.Net.Http.HttpClient.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
at Serilog.Sinks.Seq.Http.SeqIngestionApiClient.TryIngestAsync(String payload, String mediaType)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at Serilog.Sinks.Seq.Http.SeqIngestionApi.IngestAsync(String clefPayload)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at Serilog.Sinks.Seq.Batched.BatchedSeqSink.EmitBatchAsync(IEnumerable1 events) at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) at Serilog.Sinks.Seq.Batched.BatchedSeqSink.EmitBatchAsync(IEnumerable1 events)
at Serilog.Sinks.PeriodicBatching.PeriodicBatchingSink.OnTick()
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at Serilog.Sinks.PeriodicBatching.PortableTimer.OnTick()
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
at System.Threading.TimerQueue.FireNextTimers()
at System.Threading.ThreadPoolWorkQueue.Dispatch()
at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
--- End of stack trace from previous location ---

--- End of inner exception stack trace ---
--- End of inner exception stack trace ---

[nblumhardt]

Hi! Thanks for getting in touch.

I believe this is a bug in the 6.0.0 sink which we've fixed in 7.0.0-dev-* version (which has a major version increment because it relies on a rewrite of the underlying Serilog batched sink infrastructure).

Would it be possible to confirm that the 7.0.0-dev-* versions fix it for you? We're currently working to build confidence in that version so that it can be marked stable, but the fix was only made a couple of weeks ago so feedback on it would be really valuable.

Best regards,
Nick

[plj6502]

Hi Nick, Thanks for the reply - yes I will try out the 7.0.0-dev-* and get back to you with the result.

[plj6502]

Hi Nick, I have now tried 7.0.0-dev-00276 and the bug is also present here.

[nblumhardt]

Thanks for checking it out, @plj6502.

The 7.0.0-dev-* versions should pull in a rewrite (4.0.0-*) of Serilog.Sinks.PeriodicBatching, which doesn't use a background timer at all. There is still a possibility that there's an unhandled task exception in there somewhere I've missed, but the stack trace (and origin of the exception) should be completely different.

Would it be possible to please capture the stack trace/error message obtained using the updated version? And also check to ensure that the project isn't pulling in an older Serilog.Sinks.PeriodicBatching build and e.g. ignoring downgrade warnings?

Or alternatively, if there's any way to create a minimal repro that would be great (though I understand this probably isn't feasible in this case).

Best regards,
Nick

[nblumhardt]

(Edited your replies to remove your email signature.)

[poullj]

Not really in a position where I can use development versions - so in order to get our .net 8 upgrade production ready I have rolled back serilog/seq to last versions (3.0.1/5.2.3) that has worked here which too my surprise did NOT solved it as the bug was still present.
I then looked for Serilog.Sinks.PeriodicBatching.dll which were there even I cannot trace it from any nuget dependency ?

Can you please advise which versions of Serilog/Seq to use for production code with .net 8.

Exception Info: System.IO.FileNotFoundException: Could not load file or assembly 'Serilog.Sinks.PeriodicBatching, Culture=neutral, PublicKeyToken=null'. The system cannot find the file specified.
File name: 'Serilog.Sinks.PeriodicBatching, Culture=neutral, PublicKeyToken=null'
at System.Reflection.RuntimeAssembly.InternalLoad(AssemblyName assemblyName, StackCrawlMark& stackMark, AssemblyLoadContext assemblyLoadContext, RuntimeAssembly requestingAssembly, Boolean throwOnFileNotFound)
at System.Reflection.Assembly.Load(AssemblyName assemblyRef)
at Serilog.Settings.Configuration.ConfigurationReader.LoadConfigurationAssemblies(IConfiguration section, AssemblyFinder assemblyFinder)
at Serilog.Settings.Configuration.ConfigurationReader..ctor(IConfiguration configSection, AssemblyFinder assemblyFinder, ConfigurationReaderOptions readerOptions, IConfiguration configuration)
at Serilog.ConfigurationLoggerConfigurationExtensions.GetConfigurationReader(IConfiguration configuration, ConfigurationReaderOptions readerOptions, DependencyContext dependencyContext)
at Serilog.ConfigurationLoggerConfigurationExtensions.Configuration(LoggerSettingsConfiguration settingConfiguration, IConfiguration configuration, ConfigurationReaderOptions readerOptions)
at IS.DC.DCAMESClient.App.<>c__DisplayClass3_0.<.ctor>b__2(ILoggingBuilder loggingBuilder) in C:\agent_work\3\s\DanishCrown\IS.DC.DCAMESClient\App.xaml.cs:line 117
at Microsoft.Extensions.Hosting.HostingHostBuilderExtensions.<>c__DisplayClass5_0.b__1(ILoggingBuilder builder)
at Microsoft.Extensions.DependencyInjection.LoggingServiceCollectionExtensions.AddLogging(IServiceCollection services, Action`1 configure)
at Microsoft.Extensions.Hosting.HostingHostBuilderExtensions.<>c__DisplayClass5_0.b__0(HostBuilderContext context, IServiceCollection collection)
at Microsoft.Extensions.Hosting.HostBuilder.InitializeServiceProvider()
at Microsoft.Extensions.Hosting.HostBuilder.Build()

[nblumhardt]

Hi @plj6502, thanks for the update.

Serilog.Sinks.PeriodicBatching is a direct dependency of the Serilog.Sinks.Seq package; not sure what will be causing the assembly load problem.

This part:

Serilog.Sinks.PeriodicBatching, Culture=neutral, PublicKeyToken=null

Is strange - the identity of Serilog.Sinks.PeriodicBatching should be something like:

Serilog.Sinks.PeriodicBatching, Version=4.0.0.0, Culture=neutral, PublicKeyToken=24c2f752a8e58a10

Are you using trimming, bundling, or single-file publishing, or do you have custom sinks in your solution with their own builds of some dependencies?

I'm keen to get to the bottom of the problem, but I haven't been successful reproducing any unobserved task exceptions locally using either 6.0.0 or 7.0.0-dev-* of the Seq sink, unfortunately.

If the 7.0.0-dev-* can be installed properly in even a dev environment, and a stack trace from the unobserved exception collected (if present), we'll be able to nail it down and release an RTM of that package.

At the moment, though, I expect the exception will be benign (though annoying), and you should use Serilog 3.1.1, and Serilog.Sinks.Seq 6.0.0, in production, until we've validated the 7.0.0 fix and released a final version of that package.

Hope this helps, please let me know your thoughts.

[poullj]

"Would it be possible to please capture the stack trace/error message obtained using the updated version? And also check to ensure that the project isn't pulling in an older Serilog.Sinks.PeriodicBatching build and e.g. ignoring downgrade warnings?"

Using Serilog.Sinks.Seq" Version="7.0.0-dev-00276 and Serilog.Sinks.PeriodicBatching, Version=4.0.0-dev-00821....
SocketException still occurs as an unhandled exception that is dispatched to TaskScheduler.UnobservedTaskException.

It now has a slightly different stacktrace

Instead of Serilog.Sinks.PeriodicBatching.PortableTimer.OnTick() now Serilog.Sinks.PeriodicBatching.PeriodicBatchingSink.TryWaitToReadAsync

Hope this helps :-)

[nblumhardt]

Thanks! 👀

[nblumhardt]

I haven't been able to track this down; PeriodicBatchingSink does definitely end up observing task exceptions on the paths I can find. I spotted dotnet/runtime#91100 which isn't directly related, but suggests there could be some more complications at play - the reported stack trace may not actually be the one responsible for the issue.

I'm going to try some workarounds and will let you know when an update is ready. Thanks again!

[KwasiIPD]

I don't use the serilog sink but the nlog.target.seq target and have nearly the same exception.
It's in several different systems but can't reproduce it.

System.IO.IOException: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host..
---> System.Net.Sockets.SocketException (10054): An existing connection was forcibly closed by the remote host.
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.CreateException(SocketError error, Boolean forAsyncThrow)
at System.Net.Sockets.NetworkStream.ReadAsync(Memory1 buffer, CancellationToken cancellationToken) at System.Net.Http.HttpConnection.PrepareForReuse(Boolean async) at System.Net.Http.HttpConnectionPool.TryGetPooledHttp11Connection(HttpRequestMessage request, Boolean async, HttpConnection& connection, HttpConnectionWaiter1& waiter)
at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at System.Net.Http.HttpConnectionPool.SendAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
at System.Net.Http.HttpConnectionPoolManager.SendAsyncCore(HttpRequestMessage request, Uri proxyUri, Boolean async, Boolean doRequestAuth, Boolean isProxyConnect, CancellationToken cancellationToken)
at System.Net.Http.HttpConnectionPoolManager.SendAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken)
at System.Net.Http.HttpConnectionHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
at System.Net.Http.HttpMessageHandlerStage.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at System.Net.Http.SocketsHttpHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
at System.Net.Http.HttpClient.g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at NLog.Targets.Seq.SeqTarget.SendPayload(StringBuilder payload)
at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
at NLog.Targets.Seq.SeqTarget.PostBatch(IList1 logEvents) at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) at NLog.Targets.Seq.SeqTarget.PostBatch(IList1 logEvents)
at NLog.Targets.Seq.SeqTarget.Write(IList1 logEvents) at NLog.Targets.Target.WriteAsyncThreadSafe(IList1 logEvents)
at NLog.Targets.Target.WriteAsyncLogEvents(IList`1 logEvents)
at NLog.Targets.Wrappers.AsyncTargetWrapper.WriteLogEventsInQueue(Int32 batchSize, String reason)
at NLog.Targets.Wrappers.AsyncTargetWrapper.ProcessPendingEvents(Object state)
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
at System.Threading.TimerQueue.FireNextTimers()
at System.Threading.ThreadPoolWorkQueue.Dispatch()
at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
--- End of stack trace from previous location ---

--- End of inner exception stack trace ---