Assigning event types to Serilog events

One of the most powerful benefits of structured logging is the ability to treat log events as though “typed”, so that events generated by the same logging statement can be easily (and mechanically) identified in the log stream.

Given a logging statement parameterized by some data:

var total = 1;
for(var i = 0; i < 3; ++i)
{
   total *= i;
   Log.Information("Computed iteration {Counter}, total is {Total}", i, total);
}

The text representation of each event (“Computed iteration 2, total is 4”) will be different.

A traditional text-based logging system necessitates the use of regular expressions to identify and parse messages created in the loop. This is a bigger problem than it sounds: once the event is interspersed through a large stream of unrelated messages this style of processing is both slow and error-prone, as well as inconvenient.

By contrast, a structured logger like Serilog or SLAB/ETW assigns ids or types to events, so that all events generated by the statement will carry a distinct type as well as the structured fields for Counter and Total. Queries using event types can find all of the events generated by a particular logging statement, even though their text representations may differ.

Enriching events with types

Serilog treats the message template itself as the event type. By attaching "Computed iteration {Counter}, total is {Total}" to each event, all events generated from the same template can be identified.

Long strings like this can be inconvenient to record and type, so it’s often useful to take a hash of this value instead, and record that as the event type alongside other data comprising the event. Seq does this automatically by assigning a type to Serilog events on the server-side. Using Elasticsearch to store events, you might achieve the same thing with a transform.

If you just want to have the convenience of searching by event type in regular flat log files, or if you’re using a log collector without this option, it’s easy to add support for it using a Serilog enricher:

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

Line 2 adds the EventTypeEnricher that we’ll see below to the logging pipeline.

Line 3 shows the modified outputTemplate that includes the EventType value, in this case a 32-bit value formatted in hexadecimal. (This example writes to the Console sink, which is a great way to visualize the structure of Serilog events even when they’re formatted into text.)

The enricher

In this example, event types are generated using a 32-bit Murmur3 hash. The relative merits of different hash algorithms and sizes for this purpose is a post in itself – we’ll just use a readily-available one. Anything from string.GetHashCode() to SHA-1 might work here, depending on your needs.

The algorithim is from this package, which you’ll need to install first from NuGet.

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 eventId = propertyFactory.CreateProperty("EventType", numericHash);
      logEvent.AddPropertyIfAbsent(eventId);
   }
}

The enricher retrieves the original message template text, computes its hash, and attaches it the event as the EventType property.

The output

Taking our example again, including a few different events:

Log.Information("Starting up");

var total = 1;
for (var i = 0; i < 3; ++i)
{
    total += i;
    Log.Information("Computed iteration {Counter}, total is {Total}", i, total);
}

Log.Information("All done");

The output is:

Each loop of the iteration, despite carrying different values for Counter and Total, is tagged with the same event type f20ba6e0. The other two events carry their own distinct event types that identify them.

Summing up

Structured logging is a necessary response to the difficulty of sifting through log events from ever-larger, more distributed, more sophisticated applications. Alongside named property values, event types are a big part of the structured logging value proposition. You can use either raw message templates, or hashes of them, as types when working with Serilog.

If you’re using a solution that supports event types in your log data, it’d be awesome to hear how it has worked for you!