5

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?

Sam Storie
  • 4,444
  • 4
  • 48
  • 74
  • 1
    what solution did you end up going with? – Demodave Sep 30 '15 at 14:57
  • 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 :) – Sam Storie Sep 30 '15 at 15:01
  • fwiw, NLog's MappedDiagnosticsContext now has an async-safe version https://nlog-project.org/config/?tab=layout-renderers&search=context. Personally I prefer letting Application Insights do all this (e.g. then the operation id is correlated with client events too), see https://stackoverflow.com/a/70183226/8479 for details. – Rory Dec 01 '21 at 11:23

3 Answers3

5

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.

Anton Gogolev
  • 113,561
  • 39
  • 200
  • 288
  • 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. – Sam Storie Sep 30 '15 at 15:02
  • 1
    NLog ver. 4.1 introduced `${mdlc}` that makes use of `LogicalCallContext`. See also https://github.com/NLog/NLog/wiki/MDLC-Layout-Renderer – Rolf Kristensen Feb 24 '19 at 16:40
1

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

Rolf Kristensen
  • 17,785
  • 1
  • 51
  • 70
1

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.

Rory
  • 40,559
  • 52
  • 175
  • 261