Deadlock in NetworkTarget

[mikhail-barg]

This issue was initially found during testing of #902. I'm reposting it as a separate issue.

What we have noticed though is some deadlock condition happening both with previous and curent code. The setup is like following:

config:

      <target xsi:type="Network"
        onOverflow="Discard"
        newLine="true"
        layout="${msg4Json}"
        encoding="utf-8"
        connectionCacheSize="5"
        keepConnection="false"
        address="tcp://logstash.our_local_host_name.com:9002"
              name="network"
      />

test program

        static void Main(string[] args)
        {
            Logger logger = LogManager.GetCurrentClassLogger();
            for (int i = 0; i < 100000; ++i)
            {
                logger.Trace("log " + i);
            };
            Console.WriteLine("Done");
            Console.Read();
        }

Call stacks at the moment of deadlock for the 4.2.0:

Worker thread:
>   NLog.dll!NLog.Targets.NetworkTarget.Write.AnonymousMethod__a(System.Exception ex) + 0x76 bytes  
    NLog.dll!NLog.Targets.NetworkTarget.ChunkedSend.AnonymousMethod__1a(System.Exception ex) + 0x74 bytes   
    NLog.dll!NLog.Internal.NetworkSenders.TcpNetworkSender.ProcessNextQueuedItem() + 0x10c bytes    
    NLog.dll!NLog.Internal.NetworkSenders.TcpNetworkSender.SocketOperationCompleted(object sender, System.Net.Sockets.SocketAsyncEventArgs e) + 0x1ad bytes 
    mscorlib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx) + 0x285 bytes 
    mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx) + 0x9 bytes   
    mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) + 0x57 bytes    
    System.dll!System.Net.Sockets.SocketAsyncEventArgs.FinishOperationAsyncFailure(System.Net.Sockets.SocketError socketError, int bytesTransferred, System.Net.Sockets.SocketFlags flags) + 0xa6 bytes 
    System.dll!System.Net.Sockets.SocketAsyncEventArgs.CompletionPortCallback(uint errorCode, uint numBytes, System.Threading.NativeOverlapped* nativeOverlapped) + 0xa8 bytes  
    mscorlib.dll!System.Threading._IOCompletionCallback.PerformIOCompletionCallback(uint errorCode, uint numBytes, System.Threading.NativeOverlapped* pOVERLAP) + 0x96 bytes    
    [Native to Managed Transition]  

Main thread: 
>   NLog.dll!NLog.Internal.NetworkSenders.TcpNetworkSender.ProcessNextQueuedItem() + 0x64 bytes 
    NLog.dll!NLog.Internal.NetworkSenders.TcpNetworkSender.DoSend(byte[] bytes, int offset, int length, NLog.Common.AsyncContinuation asyncContinuation) + 0x1f4 bytes  
    NLog.dll!NLog.Internal.NetworkSenders.NetworkSender.Send(byte[] bytes, int offset, int length, NLog.Common.AsyncContinuation asyncContinuation) + 0x82 bytes    
    NLog.dll!NLog.Targets.NetworkTarget.ChunkedSend.AnonymousMethod__1a(System.Exception ex) + 0x38c bytes  
    NLog.dll!NLog.Targets.NetworkTarget.ChunkedSend(NLog.Internal.NetworkSenders.NetworkSender sender, byte[] buffer, NLog.Common.AsyncContinuation continuation) + 0x15b bytes 
    NLog.dll!NLog.Targets.NetworkTarget.Write(NLog.Common.AsyncLogEventInfo logEvent) + 0x469 bytes 
    NLog.dll!NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo logEvent) + 0x1a4 bytes   
    NLog.dll!NLog.LoggerImpl.WriteToTargetWithFilterChain(NLog.Internal.TargetWithFilterChain targetListHead, NLog.LogEventInfo logEvent, NLog.Common.AsyncContinuation onException) + 0x229 bytes  
    NLog.dll!NLog.LoggerImpl.Write(System.Type loggerType, NLog.Internal.TargetWithFilterChain targets, NLog.LogEventInfo logEvent, NLog.LogFactory factory) + 0x23c bytes  
    NLog.dll!NLog.Logger.WriteToTargets(NLog.LogLevel level, System.IFormatProvider formatProvider, string message) + 0xf9 bytes    
    NLog.dll!NLog.Logger.Trace(string message) + 0x59 bytes 
    NlogConsoleTest.exe!NlogConsoleTest.Program.Main(string[] args) Line 19 + 0x68 bytes    C#

call stacks at the moment of deadlock for the 4.2.1:

Worker thread:
    mscorlib.dll!System.Threading.Monitor.Enter(object obj, ref bool lockTaken) + 0x17 bytes    
>   NLog.dll!NLog.Targets.NetworkTarget.Write.AnonymousMethod__a(System.Exception ex) Line 321 + 0x1a bytes C#
    NLog.dll!NLog.Targets.NetworkTarget.ChunkedSend.AnonymousMethod__19(System.Exception ex) Line 485 + 0x10 bytes  C#
    NLog.dll!NLog.Internal.NetworkSenders.TcpNetworkSender.SocketOperationCompleted(object sender, System.Net.Sockets.SocketAsyncEventArgs e) Line 216 + 0x11 bytes C#
    System.dll!System.Net.Sockets.SocketAsyncEventArgs.OnCompleted(System.Net.Sockets.SocketAsyncEventArgs e) + 0x15 bytes  
    System.dll!System.Net.Sockets.SocketAsyncEventArgs.ExecutionCallback(object ignored) + 0xf bytes    
    mscorlib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx) + 0xa7 bytes  
    mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx) + 0x16 bytes  
    mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) + 0x41 bytes    
    System.dll!System.Net.Sockets.SocketAsyncEventArgs.FinishOperationSuccess(System.Net.Sockets.SocketError socketError, int bytesTransferred, System.Net.Sockets.SocketFlags flags) + 0x77e bytes 
    System.dll!System.Net.Sockets.SocketAsyncEventArgs.CompletionPortCallback(uint errorCode, uint numBytes, System.Threading.NativeOverlapped* nativeOverlapped) + 0x37 bytes  
    mscorlib.dll!System.Threading._IOCompletionCallback.PerformIOCompletionCallback(uint errorCode, uint numBytes, System.Threading.NativeOverlapped* pOVERLAP) + 0x6e bytes    
    [Native to Managed Transition]  

Main thread:
    mscorlib.dll!System.Threading.Monitor.Enter(object obj, ref bool lockTaken) + 0x17 bytes    
>   NLog.dll!NLog.Internal.NetworkSenders.TcpNetworkSender.ProcessNextQueuedItem() Line 227 + 0x11 bytes    C#
    NLog.dll!NLog.Internal.NetworkSenders.TcpNetworkSender.DoSend(byte[] bytes, int offset, int length, NLog.Common.AsyncContinuation asyncContinuation) Line 172 + 0x8 bytes   C#
    NLog.dll!NLog.Internal.NetworkSenders.NetworkSender.Send(byte[] bytes, int offset, int length, NLog.Common.AsyncContinuation asyncContinuation) Line 115 + 0x16 bytes   C#
    NLog.dll!NLog.Targets.NetworkTarget.ChunkedSend.AnonymousMethod__19(System.Exception ex) Line 511 + 0x37 bytes  C#
    NLog.dll!NLog.Targets.NetworkTarget.ChunkedSend(NLog.Internal.NetworkSenders.NetworkSender sender, byte[] buffer, NLog.Common.AsyncContinuation continuation) Line 514 + 0x10 bytes C#
    NLog.dll!NLog.Targets.NetworkTarget.Write(NLog.Common.AsyncLogEventInfo logEvent) Line 316 + 0x47 bytes C#
    NLog.dll!NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo logEvent) Line 204 + 0x34 bytes   C#
    NLog.dll!NLog.LoggerImpl.WriteToTargetWithFilterChain(NLog.Internal.TargetWithFilterChain targetListHead, NLog.LogEventInfo logEvent, NLog.Common.AsyncContinuation onException) Line 196 + 0x28 bytes  C#
    NLog.dll!NLog.LoggerImpl.Write(System.Type loggerType, NLog.Internal.TargetWithFilterChain targets, NLog.LogEventInfo logEvent, NLog.LogFactory factory) Line 99 + 0xe bytes    C#
    NLog.dll!NLog.Logger.WriteToTargets(NLog.LogLevel level, System.IFormatProvider formatProvider, string message) Line 542 + 0x41 bytes   C#
    NLog.dll!NLog.Logger.Trace(string message) Line 183 + 0x13 bytes    C#
    TEST.exe!TEST.Program.Main(string[] args) Line 18 + 0x46 bytes  C#
    [Native to Managed Transition]  
    [Managed to Native Transition]  
    mscorlib.dll!System.AppDomain.ExecuteAssembly(string assemblyFile, System.Security.Policy.Evidence assemblySecurity, string[] args) + 0x6b bytes    
    Microsoft.VisualStudio.HostingProcess.Utilities.dll!Microsoft.VisualStudio.HostingProcess.HostProc.RunUsersAssembly() + 0x27 bytes  
    mscorlib.dll!System.Threading.ThreadHelper.ThreadStart_Context(object state) + 0x6f bytes   
    mscorlib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx) + 0xa7 bytes  
    mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx) + 0x16 bytes  
    mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) + 0x41 bytes    
    mscorlib.dll!System.Threading.ThreadHelper.ThreadStart() + 0x44 bytes   
    [Native to Managed Transition]  

[304NotModified]

Useful info:

• https://www.interact-sw.co.uk/iangblog/2004/03/23/locking
• http://www.interact-sw.co.uk/iangblog/2004/04/26/yetmoretimedlocking
• http://www.yoda.arachsys.com/csharp/threads/

[304NotModified]

I think the scope of the lock is wrong, or the object (lock and wait on same object) - maybe we need to locks (after each other)? for the maxConnection switch and the actual send.

[304NotModified]

Can you test that @mikhail-barg ?

[kt1996]

Hey,
I am a new guy and am trying to contribute to open source development. I am familiar with threading, network programming but have built only standalone single project applications, so am having a little bit difficulty in getting this running.
For debugging I am unable to figure out where should I put the configuration as no exe file is generated in build folder, with which I could put the NLog.config file alongside. I have got a test console project running and logging with no target as no config.
I am an interested newbie, and if you guys are ok, then maybe I can work on it for a start :-D...!!

[304NotModified]

Hey!

Great that you like to help! This is a bit difficult one but if you know how to attach the debugger to a running process, it should be solvable.

I'm now on mobile but will give you tomorrow some more info!

[kt1996]

I am using the visual studio debugger only, and have created a console project in the solution (with it marked as the startup) and added Nlog.netfx45 project to its references. So I have debugging access to the NLog projects too. Just can't figure out where should I put config... :(

[mikhail-barg]

In general, you put nlog.config to your project root and in file properties you specify "copy always" or "copy if newer" for "Copy to Output Directory". You may check the TestApplication project of NLog.Windows.Forms for this.

[304NotModified]

thanks @mikhail-barg!

@kt1996 if you need some starting with NLog, you can check https://github.com/nlog/nlog/wiki/Tutorial. If you need some help after reading it, just let us know. Thanks in advance for looking at this issue!

[kt1996]

Hey, thanks a lot guys for the help. I am quite sure I have figured this bug and fixed it in my forked repository.

The issue was not with the switch as this was happening even when allowconnections was permitted but was in the scope of the lock around the actual send line 310.

Took some time understanding the code but now have sent my first pull request....Thanks again...!!

[304NotModified]

Hey! That would be great!

Do you know if the bug is also in AsyncRequestQueue?

[kt1996]

@304NotModified No idea, during debugging never came across it, so if there is a bug I don't think its related to this atleast,... Though I'll happily look into it if you can provide me the details :)

[304NotModified]

Well, the code in network target is based on the code of AsyncRequestQueue. So there's probably the same mistake there?

Edit: we have also a discussion in the PR. Should read that first :)

[kt1996]

• Sorry but I am a newbie... What is PR ? :)
• I'd be happy to look into AsyncRequestQueue too if you could provide me a test code that calls it. Thanks!!

[304NotModified]

PR= pull request (github)

There should be unit tests, but don't know which one.