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.

Hello, I'm Paul Stovell

I'm a Brisbane-based software developer, and founder of Octopus Deploy, a DevOps automation software company. This is my personal blog where I write about my journey with Octopus and software development.

I write new blog posts about once a month. Subscribe and I'll send you an email when I publish something new.

Subscribe