This post is the second-last planned for the Structured Logging Concepts in .NET series. This installment’s a bit late — let’s get this show on the road! You might be wondering…

What does serialization have to do with logging?

We’ve already explored the way that structured logs carry event data in machine-readable properties. How far can we take that idea? Does a log event property have to be a simple string or number?

Let’s imagine we’re building a content management system that stores and serves user-defined pages. Each page we create has some tags attached:

Log.Information("Created page {Title} with tags {Tags}", page.Title, string.Join(", ", page.Tags));
    // -> Created page "Widget 2000" with tags "product, mobile, en-AU"

In the example, page.Tags is a string[], carrying zero-or-more tags associated with the page. In the past I’ve written a lot of these ugly string.Join() logging statements for this kind of data.

Tags String

Since the event is a structured one, it will carry a property Tags with value "product, mobile, en-AU", and we could conceivably find events carrying a particular tag with queries resembling Tags like '%mobile%'. This is hardly the twenty-first-century experience that structured logging promises. Can we be certain of avoiding mis-matches on tags such as automobile?

We started with structured data - string[] Tags - and since the log event is going to be represented in a capable format such as JSON, we can carry the structure all the way through:

Log.Information("Created page {Title} with tags {@Tags}", page.Title, page.Tags);
    // -> Created page "Widget 2000" with tags ["product", "mobile", "en-AU"]

The @ symbol next to the Tags property name is the structure-capturing operator, and it instructs the logger (Serilog in this case) to treat Tags as structured data, instead of calling ToString() on it.

Tags Array

With an array of strings in the Tags property, precise tag-based queries are possible: Tags[?] = 'mobile' (any tag equals mobile), using Seq’s collection wildcard syntax for example.

Capturing objects

I lied a little about @. Using Serilog, it can be omitted for array data like Tags because there’s very little else a logging library can sensibly do with an array, so Serilog will capture arrays (and only arrays) as structured data by default. Personally, nothing annoys me more than opening a log file and finding the text “System.Array” right where some important data should have been recorded, hence this little special-case concession in the Serilog API. ToString() capturing can be forced for any object by prefixing the property name with $ instead of @.

To capture more complex structured data, like .NET objects, the @ operator is needed.

Log.Debug("Received {@Request}", request);
    // -> Received PublishRequest { PageId: "widget-2000", PublishAt: 08/31/2016 00:45:59 }

In the output above you see the Serilog console sink’s default rendering of instances of a DTO (“data transfer object”) like PublishRequest. Different sinks use different formats for structured data, so in JSON the Request property of the event looks like:

"Request": {"PageId": "widget-2000", "PublishAt": "2016-08-31T00:45:59.87970Z",
            "$type": "PublishRequest"}

Serializing objects into log events is great for debugging, and since support is baked into the logger rather than the app itself, there’s no additional overhead when the debug level is switched off in production. It’s common to see things like request and response messages serialized into events at the debug level.

The same technique is useful in production scenarios, for capturing information-level events, warnings, and errors, but needs to be used carefully to avoid any performance surprises. In particular, objects that aren’t already designed for serialization will often serialize poorly. If the object being serialized into a log event isn’t a DTO of some kind, watch out for circular dependencies or deep graph structures that require a lot of CPU time and memory to represent. Serilog won’t fall over in these cases, but the impact on application performance can be noticeable.

Controlling serialization

Serilog captures and formats structured data in two distinct steps. The logger captures the @-designated properties by converting them into LogEventPropertyValue instances, which represent single values, arrays, object-like structures, and dictionaries. The various sinks render the resulting structures into text, XML, JSON and so-on.

This is a powerful distinction to have: a logger might be configured to skip all properties named Password at the capturing phase, without worrying whether the event will end up in text, JSON or some other format.

The scenarios below deal with a typical DTO for incoming form data in a web application:

class UserData
{
    public string Id {get; set;}
    public string Username {get; set;}
    public string Biography {get; set;}
    public string NewPassword {get; set;}

    public override string ToString()
    {
        return Username;
    }
}

And a logging statement that records it:

Log.Information("Updating profile for {@User}", request.User);

Transformations

A statement in the spirit of the one above might be enabled in production code to audit user profile changes. If only a few of the UserData properties are of interest, they can be selected by transforming the logged object into a summarized one:

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console()
    .Destructure.ByTransforming<UserData>(u => new { u.Id, u.Username })
    .CreateLogger();

Serilog uses the term “destructuring” for the capturing process; you can read the above as “capture by transforming” if it’s clearer in those terms.

When a rule like the one above is encountered, the anonymous object returned from the ByTransforming delegate will be captured instead of the full UserData.

Attributes

Centrally controlling how objects are captured might not work well in large or loosely-coupled apps. The logger configuration isn’t an ideal place for 100 different capturing rules. To avoid this, a plug-in library Destructurama.Attributed implements an attribute-based way of controlling which members from a class are captured and serialized:

class UserData
{
    public string Id {get; set;}
    public string Username {get; set;}

    [NotLogged]
    public string Biography {get; set;}

    [NotLogged]
    public string NewPassword {get; set;}

    // ...
}

The central logger configuration then becomes:

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

Destructurama! includes a couple of other interesting plug-ins for Serilog, including F# built-in type support and JSON.NET dynamic object support.

Value types

Sometimes applications define their own types representing simple values. Domain-driven design emphasizes this with value objects - Money, DateRange, EmailAddress - and there are familiar examples in the .NET Framework like System.Uri.

The desirable way to log such a value object is often through its ToString() representation. This happens naturally when such an object is logged without @, but because the capturing process is recursive, some configuration is needed in order to avoid capturing value objects as a structure with properties when they appear as members of other types.

To log an EmailAddress object as a single string value rather than a structure with Host, Username and so-on, it can be marked as a scalar type:

    .Destructure.AsScalar<EmailAddress>()

The Destructurama.Attributed package provides the LogAsScalar type-level attribute as an alternative way of controlling this.

Scalar values are a little bit subtle in Serilog, because the ToString() conversion will happen at the point of formatting, rather than at the point of capturing. Value objects really do need immutable, value semantics for this to work safely. The reason for passing the value itself to the formatter (instead of the thread-safe string version) is so that formats with richer type representations can be accommodated.

To get the same effect for our obviously non-threadsafe UserData class, which defines ToString(), we can do this instead:

    .Destructure.ByTransforming<UserData>(u => u.ToString())

Library support

This has admittedly been a very Serilog-centric post. I promised the series would stay library-agnostic where possible - some examples from Logary would have been nice to include but I haven’t spent enough time with its API to do it justice here. You can find some info on how to capture structured data with message templates in Logary in the documentation.

Worth mentioning also is that Microsoft.Extensions.Logging is transparent when it comes to the @ symbol - it will be passed to the underlying logging provider, which can choose to recognize it as the Serilog provider does. That means the following is perfectly legal using Microsoft.Extensions.Logging:

logger.LogInformation("Updating profile for {@User}", request.User);

Whether you end up with serialized data in a User property, or just a ToString() representation in an @User property, depends on the logging provider in use.

Up next…

The last few weeks I’ve been busy putting the finishing touches on Seq 3.3, which made a dent in my time available for writing :-). In the next post, which shouldn’t take quite so long to publish, we’ll take a closer look at the kinds of options available for collecting, storing and using structured log data.

Happy logging until then!