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

1
public class Logger<T> : ILogger<T>
2
{
3
    private readonly ILogger _logger;
4

5
    public Logger(ILoggerFactory loggerFactory)
6
    {
7
        _logger = loggerFactory.CreateLogger<T>();
8
    }
9

10
    public void Log<TState>(LogLevel, EventId, TState state, Exception, Func<TState, Exception, string> formatter)
11
    {
12
        string Formatter(TState innserState, Exception innerException)
13
        {
14
            // additional logic goes here, in my case that was extracting additional information from custom exceptions
15
            var message = formatter(innserState, innerException) ?? string.Empty;
16
            return message + " additional stuff in here";
17
        }
18

19
        _logger.Log(logLevel, eventId, state, exception, Formatter);
20
    }
21

22
    public bool IsEnabled(LogLevel logLevel)
23
    {
24
        return _logger.IsEnabled(logLevel);
25
    }
26

27
    public IDisposable BeginScope<TState>(TState state)
28
    {
29
        return _logger.BeginScope(state);
30
    }
31
}

and we replaced the default logger with this code

1
services.Replace(new ServiceDescriptor(typeof(ILogger<>), typeof(Logger.Logger<>), ServiceLifetime.Singleton));

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

1
[Route("api/[controller]")]
2
public class ValuesController : Controller
3
{
4
    private readonly ILogger<ValuesController> _logger;
5

6
    public ValuesController(ILogger<ValuesController> logger)
7
    {
8
        _logger = logger;
9
    }
10

11
    [HttpGet]
12
    public IEnumerable<string> Get()
13
    {
14
        _logger.LogTrace("Get method called trace");
15
        _logger.LogWarning("Get method called warning");
16
        _logger.LogError("Get method called error");
17
        _logger.LogInformation("Get method called information");
18

19
        return new string[] {"value1", "value2"};
20
    }
21
}

was producing this output

1
TimeStamp=2018-02-28 20:14:37.2711 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Controllers.ValuesController.Get Level=TRACE Message=Get method called trace
2
TimeStamp=2018-02-28 20:14:37.3261 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Controllers.ValuesController.Get Level=WARN Message=Get method called warning
3
TimeStamp=2018-02-28 20:14:37.3261 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Controllers.ValuesController.Get Level=ERROR Message=Get method called error
4
TimeStamp=2018-02-28 20:14:37.3261 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Controllers.ValuesController.Get Level=INFO Message=Get method called information

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

1
TimeStamp=2018-02-28 20:17:27.4044 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Logger`1.Log Level=TRACE Message=Get method called trace additional stuff in here
2
TimeStamp=2018-02-28 20:17:27.5117 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Logger`1.Log Level=WARN Message=Get method called warning additional stuff in here
3
TimeStamp=2018-02-28 20:17:27.5117 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Logger`1.Log Level=ERROR Message=Get method called error additional stuff in here
4
TimeStamp=2018-02-28 20:17:27.5202 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Logger`1.Log Level=INFO Message=Get method called information additional stuff in here

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

1
LogManager.AddHiddenAssembly(typeof(Logger.Logger<>).Assembly);

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

1. Introduction#

2. Implementation#

3. NLog call site renderer issue#

4. The fix#

3. `NLog` call site renderer issue#