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

Question

I am currently reviewing our NLog configurations, and trying to set our async goals and use BufferingTarget for our mail processing processes, I found that Nlog does not seem to close mail when the application closes.

The call LogManager.Flush();does not work either, it gives NLog.NLogRuntimeException:

The first random error like "NLog.NLogRuntimeException" occurred in NLog.dll Additional information: An asynchronous exception occurred.

I found that removing async="true"from targetsmade my configuration work. The following is the configuration and source code for the console that I used to run my tests.

I saw that there are quite a few posts that may be related to this regarding the sequence of logs and / or FallbackTarget, but they did not help to solve the problem that I have.

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

Nlog ver. 4.4.1 now tries to instantly perform a manual cleanup, instead of waiting for flushTimeout = "50000" BufferingWrapper.

Answer 2

I see that the default timeout is 15 seconds.

You can try to increase the waiting time.

eg.

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