nblumhardt.com Open in urlscan Pro
2a06:98c1:3120::3  Public Scan

Form analysis
0 forms found in the DOM

Text Content

Nicholas Blumhardt


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()):

Log.Logger = new LoggerConfiguration()
    .WriteTo.RollingFile("logs-{Date}.txt")
    .Filter.ByExcluding(Matching.FromSource("Microsoft"))
    .WriteTo.Seq("https://my-seq/prd")
    .CreateLogger();


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:

Log.Logger = new LoggerConfiguration()
    .WriteTo.Seq("https://my-seq/prd")
    .Enrich.WithProperty("AppName", "Test")
    .WriteTo.Console(new JsonFormatter())
    .CreateLogger();


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:

Log.Logger = new LoggerConfiguration()
    .WriteTo.RollingFile("logs-{Date}.txt")
    .WriteTo.Logger(lc => lc
        .Filter.ByExcluding(Matching.FromSource("Microsoft"))
        .WriteTo.Seq("https://my-seq/prd"))
    .CreateLogger();


WriteTo.Logger() configures a whole additional logger element with enrichers,
filters and sinks.

When an event reaches the the sub-logger, Serilog makes a shallow copy of it and
it’s this shallow copy that passes through the sub-logger.

Now, using the same API to implement selective enrichment, the Properties
dictionary that AppName is added to isn’t the same dictionary carried by the
event in the outer pipeline.

Log.Logger = new LoggerConfiguration()
    .WriteTo.Seq("https://my-seq/prd")
    .WriteTo.Logger(lc => lc
        .Enrich.WithProperty("AppName", "Test")
        .WriteTo.Console(new JsonFormatter()))
    .CreateLogger();


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:

 1. 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
 2. 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:

Log.Logger = new LoggerConfiguration()
    .WriteTo.RollingFile("logs-{Date}.txt")
    .WriteTo.Seq("https://my-seq/prd", restrictedToMinimumLevel: LogEventLevel.Warning)
    .CreateLogger();


All sink configuration methods support this argument, and it can be applied with
virtually zero overhead.

Hope this helps!


Please enable JavaScript to view the comments powered by Disqus.


NICHOLAS BLUMHARDT

 * Nicholas Blumhardt
 * nblumhardt@nblumhardt.com

 * nblumhardt
 * nblumhardt