c# - NLog FileTarget wrapped with BufferingTargetWrapper fails to write log if there is a delay

Question

I may have stumbled across an issue with NLog, but thought I would check here first for an answer:

To recreate the issue I cloned the NLog source so I could add a delay to cause the problem. Once open in visual studio, I added a console application that references the NLog source projects and makes some very simple log calls. The NLog.config is as follows:

<nlog>
  <targets>
    <target name="buffer" type="BufferingWrapper">
      <target name="logfile" type="File" fileName="log.txt"/>
    </target>
  </targets>
  <rules>
    <logger name="*" minlevel="Debug" writeTo="logfile" />
  </rules>
</nlog>

All works as expected up to this point. The next step is to insert a delay into the flush logic of the FileTarget. (The reason I found this to be the problem is that I was originally working with the MailTarget that would hang for a duration whilst connecting to the mail server - I have substituted it for the FileTarget here instead to make recreating the problem easier).

Open the FileTarget.cs and locate the Write(AsyncLogEventInfo[] logEvents) method. Insert in the first line Thread.Sleep(5000) so that the method appears as below:

protected override void Write(AsyncLogEventInfo[] logEvents)
{
    Thread.Sleep(5000);

    // ... omitted
}

Now, compile and re-run. The log is not written.

As far as I can tell, the logic to flush all targets when the process exits uses an asynchronous method call that has a default timeout of 15 seconds which can be found in the LogFactory.cs Flush() method - this is obviously not being exceeded.

However, NLog makes use of ThreadPool.QueueUserWorkItem() (found in AsyncHelpers.cs) to orchestrate the flushing of each target in parallel. Could this simply boil down to a question of how does this form of method invocation react to a call to Thread.Sleep(), or any other form of blocking (such as connecting to a remote server, as in my original problem)?

Any ideas?

Answer 1

I have finally figured out why nothing is being logged, unfortunately there is not much that can be done about this.

According to the MSDN documentation for AppDomain.ProcessExit, which is the event handled by NLog:

The total execution time of all ProcessExit event handlers is limited, just as the total execution time of all finalizers is limited at process shutdown. The default is two seconds. An unmanaged host can change this execution time by calling the ICLRPolicyManager::SetTimeout method with the OPR_ProcessExit enumeration value.

So it seems the only way to handle this from managed code, is to manually call LogManager.Flush() before allowing the application to exit.