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

I still remember the first day I learnt recursive algorithm...

Posted by RITVN on December 26, 2017

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

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.

Log to console

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:

Production log file example

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!

Log entry example

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();
}

We are hiring

Would you like to work with the coolest IT guys in Vietnam? Apply to one of the following jobs:

C# / .Net Developer
Senior / Specialist
1000 – 3000 USD

Job requires a high level of technical skills and experience within Microsoft technologies and offers high salary, exciting projects, and constant challenges in terms of technology and design.

Tell me more
Xamarin Developer
Experienced
800 – 1500 USD

Want to have fun developing innovative Xamarin products? We are developing a number of exciting games and social applications of our own as well as supporting third party clients.

Tell me more
Technical Writer
Advanced English
2000 – 4000 USD

Job requires both good English as well as the ability to understand complex technical subjects and systems. You will mainly be writing SEO articles and guidelines for our many products.

Tell me more
Front-End Developers
Experienced
1000 – 2500 USD

We are looking to fill Developer positions with a new team that uses JavaScript, TypeScript, HTML5, AngularJS.
Knowing Ionic framework or NodeJs is a plus, but is not mandatory.

Tell me more
.NET/WPF Developers
Advanced English
1000 – 3000 USD

2 Senior Developer positions in an Offshore Development Center team. You will work directly with a Danish Project Manager at our Vietnam office. The initial project is for a multinational French company.

Tell me more
Ruby/Cucumber QA/Test engineering
Advanced English
1000 – 2000 USD

1 Senior QA/Test Engineer in an Offshore Development Center team. You will work directly with a Danish Project Manager at our Vietnam office. The initial project is for a multinational French company.

Tell me more