Log4Net Writing Exception Twice To Log with Custom Layout

Question

I am developing an ASP.Net web application and am running into an issue with Log4Net writing out exceptions with a custom layout. I am configuring a rolling file appender in my Global.asax programmatically (not using web.config setup) in the following way:

// Create basic file logging appender for the application. 
var fileAppender = new RollingFileAppender
{
     Layout = new JsonPatternLayout(),
     File = $"c:/logs/web.log",
     AppendToFile = true,
     RollingStyle = RollingFileAppender.RollingMode.Date,
     DatePattern = "yyyyMMdd'.log'",
     StaticLogFileName = true,
     Threshold = Level.Debug
};
fileAppender.ActivateOptions();
log4net.Config.BasicConfigurator.Configure(fileAppender);

JsonPatternLayout is a custom class I wrote to take the Logging event from Log4Net and serialize it to json format for easier digestion into a logging service:

public class JsonPatternLayout : PatternLayout
{
    public override void Format(TextWriter writer, LoggingEvent e)
    {
        var dic = new Dictionary<string, string>
        {
            ["level"] = e.Level.DisplayName,
            ["session"] = e.Identity,
            ["timestamp"] = e.TimeStamp.ToString(),
            ["message"] = e.RenderedMessage,
            ["logger"] = e.LoggerName,
            ["exception"] = e.ExceptionObject == null ? string.Empty : e.ExceptionObject.ToString(),
            ["thread"] = e.ThreadName,
            ["machineName"] = Environment.MachineName
        };
            writer.Write($"{JsonConvert.SerializeObject(dic)}\n");
    }
}

This results in a file output where an exception is written twice -- once in json from from my pattern layout, and again as a string (messages sanitized for clarity):

{"level":"INFO","session":"1","timestamp":"2/14/2020 5:07:12 PM","message":"Message","logger":"Logger","exception":"","thread":"7", "machineName":"Machine"}
{"level":"INFO","session":"1","timestamp":"2/14/2020 5:07:14 PM","message":"Message","logger":"Logger","exception":"","thread":"10","machineName":"Machine"}
{"level":"ERROR","session":"1","timestamp":"2/14/2020 5:07:14 PM","message":"Message","logger":"Logger","exception":"System.Exception: Boo!\r\n   at {CallStack}","thread":"10","machineName":"Machine"}
System.Exception: Boo!
   at {Call Stack}

What I want is for that second time for the exception to not be written out at all. As best as I can tell, this is not going through my formatter because its not a message I am explicitly raising, but rather from the .Net framework itself. Trapping exceptions and not re-throwing them does not keep the exception from logging a second time.

How do I stop this behavior?

Answer 1

I wound up resolving this issue by replacing Log4net with Serilog. I was able to re-use my custom formatter with a few tweaks since Serilog implements many of the same interfaces anyways:

Log.Logger = new LoggerConfiguration()
    // Configure file sink.
    .WriteTo.RollingFile(
        new JsonPatternLayout(),
        @"c:\path\logs\app-{Date}.log",
        LogEventLevel.Information,
        retainedFileCountLimit: 90)
    .CreateLogger();

public class JsonPatternLayout : ITextFormatter
{
    public void Format(LogEvent e, TextWriter writer)
    {
        var dic = new Dictionary<string, object>
        {
            ["level"] = e.Level.ToString(),
            ["session"] = System.Threading.Thread.CurrentPrincipal.Identity.Name,
            ["timestamp"] = e.Timestamp.ToLocalTime().ToString(),
            ["message"] = e.RenderMessage(),
            ["Properties"] = e.Properties,
            ["exception"] = e.Exception == null ? string.Empty : e.Exception.ToString(),
            ["machineName"] = machineName
        };
        writer.Write($"{JsonConvert.SerializeObject(dic)}\n");
    }
}

My logging messages are formatted the same way Log4net did them, and the exceptions are not doubly logged. Was a bit of a pain to replace Log4net entirely, but went very smoothly.

Many thanks to everyone who helped and look at this.