Log entries not sent after Syslog server hiccup about nlog.targets.syslog HOT 10 CLOSED

Good afternoon Luigi,

I'll give the code from your test branch a go tomorrow. I've also been doing some further investigation here and have come up with some rather interesting results, that may align with what you have found (would be good to know your views).

I've found that the problem I saw only occurs when sending logs to a REMOTE syslog server.

The test results are as follows:
What I found for the TestApp was sending to a LOCAL syslog server with messageProcessors set to 1:

• Messages delivered to the syslog server
• Stop server, results in the destination TCP port being closed
• Log messages
• Unhandled IOException raised within the Tcp:WriteAsync(int offset, ByteArray data, CancellationToken token) method, when the call to 'return Task.Factory' is made
• Log messages
• Messages are enqueued, and AsyncLogger::ProcessQueueAsync is called to take them off of the queue
• Start server
• Log messages
• Messages are delivered to the syslog server

What I found for the TestApp was sending to a REMOTE syslog server with messageProcessors set to 1:

• Messages delivered to the syslog server
• Stop server, results in the destination TCP port being closed
• Log messages
• Unhandled IOException raised within the Tcp:FramingTask(ByteArray message) method, when the call to 'return Task.Factory.FromAsync' is made
• Log messages
• Messages are enqueued, and AsyncLogger::ProcessQueueAsync is NOT called to take them off of the queue
• Start server
• Log messages
• Messages are NOT delivered to the syslog server

What I found for the TestApp was sending to a REMOTE syslog server with messageProcessors set to 1 AND framing set to nonTransparent:

• Messages delivered to the syslog server
• Stop server, results in the destination TCP port being closed
• Log messages
• Unhandled IOException raised within the Tcp:WriteAsync(int offset, ByteArray data, CancellationToken token) method, when the call to 'return Task.Factory' is made
• Log messages
• Messages are enqueued, and AsyncLogger::ProcessQueueAsync is called to take them off of the queue
• Start server
• Log messages
• Messages are delivered to the syslog server

Note that by setting framing to nonTransparent, the call into Tcp::FramingTask returns before attempting to write to the stream using Task.Factory.FromAsync.

For some reason the writing to the stream within the Tcp::FramingTask method behaves differently between connections to local and remote servers - which is strange!

I made the following change to the code to explicity and safely handle TCP IO failures:

Thoughts?

Jon.

from nlog.targets.syslog.

Thanks @JonPaz!

I thought this scenario was handled by the InitTcpClient in MessageSend/Tcp.cs: I would be really grateful if you could investigate more and let me know what you find out.

from nlog.targets.syslog.

No worries, I'll mod the code on a branch and update the issue to include steps to repeat etc. Just testing on our dev system at the mo.

from nlog.targets.syslog.

Thanks, I tried to reproduce the TCP server intermittent behavior before (using the TestApp and stopping/restarting the server) and then deployed to all our envs solving the issues, but this was clearly not enough 😞

from nlog.targets.syslog.

Hi there Luigi,

Am working with the TestApp server so that I can write self-contained repeatable steps and am having the following issue(s) - would you be able to see if you can repeat and advise on any fixes to the TestApp?

1. Set the syslogcee-tgt logger to use TCP
2. Run TestApp in debugger
3. Start syslog server
4. Send Warning log message -> message appears in TCP window
5. Stop syslog server
6. Start syslog server
7. Send Warning log message -> Get code exception, see image.
   

Cheers,

Jon

from nlog.targets.syslog.

It works on my computer 😭

I wait a bit after I stop or start the Server, btw it is not a professional Syslog server...

TestApp config file:

<?xml version="1.0" encoding="utf-8"?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xmlns:sl="https://github.com/graffen/NLog.Targets.Syslog/tree/master/src/schemas/NLog.Targets.Syslog.xsd">
    <variable name="enterpriseId" value="12345"/>
    <variable name="sequenceId" value="1"/>
    <targets>
        <target xsi:type="sl:Syslog" name="syslogcee-tgt">
            <sl:layout xsi:type="CompoundLayout">
                <layout xsi:type="SimpleLayout" text="@cee: " />
                <layout xsi:type="JsonLayout">
                    <attribute name="env" layout="DEV" />
                    <attribute name="area" layout="Provisioning" />
                    <attribute name="category" layout="Console" />
                    <attribute name="app" layout="TestApp" />
                    <attribute name="message" layout="${message}${newLine}${exception:format=ToString,StackTrace}" />
                </layout>
            </sl:layout>
            <sl:enforcement>
                <sl:throttling>
                    <sl:limit>100000</sl:limit>
                    <sl:strategy>None</sl:strategy>
                    <sl:delay>0</sl:delay>
                </sl:throttling>
                <sl:messageProcessors>1</sl:messageProcessors>
                <sl:splitOnNewLine>false</sl:splitOnNewLine>
                <sl:transliterate>false</sl:transliterate>
                <sl:replaceInvalidCharacters>false</sl:replaceInvalidCharacters>
                <sl:truncateFieldsToMaxLength>true</sl:truncateFieldsToMaxLength>
                <sl:truncateMessageTo>64512</sl:truncateMessageTo>
            </sl:enforcement>
            <sl:messageCreation>
                <sl:facility>Local4</sl:facility>
                <sl:rfc>Rfc5424</sl:rfc>
                <sl:rfc3164 hostname="notUsedHostname" tag="notUsedTag" />
                <sl:rfc5424>
                    <sl:hostname xsi:type="SimpleLayout" text="${machinename}" />
                    <sl:appName xsi:type="SimpleLayout" text="Provisioning" />
                    <sl:procId xsi:type="SimpleLayout" text="Console.TestApp" />
                    <sl:msgId xsi:type="SimpleLayout" text="-" />
                    <sl:disableBom>true</sl:disableBom>
                </sl:rfc5424>
            </sl:messageCreation>
            <sl:messageSend>
                <sl:protocol>TCP</sl:protocol>
                <sl:udp>
                    <sl:server>127.0.0.1</sl:server>
                    <sl:port>1514</sl:port>
                </sl:udp>
                <sl:tcp>
                    <sl:server>127.0.0.1</sl:server>
                    <sl:port>1514</sl:port>
                    <sl:useTls>false</sl:useTls>
                    <sl:framing>octetCounting</sl:framing>
                    <sl:dataChunkSize>8192</sl:dataChunkSize>
                </sl:tcp>
            </sl:messageSend>
        </target>
    </targets>
    <rules>
        <logger name="*" minlevel="Trace" writeTo="syslogcee-tgt" />
    </rules>
</nlog>

Starting and stopping the server multiple times tcp?.Connected is true and WriteAsync does not throw any exception 😲
Sometimes it eventually detects it is not connected and the ProcessQueueAsync method of AsyncLogger behaves correctly (t.IsFaulted is true then it calls ProcessQueueAsync again).

Also add this to TestApp app.config:

<runtime>
    <ThrowUnobservedTaskExceptions enabled="true"/>
</runtime>

from nlog.targets.syslog.

Looking at the nature of task completion sourcet result it seems that when using a TaskCompletionSource there is no automatic handling of exceptions with respect to Task.Factory.StartNew

This means that whatever exception is thrown outside tasks or continuations is not handled and results in an UnobservedTaskException: this generate the need of using try/catch.

What I found pretty strange is that the Task.Factory.FromAsync method (the root cause of evil 😄) was throwing the underlying Socket or I/O exceptions instead of returning a faulted Task 😞
What is worse is that even if I manage to return a faulted Task, while the Syslog server is down, when it is again up, after some message sent I get two unobserved task exceptions 😠:

******************** DANGEROUSLY UNOBSERVED TASK EXCEPTION!!!
System.IO.IOException: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host. ---> System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
   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.Threading.Tasks.TaskFactory`1.FromAsyncImpl[TArg1,TArg2,TArg3](Func`6 beginMethod, Func`2 endFunction, Action`1 endAction, TArg1 arg1, TArg2 arg2, TArg3 arg3, Object state, TaskCreationOptions creationOptions)
   at System.Threading.Tasks.TaskFactory.FromAsync[TArg1,TArg2,TArg3](Func`6 beginMethod, Action`1 endMethod, TArg1 arg1, TArg2 arg2, TArg3 arg3, Object state, TaskCreationOptions creationOptions)
   at System.Threading.Tasks.TaskFactory.FromAsync[TArg1,TArg2,TArg3](Func`6 beginMethod, Action`1 endMethod, TArg1 arg1, TArg2 arg2, TArg3 arg3, Object state)
   at NLog.Targets.Syslog.Extensions.TaskExtensions.SafeFromAsync[TArg1,TArg2,TArg3](TaskFactory taskFactory, Func`6 beginMethod, Action`1 endMethod, TArg1 arg1, TArg2 arg2, TArg3 arg3, Object state) in D:\AD\Development\Projects\NLog.Targets.Syslog\src\NLog.Targets.Syslog\Extensions\TaskExtensions.cs:line 32

******************** DANGEROUSLY UNOBSERVED TASK EXCEPTION!!!
System.IO.IOException: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host. ---> System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
   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.Threading.Tasks.TaskFactory`1.FromAsyncImpl[TArg1,TArg2,TArg3](Func`6 beginMethod, Func`2 endFunction, Action`1 endAction, TArg1 arg1, TArg2 arg2, TArg3 arg3, Object state, TaskCreationOptions creationOptions)
   at System.Threading.Tasks.TaskFactory.FromAsync[TArg1,TArg2,TArg3](Func`6 beginMethod, Action`1 endMethod, TArg1 arg1, TArg2 arg2, TArg3 arg3, Object state, TaskCreationOptions creationOptions)
   at System.Threading.Tasks.TaskFactory.FromAsync[TArg1,TArg2,TArg3](Func`6 beginMethod, Action`1 endMethod, TArg1 arg1, TArg2 arg2, TArg3 arg3, Object state)
   at NLog.Targets.Syslog.Extensions.TaskExtensions.SafeFromAsync[TArg1,TArg2,TArg3](TaskFactory taskFactory, Func`6 beginMethod, Action`1 endMethod, TArg1 arg1, TArg2 arg2, TArg3 arg3, Object state) in D:\AD\Development\Projects\NLog.Targets.Syslog\src\NLog.Targets.Syslog\Extensions\TaskExtensions.cs:line 32

Maybe @matteobaglini has some ideas to share 🤞

It would be really great if @JonPaz could do some tests with the DLL compiled from my handle-intermittent-syslog-server branch, so that I can merge with more confidence.

from nlog.targets.syslog.

Hi @luigiberrettini,

Have just been testing out your handle-intermittent-syslog-server branch and the addition of the the SafeFromAsync method fixes the issues that I was seeing! I think that the code changes you added are very useful. Can I suggest logging when SafeFromAsync encounters an Exception?

I'll give the code a soak on my development system over the weekend as well!

Cheers,

Jon.

from nlog.targets.syslog.

Thank you very much @JonPaz!

I would not add that log line since it is already logged in the ContinueWith of ProcessQueueAsync

I found that the unobserved exceptions are the one I observe 😲😲😲😲😲
I added a GUID to a wrapping exception just to understand what was happening and...
Look at the GUIDs below:

NLog: 2017-01-13 19:51:27.8628 Warn Task faulted Exception: System.Exception:
SPOTTED SafeFromAsync EXCEPTION (b0027d51ec094270bfefd6c8a859ce66)
---> 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 NLog.Targets.Syslog.Extensions.TaskExtensions.SafeFromAsync[TArg1,TArg2,TArg3](TaskFactory taskFactory, Func`6 beginMethod, Action`1 endMethod, TArg1 arg1, TArg2 arg2, TArg3 arg3, Object state) in D:\AD\Development\Projects\NLog.Targets.Syslog\src\NLog.Targets.Syslog\Extensions\TaskExtensions.cs:line 53

******************** DANGEROUSLY UNOBSERVED TASK EXCEPTION!!!
System.Exception:
SPOTTED SafeFromAsync EXCEPTION (b0027d51ec094270bfefd6c8a859ce66)
---> 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 NLog.Targets.Syslog.Extensions.TaskExtensions.SafeFromAsync[TArg1,TArg2,TArg3](TaskFactory taskFactory, Func`6 beginMethod, Action`1 endMethod, TArg1 arg1, TArg2 arg2, TArg3 arg3, Object state) in D:\AD\Development\Projects\NLog.Targets.Syslog\src\NLog.Targets.Syslog\Extensions\TaskExtensions.cs:line 53

from nlog.targets.syslog.

I found the bug causing unobserved task exceptions! 😎 🎉 🎆
Closed by #60

from nlog.targets.syslog.