TCP Client not properly disposing of connection

[RStivanson]

Hello,

Issue:
It appears that there is a bug in v3.0+ where the TCP client does not correctly dispose of its connection. This results in the background thread crashing silently as it tries to bind to an already bound port.

Details:
We have a site set up using IIS, and after ~20-30 minutes of inactivity (no requests/logs/etc) all logging stops due to the Graylog sink trying to reconnect on a TCP port that was already bound on the initial startup. This exception was silent and did not even show in the Windows Event Viewer, nor was it causing the application to stop functioning, however all logging (all Serilog sinks) stopped working. It would seem as if this was a detached background thread, but I'm not entirely familiar with how Serilog handles its providers/sinks. I have attached some information below, we had to use DebugDiag to catch the exception.

The offending line appears to be line 65 in the TcpTransportClient class:

serilog-sinks-graylog/src/Serilog.Sinks.Graylog.Core/Transport/Tcp/TcpTransportClient.cs

Line 65 in 64532fa

await _client.ConnectAsync(_address, port).ConfigureAwait(false);

Workaround:
There are a couple "workarounds" for these but these do not actually fix the core issue:

• Use the UDP transport type to bypass the TCP Client
• Rolling back to v2.3.0 resolves the issue as the TCP connection is properly disposed.
• Recycling the app pool also resolves the issue, but it will just reoccur after a period of inactivity.

Sink config:

"Serilog": {
  "Using": [ "Serilog.Sinks.Graylog" ],
  "MinimumLevel": {
    "Default": "Debug",
    "Override": {
      "Microsoft": "Information",
      "Microsoft.Hosting.Lifetime": "Information"
    }
  },
  "WriteTo": [
    {
      "Name": "Graylog",
      "Args": {
        "hostnameOrAddress": "[omitted]",
        "port": "12201",
        "transportType": "Tcp"
      }
    }
  ]
}

App pool config:

[eete22]

We are also experiencing this issue when using the library with version 3.1.1 and .Net framework. If the connection for some reason is closed down, the library will not manage to reconnect.

Initially, one of these errors appear in the self-log:

 System.IO.IOException: Unable to write data to the transport connection: An established connection was aborted by the software in your host machine. ---> System.Net.Sockets.SocketException: An established connection was aborted by the software in your host machine

or

System.InvalidOperationException: BeginConnect cannot be called while another asynchronous operation is in progress on the same Socket.

It then starts logging these exceptions:

System.Net.Sockets.SocketException: A connect request was made on an already connected socket

And no logs are sent to Graylog.

It would be great if the library was able to reconnect and also would retry sending the log that was being sent when the exception was thrown.

Looked briefly in the code, and seems that there was a recent change that tries to reuse the TcpClient (9e99541#diff-8e1abe872c46b6cae1e6bbbe1d75740d57568e0af85b353602c7157f5522a5e0), but as I understand it a TcpClient is not designed to be reused. So that might be a possible cause of the issue.

Full stack traces below:

Oops something going wrong System.AggregateException: One or more errors occurred. ---> System.InvalidOperationException: BeginConnect cannot be called while another asynchronous operation is in progress on the same Socket.
 at System.Net.Sockets.Socket.BeginConnect(EndPoint remoteEP, AsyncCallback callback, Object state)
 at System.Net.Sockets.Socket.BeginConnect(IPAddress address, Int32 port, AsyncCallback requestCallback, Object state)
 at System.Net.Sockets.TcpClient.BeginConnect(IPAddress address, Int32 port, AsyncCallback requestCallback, Object state)
 at System.Threading.Tasks.TaskFactory`1.FromAsyncImpl[TArg1,TArg2](Func`5 beginMethod, Func`2 endFunction, Action`1 endAction, TArg1 arg1, TArg2 arg2, Object state, TaskCreationOptions creationOptions)
 at System.Net.Sockets.TcpClient.ConnectAsync(IPAddress address, Int32 port)
 at Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<Connect>d__8.MoveNext()
--- 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 Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<EnsureConnection>d__7.MoveNext()
--- 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 Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<Send>d__6.MoveNext()
 --- End of inner exception stack trace ---
---> (Inner Exception #0) System.InvalidOperationException: BeginConnect cannot be called while another asynchronous operation is in progress on the same Socket.
 at System.Net.Sockets.Socket.BeginConnect(EndPoint remoteEP, AsyncCallback callback, Object state)
 at System.Net.Sockets.Socket.BeginConnect(IPAddress address, Int32 port, AsyncCallback requestCallback, Object state)
 at System.Net.Sockets.TcpClient.BeginConnect(IPAddress address, Int32 port, AsyncCallback requestCallback, Object state)
 at System.Threading.Tasks.TaskFactory`1.FromAsyncImpl[TArg1,TArg2](Func`5 beginMethod, Func`2 endFunction, Action`1 endAction, TArg1 arg1, TArg2 arg2, Object state, TaskCreationOptions creationOptions)
 at System.Net.Sockets.TcpClient.ConnectAsync(IPAddress address, Int32 port)
 at Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<Connect>d__8.MoveNext()
--- 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 Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<EnsureConnection>d__7.MoveNext()
--- 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 Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<Send>d__6.MoveNext()<---

Oops something going wrong System.AggregateException: One or more errors occurred. ---> System.IO.IOException: Unable to write data to the transport connection: An established connection was aborted by the software in your host machine. ---> System.Net.Sockets.SocketException: An established connection was aborted by the software in your host machine
 at System.Net.Sockets.Socket.BeginSend(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags, AsyncCallback callback, Object state)
 at System.Net.Sockets.NetworkStream.BeginWrite(Byte[] buffer, Int32 offset, Int32 size, AsyncCallback callback, Object state)
 --- End of inner exception stack trace ---
 at System.Net.Sockets.NetworkStream.BeginWrite(Byte[] buffer, Int32 offset, Int32 size, AsyncCallback callback, Object state)
 at System.IO.Stream.<>c.<BeginEndWriteAsync>b__53_0(Stream stream, ReadWriteParameters args, AsyncCallback callback, Object state)
 at System.Threading.Tasks.TaskFactory`1.FromAsyncTrim[TInstance,TArgs](TInstance thisRef, TArgs args, Func`5 beginMethod, Func`3 endMethod)
 at System.IO.Stream.BeginEndWriteAsync(Byte[] buffer, Int32 offset, Int32 count)
 at System.IO.Stream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
 at System.IO.Stream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count)
 at Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<Send>d__6.MoveNext()
 --- End of inner exception stack trace ---
---> (Inner Exception #0) System.IO.IOException: Unable to write data to the transport connection: An established connection was aborted by the software in your host machine. ---> System.Net.Sockets.SocketException: An established connection was aborted by the software in your host machine
 at System.Net.Sockets.Socket.BeginSend(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags, AsyncCallback callback, Object state)
 at System.Net.Sockets.NetworkStream.BeginWrite(Byte[] buffer, Int32 offset, Int32 size, AsyncCallback callback, Object state)
 --- End of inner exception stack trace ---
 at System.Net.Sockets.NetworkStream.BeginWrite(Byte[] buffer, Int32 offset, Int32 size, AsyncCallback callback, Object state)
 at System.IO.Stream.<>c.<BeginEndWriteAsync>b__53_0(Stream stream, ReadWriteParameters args, AsyncCallback callback, Object state)
 at System.Threading.Tasks.TaskFactory`1.FromAsyncTrim[TInstance,TArgs](TInstance thisRef, TArgs args, Func`5 beginMethod, Func`3 endMethod)
 at System.IO.Stream.BeginEndWriteAsync(Byte[] buffer, Int32 offset, Int32 count)
 at System.IO.Stream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
 at System.IO.Stream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count)
 at Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<Send>d__6.MoveNext()

Oops something going wrong System.AggregateException: One or more errors occurred. ---> System.Net.Sockets.SocketException: A connect request was made on an already connected socket
  at System.Net.Sockets.Socket.BeginConnectEx(EndPoint remoteEP, Boolean flowContext, AsyncCallback callback, Object state)
  at System.Net.Sockets.Socket.BeginConnect(EndPoint remoteEP, AsyncCallback callback, Object state)
  at System.Net.Sockets.Socket.BeginConnect(IPAddress address, Int32 port, AsyncCallback requestCallback, Object state)
  at System.Net.Sockets.TcpClient.BeginConnect(IPAddress address, Int32 port, AsyncCallback requestCallback, Object state)
  at System.Threading.Tasks.TaskFactory`1.FromAsyncImpl[TArg1,TArg2](Func`5 beginMethod, Func`2 endFunction, Action`1 endAction, TArg1 arg1, TArg2 arg2, Object state, TaskCreationOptions creationOptions)
  at System.Net.Sockets.TcpClient.ConnectAsync(IPAddress address, Int32 port)
  at Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<Connect>d__8.MoveNext()
--- 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 Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<EnsureConnection>d__7.MoveNext()
--- 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 Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<Send>d__6.MoveNext()
  --- End of inner exception stack trace ---
---> (Inner Exception #0) System.Net.Sockets.SocketException (0x80004005): A connect request was made on an already connected socket
  at System.Net.Sockets.Socket.BeginConnectEx(EndPoint remoteEP, Boolean flowContext, AsyncCallback callback, Object state)
  at System.Net.Sockets.Socket.BeginConnect(EndPoint remoteEP, AsyncCallback callback, Object state)
  at System.Net.Sockets.Socket.BeginConnect(IPAddress address, Int32 port, AsyncCallback requestCallback, Object state)
  at System.Net.Sockets.TcpClient.BeginConnect(IPAddress address, Int32 port, AsyncCallback requestCallback, Object state)
  at System.Threading.Tasks.TaskFactory`1.FromAsyncImpl[TArg1,TArg2](Func`5 beginMethod, Func`2 endFunction, Action`1 endAction, TArg1 arg1, TArg2 arg2, Object state, TaskCreationOptions creationOptions)
  at System.Net.Sockets.TcpClient.ConnectAsync(IPAddress address, Int32 port)
  at Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<Connect>d__8.MoveNext()
--- 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 Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<EnsureConnection>d__7.MoveNext()
--- 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 Serilog.Sinks.Graylog.Core.Transport.Tcp.TcpTransportClient.<Send>d__6.MoveNext()<---