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?

Pennington

what solution did you end up going with? – Alroy

I actually decided to use Serilog for logging instead of NLog. Serilog provides a thread-safe context using (I presume) the LogicalCallContext method described below. With Serilog I can use the technique I describe in my question, but it actually works :) – Pennington

fwiw, NLog's MappedDiagnosticsContext now has an async-safe version nlog-project.org/config/…. Personally I prefer letting Application Insights do all this (e.g. then the operation id is correlated with client events too), see https://mcmap.net/q/2034900/-activity-correlation-with-azure-application-insights-asp-net-mvc-and-nlog for details. – Aphonia

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.

Soneson

Accepting this answer because it's ultimately what works, however I actually switched to Serilog as our logging library because it provides exactly what I need. – Pennington

NLog ver. 4.1 introduced ${mdlc} that makes use of LogicalCallContext. See also github.com/NLog/NLog/wiki/MDLC-Layout-Renderer – Insula

Answer 2

NLog.Extension.Logging ver. 1.0 is able to capture context-properties created with ILogger.BeginScope. These can be extracted using NLog ${mdlc}.

Microsoft engine will by default inject properties like RequestId, RequestPath, etc.

See also: https://github.com/NLog/NLog.Extensions.Logging/wiki/NLog-properties-with-Microsoft-Extension-Logging

Insula

Answer 3

If you're using Application Insights they automatically set System.Diagnostics.Activity.Current to an object that has all the Application Insights info you could want and more, including RootId and Id that lets you correlate with other events.

See this answer for more details and how to log it easily with nlog.

Aphonia