Serilog Tutorial

Nicholas Blumhardt -

Structured logging has exploded in popularity over the past few years. We've put together this streamlined guide to Serilog, .NET's favorite structured logging library, so you can get up and running fast.

Updated May 2022 for .NET 6, C# 10, and Serilog 2.11.

Contents

  1. Setting goals
  2. Hello, Serilog!
  3. Events and levels
  4. Emitting and collecting structured data
  5. Tagging events for filtering and correlation
  6. Finding needles in the haystack
  7. What's next?
  8. Getting help

1. Setting goals

You might be joining a project that already uses Serilog, you may have a new .NET application to start, or you could just be curious about modern structured logging in general: great! You're in the right place :-)

But, on a deeper level, your goals are probably:

  1. To discover bugs and errors in your code, before users do,
  2. To find the causes of production problems faster, and,
  3. To get insights into how your system is performing.

Serilog helps with all of these things by recording events from your application in a format that's both easy to read, and crucially, easy to filter and query without writing regular expressions.

In this tutorial we'll work through the most key moving parts that make awesome production diagnostics possible.

2. Hello, Serilog!

Let's get started! To follow along, you'll need to create a new .NET console application, either for the full .NET Framework or .NET Core.

Serilog is distributed through NuGet. The project is organized into the core Serilog package, plus many sinks (more than a hundred!), which are plug-ins for writing events to the terminal, to files, databases, and log servers.

We'll start with Serilog and Serilog.Sinks.Console, and talk later about some of the other options:

dotnet add package Serilog
dotnet add package Serilog.Sinks.Console

Here's the world's simplest Serilog configuration:

// Program.cs
using Serilog;

using var log = new LoggerConfiguration()
    .WriteTo.Console()
    .CreateLogger();

log.Information("Hello, Serilog!");
log.Warning("Goodbye, Serilog.");

Let's break this down a bit:

  • The LoggerConfiguration class provides a fluent interface for building a logging pipeline
  • WriteTo.Console() adds the console sink to the pipeline
  • CreateLogger() assembles everything and returns a Logger object, which implements ILogger
  • The Logger also implements IDisposable, so we add the using keyword to ensure it's cleaned up when we're done
  • Finally, log.Information() and log.Warning() emit events through the logger

That the logging pipeline is disposable may come as a bit of a surprise, but keep in mind that loggers often write to files, databases, and so-on: many sinks have to do work in order to shut down cleanly. Only the root logger needs to be disposed, and even then, only just before the application exits: classes within your app that use the logger don't need to be aware of this detail.

Did you run the program? Here is what you will have seen:

Now the immediate question is: how do other classes in my application get at this log object? Apart from just passing it around everywhere, there are two possibilities. If you're using an IoC container, you might have components receive an ILogger through dependency injection. Packages like AutofacSerilogIntegration or Serilog.AspNetCore can be used to set that up.

Alternatively, you can store the Logger in a well-known location; Serilog has a built-in static Log class for this:

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console()
    .CreateLogger();

Log.Information("Hello again, Serilog!");

Log.CloseAndFlush();

The Log class provides all of the same methods as the ILogger interface. Instead of a using declaration, we call Log.CloseAndFlush() to shut things down.

You might choose to work with ILogger and dependency injection, or the static Log class - the choice is a matter of personal taste and preference. To keep things simple, we'll use the static Log class in this tutorial.

Chances are, you're not writing a console application. We'll use a console app as a widely-understood example, but once you've completed the tutorial you should check out the documentation for your target platform (for example, ASP.NET Core).

3. Events and levels

Coming from an older library such as log4net, the biggest change in mindset that you need to make when approaching Serilog is to think in terms of log events, not log messages. An event is made up of:

  • A timestamp recording when the event happened
  • A level describing when the event should be captured
  • A message documenting what the event represents
  • Named properties describing the event
  • Possibly an Exception object

You can format a log event into human-readable text for the console, as we saw in the first example:

11:33:01 [INF] Hello, Serilog!

Or, you might format the same event as JSON and send it to a remote log server:

{"@t":"2017-11-20T11:33:01.22138","@m":"Hello, Serilog!"}

Behind the scenes, logging statements in your application create LogEvent objects, while the sinks attached to the pipeline figure out how to record them.

Logging levels

Serilog is fast, but constructing and recording detailed log events all the time can waste CPU, disk, and network resources. To manage this, Serilog events are assigned levels like Debug, Information, Warning and Error. There's a Log.*() method for each supported level.

During development, debug-level events might be switched on:

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug() // <- Set the minimum level
    .WriteTo.Console()
    .CreateLogger();

// In a tight loop...
Log.Debug("Processing item {ItemNumber} of {ItemCount}", itemNumber, itemCount);

In production, it's usual to switch off Debug events and set the minimum level to Information so that only important events are logged. Read more about the Serilog levels in the documentation.

Tip: Serilog has special handling for Exception objects; methods like Log.Error() take the exception as the first parameter, e.g. Log.Error(ex, "Task {TaskName} was canceled", task). Don't include exceptions in the log message itself.

4. Emitting and collecting structured data

Let's back up to that last code snippet:

var itemNumber = 10;
var itemCount = 999;
Log.Debug("Processing item {ItemNumber} of {ItemCount}", itemNumber, itemCount);

Did you notice the named placeholders like {ItemNumber} in the log message? This isn't a C# interpolated string: the Log.*() methods accept message templates, a variation of .NET format strings that support {Named} placeholders in addition to the usual {0} positional ones.

This might seem a little strange, until you realize that by doing this, Serilog can capture parts of the message as first-class properties alongside the human-friendly text:

{
    "@t": "2017-11-20T11:33:01.22138",
    "@l": "Debug",
    "@m": "Processing item 10 of 999",
    "ItemNumber": 10,
    "ItemCount": 999
}

Why do we want to do this? Because the interesting fields attached to the log event as properties, we can immediately use nice simple filters like ItemNumber > 900 to find events, without having to extract information from the message via regular expressions.

Taking this one step further, we can use the @ structure-capturing operator to grab not just flat property values, but complete objects:

var user = new { Name = "Nick", Id = "nblumhardt" };
Log.Information("Logged on user {@User}", user);

Here, the user object is captured in the resulting JSON, so that we can find events using queries like User.Id = 'nblumhardt':

{
    "@t": "2017-11-20T11:33:01.22138",
    "@m": "Logged on user {\"Name\": \"Nick\", \"Id\": \"nblumhardt\"}",
    "User": {"Name": "Nick", "Id": "nblumhardt"}
}

Production monitoring and debugging are already tough, time-consuming, and often stressful tasks: by putting relevant data at our fingertips, Serilog removes one of the biggest sources of friction from ops-related activities.

Tip: Install the amazing Serilog Analyzer from the Visual Studio Marketplace to have message template syntax checked as-you-type.

How much difference this actually makes depends strongly on how you collect the events from Serilog. Traditionally, log events went into text files and were searched with grep. Serilog can record text files, too, but you can't execute ItemNumber > 900 in Notepad, so you'll need to evaluate more powerful tools to do this.

Writing events to JSON log files

If your needs are simple, you can write JSON to log files, and use a JSON-aware tool to query the file directly. Serilog's file sink and compact JSON formatter make the first part easy. Let's try another small console application, with the following packages installed:

dotnet add package Serilog;
dotnet add package Serilog.Sinks.File
dotnet add package Serilog.Formatting.Compact

In Program.cs:

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    .WriteTo.File(new CompactJsonFormatter(), "log.clef")
    .CreateLogger();

var itemCount = 99;
for (var itemNumber = 0; itemNumber < itemCount; ++itemNumber)
    Log.Debug("Processing item {ItemNumber} of {ItemCount}", itemNumber, itemCount);

Log.CloseAndFlush();

Running this app will produce a newline-delimited JSON stream in log.clef, using Serilog's compact log event format. (Without the CompactJsonFormatter, we'd have created a simple flat log file instead.)

If you open the file in a text editor, you'll see JSON events like the examples we've been using above.

CLEF tool is a handy command-line app for querying CLEF-formatted log files:

Notice the filter ItemNumber > 95 on the second line: effortlessly locating events in large log streams is what structured logging is all about.

Writing events to a log server

It's vastly more convenient to send log events from multiple apps to a central server or log aggregation service, instead of trying to shuffle log files around in production.

Log servers usually receive events across the network, via HTTP/S or UDP, and provide a user interface for developers and ops engineers to search and analyze the log stream when things go wrong.

There are Serilog sinks available for a huge range of log servers, many with structured data support. Our team builds Seq, so naturally that's our favorite! We'll use it to illustrate some of the examples here, but the concepts will apply to whichever log server you choose.

After downloading and installing the Windows MSI or running the datalust/seq Docker image, install the Seq sink package:

dotnet add package Serilog.Sinks.Seq

And add WriteTo.Seq() into the logger configuration:

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    .WriteTo.Seq("http://localhost:5341")
    .CreateLogger();

After running the app, opening a browser on http://localhost:5341 will show the events, and we can filter them based on their structured properties:

Behind the scenes, HTTP-based sinks like Serilog.Sinks.Seq use the foundations provided by Serilog for asynchronous, batched communication with the server. This ensures logging statements stay fast and don't incur the cost of waiting for network operations.

Tip: Because log batches are sent asynchronously, it's particularly important to make sure that Logger.Dispose() or Log.CloseAndFlush() is called before your application exits. This will make sure queued events are sent to the server, and any outstanding network requests can complete.

5. Tagging events for filtering and correlation

We just saw how message templates make what we'd have traditionally thought of as the log "message" able to be searched and analyzed efficiently.

The other side of structured logging is identifying sets of events related though some kind of causal or spatial connection. Events raised:

  • During the processing of a single HTTP request
  • From a particular machine, application, service or component
  • Relating to a single customer, order or transaction
  • Arising from a causal chain of events

Serilog handles all of these cases (and more) through a single concept called enrichment. Enrichment is just the act of adding additional properties to events, other than the ones originating from the message template.

Enriching with fixed properties

The simplest method of enrichment is to add a fixed property value to all events originating from a logging pipeline. This is done using Enrich.WithProperty() in the logger configuration:

Log.Logger = new LoggerConfiguration()
    .Enrich.WithProperty("Application", "Demo")
    .WriteTo.Seq("http://localhost:5341")
    .CreateLogger();

On LogEvents, properties added through enrichment appear the same as properties originating from the message template:

{
    "@t": "2017-11-20T11:33:01.22138",
    "@l": "Debug",
    "@m": "Processing item 10 of 999",
    "ItemNumber": 10,
    "ItemCount": 999,
    "Application": "Demo"
}

This strategy is useful for zooming in on a particular log source in a centralized log stream; properties added this way include things like Application, Environment, and Version.

Enriching with event- or logger-specific properties

Instead of enriching all events with the same value, properties can be added to just one or a few related events by creating and using a contextual logger:

var orderLog = Log.ForContext("OrderId", order.Id);
orderLog.Information("Looking up product codes");
// ...
orderLog.Information("Product lookup took {Elapsed} ms", elapsed.TotalMilliseconds);

Here, both events emitted through orderLog will have an OrderId property attached.

Enrichment is additive: if the Application property is set at the pipeline level, then the the second event above will carry Elapsed (from the message), OrderId (from the contextual logger) and Application (from the logging pipeline).

Enriching with source type information

A special case of logger-specific enrichment is seen in how events are tagged with the class that created them.

Inside a class called HomeController, a type-specific logger is created using:

readonly ILogger _log = Log.ForContext<HomeController>();

Events emitted through _log will carry a SourceContext property with value "MyApp.Controllers.HomeController".

Enriching with ambient context

To enrich all events raised within a unit of work, Serilog provides LogContext. This first needs to be enabled at the LoggerConfiguration level with Enrich.FromLogContext():

Log.Logger = new LoggerConfiguraition()
     .Enrich.FromLogContext()
     // ...

The LogContext can be thought of as a stack of (key, value) pairs; when events are enriched from the log context, these are added to the event as properties.

using (LogContext.PushProperty("MessageId", message.Id))
{
    Log.Debug("Dispatching message of type {MessageType}", message.GetType());
    await handler.HandleAsync(message);
}

What's interesting about LogContext is that nothing needs to be passed around. In the example code, the implementation of HandleAsync(), and any other methods called by it, can use Log and ILogger directly - the MessageId property will be picked up and added behind the scenes.

Tip: LogContext is a stack; properties that are pushed onto the stack must be popped back off again by disposing the object returned from PushProperty() - the using block is mandatory.

Plugging in enrichers

All of the enrichment APIs we've seen are implemented using enrichers, objects that implement Serilog's ILogEventEnricher interface.

The NuGet ecosystem provides some interesting pre-built enrichers for things like thread details, machine information, and user details.

Serilog.Enrichers.Thread adds the handy Enrich.WithThreadId() extension:

// dotnet add package Serilog.Enrichers.Thread

Log.Logger = new LoggerConfiguration()
    .Enrich.WithThreadId()
    // ...

This will attach a ThreadId property to events, so that interleaved events can be teased apart again.

We'll see a brief example in the next section of how you can also write and plug in your own application-specific enrichers.

6. Finding needles in the haystack

If we can call message templates and enrichment two pillars of structured logging with Serilog, the third pillar is the idea of implicit event types.

Structured logging is geared towards handling large amounts of log data efficiently. One interesting observation about large log streams is that there are many more events than there are logging statements producing them.

Log.Debug("Processing item {ItemNumber} of {ItemCount}", itemNumber, itemCount);

What this means, here, is that despite producing many unique message strings like "Processing item 31 of 4159", every event generated by this logging statement shares the same message template, "Processing item {ItemNumber} of {ItemCount}".

Serilog and many of its sinks take advantage of this fact to radically improve the experience of querying and filtering log events. If the message template is preserved along with the event, then a filter like the one below can immediately exclude thousands of events from a noisy logging statement, making it easier to see the interesting events that would otherwise be drowned out:

@MessageTemplate <> 'Processing item {ItemNumber} of {ItemCount}'

The inverse also works - zooming in on an event type makes it possible to find all events from a single logging statement.

How you can take advantage of this ability depends on where you store and search logs. We'll have a look at the details next.

Tip: String concatenation, C# string interpolation, and other techniques that pre-format messages before reaching Serilog will prevent you from taking advantage of this feature. See How (not) to parameterize Serilog events for a discussion of this trap.

Implicit event types

Storing, and then filtering on a wordy message template isn't always ideal. Instead, it's common to create a numeric hash value from the message template, and store this with the event instead:

Seq does this automatically, which we can see by expanding one of the events we logged earlier, and examining the Type assigned to them:

Event type enrichment

Log files, and log servers that don't support message templates natively, can still receive event types by enriching the events explicitly within the Serilog pipeline.

To do this, a custom enricher attaches an EventType property to each event:

// dotnet add package Murmurhash

class EventTypeEnricher : ILogEventEnricher
{
   public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
   {
      var murmur = MurmurHash.Create32();
      var bytes = Encoding.UTF8.GetBytes(logEvent.MessageTemplate.Text);
      var hash = murmur.ComputeHash(bytes);
      var numericHash = BitConverter.ToUInt32(hash, 0);
      var eventType = propertyFactory.CreateProperty("EventType", numericHash);
      logEvent.AddPropertyIfAbsent(eventType);
   }
}

When plugged into the pipeline, this makes the {EventType} property available to sinks:

Log.Logger = new LoggerConfiguration()
   .Enrich.With<EventTypeEnricher>()
   .WriteTo.Console(outputTemplate:
       "{Timestamp:HH:mm:ss} [{EventType:x8} {Level:u3}] {Message:lj}{NewLine}{Exception}")
   .CreateLogger();

The argument to WriteTo.Console() is a Serilog output template, describing how to format properties of the log event into text. Most text-based sinks, including Serilog.Sinks.File, can accept output templates to direct formatting.

The output is shown below:

7. What's next?

Serilog is a powerful library with an extensive ecosystem of plug-ins and tooling. We've really only covered the absolute basics - depending on how you want to use Serilog, and the frameworks and platforms you work with, there's a lot more to discover.

Here are some articles and extensions to get you started:

  • Debugging and diagnostics - if you're having trouble getting Serilog or a sink to work, check out this page on the Serilog wiki
  • appsettings.json configuration - in this article we've only shown the C# configuration API; Serilog.Settings.Configuration adds support for logger configuration in .NET Core JSON settings
  • XML <appSettings> configuration - Serilog.Settings.AppSettings adds support for reading logger configuration from .NET Framework configuration files
  • ASP.NET Core integration - the Serilog.AspNetCore package seamlessly integrates Serilog into ASP.NET Core apps to take advantage of the structured log events emitted by the framework
  • ASP.NET integration - check out SerilogWeb.Classic for a quick-and-painless way to record unhandled exceptions and request timings from classic ASP.NET projects
  • Smart logging middleware for ASP.NET Core - improve the quality of request logging in ASP.NET Core with the middleware from this article
  • Timed operations - SerilogTimings is a small wrapper for Serilog that makes it easy to log operation timings
  • Autofac-Serilog integration - use AutofacSerilogIntegration to inject Serilog ILoggers through Autofac with type information automatically added
  • Code analysis for Serilog - mentioned earlier, Serilog Analyzer checks message template syntax in Visual Studio as-you-type, and detects many potential Serilog usage issues
  • Dynamic formatting and filtering - Serilog.Expressions makes it possible to format or filter events using a simple template/expression language
  • Async wrapper - the latency of logging to files or the console can be reduced further using the Serilog.Sinks.Async package
  • Sink READMEs - most sinks, including Serilog.Sinks.File, Serilog.Sinks.Console, Serilog.Sinks.Seq and others, have good README documents in their GitHub repositories with detailed instructions for using the sink
  • Structured Logging Concepts in .NET series - this blog series on structured logging has more detail on much of what we've covered in this tutorial
  • F# support - if your application is written in F#, Destructurama.FSharp will let you log F# types seamlessly through Serilog
  • JSON.NET support - Destructurama.JsonNet extends Serilog to allow JSON.NET dynamic objects to be logged as structured data
  • Exception enricher - Serilog.Exceptions collects additional exception-type-specific information and attaches it to log events
  • Async stack trace unmangling - Serilog.Enrichers.Demystify plugs in Ben Adams' Demystifier to improve the readability of exception stack traces

8. Getting help

There are three great community support channels for Serilog:

  • Stack Overflow - if you have a Serilog usage question, the Serilog tag on Stack Overflow is a great place to start; it's actively monitored, and you'll be helping others with the same question by leaving an easily-found answer
  • Gitter Chat - if your question doesn't fit the Stack Overflow format, or if you just want to sanity check an approach, the Gitter chat room is a quick way to get in touch with others in the Serilog community
  • GitHub Issues - finally, if you've found a bug or want to suggest an improvement to Serilog, GitHub is the place; the Serilog organization houses repositories and issue trackers for the core library as well as many of the sinks and extensions

Happy logging!