ASP.NET Core Structured Logging and Seq

Update July 2016: RTM is here! This post was originally written for RC1, but has now been brought up-to-date to cover .NET Core 1.0.

ASP.NET Core is a complete rewrite of ASP.NET, targeting .NET Core on Linux and OS X as well as Windows.

Among the many upgrades in the new version is a completely rewritten diagnostic logging pipeline that not only emits interesting events from the framework, but uses structured logging to do so.

Structured Logging in ASP.NET Core

Like Serilog, ASP.NET Core uses message templates (named placeholders in format strings) to capture structured properties along with textual log data:

logger.Information("Handled in {Elapsed} ms", timer.ElapsedMilliseconds);

If this event is written out to the console, it will be formatted as plain text:

Handled in 456 ms

This is ideal during development, when a readable text format is preferred.

But, when the logging provider supports structured data, the properties associated with the event can be preserved in a machine-readable form:

{
  "MessageTemplate": "Handled in {Elapsed} ms",
  "Properties": {
    "Elapsed": 456
  }
}

Armed with structured log data, it's easy to slice and dice logs with queries like:

Elapsed > 300

This is a game-changing capability for complex distributed apps, or when log data runs more than a few hundred events in a day.

Setting Up

These instructions assume that you've created a new ASP.NET web application using the template in Visual Studio (File > New... > Project > ASP.NET Web Application).

Out of the box it should look something like this:

The packages we'll install are:

Serilog - a logging framework for structured data
Serilog.Extensions.Logging - an ASP.NET logging provider that implements ASP.NET's ILogger on top of Serilog
Serilog.Sinks.Seq - a Serilog sink that ships events to Seq over HTTP

To really take advantage of ASP.NET Core's logging today, you'll need a complete logging provider like Serilog to handle the task of shipping log events to most back-end storage targets, as only a few basic providers such as a console logger are there today. Over time it's likely ASP.NET Core will gain more capabilities of its own in this area.

Crucially, all of the packages supporting ASP.NET Core are currently pre-release, so make sure to include the -Pre switch when installing from the Package Manager Console:

Install-Package Serilog
Install-Package Serilog.Extensions.Logging
Install-Package Serilog.Sinks.Seq

Then, the following lines added to Startup.cs will configure the Serilog back-end:

public Startup(IHostingEnvironment env)
{
    // Configure the Serilog pipeline
    Log.Logger = new LoggerConfiguration()
        .MinimumLevel.Debug()
        .Enrich.FromLogContext()
        .WriteTo.Seq("http://localhost:5341")
        .CreateLogger();

This assumes you have Seq running locally on your development machine, listening on the default port. Replace http://localhost:5341 with the address of you Seq server if it lives somewhere else.

(Adding Enrich.FromLogContext() here ensures that any events written directly through Serilog will seamlessly pick up correlation ids like RequestId from ASP.NET.)

Finally, also in Startup.cs, add Serilog to the ILoggerFactory that's passed into the Configure() method:

public void Configure(IApplicationBuilder app,
                      IHostingEnvironment env,
                      ILoggerFactory loggerFactory)
{
    loggerFactory.AddConsole(Configuration.GetSection("Logging"));
    loggerFactory.AddDebug();

    // Add Serilog to the logging pipeline
    loggerFactory.AddSerilog();

When you refresh the application, all kinds of interesting data from the framework's inner workings will appear in Seq:

In this screenshot you can see a few familiar MVC processes going on - requests started and finished, actions invoked and views selected.

Writing custom events

It would be interesting, but fairly underwhelming, if the story ended here. The real value in the new logging pipeline is that your own application events get the same treatment.

The simplest way to start logging from your own controllers is to take a dependency on type ILogger<T>:

public class HomeController : Controller
{
    readonly ILogger<HomeController> _logger;

    public HomeController(ILogger<HomeController> logger)
    {
        _logger = logger;
    }

The T generic parameter is passed so that log events can be tagged with the class that raised them.

ILogger<T> has methods like LogInformation(), LogWarning() and LogError() to write events to the logging pipeline:

    public IActionResult Index()
    {
        var machine = Environment.GetEnvironmentVariable("COMPUTERNAME");
        _logger.LogInformation("Hello from {MachineName}!", machine);
        return View();
    }

Look carefully at the properties attached to the resulting event:

The first thing to notice is that the MachineName argument we supplied in the format string is there as a first-class property that can be used when searching for events.

The second thing to observe is RequestId - this little gem is added automatically by the ASP.NET framework to all events raised during a web request. Filtering down to a single RequestId will find all events related to just that HTTP request - your own, and the ones raised by the framework. If you don't use this technique already, it's something you absolutely must try.

Alternatives for ASP.NET 4.6

Not using ASP.NET Core just yet? Check out the Serilog support for ASP.NET 4.6, which adds a lot of structured logging goodness through a NuGet package.

Happy logging!