Can't get TCP logging to work

[mrtoby]

I have no problems to configure and log over UDP to my papertrail destination using this library.
Also, I can easily get data into papertrail by using telnet (over unsecured TCP connection).
But when I try to do the same using this library I only get an exception in the internal NLog log.

2018-06-12 16:13:33.2253 Warn Task faulted Exception: System.IO.IOException: Unable to write data to the transport conne
ction: An existing connection was forcibly closed by the remote host. ---> System.Net.Sockets.SocketException: An existi
ng connection was forcibly closed by the remote host
   at System.Net.Sockets.Socket.BeginSend(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags, AsyncCallbac
k callback, Object state)
   at System.Net.Sockets.NetworkStream.BeginWrite(Byte[] buffer, Int32 offset, Int32 size, AsyncCallback callback, Objec
t state)
   --- End of inner exception stack trace ---
   at System.Net.Sockets.NetworkStream.BeginWrite(Byte[] buffer, Int32 offset, Int32 size, AsyncCallback callback, Objec
t state)
   at NLog.Targets.Syslog.Extensions.TaskExtensions.SafeFromAsync[TArg1,TArg2,TArg3](TaskFactory taskFactory, Func`6 beg
inMethod, Action`1 endMethod, TArg1 arg1, TArg2 arg2, TArg3 arg3, Object state)

My configuration code looks like this:

            SyslogTarget = new SyslogTarget
            {
                Name = "syslog",
                Layout =
                    "${level}: ${logger} ${message} ${onexception: -- ${exception:format=type,message} -- ${stacktrace:topFrames=20}}",
                MessageSend =
                {
                    Protocol = ProtocolType.Tcp,
                    Tcp =
                    {
                        Server = host,
                        Port = port,
                        Tls = {Enabled = false}
                    }
                },
                MessageCreation =
                {
                    Facility = Facility.Local7,
                    Rfc = RfcNumber.Rfc5424,
                    Rfc5424 = {AppName = application}
                }
            };
            Config.AddTarget("syslog", SyslogTarget);

Since manual logging using telnet works like a charm from the same computer - I have a hard time believing that the problem is a network problem, or a papertrail related problem.

[luigiberrettini]

Try all the steps in this guide:
https://help.papertrailapp.com/kb/configuration/troubleshooting-remote-syslog-reachability/

Then run the sample application from Visual Studio, editing the text configuration file, to debug the error in SafeFromAsync

Finally try running this code to see if you still get an error:

var tcp = new TcpClient();
tcp.Connect(stringIpAddress, integerPort);
byte[] data = { 0x68, 0x65, 0x6C, 0x6C, 0x6F, 0x0A };
tcp.GetStream().Write(data, 0, data.Length);

[luigiberrettini]

Closing for inactivity: feel free to reopen if needed

[mrtoby]

Hi, it is vacation times in Sweden so I will be unresponsive from time to time.
I have went trough the troubleshooting guide as good as possible, considering I'm running on windows.
My actual services are running on linux machines in Kubernetes, but it doesn't seem to work in any of the places.

I added your sample code (above) to my project and it works like a charm - "hello" to you too!
It also works to log using telnet.

I have no clue about what is wrong...

[luigiberrettini]

You should then debug my code because I extracted those lines from what it does

Try also to run a Syslog Linux VM or container to reduce the complexity due to Kubernetes

[mrtoby]

I have tried to make a code review of the source here in github and I can not really see any problem... Very confusing.

[mrtoby]

I will try to make a local dependency and debug your code and see what happen.

[mrtoby]

While debugging I never reached Tcp.WriteAsync(..).

I tried to change from the default FramingMethod.OctetCounting to FramingMethod.NonTransparent. By doing so, I got calls through to WriteAsync and logs started to appear in papertrail.

My project use TargetFramework netcoreapp2.0, could that be a problem?

In some documentation it seems like the methods Stream.BeginWrite and Stream.EndWrite is legacy and should be avoided. To me it looks complicated to use them, but maybe this is a compability issue?

[luigiberrettini]

While debugging I never reached Tcp.WriteAsync

The original error you reported is System.IO.IOException: Unable to write data to the transport conne ction: An existing connection was forcibly closed by the remote host: this means that a write is tried and fails.

I tried to change from the default FramingMethod.OctetCounting to FramingMethod.NonTransparent. By doing so, I got calls through to WriteAsync and logs started to appear in papertrail.

The framing method should be supported and configured by the Syslog server and cannot cause an IOException: can you debug framing and tell me what exception prevents WriteAsync to be called?
If you try the test bed I detailed in the README you can see that frames arrive even with octet-counting
framework

My project use TargetFramework netcoreapp2.0, could that be a problem?

The target framework is not a problem and you can see that the test console application is targeting netcoreapp2.0

In some documentation it seems like the methods Stream.BeginWrite and Stream.EndWrite is legacy and should be avoided. To me it looks complicated to use them, but maybe this is a compability issue?

SafeFromAsync is doing what it is advised to do with FromAsync but avoiding problems related to errors not being wrapped in a Task, therefore it is correct to use Begin/End methods

[mrtoby]

It seems like papertrail closes the remote connection whenever the framing header is written. I suspect that papertrail do not support framing for unsecure TCP connections. As soon as I disable octet framing, it works fine.

If I try to enable TLS without client certificates the connection is closed immediately when AuthenticateAsClient is called. Looking into papertrail documentation it seems like client certificate is required (but it is not clearly stated). If I install the certificates and enable client certificates, the remote server still close the connection as soon as I try to authenticate.

And I have enabled all connection methods UDP, TCP and TCP/TLS in papertrail so that should not be the issue.

[iangregory]

I'm seeing the same IOException with v5.0.0 (full framework) with a tcp connection to an rsyslog server. Missing messages are accompanied by the following in syslog.log

netstream session 0x7fb7e4002020 will be closed due to error

I tried switching the framing to NonTransparent which has improved the issue but still results in some missing messages. Downgrading to 4.1.0 with the exact same configuration resolves the issue.

[mrtoby]

I'm back from vacation now - and will be much more responsive. Is there anything more I could do to get closer to a solution of this issue?

[luigiberrettini]

The biggest changes from 4.1.0 to 5.0.0 are:

• Add support for .NET Standard 2.0 #102 Support .NET 4.5 and .NET Standard 2.0 as target frameworks using Cake as a build tool
• Support cross-platform TCP socket initialization #131 Support cross-platform TCP socket initialization

What you can try to do is commenting the following lines and see if the error is still present:

var socketInitialization = SocketInitialization.ForCurrentOs(tcp.Client);
socketInitialization.DisableAddressSharing();
socketInitialization.DiscardPendingDataOnClose();
socketInitialization.SetKeepAlive(keepAliveConfig);

[mrtoby]

I used the latest code in the master branch and made the change you suggested above (commenting out the lines in Tcp.cs). Now logging over TCP (without touching the framing method) works like a charm. Also, I tried activating TLS and that works fine too!

So how do we take this further?
What are the conditions when these lines are needed and when not?

[luigiberrettini]

DisableAddressSharing() and DiscardPendingDataOnClose() are called always and were present also in version 4.1.0 even if implemented differently

SetKeepAlive(keepAliveConfig) has an impact only if keepAliveConfig.Enabled is true

If possible try to identify which line or lines of the three aboves is the source of the issue, thanks for the support!

[mrtoby]

I will try to comment out different combinations of the socket initialization stuff and see if I can narrow down the problem somehow.

Just realize I forgot to mention, that on my own machine I run windows but I host my services in linux dockers using kubernetes in Azure. The problem appear both on my machine and in my hosted environment. So the problem seems to be cross platform :-)

[mrtoby]

Papertrail had an outage most of yesterday(!), but I have now tested and found out that it was the keep alive configuration that messed up things for me. If I change my configuration to set KeepAlive.Enabled = false everything seems to work fine. No idea why...

Still, I do not really understand why a keepalive configuration would mess up things and close the connection all the time. The default times in the keepalive configuration was single digit times, can that be a problem?

[luigiberrettini]

As per my comment it seems that the problem is due to the ApplyKeepAliveValues method implementation called by the SetKeepAlive method:

• Linux
• OS X
• Windows

Version 5.0.0 introduced the implementation for Linux and OS X, but, since you said version 4.1.0 was working, you are using Windows.

Version 4.1.0

// Disable address sharing
tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.ExclusiveAddressUse, true);

// Discard pending data on close
tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.DontLinger, false);
tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.Linger, new LingerOption(true, 0));

// Set keep-alive
tcp.Client.IOControl(IOControlCode.KeepAliveValues, keepAlive.ToByteArray(), null);

Version 5.0.1

// socketInitialization.DisableAddressSharing();
Socket.ExclusiveAddressUse = true;

// socketInitialization.DiscardPendingDataOnClose();
Socket.LingerState = new LingerOption(true, 0);

// socketInitialization.SetKeepAlive(keepAliveConfig);
Socket.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.KeepAlive, keepAliveConfig.Enabled);
if (keepAliveConfig.Enabled)
{
    if (isWin10V1703OrLater)
        Socket.SetSocketOption(SocketOptionLevel.Tcp, TcpKeepAliveRetryCount, keepAliveConfig.RetryCount);

    if (isBelowWin10V1709)
    {
        // Call WSAIoctl via IOControl
        Socket.IOControl(IOControlCode.KeepAliveValues, new IOControlKeepAliveValues(keepAliveConfig).ToByteArray(), null);
        return;
    }
    Socket.SetSocketOption(SocketOptionLevel.Tcp, TcpKeepAliveTime, keepAliveConfig.Time);
    Socket.SetSocketOption(SocketOptionLevel.Tcp, TcpKeepAliveInterval, keepAliveConfig.Interval);
}

You should try to use version 4.1.0 code for the disable address sharing and discard pending data on close steps and see if this solves the problem.
If not it means that the set keep-alive step is the source of all evil and you should kindly check if isWin10V1703OrLater and/or isBelowWin10V1709 are true.

[mrtoby]

I have a hard time figuring out if we understand each other or not. I'm trying to be helpful, but I am not sure I am... Sorry.

When it comes to operating systems, I have problem with "vanilla" 5.0.1 on both windows and linux.

I have cloned your master branch and is currently located at the tag "5.0.1".

Test 1
I change the code in Tcp.cs by commenting out the following line in Tcp.Init():
// socketInitialization.SetKeepAlive(keepAliveConfig);
Result: Logging over https works fine.

Test 2
I change the TcpConfig so KeepAlive.Enabled = false.
Result: Logging over https works fine.

Test 3
I modified the code according to your suggestion titled "4.1.0" above, like this:

protected override Task Init()
{
    tcp = new TcpClient();
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.ExclusiveAddressUse, true);
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.DontLinger, false);
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.Linger, new LingerOption(true, 0));

    /*
    var socketInitialization = SocketInitialization.ForCurrentOs(tcp.Client);
    socketInitialization.DisableAddressSharing();
    socketInitialization.DiscardPendingDataOnClose();
    socketInitialization.SetKeepAlive(keepAliveConfig);
    */
    return tcp
        .ConnectAsync(IpAddress, Port)
        .Then(_ => stream = SslDecorate(tcp), CancellationToken.None);
}

Result: Logging over https works fine.

Test 4
I changed the code like this:

protected override Task Init()
{
    tcp = new TcpClient();
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.ExclusiveAddressUse, true);
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.DontLinger, false);
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.Linger, new LingerOption(true, 0));

    var socketInitialization = SocketInitialization.ForCurrentOs(tcp.Client);
    // socketInitialization.DisableAddressSharing();
    // socketInitialization.DiscardPendingDataOnClose();
    socketInitialization.SetKeepAlive(keepAliveConfig);

    return tcp
        .ConnectAsync(IpAddress, Port)
        .Then(_ => stream = SslDecorate(tcp), CancellationToken.None);
}

Result: I get exception at Tcp.cs at line 88 (in SslDecorate) while calling sslStream.AuthenticateAsClient. System.IO.IOException: 'Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host.'

Test 5
I debugged the running code too see the value of the version variables in SocketInitializationForWindows.cs:
Result: isWin10V1703OrLater = false, isBelowWin10V1709 = true

Did this contain the information you wanted?

[luigiberrettini]

Thanks @mrtoby, you did a great job and I am sorry that what I said was not clear.

Let's address first the behavior on Windows, since Linux was not supported before and, at the moment, we cannot know if it can work with different code.

Supposing, as you did, to clone the master branch (v5.0.1 tag) I need this further tests:

Test A

protected override Task Init()
{
    tcp = new TcpClient();

    // Disable address sharing
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.ExclusiveAddressUse, true);
    
    // Discard pending data on close
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.DontLinger, false);
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.Linger, new LingerOption(true, 0));
    
    // Set keep-alive
    tcp.Client.IOControl(IOControlCode.KeepAliveValues, new IOControlKeepAliveValues(keepAliveConfig).ToByteArray(), null);
    
    return tcp
        .ConnectAsync(IpAddress, Port)
        .Then(_ => stream = SslDecorate(tcp), CancellationToken.None);
}

Test B

protected override Task Init()
{
    tcp = new TcpClient();

    // Disable address sharing
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.ExclusiveAddressUse, true);

    // Discard pending data on close
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.DontLinger, false);
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.Linger, new LingerOption(true, 0));

    // Set keep-alive
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.KeepAlive, keepAliveConfig.Enabled);
    tcp.Client.IOControl(IOControlCode.KeepAliveValues, new IOControlKeepAliveValues(keepAliveConfig).ToByteArray(), null);
    
    return tcp
        .ConnectAsync(IpAddress, Port)
        .Then(_ => stream = SslDecorate(tcp), CancellationToken.None);
}

Test C

protected override Task Init()
{
    tcp = new TcpClient();

    var socketInitialization = SocketInitialization.ForCurrentOs(tcp.Client);

    // Disable address sharing
    socketInitialization.DisableAddressSharing();

    // Discard pending data on close
    socketInitialization.DiscardPendingDataOnClose();

    // Set keep-alive
    tcp.Client.IOControl(IOControlCode.KeepAliveValues, new IOControlKeepAliveValues(keepAliveConfig).ToByteArray(), null);
    
    return tcp
        .ConnectAsync(IpAddress, Port)
        .Then(_ => stream = SslDecorate(tcp), CancellationToken.None);
}

Test D

protected override Task Init()
{
    tcp = new TcpClient();

    var socketInitialization = SocketInitialization.ForCurrentOs(tcp.Client);

    // Disable address sharing
    socketInitialization.DisableAddressSharing();

    // Discard pending data on close
    socketInitialization.DiscardPendingDataOnClose();

    // Set keep-alive
    tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.KeepAlive, keepAliveConfig.Enabled);
    tcp.Client.IOControl(IOControlCode.KeepAliveValues, new IOControlKeepAliveValues(keepAliveConfig).ToByteArray(), null);
    
    return tcp
        .ConnectAsync(IpAddress, Port)
        .Then(_ => stream = SslDecorate(tcp), CancellationToken.None);
}

[mrtoby]

I performed the tests above with TLS enabled and I got the same result: Exception at Tcp.cs line 105, sslStream.AuthenticateAsClient System.IO.IOException: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host. Inner exception: SocketException: An existing connection was forcibly closed by the remote host I tried this at two different offices and at home: it seems unlikely that it is a local network issue or something like that.

[luigiberrettini]

1. Could you perform the same tests with TLS disabled?
2. What is the behavior of version 4.1.0 of the library with TLS enabled and disabled?
3. What is the behavior of the following code (in a simple console application) with TLS enabled and disabled?

public class MyTest
{
    private readonly bool useTls;
    private readonly TlsConfig tlsConfig;
    private readonly string ipAddress;
    private readonly int port;
    private readonly string serverNameInTheCertificate;
    
    public MyTest()
    {
        useTls = false;
        tlsConfig = new TlsConfig();
        //
        // Setup TLS configuration
        //
        ipAddress = '127.0.0.1';
        port = 60123;
        serverNameInTheCertificate = 'myAmazingSecureServer';
    }

    public void Go()
    {
        var tcp = new TcpClient();

        // Disable address sharing
        tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.ExclusiveAddressUse, true);

        // Discard pending data on close
        tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.DontLinger, false);
        tcp.Client.SetSocketOption(SocketOptionLevel.Socket, SocketOptionName.Linger, new LingerOption(true, 0));
            
        // Set keep-alive
        tcp.Client.IOControl(IOControlCode.KeepAliveValues, new IOControlKeepAliveValues(keepAliveConfig).ToByteArray(), null);

        tcp.Connect(ipAddress, port);

        
        byte[] data = { 0x68, 0x65, 0x6C, 0x6C, 0x6F, 0x0A };
        
        var tcpStream = tcp.GetStream();
        if (!useTls)
        {
            tcpStream.Write(data, 0, data.Length);
            return;
        }
        
        var sslStream = new SslStream(tcpStream, true);
        sslStream.AuthenticateAsClient(serverNameInTheCertificate, tlsConfig.RetrieveClientCertificates(), SslProtocols.Tls12, false);
        sslStream.Write(data, 0, data.Length);
    }
}

public class TlsConfig
{
    private bool enabled;
    private bool useClientCertificates;
    private StoreLocation certificateStoreLocation;
    private StoreName certificateStoreName;
    private X509FindType certificateFilterType;
    private string certificateFilterValue;

    public bool Enabled { get; set; }

    public bool UseClientCertificates { get; set; }

    public StoreLocation CertificateStoreLocation { get; set; }

    public StoreName CertificateStoreName { get; set; }

    public X509FindType CertificateFilterType { get; set; }

    public string CertificateFilterValue { get; set; }

    public TlsConfig()
    {
        enabled = false;
        useClientCertificates = false;
        certificateStoreLocation = StoreLocation.CurrentUser;
        certificateStoreName = StoreName.My;
        certificateFilterType = X509FindType.FindBySubjectName;
        certificateFilterValue = null;
    }

    public X509Certificate2Collection RetrieveClientCertificates()
    {
        if (!useClientCertificates)
            return null;

        var store = new X509Store(certificateStoreName, certificateStoreLocation);
        try
        {
            store.Open(OpenFlags.ReadOnly);
            return certificateFilterValue == null ?
                store.Certificates :
                store.Certificates.Find(certificateFilterType, BuildFindValue(), false);
        }
        finally
        {
            store.Close();
        }
    }

    private object BuildFindValue()
    {
        switch (certificateFilterType)
        {
            case X509FindType.FindByTimeExpired:
            case X509FindType.FindByTimeNotYetValid:
            case X509FindType.FindByTimeValid:
            {
                return DateTime.Parse(certificateFilterValue);
            }
            case X509FindType.FindByKeyUsage:
            {
                if (int.TryParse(certificateFilterValue, out var keyUsages))
                    return keyUsages;
                return certificateFilterValue;
            }
            case X509FindType.FindByThumbprint:
            case X509FindType.FindBySubjectName:
            case X509FindType.FindBySubjectDistinguishedName:
            case X509FindType.FindByIssuerName:
            case X509FindType.FindByIssuerDistinguishedName:
            case X509FindType.FindBySerialNumber:
            case X509FindType.FindByTemplateName:
            case X509FindType.FindByApplicationPolicy:
            case X509FindType.FindByCertificatePolicy:
            case X509FindType.FindByExtension:
            case X509FindType.FindBySubjectKeyIdentifier:
            {
                return certificateFilterValue;
            }
            default:
            {
                throw new ArgumentOutOfRangeException();
            }
        }
    }
}

public class IOControlKeepAliveValues
{
    private readonly int onOffOffset;
    private readonly int timeOffset;
    private readonly int intervalOffset;
    private readonly int structSize;
    private readonly uint onOff;
    private readonly uint time;
    private readonly uint interval;

    public IOControlKeepAliveValues(KeepAliveConfig keepAliveConfig)
    {
        var uintSize = Marshal.SizeOf(typeof(uint));
        onOffOffset = 0;
        timeOffset = uintSize;
        intervalOffset = 2 * uintSize;
        structSize = 3 * uintSize;
        onOff = (uint)(keepAliveConfig.Enabled ? 1 : 0);
        time = (uint)keepAliveConfig.Time;
        interval = (uint)keepAliveConfig.Interval;
    }

    public byte[] ToByteArray()
    {
        var keepAliveSettings = new byte[structSize];
        BitConverter.GetBytes(onOff).CopyTo(keepAliveSettings, onOffOffset);
        BitConverter.GetBytes(time).CopyTo(keepAliveSettings, timeOffset);
        BitConverter.GetBytes(interval).CopyTo(keepAliveSettings, intervalOffset);
        return keepAliveSettings;
    }
}

[mrtoby]

Ok, so here are my results: *Test without TLS enabled* A - No exception thrown, but no logs appear on the server B - No exception thrown, but no logs appear on the server C - No exception thrown, but no logs appear on the server D - No exception thrown, but no logs appear on the server For all cases A-D above, if I turn off keep-alive, it works. *Test with 4.1.0* Since I am running dotnet core, changing to 4.1.0 do not really work since they not are compatible. So I made a different test program for testing 4.1.0 on my computer/network. The test program for dotnet framework 4.6 and NLog.Targets.Syslog 4.1.0 works with TLS on and keep-alive on or off. *Test with your custom program* I had to add a main function that create an instance of MyTest and then call Go(). I also had to add the field keepAliveConfig. I added this in the constructor to MyTest: tlsConfig = new TlsConfig(); tlsConfig.Enabled = false; keepAliveConfig = new KeepAliveConfig(); keepAliveConfig.Enabled = true; All 4 permutations of true/false for tls and keep alive works fine. No exception and the test "hello" reach the server. Hope this gives you more clues... :-) Tobias

[luigiberrettini]

Thanks @mrtoby!

My source code include a test utility with GUI: you did not need to create custom code to test the 4.1.0 .NET classic version

Apart from being synchronous, the code above has been extracted from my 5.0.1 code: I really do not understant where is the problem 😞

I just found out that Papertrail has free accounts: I will try to debug myself, but I do not think the solution can come anytime soon.

Thanks a lot for your support 👍

[markdascher]

We've worked with several customers on this issue recently. Running a packet trace shows the TCP three-way handshake, followed by the TLS Client Hello, and then the client inexplicably resets the connection without waiting for a response. Adding <keepAlive enabled="false" /> seems to solve the problem, but I've never been able to reproduce the problem myself. So my guess is one of the permutations here doesn't play well with a particular Windows build. Not sure if any of that is new information, but we'll let you know if we learn any more details.

[luigiberrettini]

I have made some changes in the management of keep-alive and removed the connection check and I am going to publish a new release soon

It would be really great if you could help me see if there are some regressions or if this issue is solved with the latest build artifacts

[mrtoby]

It works perfect - thanks!

[luigiberrettini]

With keep-alive enabled? 😲
The dream came true 🎉

[mrtoby]

Yup, keep-alive and TLS enabled and everything works fine! Really nice!

[luigiberrettini]

Closed by #176