How we do Semantic Logging

I know full well that what I’m showing here is polarizing and some of you are going to hate it, but what we did does have some significant benefits and it’s possible it could be pulled off later with cleaner usage mechanics. When you read this and start saying, “isn’t this like Serilog?”, please just read to the end. 

I’ve frequently used the term “semantic logging” to describe the mechanism we still use in FubuMVC for our logging abstraction. By semantic logging, I mean that we log strong-typed messages for most framework audit and debug actions.

To make that concrete, this is part of our ILogger interface that FubuMVC uses internally:

    public interface ILogger
    {
        // LogTopic is yes, a standardized base
        // class with some basic properties for
        // timestamps and a Guid Id
        void DebugMessage(LogTopic message);
        void InfoMessage(LogTopic message);

        // This is the mechanism for conditional logging if
        // there is a registered listener for whatever T is
        void DebugMessage<T>(Func<T> message) where T : class, LogTopic;
        void InfoMessage<T>(Func<T> message) where T : class, LogTopic;
    }

Taking the service bus part of FubuMVC as an example, we have these log topic types that get logged at various points in message sending and handling:

1. EnvelopeSent — in service bus parlance, an “envelope” would be a message plus whatever metadata the service bus needs to get it to the right place.
2. EnvelopeReceived
3. MessageSuccessful
4. MessageFailed

For a concrete example from inside our service bus features, we log an EnvelopeSent log record any time a message is sent from the service bus client:

private void sendToChannel(Envelope envelope, ChannelNode node)
{
    var replyUri = _router.ReplyUriFor(node);

    var headers = node.Send(envelope, _serializer, replyUri: replyUri);
    _logger.InfoMessage(() => new EnvelopeSent(new EnvelopeToken
    {
        Headers = headers,
        Message = envelope.Message
    }, node));
}

As you can see above, we pass a Func<EnvelopeSent> into the logger.InfoMessage() method instead of directly building an EnvelopeSent object. We do that so that the logging can be optional, so that if nothing is listening for the EnvelopeSent log record type, that Func in never executed. Some of you might argue that this is a little less efficient at runtime than doing the if (_logger.ListensFor(typeof(EnvelopeSent)) _logger.InfoMessage(new EnvelopeSent{}); approach and you’d be correct, but I prefer using the Func approach to express the optional logging because I think it’s more terse and easier to read.

Internally, the actual “sinks” for these log records have to implement this interface (partially elided for space):

    public interface ILogListener
    {
        bool IsDebugEnabled { get; }
        bool IsInfoEnabled { get; }

        // Does this particular listener
        // care about a log record type?
        bool ListensFor(Type type);

        void DebugMessage(object message);
        void InfoMessage(object message);

    }

With this interface, you are able to subscribe for certain log record types being logged by the application.

We manage both ILogger and the full collection of ILogListener’s through our application’s IoC container. While there probably isn’t a more polarizing technique in the software world than using an IoC tool, in our case I think it’s been very advantageous for us because of how easy that makes it to add or remove log listeners and to govern the lifecycle or scoping of log listeners (think about having a log listener scoped to a single HTTP request that makes it stupidly easy to correlate log messages to a certain HTTP request).

 

The Downside

Some of my coworkers don’t like this approach because of the need to add all the extra Type’s to your code. To their point, I don’t think you’d bother to make every single log message its own special type, only things that are more valuable to key off of in system diagnostics or in tooling like our test automation support sample I’m showing in another section below. We do have some basic “Info(string message) or Debug(string message)” support too in our ILogger, but my advice for that kind of thing has been to go straight to some kind of low level logging tool like NLog or log4net.

The benefits are richer system monitoring because it’s so easy to intelligently parse and filter the information being logged.

Some Valuable Usages

 

• Our HTTP request tracing in FubuMVC depends on a custom ILogListener that tracks any and all log topic records to the record of that HTTP request. By being able to listen for only certain log topic Type’s, we can easily move our diagnostic trace level from nothing to a production mode where we only hang on to certain types of logging actions to a very verbose, record everything mode for local development. Ditto for our service bus support inside of FubuMVC (was FubuTransportation).
• Having the strong typed log record messages made it fairly simple to create powerful visualizations of different logging actions in FubuMVC’s built in diagnostics
• I actually think it’s easier to filter out what logging message types you care about listening for than trying to filter logging output by the classes or namespaces in your application like folks do with tools like log4net or NLog.
• We can inject custom ILogListener’s in automated testing harnesses to gather a lot of application diagnostics and embed these diagnostics directly into our acceptance testing output reports. That’s been extremely valuable for us to troubleshoot failing tests or understand performance problems in our code by having an easy correlation between each automated test and the logging records.  I’ll write a blog post about how we do that someday.
• In my very next blog post I’ll talk about how we use an ILogListener to monitor the activity of a service bus applications so that you can much more reliably coordinate automated test harnesses with the application code.

Replace with Serilog the next time around?

I’m very happy with what we were able to do in terms of its impact, and “semantic logging” has consistently been in my “keep from FubuMVC” column in our planning for whatever we do next. In the longer term though, I think I’d like look to look at using Serilog as our underlying logging mechanism and just figure out how we could inject custom listeners into Serilog to replace our diagnostic and test automation abilities. It would mean giving up on the strong typed messages that *I* like, but might be more palatable for other developers. Now that we’ve mostly replaced server side rendering with a React.js based UI in our diagnostics, it might make more sense anyway to do the visualizations against a JSON body.

Mostly though, that’s just a way to have less custom OSS code that I have to support and maintain;)

 

What about…?

Anytime I write a blog post like this I get a flood of “have you tried XYZ?” kind of questions about other tools that I may or may not have heard of. I’ll try to cover some of them:

• log4net? NLog? – now that NLog is strong named (boo!), I don’t have any preference for either and I would never in a million years consider coupling any of my OSS projects to either. In other news, strong naming still sucks and it’s something you have to consider when you release an OSS tool
• There is the Semantic Logging Block tool from Microsoft P&P. I haven’t used it, and my informal Twitter poll on it suggests that folks prefer Serilog over it.
• What about taking a dependency on Common Logging then doing whatever you want for the actual logging? I looked at doing this years ago when we first introduced logging into FubuMVC and decided against it. My thinking is that Common Logging suffers from a “boiling the ocean” kind of problem that bloats its API surface.
• Liblog? It’s probably a better alternative to Common Logging without some of the compatibility headaches brought on by strong naming conflicts, but doesn’t really address the idea of semantic logging
• I know that once upon a time the Glimpse guys were throwing around a similar idea for semantic logging (they weren’t using the same terminology though) with rich logging messages that you could consume in your own application monitoring tooling.