Serilog 2.0 adventures with sub-loggers

Jul 19, 2016 • nblumhardt

The WriteTo.Logger() method pipes events from one Serilog logger into another. While this has been around since Serilog 1.3, some rough edges made it harder to configure correctly than it should have been. In Serilog 2.0 the handling of sub-loggers has been polished up, so now is a good time to write a little about this API.

Why sub-loggers?

Behind the scenes, Serilog treats logging as an event pipeline. It’s not general-purpose like Rx, but if you’re familiar with the idea there are some similarities.

You might expect that because of this, you could write a logger configuration like the following to send all events to one sink (RollingFile()) and a subset to another (everything not from a Microsoft log source to Seq()):

This isn’t the case; in fact, each LoggerConfiguration produces only a single element in the pipeline, with filtering, enrichment, sink dispatching and so-on integrated into it in a fixed order. The configuration above results in events being filtered before reaching either sink.

Here’s another example where we might like to have ordered configuration:

The intention of this snippet is to add the AppName property to the console logs but not send it to Seq. Yet, because the Seq sink runs a background thread to serialize and transmit batches of events after some delay, extra work would be needed to prevent the AppName property showing up anyway. Instead, the configuration above performs enrichment before writing to either sink.

Making these kinds of configurations efficient and safe would have added overhead throughout Serilog, regardless of whether a particular configuration called for it or not. Combined with the challenge of representing and preserving an ordered configuration everywhere, for example through XML configuration, it’s unclear whether the end result could be made as simple and robust as the single-element-per-LoggerConfiguration design.

Serilog chose instead to side-steps these issues and impose a set order of activities that can be implemented efficiently and safely. The escape hatch is WriteTo.Logger().

WriteTo.Logger(), shallow copies, and immutability

To control ordering through LoggerConfiguration Serilog provides the WriteTo.Logger() method. Here’s the first example rewritten to perform as intended:

Serilog can do this shallow copy reasonably cheaply - for each sub-logger, only a LogEvent object and the dictionary need to be allocated. The property values themselves, i.e. log data carried on the event, is immutable and therefore can be shared safely between the original event and the copy.

Two minor caveats

There are two small things that bear mentioning, though now that you know how sub-loggers work, neither should be surprising:

The minimum level set on the sub-logger is limited by the minimum level of the outer, root logger: you can’t set a sub-logger to Debug-level and get Debug events if the root logger is only generating Information, and

Destructuring policies set on the sub-logger won’t have any effect, since by the time an event reaches the sub-logger all of the associated data has already been captured.

When to use sub-loggers

Logging pipelines are best kept simple, so sub-loggers aren’t something you should see or use every day. In a nutshell, if the events or event properties sent to different sinks should differ, WriteTo.Logger() is probably the solution.

One exception; if all you need to do is limit the events going to a sink by level, use the much more efficient restrictedToMinimumLevel parameter instead: