NLog Logger.Trace hangs forever

Question

I have a Windows service application running under my username (installed via installutil).

Here are my start/stop event overloads:

protected override void OnStart(string[] args)
{
    try
    {
        Debugger.Launch();
    }
    catch (Exception ex)
    {
        logger.Fatal("...");
        throw;
    }
}

protected override void OnStop()
{
    logger.Trace("service stopped.");
}

logger is an NLog Logger instance, obtained like this:

private static Logger logger = LogManager.GetCurrentClassLogger();

Here is my NLog.config:

<?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"
      autoReload="true">

    <!-- 
  See http://nlog-project.org/wiki/Configuration_file 
  for information on customizing logging rules and outputs.
   -->
    <targets>
        <target xsi:type="Debugger" name="debugger_target" />
        <target xsi:type="Chainsaw" name="chainsaw_target" address="udp4://localhost:4141"/>
        <!--
        <target xsi:type="File" name="f" fileName="${basedir}/logs/${shortdate}.log"
            layout="${longdate} ${uppercase:${level}} ${message}" />
        -->
    </targets>

    <rules>
        <logger name="*" minlevel="Trace" writeTo="chainsaw_target"/>
    </rules>
</nlog>

Then in a specific case I want to add a console log:

    private static void InitializeLogConfiguration()
    {
        var logConfig = LogManager.Configuration ?? new LoggingConfiguration();

        var consoleRule = new ColoredConsoleTarget("logConsole");
        consoleRule.Layout = Layout.FromString("${longdate}|${level:uppercase=true}|${logger}|${newline}${message:withexception=true}${newline}");
        logConfig.AddRule(LogLevel.Trace, LogLevel.Fatal, consoleRule);
        logConfig.DefaultCultureInfo = CultureInfo.InvariantCulture;

        LogManager.Configuration = logConfig;
    }

The service starts up just fine, and the debugger attaches as one would expect, and if I continue from there the service completes its start.

If I then stop the service, a breakpoint in OnStop hits, but when I try to continue over the logger.Trace call, it hangs indefinitely and becomes unresponsive to the service container.

Answer 1

I was seeing this happening due to a known issue with the blocking calls to StandardOutput.ReadToEnd() where combinations of reading and writing to redirected console can deadlock. If you are using NLog to write to a console and you need to read from that console in the same thread I recommend trying the AsyncTargetWrapper. This will run logging operations on a different thread so your application can move on with it's own life and not get stuck waiting around for a task that never returns.

You can add it to your nlog.config by adding async="true" to your targets section like this:

<?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"
      autoReload="true">

    <!-- 
  See http://nlog-project.org/wiki/Configuration_file 
  for information on customizing logging rules and outputs.
   -->
    <targets async="true">
        <target xsi:type="Debugger" name="debugger_target" />
        <target xsi:type="Chainsaw" name="chainsaw_target" address="udp4://localhost:4141"/>
        <!--
        <target xsi:type="File" name="f" fileName="${basedir}/logs/${shortdate}.log"
            layout="${longdate} ${uppercase:${level}} ${message}" />
        -->
    </targets>

    <rules>
        <logger name="*" minlevel="Trace" writeTo="chainsaw_target"/>
    </rules>
</nlog>

Of if you are defining the console log in code, like I was, you can wrap the target like this:

LogManager.Setup().LoadConfiguration(c => c.ForLogger(LogLevel.Trace).WriteToConsole().WithAsync());

You still have to be careful to avoid the issues seen in process redirected console output.