Logging in modern (web) applications

"Your application is broken", they say. You ask what doesn't work, and they say: "We get an error". Fantastic. What sort of error? "Well, it's on a blue screen". Aha...

In recent posts, I've covered some approaches on doing complex validation and monitoring the health of your (web) applications. Now, continuing the trend, I want to talk about another really important aspect - logging. That is what can save your nerves in situations and conversations such as the one above. There are lots of different approaches to logging, and as you might expect, the new ASP.NET 5 stack is bringing with it a completely new one - one which I will talk about in an upcoming post too. But, the fundamentals of what I want to show today are no different.

Writing to a log file

Ah yes, the trusted solution for most beginner developers. We all started out writing logs into a file. Usually, we opened a file, and just outputed stuff, like function name. Then came the parameters, and the results, and so on. There are many libraries that are really good at logging to a file, like NLog, log4net, etc. But the problem with this is that file logs are really a pain. Especially if you are running in the cloud, or worse, on multiple hundreds of client machines (e.g. like in a Point Of Sale). The reason is simple: you generally can't access the files on those two deployments. Sure, you could technically RDP on your cloud server, and you can probably RDP on your client machine (with permission) but that won't really get you anywhere fast. And you want to be prepared.

Writing to the database/data source

The next step then, is to try and write to a data source/store. That can be a database or like the Event Log (this can actually be used by Azure and made available to the devs), or you can write to Table Storage (or a similar alternative). Of course, all of these approaches, including logging to a file, have their benefits and their problems. But mostly, they have problems.

Logging as a Service

Ideally, you'll want to have your logs someplace outside of your application (e.g. not inside the app's database). You know, in case something goes wrong, you may want to check the logs. That's hard to do if your db is also down. Luckily, there are companies that are offering logging as a service. One such company is Logentries. I met Trevor, one of the co-founders of Logentries, when I was at Techstars with Zepppelin (now Databox). The thing that struck me the most, apart from my realization that I could absolutely not understand the Irish accent; the company is from Dublin, was just how excited they were about the service. We didn't use them back then, but when the opportunity came, and I led a greenfield project back in Slovenia, I looked into the service.

Love at first log

They do a lot of things, but the core feature is centralization of log data. They're basically a remote data store for all your logs. That makes it really nice if you have cloud hosted, or customer-deployed applications, like we do. It means that I always have a real-time log feed available of what the application is doing. Regardless of where it'deployed (now, obviously there's a caveat, if there's a firewall there, or if the customer explicility disables it, etc., but you get the picture).

We initially used Logentries with log4net, like explained in their getting started guide. But I'm really not a fan of configuration files (especially not XML ones).

Enter... Serilog

Serilog, like Logentries, is basically the next best thing since slided bread. To explain, let me borrow from their website:

Like many other libraries for .NET, Serilog provides diagnostic logging to files, the console, and elsewhere. It is easy to set up, has a clean API, and is portable between recent .NET platforms.

Unlike other logging libraries, Serilog is built with powerful structured event data in mind.

The key part of that quote is the structured event. You'll understand more when we get to the samples.

Let's get logging...

Step 1: If you don't have an account already, register for one at Logentries.comStep 2: Create a Log

I like to do it manually, so I pick the Manual option.

When you enter the details, press create Log, and you get yourself a token. Take note of that token, as you'll need it.

Step 3: Install Serilog and the Logentries sink into your application

PM> Install-Package Serilog
PM> Install-Package Serilog.Sinks.Logentries

Serilog works with the concepts of sink. Each log basically has one or more sinks to where your log data flows. You can browse the serilog tag on NuGet to see the available sinks, extensions and related third-party packages.

Step 4: Send a demo entry

To create a log instance, you need to run the following code. This is where you need the token from above.

var log = new LoggerConfiguration()
            .WriteTo.Logentries("LOGENTRIES_TOKEN")
            .CreateLogger();


log.Information("Our first log entry.");

In a couple moments, we should start to see the first entries in the log:

But that doesn't really make it any more interesting. Let's see what that structured stuff was all about, shall we?

var someData = new
{
 Left = 100,
 Right = 500,
 Top = 504,
 Bottom = 143
};


log.Information("Our first log entry {@SomeData}.", someData);

What that does is basically provide you with a DSL (Domain Specific Language) that is customized for logging. The @ basically tells the engine to serialize the provided field as JSON. So, the above will render like:

Our first log entry { Left: 100, Right: 500, Top: 504, Bottom: 143 }.

Some apps (like Logentries) will actually let you do queries where you're able to say stuff like Left < 105 , specify a range of values, etc. This is where things get really interesting. You can do more complex queries, like only look at things where the value for a certain tenant fell bellow something. Logentries even allows you to do aggregate queries, so you can do averages, sums, etc. You can, for example, calculate the average response time for a given tenant/client, etc. Powerful stuff, really powerful stuff.

Context is king

By now we all know that context really matters. When something goes wrong, you need to know as much as possible about the context. For example, what client was using the app, which device, time, stuff like correlation ID, etc. SeriLog actually lets you do that by adding Enrichers to the logging engine. An enricher is really just a class that adds data (context) to each log message sent out.

For example, in my simple app, I've decided to enrich it with data about the request, about the tenant and some other minor things, like app version.

Using it in your app

However, for me personally, the biggest issue has always been using it in an application. I am a huge proponent of Dependency Injection. But, for logging, that just seems to clumsy. Injecting some interface (e.g. ILog) into all my classes seems redundant. So, over the years I've come to use a solution I really like. Often though, it can be considered an anti-pattern, because it relies on a static accessor, but... If it works, why not use it (where it makes sense, of course).

Here's what I wanted my code to look like, anywhere inside the application:

Log.As.Information("Something has happened, but it's not really relevant.");
Log.As.Warning("This is more severe.");
Log.As.Error("This is extreme.");


throw Log.ANewException("this is so severe, we want to throw an exception");

And it's really easy to achieve. The main code is this:

/// <summary>
/// This class contains all functions related to logging.
/// </summary>
public static class Log
{
    public static void Initialize(ILogGateway gateway)
    {
        As = gateway;
    }


    public static ILogGateway As { get; private set; }


    /// <summary>
    /// Creates a new exception with the given message logs it, and then 
    /// return it to the caller to be thrown.
    /// </summary>
    /// <param name="message"></param>
    /// <param name="parameters"></param>
    [DebuggerHidden]
    public static Exception ANewException(string message, params object[] parameters)
    {
        var e = new Exception(String.Format(message, parameters));


        As.Error(e);


        return e;
    }
}

The ILogGateway interface looks like this:

/// <summary>
/// Abstracts the required functionality of a logging gateway.
/// </summary>
public interface ILogGateway
{
    /// <summary>
    /// Called to log information, non-critical to the running of the application.
    /// </summary>
    /// <param name="template"></param>
    /// <param name="objects"></param>
    void Info(string template, params object[] objects);


    /// <summary>
    /// Called to log warnings, special conditions that seriously affect the application.
    /// </summary>
    /// <param name="template"></param>
    /// <param name="objects"></param>
    void Warning(string template, params object[] objects);


    /// <summary>
    /// Called when a critical error happens (e.g. exception that isn't handled).
    /// </summary>
    /// <param name="template"></param>
    /// <param name="objects"></param>
    void Error(string template, params object[] objects);


    /// <summary>
    /// Logs an exception with a predefined message.
    /// </summary>
    /// <param name="e"></param>
    /// <param name="methodName"></param>
    Exception Error(Exception e, [CallerMemberName]string methodName = "Unknown");
}

Then I basically have an implementation, like SeriLogGateway:

public struct SeriLogGateway : ILogGateway
{
    private readonly ILogger _logger;


    public SeriLogGateway(string apiToken, string logLevel, string outputTemplate, string appVersion)
    {
        var loggingLevel = ResolveLogLevel(logLevel);


        _logger = new LoggerConfiguration()
                   .Enrich.With(new RequestContextEnricher())
                   .Enrich.WithProperty("Version", appVersion)
                   .WriteTo.Logentries(apiToken, true, 50, null, loggingLevel, outputTemplate)
                   .CreateLogger();
    }


    ...


}

The only thing that remains is the following snippet in the app start process (e.g. Global.asax, or an Owin startup class):

Log.Initialize(new SeriLogGateway(logentriesToken, logEventLevel, loggingTemplate, appVersion));
Log.As.Info("Application has started & logging is initalized.");

Conclusion

That's it for this post. I hope it showed you some aspects of logging that are interesting & new. If you can, I'd really urge you to start a free trial of Logentries, and give it a spin. The code for this blog post is published on my GitHub, so you're welcome to start with that.

One last thing, about that t-shirt. Logentries were kind enough to send our team a bunch of shirts when we told them we were doing demos of their app at NT conference. I'll randomly pick 3 people, out of everybody who will leave a comment on this blog to tell me how they're solving logging in their app.