Log Tapping

Octopus uses log4net, my favourite logging library. It also performs a lot of background tasks - for example, deploying applications.

I wanted the output from log4net to be written to the event log (in the case of warnings/errors), as well as to the UI. However, I didn't want to end up with this:

log.Error(ex);
job.Output.Append(ex);

One of my tricks was to set up a "log tapper" - much like a wire tap. This allows me to "listen in" on the log4net chatter within a specific context. For example:

var output = new StringBuilder();

log.Info("Starting the job");

using (LogTapper.CaptureTo(output))
{
    log.Info("Doing the work...");

    someObject.DoSomethingThatAlsoHappensToLog();
}

log.Info("Finished the job");

The LogTapper sets up a scope - within the current thread, and as long as the using block is open, and log messages written by log4net will be appended to the StringBuilder in addition to their normal destinations.

Doing this means I can present the log4net output of a job in the UI, without it being mixed up with the output from lots of other jobs.

The LogTapper implementation is quite simple:

public class LogTapper : IDisposable
{
    LogTapper(StringBuilder builder)
    {
        ThreadContext.Properties["LogOutputTo"] = builder;
    }

    public static IDisposable CaptureTo(StringBuilder builder)
    {
        return new LogTapper(builder);
    }

    public void Dispose()
    {
        ThreadContext.Properties.Remove("LogOutputTo");
    }
}

ThreadContext is a log4net class, and it stores properties that are available to all log4net appenders on a per-thread basis.

To make the implementation work, I then set up a log4net Appender. Whenever a log is written, if a "log tapper" is active on the current thread, it will log the same message to the tapper:

public class LogTapAppender : IAppender
{
    public string Name { get; set; }

    public void DoAppend(LoggingEvent loggingEvent)
    {
        var capture = ThreadContext.Properties["LogOutputTo"] as StringBuilder;
        if (capture == null)
            return;

        capture.AppendLine(DateTime.UtcNow.ToString("yyyy-MM-dd HH:mm:ss") + " " + loggingEvent.Level.DisplayName.PadRight(6, ' ') + " " + loggingEvent.RenderedMessage);

        if (loggingEvent.ExceptionObject != null)
        {
            capture.Append(loggingEvent.ExceptionObject.ToString());
            capture.AppendLine();
        }
    }

    public void Close()
    {
    }
}

What I like about this approach is that all of my components just write useful information to the log4net ILog - they don't need to know if they are being called within the context of a UI, or a job, or any other alternative way of recording their progress. My higher-level controlling classes can siphon the output of any components they call into the place that makes the most sense for them.

A picture of me

Welcome, my name is Paul Stovell. I live in Brisbane and work on Octopus Deploy, an automated deployment tool for .NET applications.

Prior to founding Octopus Deploy, I worked for an investment bank in London building WPF applications, and before that I worked for Readify, an Australian .NET consulting firm. I also worked on a number of open source projects and was an active user group presenter. I was a Microsoft MVP for WPF from 2006 to 2013.

kibria
kibria
03 Nov 2011

NICE