nlog: Using "Trace" output makes Logger.Error() throw an exception - how to fix?

Question

I'm using NLog for our logging. I am trying to set up a way of getting it to output stuff to System.Diagnostics.Trace(), so I set up the NLog.config file as follows:

<targets>
  <target name="debugOutput" xsi:type="Trace" />
</targets>
<rules>
  <logger name="*" minlevel="Debug" writeTo="debugOutput" />
</rules>

This works fine for all the logging levels EXCEPT for Error() and Fatal().

For example, the following code:

private static readonly Logger _logger = LogManager.GetCurrentClassLogger();
...
_logger.Trace("Sample trace message\n");
_logger.Debug("Sample debug message\n");
_logger.Info("Sample informational message\n");
_logger.Warn("Sample warning message\n");
_logger.Error("Sample error message\n");
_logger.Fatal("Sample fatal error message\n");

throws exceptions when _logger.Error() and _logger.Fatal() are called:

2012-09-28 12:08:04.9296|DEBUG|ClassLibraryUsingNLog.Test|Sample debug message

2012-09-28 12:08:04.9636|INFO|ClassLibraryUsingNLog.Test|Sample informational message

2012-09-28 12:08:04.9906|WARN|ClassLibraryUsingNLog.Test|Sample warning message

---- DEBUG ASSERTION FAILED ----
---- Assert Short Message ----
2012-09-28 12:08:05.0176|ERROR|ClassLibraryUsingNLog.Test|Sample error message

---- Assert Long Message ----

   at NLog.Targets.TraceTarget.Write(LogEventInfo logEvent)
   at NLog.Targets.Target.Write(AsyncLogEventInfo logEvent)
   at NLog.Targets.Target.WriteAsyncLogEvent(AsyncLogEventInfo logEvent)
   at NLog.LoggerImpl.WriteToTargetWithFilterChain(TargetWithFilterChain targetListHead, LogEventInfo logEvent, AsyncContinuation onException)
   at NLog.LoggerImpl.Write(Type loggerType, TargetWithFilterChain targets, LogEventInfo logEvent, LogFactory factory)
   at NLog.Logger.WriteToTargets[T](LogLevel level, IFormatProvider formatProvider, T value)
   at NLog.Logger.Error(String message)
   at ClassLibraryUsingNLog.Test.Func() in c:\Test\CS4.x\ClassLibraryUsingNLog\Test.cs:line 15
   at ConsoleAppIndirectlyUsesNLog.Program.Main(String[] args) in C:\Test\CS4.x\ConsoleAppIndirectlyUsesNLog\Program.cs:line 11

First-chance exception at 0x7686b9bc in ConsoleAppIndirectlyUsesNLog.exe: Microsoft C++ exception: EEMessageException at memory location 0x0053e8d4..
---- DEBUG ASSERTION FAILED ----
---- Assert Short Message ----
2012-09-28 12:08:06.7936|FATAL|ClassLibraryUsingNLog.Test|Sample fatal error message

---- Assert Long Message ----

   at NLog.Targets.TraceTarget.Write(LogEventInfo logEvent)
   at NLog.Targets.Target.Write(AsyncLogEventInfo logEvent)
   at NLog.Targets.Target.WriteAsyncLogEvent(AsyncLogEventInfo logEvent)
   at NLog.LoggerImpl.WriteToTargetWithFilterChain(TargetWithFilterChain targetListHead, LogEventInfo logEvent, AsyncContinuation onException)
   at NLog.LoggerImpl.Write(Type loggerType, TargetWithFilterChain targets, LogEventInfo logEvent, LogFactory factory)
   at NLog.Logger.WriteToTargets[T](LogLevel level, IFormatProvider formatProvider, T value)
   at NLog.Logger.Fatal(String message)
   at ClassLibraryUsingNLog.Test.Func() in c:\Test\CS4.x\ClassLibraryUsingNLog\Test.cs:line 16
   at ConsoleAppIndirectlyUsesNLog.Program.Main(String[] args) in C:\Test\CS4.x\ConsoleAppIndirectlyUsesNLog\Program.cs:line 11

However, if I change the config file to output to OutputDebugString instead, by changing xsi:type to "OutputDebugString" as follows:

<targets>
  <target name="debugOutput" xsi:type="OutputDebugString" />
</targets>
<rules>
  <logger name="*" minlevel="Debug" writeTo="debugOutput" />
</rules>

then it all works as expected without any exceptions. I get this output in the debug output window (after changing the project settings to support unmanaged debugging):

2012-09-28 12:16:13.4166|DEBUG|ClassLibraryUsingNLog.Test|Sample debug message
2012-09-28 12:16:13.4166|INFO|ClassLibraryUsingNLog.Test|Sample informational message
2012-09-28 12:16:13.4166|WARN|ClassLibraryUsingNLog.Test|Sample warning message
2012-09-28 12:16:13.4266|ERROR|ClassLibraryUsingNLog.Test|Sample error message
2012-09-28 12:16:13.4266|FATAL|ClassLibraryUsingNLog.Test|Sample fatal error message

Is there a way to make this work with outputting to System.Diagnostics.Trace() without throwing exceptions for Logger.Error() and Logger.Fatal()? And why does it behave this way?

Answer 1

Further to the first answer:

The NLog TraceTarget calls Trace.Fail wehn the LogLevel is >= LogLevel.Error

The Trace.Fail method is documented here http://msdn.microsoft.com/en-us/library/95s7fba5.aspx

The cause of the problem appears to be:

The default behavior for the default trace listener is to output the message parameter to a message box when the application runs in user-interface mode, and to the TraceListener instances in the Listeners collection.

You can demonstrate the problem in a console app

 static void Main( string[ ] args ){
  Trace.TraceInformation( "Hello world" );
  Trace.Fail("A failure");
}

You can "fix" this by removing the DefaultTraceListener before adding your own TraceListener

static void Main( string[ ] args ){
  Trace.Listeners.Clear();
  Trace.Listeners.Add( new ConsoleTraceListener( ) );
  Trace.TraceInformation( "Hello world" );
  Trace.Fail("A failure");
}

Alternatively you can set the AssertUiEnabled property of the DefaultTraceListener to false.

static void Main( string[ ] args ){
  Trace.Listeners.OfType<DefaultTraceListener>().First().AssertUiEnabled = false;
  Trace.TraceInformation( "Hello world" );
  Trace.Fail("A failure");
}

This suppresses the Assert Failure Dialog however the Trace Output still contains a spurious stack dump

If you just want to send logging information to the Visual Studion Output window use the DebuggerTarget

Answer 2

Internally, the TraceTarget uses System.Diagnostics.Trace.Fail to write the message.

Here is the code for the NLog TraceTarget's Write method:

protected override void Write(LogEventInfo logEvent)
{
    if (logEvent.Level >= LogLevel.Error)
    {
        Trace.Fail(this.Layout.Render(logEvent));
    }
    else
    {
        Trace.WriteLine(this.Layout.Render(logEvent));
    }
}

I don't have an answer for why Trace.Fail is apparently failing. However, knowing that NLog uses Trace.Fail, you might experiment with using Trace.Fail (at the same call site where you are logging with NLog) and see if you can diagnose what is going wrong with Trace.Fail. It could have something to do with the System.Diagnostics configuration (or lack of same) in your app.config file.

Note that in the MSDN documentation for Trace.Fail, it says that if the DefaultTraceListener is not present, a MessageBox is used. I notice in your output that you are using a Console app. Is it possible that MessageBox does not work correctly in the context of a Console app?

Here is a link to a relatively old blog posting by Scott Hanselman that might shed some light on your problem. Towards the bottom he describes a problem with Trace.Fail in a non-UI context and proposes a solution that might work for you.

To summarize, he suggests putting this (specifically, the assertuienabled flag) in your app.config/web.config (or set it via code).

<configuration>
   <system.diagnostics>
      <assert assertuienabled="false" logfilename="c:\log.txt"/>
   </system.diagnostics>
</configuration>

Good luck!

Answer 3

NLog 4.5 introduces the setting rawWrite=true that forwards to Trace.WriteLine independent of LogLevel.

<targets>
  <target xsi:type="Trace" name="debugOutput" rawWrite="true" />
</targets>

See also: https://github.com/nlog/nlog/wiki/Trace-target

P.S. Since NLog 2.0.1 then only LogLevel.Fatal is mapped to Trace.Fail