Logging

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

public class Logger<T> : ILogger<T>
{
    private readonly ILogger _logger;

    public Logger(ILoggerFactory loggerFactory)
    {
        _logger = loggerFactory.CreateLogger<T>();
    }

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

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

    public bool IsEnabled(LogLevel logLevel)
    {
        return _logger.IsEnabled(logLevel);
    }

    public IDisposable BeginScope<TState>(TState state)
    {
        return _logger.BeginScope(state);
    }
}

public class Logger<T> : ILogger<T>

{

private readonly ILogger _logger;

public Logger(ILoggerFactory loggerFactory)

{

_logger = loggerFactory.CreateLogger<T>();

}

public void Log<TState>(LogLevel, EventId, TState state, Exception, Func<TState, Exception, string> formatter)

{

string Formatter(TState innserState, Exception innerException)

{

// additional logic goes here, in my case that was extracting additional information from custom exceptions

var message = formatter(innserState, innerException) ?? string.Empty;

return message + " additional stuff in here";

}

_logger.Log(logLevel, eventId, state, exception, Formatter);

}

public bool IsEnabled(LogLevel logLevel)

{

return _logger.IsEnabled(logLevel);

}

public IDisposable BeginScope<TState>(TState state)

{

return _logger.BeginScope(state);

}

and we replaced the default logger with this code

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

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

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

    public ValuesController(ILogger<ValuesController> logger)
    {
        _logger = logger;
    }

    [HttpGet]
    public IEnumerable<string> Get()
    {
        _logger.LogTrace("Get method called trace");
        _logger.LogWarning("Get method called warning");
        _logger.LogError("Get method called error");
        _logger.LogInformation("Get method called information");

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

[Route("api/[controller]")]

public class ValuesController : Controller

{

private readonly ILogger<ValuesController> _logger;

public ValuesController(ILogger<ValuesController> logger)

{

_logger = logger;

}

[HttpGet]

public IEnumerable<string> Get()

{

_logger.LogTrace("Get method called trace");

_logger.LogWarning("Get method called warning");

_logger.LogError("Get method called error");

_logger.LogInformation("Get method called information");

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

}

was producing this output

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

TimeStamp=2018-02-28 20:14:37.2711 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Controllers.ValuesController.Get Level=TRACE Message=Get method called trace

TimeStamp=2018-02-28 20:14:37.3261 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Controllers.ValuesController.Get Level=WARN Message=Get method called warning

TimeStamp=2018-02-28 20:14:37.3261 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Controllers.ValuesController.Get Level=ERROR Message=Get method called error

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

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

TimeStamp=2018-02-28 20:17:27.4044 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Logger`1.Log Level=TRACE Message=Get method called trace additional stuff in here

TimeStamp=2018-02-28 20:17:27.5117 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Logger`1.Log Level=WARN Message=Get method called warning additional stuff in here

TimeStamp=2018-02-28 20:17:27.5117 Callsite=AspNetCoreCustomLoggerAndNLogCallsiteIssue.Logger`1.Log Level=ERROR Message=Get method called error additional stuff in here

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

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

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. 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

public class HomeController : Controller
{
    private static readonly Logger Logger = LogManager.GetCurrentClassLogger();
    
    public async Task<ActionResult> Index()
    {
        await PreprocessRequest(nameof(Index));
        return View();
    }
    
    private static async Task PreprocessRequest(string actionName)
    {
        Logger.Info($"Log from {actionName} action, from thread={Thread.CurrentThread.ManagedThreadId}");
        
        await Task.Run(() => Logger.Info($"Log from {actionName}, from thread {Thread.CurrentThread.ManagedThreadId} assigned by scheduler"))
                  .ConfigureAwait(continueOnCapturedContext: false);
        Logger.Info($"Log from {actionName} action, from async continuation, from thread {Thread.CurrentThread.ManagedThreadId}");
               
        var thread =
            new Thread(() => Logger.Info($"Log from {actionName} action, from explicitly created thread {Thread.CurrentThread.ManagedThreadId}"));
        thread.Start();
        thread.Join();
    }
}

public class HomeController : Controller

{

private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

public async Task<ActionResult> Index()

{

await PreprocessRequest(nameof(Index));

return View();

}

private static async Task PreprocessRequest(string actionName)

{

Logger.Info($"Log from {actionName} action, from thread={Thread.CurrentThread.ManagedThreadId}");

await Task.Run(() => Logger.Info($"Log from {actionName}, from thread {Thread.CurrentThread.ManagedThreadId} assigned by scheduler"))

.ConfigureAwait(continueOnCapturedContext: false);

Logger.Info($"Log from {actionName} action, from async continuation, from thread {Thread.CurrentThread.ManagedThreadId}");

var thread =

new Thread(() => Logger.Info($"Log from {actionName} action, from explicitly created thread {Thread.CurrentThread.ManagedThreadId}"));

thread.Start();

thread.Join();

}

Default log file usually looks like that

TimeStamp=2016-07-03 11:56:02.2327 ThreadId=5 Level=INFO Message=About to start GET / request
TimeStamp=2016-07-03 11:56:02.3797 ThreadId=5 Level=INFO Message=Log from Index action, from thread=5
TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index, from thread 6 assigned by scheduler
TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index action, from async continuation, from thread 6
TimeStamp=2016-07-03 11:56:02.3917 ThreadId=14 Level=INFO Message=Log from Index action, from explicitly created thread 14
TimeStamp=2016-07-03 11:56:04.8250 ThreadId=8 Level=INFO Message=Request completed with status code: 200

TimeStamp=2016-07-03 11:56:02.2327 ThreadId=5 Level=INFO Message=About to start GET / request

TimeStamp=2016-07-03 11:56:02.3797 ThreadId=5 Level=INFO Message=Log from Index action, from thread=5

TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index, from thread 6 assigned by scheduler

TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index action, from async continuation, from thread 6

TimeStamp=2016-07-03 11:56:02.3917 ThreadId=14 Level=INFO Message=Log from Index action, from explicitly created thread 14

TimeStamp=2016-07-03 11:56:04.8250 ThreadId=8 Level=INFO Message=Request completed with status code: 200

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

public class LoggingHttpModule : IHttpModule
{
    private const string CorrelationIdKey = "correlationid";

    private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

    public void Init(HttpApplication context)
    {
        context.BeginRequest += HandleBeginRequest;
        context.EndRequest += HandleEndRequest;
    }

    public void Dispose()
    {
    }

    private void HandleBeginRequest(object sender, EventArgs e)
    {
        var value = Guid.NewGuid().ToString();
        var httpApplication = (HttpApplication) sender;
        var httpContext = httpApplication.Context;
        MappedDiagnosticsLogicalContext.Set(CorrelationIdKey, value);
        Logger.Info($"About to start {httpContext.Request.HttpMethod} {httpContext.Request.RawUrl} request");
    }

    private void HandleEndRequest(object sender, EventArgs e)
    {
        var httpApplication = (HttpApplication) sender;
        var httpContext = httpApplication.Context;
        Logger.Info($"Request completed with status code: {httpContext.Response.StatusCode} ");
    }
}

public class LoggingHttpModule : IHttpModule

{

private const string CorrelationIdKey = "correlationid";

private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

public void Init(HttpApplication context)

{

context.BeginRequest += HandleBeginRequest;

context.EndRequest += HandleEndRequest;

}

public void Dispose()

{

}

private void HandleBeginRequest(object sender, EventArgs e)

{

var value = Guid.NewGuid().ToString();

var httpApplication = (HttpApplication) sender;

var httpContext = httpApplication.Context;

MappedDiagnosticsLogicalContext.Set(CorrelationIdKey, value);

Logger.Info($"About to start {httpContext.Request.HttpMethod} {httpContext.Request.RawUrl} request");

}

private void HandleEndRequest(object sender, EventArgs e)

{

var httpApplication = (HttpApplication) sender;

var httpContext = httpApplication.Context;

Logger.Info($"Request completed with status code: {httpContext.Response.StatusCode} ");

}

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

<!--rest of the code omitted -->
<system.webServer>
  <modules>
  <!--rest of the code omitted -->
    <add name="LoggingHttpModule" type="AspNetMvcLoggingWithCorrelationId.HttpModules.LoggingHttpModule"/>
  </modules>
</system.webServer>
<!--rest of the code omitted -->
<system.web>
<!--rest of the code omitted -->
  <httpModules>
  <!--rest of the code omitted -->
    <add name="ApplicationInsightsWebTracking" type="Microsoft.ApplicationInsights.Web.ApplicationInsightsHttpModule,Microsoft.AI.Web"/>
  </httpModules>
</system.web>