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