1 year ago

#364768

test-img

Banshee

IOException from Serilog with SEQ? How to troubleshoot and solve?

I have a simple Windows Service with the following features :

  • .Net 6.0
  • RabbitMQ
  • Serilog
  • Serilog Seq, email, console, MSSql, Configuration...
  • Dependency Injection (Microsoft)
  • EntityFramework
  • HostBuilder

The service starts up fine MQ queues are created and log data is coming in to both console and Seq. A couple of seconds after startup(while application waiting on MQ messages) an IOException is thrown which is posted to both console and Seq, this is how the console looks like :

    [17:31:25.720 [Information] Myapp.Cloud.SharedObjectService.Program "Myapp.Cloud.SharedObjectService" microservice starting up.
    
    [17:31:25.790 [Information] Myapp.Cloud.SharedObjectService.Program Database: Data Source=Uranus;Initial Catalog=MyappCloudDev;User ID=sa;Password=jaffa
    
    [17:31:26.689 [Information]  "Myapp.Cloud.SharedObjectService" all built.
    
    [17:31:26.982 [Information] Myapp.Cloud.MQ.MQCloudProducer MQCloudProducer.Producer is connecting to MQ service "Myapp.Cloud.MQ" at "localhost"
    
    [17:31:26.982 [Information] Myapp.Cloud.MQ.MQCloudConsumer MQCloudConsumer.Connecting to MQ service "Myapp.Cloud.MQ" at "localhost" with user """" and DestinationCode "SharedObjectService"
    
    [17:31:27.143 [Information] Myapp.Cloud.MQ.MQCloudProducer Producer connected to MQ service "Myapp.Cloud.MQ".
    
    [17:31:27.144 [Information] Myapp.Cloud.MQ.MQCloudConsumer MQCloudConsumer.Connecting to MQ service "Myapp.Cloud.MQ" at "localhost" with user """" and DestinationCode "SharedObjectService"
    
    [17:31:27.144 [Information] Myapp.Cloud.SharedObjectService.BusinessLogicLayer.SharedObjectService "SharedObject" microservice started.
    
    [17:31:36.504 [Information] Myapp.Cloud.MQ.MQCloudConsumer MQCloudConsumer.Connected to MQ service queue "Myapp.Cloud.MQ":"SendSharedObject" at "localhost".
    
    [17:31:36.504 [Information] Myapp.Cloud.MQ.MQCloudConsumer MQCloudConsumer.Connected to MQ service queue "Myapp.Cloud.MQ":"OutputResponse" at "localhost".
    
    FirstChanceException : 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.Socket.AwaitableSocketAsyncEventArgs.ReceiveAsync(Socket socket, CancellationToken cancellationToken)
       at System.Net.Sockets.Socket.ReceiveAsync(Memory`1 buffer, SocketFlags socketFlags, Boolean fromNetworkStream, CancellationToken cancellationToken)
       at System.Net.Sockets.NetworkStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken)
       at System.Net.Http.HttpConnection.<CheckUsabilityOnScavenge>g__ReadAheadWithZeroByteReadAsync|44_0()
       at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
       at System.Net.Http.HttpConnection.<CheckUsabilityOnScavenge>g__ReadAheadWithZeroByteReadAsync|44_0()
       at System.Net.Http.HttpConnection.CheckUsabilityOnScavenge()
       at System.Net.Http.HttpConnectionPool.<CleanCacheAndDisposeIfUnused>g__IsUsableConnection|115_2(HttpConnectionBase connection, Int64 nowTicks, TimeSpan pooledConnectionLifetime, TimeSpan pooledConnectionIdleTimeout)
       at System.Net.Http.HttpConnectionPool.<CleanCacheAndDisposeIfUnused>g__ScavengeConnectionList|115_1[T](List`1 list, List`1& toDispose, Int64 nowTicks, TimeSpan pooledConnectionLifetime, TimeSpan pooledConnectionIdleTimeout)
       at System.Net.Http.HttpConnectionPool.CleanCacheAndDisposeIfUnused()
       at System.Net.Http.HttpConnectionPoolManager.RemoveStalePools()
       at System.Net.Http.HttpConnectionPoolManager.<>c.<.ctor>b__11_0(Object s)
       at System.Threading.TimerQueueTimer.CallCallback(Boolean isThreadPool)
       at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
       at System.Threading.TimerQueue.FireNextTimers()
       at System.Threading.TimerQueue.AppDomainTimerCallback(Int32 id)
       at System.Threading.UnmanagedThreadPoolWorkItem.System.Threading.IThreadPoolWorkItem.Execute()
       at System.Threading.ThreadPoolWorkQueue.Dispatch()
       at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
       at System.Threading.Thread.StartCallback()
    --- End of stack trace from previous location ---
    
       --- End of inner exception stack trace ---
       at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    FirstChanceException : 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.
       --- End of inner exception stack trace ---
       at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)

Its only the AppDomain.CurrentDomain.FirstChanceException that fetch this exception. Break on all errors or stepping do not show exception or where it occurs? The Exception do only have a system stacktrace, nothing related ty the project code.

If I remove the Seq part of the appsettings file the problem is gone.

The Serilog part of appsettings.json look like this :

    "serilog": {
        "Using": [ "Serilog.Sinks.MSSqlServer", "Serilog.Sinks.Email" ],
        "MinimumLevel": {
          "Default": "Information",
          "Override": {
            "Microsoft": "Warning",
            "System": "Warning"
          }
        },
        "Enrich": [ "FromLogContext", "WithMachineName", "WithProcessId" ],
        "WriteTo": [
          {
            "Name": "Console",
            "Args": {
              "outputTemplate": "[{Timestamp:HH:mm:ss.fff} [{Level}] {SourceContext} {Message}{NewLine}{Exception}",
              "theme": "Serilog.Sinks.SystemConsole.Themes.AnsiConsoleTheme::Code, Serilog.Sinks.Console"
            }
          },
          {
            "Name": "File",
            "Args": {
              "path": "/Logs/log.txt",
              "outputTemplate": "{Timestamp:G} {SourceContext} [{Level}] {Message}{NewLine:1}{Exception:1}",
              "formatter": "Serilog.Formatting.Json.JsonFormatter, Serilog",
              "fileSizeLimitBytes": 1000000,
              "rollOnFileSizeLimit": "true",
              "shared": "true",
              "flushToDiskInterval": 3
            }
    
          },
          {
            "Name": "Seq",
            "Args": {
              "serverUrl": "http://localhost:8081/"
            }
          },
          {
            "Name": "MSSqlServer",
            "Args": {
              "connectionString": "Data Source=x;Initial Catalog=MyAppClouddev;User ID=x;Password=x",
              "tableName": "Logs",
              "restrictedToMinimumLevel": "Fatal"
            }
          }
        ]
      }

Serilog are called like this(Structured logging) :

_logger.LogInformation("OutputResponse received {@message}, {@messageGuid}, {@messageChainGuid}", args.Data, args.Data.MessageGuid, args.Data.MessageChainGuid);

Some times it might not just be string values that are logged but whole objects.

How do you troubleshoot this?

EDIT : When turning off "just my code" I can see that the exception is thrown from within a Microsoft library and I can see that the URL(with port) is the same as the SEQ service got(serverURL) so that Is why I Think the problem are due to this sink. And if I remove the Seq part of the configuration I do not get any exceptions. The regular logging to console are working just fine.

serilog

ioexception

seq

0 Answers

Your Answer

Accepted video resources