Structured Logging in ASP.NET Core using Serilog

In my previous story i wrote some words about logging in general and how it is implemented in ASP.NET Core by default. Here, I will continue on structured logging and tell you something more about third-party providers that i was writing about. I will use the same BookStore example.

Basically, on plain-text logging we rely both on regular expressions that we write to search through the logs and unchangable format that logs have. Structure logging goes way beyond that and gives us structure that can be easily searchable and in a same way easy to read. Structured logging gives us some extended view into our logs.Тhis structure that i am talking about can be projected to a database and all those columns that are frequently searched can be indexed. In that way we can also speed up searching, possibly terabytes of logs.

Here, i will use Seq which is a log server that can receive events and host the main web app that communicates over http/https. With Seq we can see how events look like and how we could benefit from having structured logs.

Serilog

Serilog for ASP.NET Core is distributed through NuGet. For ASP.NET Core 2.0+ Serilog.AspNetCore NuGet package is recommended.

What Providers are in ASP.NET Core, Sinks are in Serilog. There are sinks for almost anything and you just need to pull that NuGet package that you are interested in. Basically NuGet packages for sinks are named Serilog.Sinks.[NameOfThatSink]. So if we want to pull sink for a file, we would get Serilog.Sinks.File NuGet package.

Serilog understands Log Event as something that is triggered when something is logged to a sink.

Log Event consists of:

• Timestamp that says when event happened
• Level that’s log event severity
• Message explaining what event represents
• Properties that describe that event. I call them tokens that are important for us in a message that we log. Later we would search logs by this tokens.
• Exception optionally describing exception if happened

Similarly to ASP.NET Core, Serilog comes with six levels of severity. From lower to higher severity respectively:

• Verbose for tracing mostly sensitive information and all kind of others. Switched on on production only in unusual situations.
• Debug internal control flow and diagnostics.
• Information for application flow. Events of interest. This is by default minimum logging level.
• Warning indicators of possible issue or operation degradation
• Error indicating a failure within the application but only on a operation level or connected system
• Fatal critical errors that cause application crash

If we want to use Serilog logger besides adding NuGet both for Serilog and Sinks that we want to output to we would need to configure that logger. Basically Serilog gives us globally-shared logger object that we assign our logger configuration to and then use this logger through our application.
Also we would need to set Serilog as a logging provider with UseSerilog extension method to IWebHostBuilder.

That is usually done like this:

And then we would log almost in a same way as in ASP.NET Core default logger:

So basically when we log something to the sink, we are emitting an event through the logger.

By logging this way, when we have {ID} Serilog is creating key-value pair behind the scenes with key ID and value id and that is the property that we will get along with other parts of event. I call them tokens by which structure logging is possible. Having these tokens means we can structure our log better and search more fluently. What that means? Well if we would need to group logs by book id we would just filter them by this ID property.

We can also pass whole object, and if we want to serialize it we would need to add @ sign in front of property name.

Log.ForContext<BookStoreController>().Information(“Got book={@Book} from the shelf”, book);

would produce this log:

[11/17/2018 11:38:30 +01:00 BookStore.Controllers.BookStoreController INFO] Got book=Book {Id=3, Name=”ASP.NET Core”} from the shelf

If we log this to Seq we could also search by any of the fields inside of this object:

.ForContext<BookStoreController>() call is optional. With that call we are enriching our event log with additional properties connected to the context we specified. Because of this we can see fields like ActionName, ActionId, …

Enrichment is another concept that Serilog has. There are various ways to enrich our log event and many enrichers available through NuGet that can use. We can also build our own Enricher and use that one. We just need to implement Serilog’s ILogEventEnricher interface.

Another catch is format that we log to a file. By default, without specifying formatter, default message template is used and logged into a file. If we want that to be a JSON we would need to specify JsonFormatter of some kind. We can also build our own formatter and satisfy all our needs. Only need to implement ITextFormatter interface. There is also Serilog’s CompactJsonFormatter that maybe has all we need.

Tips

• Make logging as part of the solution not a problem. We can produce gigabytes of logs a day and never look at them. Even if someone does, if they are in a unstructured format, searching through them can be very painful. So structured logs are right way to go.
• Log smart. Don’t log everything, also think in terms of a severity.
• Better structure of our logs means better quality of our logs
• Make it configurable. Make sure your logs are locally configured, read configuration from a file so you can change that easily. Most of the time we don’t need Trace but when we do, it would be great if we can switch that easy.

Conclusion

Serilog is providing us with all we need to log things proper. It is easily configurable and extendable. There are sinks for almost anything already available. We can enrich our context easily and make format of our logs the way we like. Structure logging is amazing, but be careful. Have in mind these ending tips when you are setting up your logger and logging something.