The art of simplicity

Serilog is one of the most popular structured logging libraries for .NET, offering excellent performance and flexibility. While Serilog comes with many built-in sinks for common destinations like files, databases, and cloud services, we created a custom sink to guarantee compatibility with an existing legacy logging solution. However as we noticed some performance issues, we decided to rewrite the implementation to use a batched sink. In this post, we'll explore how to build your own batched sink in Serilog, which can significantly improve performance when dealing with high-volume logging scenarios. At least that is what we are aiming for… Understanding Serilog's batched sink architecture Serilog has built-in batching support and handles most of the complexity of batching log events for you. Internally will handle things like: Collecting log events in an internal queue Periodically flushing batches based on time intervals or batch size limits Handling backpre...

At one of my clients, Seq is used as the main tool to store structured log messages. If you never heard about Seq before, on their website they promote Seq like this: The self-hosted search, analysis, and alerting server built for structured logs and traces. It certainly is a great tool, easy to use with a lot of great features. But hey, this post is not to promote Seq, I want to talk about a problem we encountered when using it. A developer contacted me and shared the following screenshot: Instead of the structured log message itself being logged, we got the error message above for a subset of our messages. The problem was that the structured log message contained a large JSON object exceeding the default limit of 262144 bytes. Although you could wonder if it’s a good idea to log such large messages in general, for this specific use case it made sense. So you can override the default for a specific application by setting the eventBodyLimitBytes argument when configurin...

In .NET 7 and before the default request logging in ASP.NET Core is quite noisy, with multiple events emitted per request. That is one of the reasons why I use the Serilog.AspNetCore package . By adding the following line to my ASP.NET Core application I can reduce the number of events to 1 per request. The result looks like this in Seq :   Starting from .NET 8 the HTTP logging middleware has several new capabilities and we no longer need Serilog to achieve the same result. By configuring the following 2 options, we could achieve this: HttpLoggingFields.Duration : When enabled, this emits a new log at the end of the request/response measuring the total time in milliseconds taken for processing. This has been added to the HttpLoggingFields.All set. HttpLoggingOptions.CombineLogs : When enabled, the middleware will consolidate all of its enabled logs for a request/response into one log at the end. This includes the request, request body, response, response body...

When you are using the built-in logging in ASP.NET Core, you can filter out specific information by changing the log levels in the appsettings.json: But when you switch to Serilog, this no longer works and the configuration values are ignored. Our original configuration looked like this: Here is what was logged by default after switching to Serilog: 2022-02-03 12:17:07.861 +01:00 [WRN] Failed to determine the https port for redirect. 2022-02-03 12:17:58.429 +01:00 [WRN] Failed to determine the https port for redirect. 2022-02-03 12:19:19.555 +01:00 [WRN] Failed to determine the https port for redirect. 2022-02-03 12:20:21.553 +01:00 [INF] OnStarted has been called. 2022-02-03 12:20:21.631 +01:00 [INF] Request starting HTTP/1.1 POST http://localhost/mail/ application/json;+charset=utf-8 318 2022-02-03 12:20:21.631 +01:00 [INF] Request starting HTTP/1.1 POST http://localhost/mail/ application/json;+charset=utf-8 318 2022-02-03 12:20:21.631 +01:00 [I...

By default logging in ASP.NET Core generates a lot of log messages for every request. Thanks to the Serilog's RequestLoggingMiddleware that comes with the Serilog.AspNetCore NuGet package you can reduce this to a single log message: But what if you want to extend the log message with some extra data? This can be done by setting values on the IDiagnosticContext instance. This interface is injected as a singleton in the DI container. Here is an example where we add some header info to the request log:

Structured logging is the future and tools like ElasticSearch and Seq can help you manage and search through this structured log data. While testing Seq, a colleague told me that he couldn’t access Seq. Instead his browser returned the following error: ERR_SSL_PROTOCOL_ERROR The problem was that he tried to access the Seq server using HTTPS although this was not activated. By default Seq runs as a windows service and listens only on HTTP. To enable HTTPS some extra work needs to be done: First make sure you have a valid SSL certificate installed in either the Local Machine or Personal certificate store of your Seq server. Open the certificate manager on the server, browse to the certificate and read out the thumbprint value. Now open a command prompt on the server and execute the following commands: seq bind-ssl --thumbprint="THUMBPRINT HERE --port=9001 seq config -k api.listenUris -v https://YOURSERVER:9001 seq restart Remark...

The ‘classic’ way I used to attach extra properties to a log message in Serilog was through the LogContext. From the documentation : Properties can be added and removed from the context using LogContext.PushProperty() : Disadvantage of using the LogContext is that the additional information is only available inside the scope of the specific logcontext(or deeper nested contexts). This typically leads to a larger number of logs which doesn’t always help to find out what is going on. Today I try to follow a different approach where I only log a single message at the end of an operation. Idea is that the log message is enriched during the lifetime of an operation and that we end up with a single log entry. This is easy to achieve in Serilog thanks to the IDiagnosticContext interface. The diagnostic context is provides an execution context (similar to LogContext) with the advantage that it can be enriched throughout its lifetime. The request logging middleware then uses this to e...

So far I always used the Stopwatch class to track timings in my applications and just added the result to my log message. Until I discovered the SerilogTimings nuget package. Usage is simple, after you have configured Serilog, you can use Operation.Time() to time an operation: At the completion of the using block(!), a message will be written to the log like: [INF] Submitting payment for order-12345 completed in 456.7 ms You can also use it directly on top of an ILogger instance: More info about this library can be found here: https://github.com/nblumhardt/serilog-timings

Before MassTransit 6, separate NuGet packages existed that allowed you to integrate the logging framework of your choice with MassTransit. In our case we were using Serilog and a MassTransit.SerilogIntegration NuGet package to bring the 2 together. In MassTransit 6 the previous abstraction has been removed and is replaced by Microsoft.Extensions.Logging.Abstractions . To enable integration you need to call MassTransit.Context.LogContext.ConfigureCurrentLogContext(loggerFactory); before configuring the bus or directly pass on the ILogger instance MassTransit.Context.LogContext.ConfigureCurrentLogContext(logger); Integration with Serilog can now be done through the serilog-extensions-logging NuGet package. More information here; https://www.nuget.org/packages/MassTransit.SerilogIntegration/

One of the hidden features of ASP.NET Core is the support for LoggerMessage . From the documentation : LoggerMessage features create cacheable delegates that require fewer object allocations and reduced computational overhead compared to logger extension methods , such as LogInformation , LogDebug , and LogError . For high-performance logging scenarios, use the LoggerMessage pattern. LoggerMessage provides the following performance advantages over Logger extension methods: Logger extension methods require "boxing" (converting) value types, such as int , into object . The LoggerMessage pattern avoids boxing by using static Action fields and extension methods with strongly-typed parameters. Logger extension methods must parse the message template (named format string) every time a log message is written. LoggerMessage only requires parsing a template once when the message is defined. The best way to use it is through some extension methods ...

One of the lesser known features inside Serilog is the support for filter expressions. This gives you a SQL like syntax to filter your log messages. To enable this feature you have to install the Serilog.Filters.Expressions nuget package. More information: https://nblumhardt.com/2017/01/serilog-filtering-dsl/

One of the lesser known features inside Serilog is the support for sub loggers. This allows you to redirect (part of) the log traffic to different sinks based on certain conditions. To create and use a sub logger you have to use the WriteTo.Logger() method. On this method you can create a whole new logger element with its own enrichers, filters and sinks: In this example all log data with a warning level(including coming from Microsoft) is written to warning.txt and all Microsoft related data is logged to microsoft.txt. More information here: https://nblumhardt.com/2016/07/serilog-2-write-to-logger/

With the introduction of Roslyn as the compiler platform in Visual Studio, we got support for Roslyn analyzers. If you never heard about it, read this great introduction here; https://andrewlock.net/creating-a-roslyn-analyzer-in-visual-studio-2017/ . Although creating your own analyzer is not that easy, using them is. And there are a lot of situations where an analyzer can prevent you from making some stupid mistakes. One example I liked was when using Serilog. Serilog is a structured logging framework where your messages are logged using message templates. Parameters used inside these message templates are serialized and stored as separate properties on the log event giving you great flexibility in searching and filtering through log data. Here is an example from the Serilog website : The Position and the Elapsed properties are stored separately from the message. Problem is that you can easily make a mistake, although the message template expects 2 parameters it is possibl...

If you ever had to maintain an application, you know that good logs are your best friend. That is one of the reasons why I’m a big fan of Serilog , a structured logging framework for .NET. And if you ask me how much logging do we need, I would answer that you can not have too much log data. Of course all this log data introduces its own challenges, like how can you search fast through all these logs but also the impact it has on the performance of your application. If you start writing thousands of messages a second to the Console, you’ll see your application slowing down. To mitigate this problem, most Serilog sinks write messages by default in asynchronous batches to reduce application latency and improve network performance. Unfortunately there are few sinks that don’t do this by default, by example the Console sink .  For these cases, you can use Serilog.Sinks.Async . It provides an async wrapper WriteTo.Async() that moves logging onto a worker thread, so that applicat...