Approach for tying all NLog logs back to the original request within WebAPI?

Question

I am working to build an API using WebAPI, and have been using NLog for logging throughout the stack. My API solution has two main projects including:

• The website layer itself that implements the controllers and webapi stuff
• A service layer that implements "async" commands and handlers in a CQRS-like fashion

What I'm trying to achieve is to automatically generate a unique ID that I can attach to log statements so that any logs written while servicing a single request, no matter what layer they came from, can be linked back to that original request. I'd also like this to work without passing the unique ID around, or having the log statements themselves be concerned with including it in their calls.

With that goal in mind I started looking into writing a custom delegating handler to intercept each request (following this post for guidance) and add a unique ID as a property within NLog. I ended up with the following:

/// <summary>
/// This class is a WebAPI message handler that helps establish the data and operations needed
/// to associate log statements through the entire stack back to the originating request.
/// 
/// Help from here: http://weblogs.asp.net/fredriknormen/log-message-request-and-response-in-asp-net-webapi
/// </summary>
public class InitializeLoggingMessageHandler : DelegatingHandler
{
    private ILogger _logger;

    // The logger is injected with Autofac
    //
    public InitializeLoggingMessageHandler(ILogger logger)
    {
        _logger = logger;
    }

    protected async override System.Threading.Tasks.Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, System.Threading.CancellationToken cancellationToken)
    {
        // Get a unique ID for this request
        //
        var uniqueId = Guid.NewGuid().ToString();

        // Now that we have a unique ID for this request, we add it to NLog's MDC as a property
        //  we can use in the log layouts. We do NOT use the global diagnostic context because
        //  WebAPI is multi-threaded, and we want the ID to be scoped to just the thread servicing
        //  this request.
        //
        NLog.MappedDiagnosticsContext.Set("UniqueId", uniqueId);

        // Capture some details about the request for logging
        //
        var requestInfo = string.Format("{0} {1}", request.Method, request.RequestUri);
        var requestMessage = await request.Content.ReadAsByteArrayAsync();

        _logger.Info("Request: {0} - {1}", requestInfo, Encoding.UTF8.GetString(requestMessage));

        var response = await base.SendAsync(request, cancellationToken);

        return response;
    }
}

With this code I can then use the unique ID in log layouts like so:

<target xsi:type="Debugger" name="DebugLogger" 
        layout="${longdate} ${logger} ${mdc:item=UniqueId} ${message}" />

The problem with this approach is that I'm using NLog's MappedDiagnosticsContext to try to save the unique ID as a property that can be used within layouts (so my code doing the logging doesn't need to know). This is a thread-local mechanism for storing values, so it breaks down when you have async code since the thread that starts a request, may not be the one that executes all of it.

So what happens is the first log messages have the unique ID included, but the ones later on could be missing it since they're on a different thread and can't access the value. I also can't use the GlobalDiagnosticsContext within NLog because it's truly global, so multiple requests in WebAPI would easily overwrite the unique ID, and the data would be useless.

So with the goal of associating all log messages back to the request that originated within WebAPI, is there another mechanism that I should be considering?

Answer 1

Take a look at LogicalCallContext. As of .NET 4.5, it supports async scenarios.

Mr. Jeffrey Richter:

The .NET Framework has a little-known facility that allows you to associate data with a “logical” thread-of-execution. This facility is called logical call context and it allows data to flow to other threads, AppDomains, and even to threads in other processes.