Help me please to format exception logged with file logger
I would like to have exceptions to be logged with new line separator between inner exceptions (if any) with exception type surrounded with some special sort of symbols, like [ArgumentException] to make it different from error text, and exceptions to be intended with tab just to make it easy to read stack traces
I've checked the latest NLog 4.4.12 package but the problem is that it is not so easy to parameterize default layout to get something like
2017-10-04 15:13:22.5823 NLogTest.Program starting
2017-10-04 15:13:22.5823 NLogTest.Program failed to start NLogTest
[ArgumentException] bad try
at NLogTest.Classes.UnitOfWork.tryException() in d:\projects\NLogTest\Program.cs:line 62
at NLogTest.Program.Main(String[] args) in d:\projects\NLogTest\Program.cs:line 19
[ArgumentException] outer exception
at NLogTest.Classes.UnitOfWork.outerException() in d:\projects\NLogTest\Program.cs:line 49
at NLogTest.Classes.UnitOfWork.tryException() in d:\projects\NLogTest\Program.cs:line 57
[KeyNotFoundException] innerException
at NLogTest.Classes.UnitOfWork.innerException() in d:\projects\NLogTest\Program.cs:line 38
at NLogTest.Classes.UnitOfWork.outerException() in d:\projects\NLogTest\Program.cs:line 45
2017-10-04 15:13:22.5823 NLogTest.Program the end
This is exception file log that I'd like to get. I've tried with layout like
layout="${longdate} ${logger} ${message}${onexception:${newline}${exception:format=tostring}}"
it uses standard tostring exception method but the result is not the same. I do not like that
2017-10-04 15:28:52.6881 NLogTest.Program failed to start NLogTest
System.ArgumentException: bad try ---> System.ArgumentException: outer exception ---> System.Collections.Generic.KeyNotFoundException: innerException
at NLogTest.Classes.UnitOfWork.innerException() in d:\projects\NLogTest\Program.cs:line 40
at NLogTest.Classes.UnitOfWork.outerException() in d:\projects\NLogTest\Program.cs:line 47
--- End of inner exception stack trace ---
at NLogTest.Classes.UnitOfWork.outerException() in d:\projects\NLogTest\Program.cs:line 51
at NLogTest.Classes.UnitOfWork.tryException() in d:\projects\NLogTest\Program.cs:line 59
--- End of inner exception stack trace ---
at NLogTest.Classes.UnitOfWork.tryException() in d:\projects\NLogTest\Program.cs:line 64
at NLogTest.Program.Main(String[] args) in d:\projects\NLogTest\Program.cs:line 20
Inner exception messages stack trace are detached in the log (so it is hard to read log later) in case if exception is re-thrown more then twice and there is no tab (space) before exception type name.
The best result I've got was with layout below
layout="${longdate} ${logger} ${message}${onexception:${newline}${exception:maxInnerExceptionLevel=10:format=shortType,message,stacktrace:separator=*:innerExceptionSeparator=
	}}"
and it is
2017-10-04 15:49:02.6188 NLogTest.Program failed to start NLogTest
ArgumentException*bad try* at NLogTest.Classes.UnitOfWork.tryException() in d:\projects\NLogTest\Program.cs:line 64
at NLogTest.Program.Main(String[] args) in d:\projects\NLogTest\Program.cs:line 20
ArgumentException*outer exception* at NLogTest.Classes.UnitOfWork.outerException() in d:\projects\NLogTest\Program.cs:line 51
at NLogTest.Classes.UnitOfWork.tryException() in d:\projects\NLogTest\Program.cs:line 59
KeyNotFoundException*innerException* at NLogTest.Classes.UnitOfWork.innerException() in d:\projects\NLogTest\Program.cs:line 40
at NLogTest.Classes.UnitOfWork.outerException() in d:\projects\NLogTest\Program.cs:line 47
However it is very hard to read. First stack trace line is on the same line as exception message. Inner error message is intended but inner stack trace - no.
Is there anything in layout that I've missed ? Should I create custom exception layout renderer ? Here is c# source code that I've used to raise exception
Writing an NLog layout renderer is simple enough so I've managed to create an exception layout renderer that formats exceptions exactly as requested.
The latest custom layout source code version can be found on gist Sample configuration for console and file logger is available also. There is NLog.IndentException NuGet package also. See the end of this answer for a snapshot of the code in case of link rot.
Additionally I've added a stack trace filter. Sometimes exceptions are logged more than once. May be because of bad design (exception should be logged only once) or maybe because the same method can be used from external code (so exception should be logged locally before is thrown out) or by another method in the same solution. In such case inner exception can be logged more than once. To reduce the size of the stack trace, I've added a configuration to skip stack trace logging if exception was previously logged (:LogStack=false). Only the exception type and message are logged in this case. Like below:
[1] 2017-10-04 16:55:17.2227 Debug NLogTest.Program starting
[1] 2017-10-04 16:55:17.2527 Error NLogTest.Classes.UnitOfWork tryException failure
[ArgumentException] outer exception
at NLogTest.Classes.UnitOfWork.outerException() in d:\projects\NLogTest\Program.cs:line 48
at NLogTest.Classes.UnitOfWork.tryException() in d:\projects\NLogTest\Program.cs:line 56
[KeyNotFoundException] innerException
at NLogTest.Classes.UnitOfWork.innerException() in d:\projects\NLogTest\Program.cs:line 37
at NLogTest.Classes.UnitOfWork.outerException() in d:\projects\NLogTest\Program.cs:line 44
[1] 2017-10-04 16:55:17.2697 Error NLogTest.Program failed to start NLogTest
[ArgumentException] bad try
at NLogTest.Classes.UnitOfWork.tryException() in d:\projects\NLogTest\Program.cs:line 61
at NLogTest.Program.Main(String[] args) in d:\projects\NLogTest\Program.cs:line 17
[ArgumentException] outer exception
[KeyNotFoundException] innerException
Outer exception and innerException are logged twice. First time as outer exception was caught, and second when they are logged as inner exceptions. However since the log contains the stack trace already, only the exception type and message are logged.
IndentExceptionLayoutRenderer.cs
using NLog;
using NLog.LayoutRenderers;
using System;
using System.Linq;
using System.Text;
using System.Collections.Concurrent;
namespace NLogTest
{
/// <summary>
/// renders exception starting from new line
/// with short type exception name followed by message
/// and stacktrace (optionally)
/// if exception is logged more than once (catched, logged and re-thrown as inner), stack trace is not written
/// </summary>
[LayoutRenderer("IndentException")]
public class IndentExceptionLayoutRenderer : LayoutRenderer
{
/// <summary>
/// indent before exception type (default is tab)
/// </summary>
public string Indent { get; set; }
/// <summary>
/// indent between each stack trace line (default is two tab characters)
/// </summary>
public string StackTraceIndent { get; set; }
/// <summary>
/// is written before exception type name (default [)
/// </summary>
public string BeforeType { get; set; }
/// <summary>
/// is written after exception type name (default ])
/// </summary>
public string AfterType { get; set; }
/// <summary>
/// separator between exception type and message
/// </summary>
public string Separator { get; set; }
/// <summary>
/// log stack trace or not (for console logger e.g.)
/// </summary>
public bool LogStack { get; set; }
/// <summary>
/// holds logged already exceptions just to skip surplus stack logging
/// </summary>
static ConcurrentQueue<Exception> _loggedErrors = new ConcurrentQueue<Exception>();
public IndentExceptionLayoutRenderer()
{
Indent = "\t";
StackTraceIndent = "\t\t";
BeforeType = "[";
AfterType = "]";
LogStack = true;
Separator = " ";
}
protected override void Append(StringBuilder builder, LogEventInfo logEvent)
{
var e = logEvent.Exception;
while (e != null)
{
builder.AppendFormat("{1}{2}{0}{3}{4}", e.GetType().Name, Indent, BeforeType, AfterType, Separator);
builder.Append(e.Message);
if (LogStack)
{
var stackTraceWasLogged = _loggedErrors.Contains(e);
if (!stackTraceWasLogged)
{
builder.AppendLine();
_loggedErrors.Enqueue(e);
builder.AppendFormat("{0}", e.StackTrace.Replace(" ", StackTraceIndent));
}
if (_loggedErrors.Count > 50)
{
_loggedErrors.TryDequeue(out Exception ex1);
_loggedErrors.TryDequeue(out Exception ex2);
}
}
e = e.InnerException;
if (e != null)
builder.AppendLine();
}
}
}
}
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"
xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
autoReload="true"
throwExceptions="false"
internalLogLevel="Off" internalLogFile="%temp%\nlog-internal.log">
<!-- optional, add some variables
https://github.com/nlog/NLog/wiki/Configuration-file#variables
-->
<variable name="logfilename" value="NLogTest" />
<targets>
<target xsi:type="ColoredConsole"
name="console"
useDefaultRowHighlightingRules="true"
detectConsoleAvailable="true"
layout="${message}${onexception:${newline}${exception:maxInnerExceptionLevel=10:format=shortType,message}}" />
<target name="file" xsi:type="File"
fileName="${basedir}/${logfilename}.log"
keepFileOpen="false"
layout="${longdate} ${logger} ${message}${onexception:${newline}${exception:maxInnerExceptionLevel=10:format=shortType,message,stacktrace:separator=*:innerExceptionSeparator=
	}}" />
</targets>
<rules>
<logger name="*" minlevel="Debug" writeTo="file" />
<logger name="*" minlevel="Trace" writeTo="Console" />
</rules>
</nlog>
NLog.exceptionIndent.config
<target xsi:type="ColoredConsole"
name="console"
useDefaultRowHighlightingRules="true"
detectConsoleAvailable="true"
layout="${level} ${message}${onexception:${newline}${IndentException:LogStack=false:separator=	:beforeType=:aftertype=}}" />
<target name="file" xsi:type="File"
fileName="${basedir}/${logfilename}.log"
keepFileOpen="false"
layout="[${threadid}] ${longdate} ${level} ${logger} ${message}${onexception:${newline}${IndentException}}" />
NLogTest.cs
using NLog;
using NLogTest.Classes;
namespace NLogTest
{
class Program
{
static ILogger Log = LogManager.GetCurrentClassLogger();
static void Main(string[] args)
{
Log.Debug("starting");
try
{
new UnitOfWork().TryException();
}
catch (Exception e)
{
Log.Error(e, "failed to start NLogTest");
Console.ReadKey();
}
Log.Debug("the end");
}
}
}
namespace NLogTest.Classes
{
class UnitOfWork
{
static ILogger Log = LogManager.GetCurrentClassLogger();
public void InnerException()
{
throw new KeyNotFoundException("innerException");
}
public void OuterException()
{
try
{
InnerException();
}
catch (Exception e)
{
throw new ArgumentException("outer exception", e);
}
}
public void TryException()
{
try
{
OuterException();
}
catch (Exception e)
{
Log.Error(e, "tryException failure");
throw new ArgumentException("bad try", e);
}
}
}
}