When logs can tell stories – The art of logging with Serilog

I still remember the first day I learnt recursive algorithm…

Phan Hữu Nam Kha (PNK), team leader of Casewhere team, told a great story about logging that we are happy to share with you

I still remember the first day I learnt recursive algorithm. I tried to type the whole program in the textbook into the computer and debug step by step but hmm… “A procedure calls itself”, it is too much troubles for a high-school boy to understand. After spending about an hour desperately trying to debug, I decided to log all the output to the computer screen. It’s turned out the best decision I’ve made, everything was suddenly easy to understand.

Since that day, I started to realize that logging is so powerful and I couldn’t remember how many times a log file has saved my life so far. Released application like a black box beyond our reach, logging sometimes is the only way to know what is happening inside.

Why logging needs a good strategy?

Imaging your software serves hundred users at the same time. A typical log file may end up like this:

This is no longer one man’s story, a lot of different things happened but we have no idea which entries relate to others. On the other hand, while the logs may contain useful information, the messages are flattened into string. It is so hard to extract useful information like user name, booking order number… Often, developers blindly do the logging without having a clear strategy, without thinking much about how the logs are written and later parsed and consumed. Valuable information gets lost or buried in the log messages. Logging is designed to aid troubleshooting, but if it takes too much time to understand, to connect all the info together, then it’s not aiding anything at all. A huge amount of log data becomes less useful or entirely useless.

Write logs that can tell stories

First, you need to be able to get back the whole story, namely there must be a way to string together all related log entries. That is when CorrelationId comes into play. Imagine all log entries in a HTTP context, which starts from the presentation layer, down to the business layers, end up at the persistence layer, share a same correlation id. When something went wrong, you can easily spot possible causes by viewing the whole picture. There are many ways to implement CorrelationId. Take Web Application as an example, HttpContext is best the place to store CorrelationId. For cases where HttpContext does exist such as background threads you can use CallContext instead.

Next, a log entry is something more than just text message. It should carry all information that is essential for troubleshooting. Depending on specific situations or projects but things such as Username, Assembly are always useful. A Log Category is also necessary, for example, by indexing Log Category in log database, you can quickly find out whether Text Resource was built this morning or which feature is used the most. If you’re on a Web Application, probably you will need to enrich the log entry with the Request Url. If you’re on a multitenant project, you may want a TenantId. There are a lot of things to consider!

Code design and considerations

Writing log should be very easy, otherwise, lazy developers will not volunteer to write log for their new code. My favorite method is using Static Class, also avoid inject loggers as service dependencies.

When design logging strategy, you have to consider about security. Things like password, credit card, social security number should never be logged. Writing log of course will affect your application performance but it is affordable cost. A common approach is to hook into the infrastructure e.g. Http Pipeline, Message Dispatcher, Command Handler to automatically capture all data transfer. That is a good approach, however, logging big objects or heavy data like byte array that could degrade your application performance and pollute your log data. How best to prevent all of this, I will discuss in next section.

The art of logging with Serilog

Why Serilog? Serilog is built with powerful structured event data in mind. Writing logs using Serilog has never been easier with DSL, Enricher, Destructor… Furthermore, they provide more than 50 sinks to support writing log events to most of data storages popular these days in various ways. In this post, I will only discuss some outstanding features, but you can read more here

Text formatting can be done using DSL:

logger.Information("Send request {Method} {PathAndQuery} DONE in {@Elapsed}",  
req.HttpMethod, req.Url.PathAndQuery, sw.Elapsed);

{
    "Timestamp": "2017-12-22T13:06:35.5104381+00:00",
    "MessageTemplate": "Send request {Method} {PathAndQuery} DONE in {@Elapsed}",
    "Level": "Information",
    "Exception": null,
    "RenderedMessage": "Send request \"POST\" \"/service/external/v0.1/runworkflow\" DONE in 00:00:00.0015139",
    "Properties": {
        "Method": "POST",
        "PathAndQuery": "/service/external/v0.1/runworkflow",
        "Elapsed": "00:00:00.0015139",
        "Assembly": "*******.Worker.Api 1.0.0.0",
        "AppName": "WorkerAPI",
        "Url": "/service/external/v0.1/runworkflow",
        "Context": "",
        "CorrelationId": "xCv1G8Q6Umiga6VdAGJQ"
    }
}

Support loading configuration from XML, JSON…

<add key="serilog:using:RavenDB" value="Serilog.Sinks.RavenDB" />
<add key="serilog:write-to:RavenDB.connectionStringName" value="Logs" />

Easy to enrich more information with LogContext and Enrichers

public class IdentityEnricher : ILogEventEnricher
{
    public const string PropertyName = "Username";

    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        var userName = Thread.CurrentPrincipal?.Identity?.Name;
        if (!string.IsNullOrEmpty(userName))
            logEvent.AddPropertyIfAbsent(new LogEventProperty(PropertyName, new ScalarValue(userName)));
    }
}

Use Destruction to avoid logging sensitive or unwanted data

Avoid logging big objects, recursive or non-sense data e.g. byte array

Log.Logger = new LoggerConfiguration()
    .ReadFrom.AppSettings()
    .Destructure.AsScalar<byte[]>()
    .CreateLogger();

Simplest way to deal with sensitive property is Serilog.Extras.Attributed

public class LoginModel
{
    public string Username { get; set; }
    [NotLogged]
    public string Password { get; set; }
    public bool RememberMe { get; set; }
}

If you don’t want to pollute your class model, then use a transforming method:

var logger = new LoggerConfiguration()
    .ReadFrom.AppSettings()
    .Destructure.ByTransforming<LoginModel>(model => new 
    {
        model.Username, model.RememberMe
    })
    .CreateLogger();

Or create a DestructingPolicy if you have more complex logic:

public class CustomDestructingPolicy : IDestructuringPolicy
{
    public bool TryDestructure(object value, ILogEventPropertyValueFactory propertyValueFactory, 
        out LogEventPropertyValue result)
    {
        // perform your own destruction logic
    }
}
//...
static void Main(string[] args)
{
    var logger = new LoggerConfiguration()
        .ReadFrom.AppSettings()
        .Destructure.By<CustomDestructingPolicy>()
        .CreateLogger();
}

-Phan Huu Nam Kha-