ASP.NET Core – custom ILogger<T> and Nlog callsite layout renderer issue

1. Introduction

In my current project, we use Microsoft.Extensions.Logging.ILogger<T> default implementation as our logging mechanism. This basically comes with the ASP.NET Core 2.0 package and it was working fine so far. However recently we decided to switch the default implementation with a custom one, due to the fact that we wanted to have some additional logic applied for all of the logging providers.

2. Implementation

The custom implementation itself is very similar to the original one, we came up with something like that

and we replaced the default logger with this code

As you can see we basically wanted to add information from custom exceptions to the message. Due to the fact that this is added in here, we don’t have to modify all of our existing logging providers.

3. NLog call site renderer issue

Once we run the application all of the providers were working fine and were producing expected output apart from NLog provider. Originally NLog provider for the following code

was producing this output

However, after introducing new implementation of ILogger<T>, it started appending wrong caller member name

After some digging, it turned out that the issue lies in the (indirect)configuration of NLog’s callsite layout renderer. Long story short, when you add NLog provider to your logger providers, under the hood it adds Microsoft.Extensions.Logging.Abstractions assembly(among others) to something called hidden assembly collection. Once the NLog tries to figure out what is the caller member name, it crawls the stack trace to find a method name. If the method in current frame comes from a hidden assembly, logger skips it and continues iteration. As we changed the Logger<T> to our custom one, it is no longer part of Microsoft.Extensions.Logging.Abstractions assembly, so the NLog reports Log method from our custom logger as a caller member name.

4. The fix

In order to restore previous behavior you have to add custom logger assembly to the hidden assembly collection. You can do it via

Of course, if the logger is located in the same assembly as rest of your code, this might not be the perfect solution – as this will impact the way the callsite is rendered for other parts of your code in this assembly. In that case, you might consider moving the logging piece to separate assembly or resign from using callsite layout renderer at all. We decided to replace it with logger layout renderer as callsite layout renderer, either way, wouldn’t be used in production environments.

Source code for this post can be found here

ASP.NET Core – custom ILogger<T> and Nlog callsite layout renderer issue

NLog – tracking flow of requests using MappedDiagnosticsLogicalContext

1. Problem

Everyone who has ever had to analyze logs from production environment knows, that quite often it is not an easy task. Usually application flow is deduced by log entries matched by thread id, which is problematic when you deal with multithreading scenarios. Say for example we have following piece of code

Default log file usually looks like that

Having multiple simultaneous Index requests, makes it almost impossible to figure out which log entry is part of which call. Fortunately with NLog it is possible to solve this problem without too much of a hassle.

2. Proposed solution

The whole idea is to leverage MappedDiagnosticsLogicalContext “storage” to keep some unique identifier of request for entire call. Note, that this identifier will be accessible also from other threads created from within given call. In order to set unique request id (also known as correlation id) I will use custom HttpModule. The very first implementation looks like that

Once the HttpModule is ready it is necessary to register it in web.config.

From now on, every request goes through LogginHttpModule and proper correlationId is set in MappedDiagnosticsLogicalContext.
As we want to have correlationId included in log files it is necessary to modify Nlog.config. In my case it looks like that

Note that we can access our correlationId variable via ${mdlc:item=correlationid}
Log file after the changes looks like that

This is almost perfect, however for some reasons correlationId is lost in EndRequest event handler. I am not sure if this is bug in NLog (I’ve posted question in Nlog’s github) or it is by design, however there is easy workaround for that. We can store our correlationId in HttpContext.Items collection and reassign it to MappedDiagnosticsLogicalContext in EndRequest event handler.

After these changes our log file finally looks OK

Source code for this post can be found here

NLog – tracking flow of requests using MappedDiagnosticsLogicalContext