NLog does not flush buffered logs when targets are set as async

Question

I'm currently revising our NLog configurations and while trying to set our targets async and use a BufferingTarget for our mail processsing, I've found that Nlog does not seems to flush the mail on application close.

Calling the LogManager.Flush(); does not work either, it gives a NLog.NLogRuntimeException :

A first chance exception of type 'NLog.NLogRuntimeException' occurred in NLog.dll Additional information: Asynchronous exception has occurred.

I've found that removing the async="true" from the targets made my configuration works. Below is the configuration and the console source code I've used to do my tests.

I saw that there is quite a few of post that could be related to this one, regarding log sequence and/or FallbackTarget, but they didn't help much to resolve the issue I have currently.

Console Application

class Program
{
    static void Main(string[] args)
    {
        Logger logger = LogManager.GetCurrentClassLogger();

        logger.Debug("Debug Message");
        logger.Debug("Debug Message");

        LogManager.Flush();
        LogManager.Shutdown();
    }
}

Nlog Configuration

  <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    internalLogFile="Logs\Nlogs.txt"
    throwExceptions="true">

    <variable name="LongLayout" value="${longdate} | ${machinename} | ${logger} | ${callsite} (${callsite-linenumber}) | ${message}${onexception:${newline}${exception:format=Type}${newline}${newline}${exception:format=tostring}}"/>
    <variable name="ShortLayout" value="${longdate} | ${callsite} (${callsite-linenumber}) | ${message}${onexception:${newline}${exception:format=Type}${newline}${newline}${exception:format=tostring}}"/>

    <targets async="true">
      <target name="Console" xsi:type="ColoredConsole" layout="${ShortLayout}"/>
      <target name="File" xsi:type="File"
              fileName="${basedir}\Logs\${level}.log"
              archiveFileName="${basedir}\Logs\Archives\${level}_${shortdate}_{##}.log"
              archiveAboveSize="1000000"
              layout="${LongLayout}"/>
      <target name="MailBuffer" xsi:type="BufferingWrapper" flushTimeout="50000" slidingTimeout="false">
        <target name="Mail" xsi:type="Mail"
              smtpServer="smtp.gmail.com"
              smtpPort="587"
              smtpAuthentication="Basic"
              smtpUserName="username"
              smtpPassword="password"
              enableSsl="true"
              from="from"
              to="to"
              subject="Service: ${machinename} | ${logger} | ${level}"
              body="${LongLayout}${newline}"/>
      </target>
    </targets>

    <rules>
      <logger name="*" levels="Fatal,Error,Warn,Debug,Info,Trace" writeTo="Console" enabled="true" />
      <logger name="*" levels="Fatal,Error,Warn,Debug,Info,Trace" writeTo="File" enabled="true" />
      <logger name="*" levels="Fatal,Error,Warn,Debug,Info,Trace" writeTo="MailBuffer" enabled="true" />
    </rules>    
  </nlog>

Exception Stack Trace

at NLog.Common.AsyncHelpers.RunSynchronously(AsynchronousAction action)
   at NLog.LogFactory.Flush(TimeSpan timeout)
   at NLog.LogFactory.Flush()
   at NLog.LogManager.Flush()
   at MyProject.NlogTests.Program.Main(String[] args) in p:...\Program.cs:line 15

Nlog Log File (Simplified)

2016-12-09 17:29:55.0471 Trace Opening \bin\Dev\\Logs\Info.log with allowFileSharedWriting=False
2016-12-09 17:29:55.5354 Trace LogFactory.Flush(00:00:15)
2016-12-09 17:29:55.5354 Trace Flushing all targets...
2016-12-09 17:29:55.5354 Trace ForEachItemInParallel() 3 items
2016-12-09 17:29:55.5819 Trace Flushing 1 events.
2016-12-09 17:29:55.6119 Trace Opening \bin\Dev\\Logs\Info.log with allowFileSharedWriting=False
2016-12-09 17:29:55.6209 Trace Continuation invoked: 
2016-12-09 17:29:55.6209 Trace Parallel task completed. 2 items remaining
2016-12-09 17:29:55.6825 Trace Flushing 0 events.
2016-12-09 17:29:55.6825 Trace Continuation invoked: 
2016-12-09 17:29:55.6825 Trace Parallel task completed. 1 items remaining
2016-12-09 17:30:16.7442 Trace LogFactory.Flush(00:00:15)
2016-12-09 17:30:16.7442 Trace Flushing all targets...
2016-12-09 17:30:16.7702 Trace ForEachItemInParallel() 3 items
2016-12-09 17:30:16.8032 Trace Flushing 0 events.
2016-12-09 17:30:16.8032 Trace Flushing 0 events.
2016-12-09 17:30:16.8032 Trace Continuation invoked: 
2016-12-09 17:30:16.8032 Trace Parallel task completed. 2 items remaining
2016-12-09 17:30:16.8032 Trace Continuation invoked: 
2016-12-09 17:30:16.8032 Trace Continuation invoked: 
2016-12-09 17:30:16.8167 Trace Parallel task completed. 1 items remaining
2016-12-09 17:30:16.8167 Trace Parallel task completed. 0 items remaining
2016-12-09 17:30:16.8167 Info Shutting down logging...
2016-12-09 17:30:16.8167 Info Closing old configuration.
2016-12-09 17:30:16.8167 Trace LogFactory.Flush(00:00:15)
2016-12-09 17:30:16.8167 Trace Flushing all targets...
2016-12-09 17:30:16.8167 Trace ForEachItemInParallel() 3 items
2016-12-09 17:30:16.8457 Trace   Using basic authentication: Username='########@########.com' Password='********'
2016-12-09 17:30:16.8472 Debug Sending mail to ########@########.com using smtp.gmail.com:587 (ssl=True)
2016-12-09 17:30:16.8472 Trace   Subject: 'Service: ####### | ######### | Info'
2016-12-09 17:30:16.8472 Trace   From: '########@########.com'

Answer 1

I see that the default timeout is 15 seconds.

You could try increasing the timeout.

e.g.

LogManager.Flush(TimeSpan.FromSeconds(60)); 

Answer 2

NLog ver. 4.4.1 now attempts to handle manual flush instantly, instead of waiting for the flushTimeout="50000" of the BufferingWrapper.