Logging “levels” in a structured world
Every logging framework I’ve ever used has a notion of “levels” like “information”, “warning” and “error” that assign importance to events.
This is necessary because logging produces a lot of data – most of which is less exciting than trimming your dog’s toenails.
Except… when things go wrong, and suddenly that mundane note about successfully starting up saves months of debugging pain.
So, the essential idea of levels is to make it possible to turn “up” and “down” the amount of information being written to a log.
Serilog defines the following levels:
// Anything and everything you might want to know about
// a running block of code.
Verbose,
// Internal system events that aren't necessarily
// observable from the outside.
Debug,
// "Things happen."
Information,
// Service is degraded or endangered.
Warning,
// Functionality is unavailable, invariants are broken
// or data is lost.
Error,
// If you have a pager, it goes off when one of these
// occurs.
Fatal
Many logging frameworks have quite complex support for custom levels, and add on other features like categories and keywords so that control over logging output can be controlled at a finer grain.
In Serilog the levels are fixed – internally they’re represented in an enum
, and there are no other built-in notions of categorization. Why is that?
You can create your own
Serilog events can carry any key/value property data that you like. If you want to introduce additional logging categories, you can just add those properties to loggers in your app, and do whatever you like with the data.
Let’s say in our architecture we’re interested in “subsystems” and want to categorize events that way:
var log = Log.ForContext("Subsystem", "Ordering");
log.Information("Checking status of {OrderNumber}…", num);
// More logging via ‘log’
This code sets up a logger that will tag all events with a value of "Ordering"
for the Subsystem
property.
Depending on your log store, you should be able to write a filter like this one to include (or exclude) events from the ordering subsystem:
Subsystem == "Ordering"
The nice thing about this approach is that you can create as many kinds of catgory as you need - subsystems, regions, organizational departments, whatever you like - and use all of them together.
Structured events make tighter control possible
Look at a verbose log. What do you see? Well, most of the verbosity will come from low-level events, but more than that: most of the verbosity will be due to a handful of events.
Classic text logging doesn’t deal well with this; since events are just blobs of text, there’s a lot of effort involved in turning off just one or two.
Serilog doesn’t have this issue. Each event has a MessageTemplate
that uniquely identifies the event. Turning off a single event is just a matter of filtering out those with a specific template. Of course, you need a structured log store to make this work (Seq’s Event Types provide this for example) but it’s natural that if you’re using a structured logger you’ll be using one of the many storage options that maintain this ability.
With the most verbose offenders out of the way, even low-level logs can be quite pleasant to browse.
So what’s the point here?
Categorizing events up-front is less important when writing structured logs, and if you’re going to bother with anything finer that than the simple Information, Warning, Error and so-on provided out of the box by Serilog, you’ll be better served with a categorization system (or systems) of your own, than anything Serilog could define for you.