Tracing between logs with a correlation ID

Attempting to match timestamps and whatnot to correlate requests over various logs may be quite tedious. Adding a correlation ID to your website makes this easier and may save you quite a bit of time. This is what we did at my current client for all of their Episerver websites. I Implemented this together with my collegue Svante Seleborg.

Passing a correlation ID through your application

We want to set up a correlation ID early in the request cycle so that we are able to use it throughout our entire application. This may be done in a HttpModule. I have edited the below code and replaced our generation of the correlation ID with a guid value for simplicity. You may want to use something else.

HttpHeaders.CorrelationId is just the string value X-Correlation-ID.

public class FirstCorrelationModule : IHttpModule
{
  public void Init(HttpApplication context)
  {
    _ = context ?? throw new ArgumentNullException(nameof(context));

    context.BeginRequest += Context_BeginRequest;
    context.EndRequest += Context_EndRequest;
  }

  private void Context_BeginRequest(object sender, EventArgs e)
  {
    var application = (HttpApplication)sender;

    HttpContext httpContext = application.Context;

    string correlationId = Guid.NewGuid().ToString();
    httpContext.Items.Add(HttpHeaders.CorrelationId, correlationId);
    httpContext.Response.Headers.Add(HttpHeaders.CorrelationId, correlationId);
  }

The correlation ID is added to the context items collection in BeginRequest since we want it available throughout our application. Here you may of course also use correlation IDs provided by other sources, like for instance Instana.

Since the response headers may disappear (like when new response messages are created in the application) we want to ensure that the header is still set when we reach EndRequest. Since there is no guarantee that the headers have not already been written once we get there, the X-Correlation-ID header is also set in BeginRequest.

private void Context_EndRequest(object sender, EventArgs e)
{
  var application = (HttpApplication)sender;

  HttpContext httpContext = application.Context;
  HttpResponse httpResponse = httpContext.Response;
  if (!httpResponse.HeadersWritten && httpResponse.Headers[HttpHeaders.CorrelationId] == null)
  {
    string correlationId = httpContext.Items[HttpHeaders.CorrelationId]?.ToString() ?? Guid.NewGuid().ToString();
    httpResponse.Headers.Add(HttpHeaders.CorrelationId, correlationId);
  }
}

Custom logging: Adding a correlation ID to your application logs

Adding the correlation ID to your custom application logging is not as simple as it may seem. Especially if you consider async code, singletons and so on. Below is an example of an implementation of Episerver’s ILogger interface using NLog.

Note that there is absolutely no guarantee that we will have a HttpContext at this time, even though we quite often probably will.

public class NLogger : EPiServer.Logging.ILogger
{
  private readonly Logger _nLogLogger;

  public NLogger(string name)
  {
    _nLogLogger = NLog.LogManager.GetLogger(name);
  }

  public void Log<TState, TException>(
    Level level,
    TState state,
    TException exception,
    Func<TState, TException, string> messageFormatter,
    Type boundaryType) where TException : Exception
  {
    if (messageFormatter == null)
    {
      _nLogLogger.Log(LogLevel.Error, $"Attempt to log with NULL messageFormatter and state='{state?.ToString() ?? "(NULL)"}'", exception);
      return;
    }

    // Interesting part here
    Func<TState, TException, string> formatter = HttpContext.Current != null ? (s, ex) => $"Id:{HttpContext.Current.Items[HttpHeaders.CorrelationId]} {messageFormatter(s, ex)}" : messageFormatter;

    try
    {
      _nLogLogger.Log(MapToNLogLevel(level), exception, () => formatter(state, exception));
    }
    catch (FormatException fe)
    {
      _nLogLogger.Log(LogLevel.Error, $"Did you get your log message indices wrong?", fe);
      throw;
    }
  }

The above code tries to concatenate the correlation ID to the log message if there is one. This is not guaranteed to add the ID to all of your log entries as we try to access the context via HttpContext.Current. Dependency injection would obviously not work either. The only way to be sure would be passing the context to the Log method from a place where we knew it existed and we had the correct one. This is however quite tricky due to singletons as well as the way the CMS handles logger factories.

IIS logs: Adding a correlation ID to your IIS logs

In order to add extra information such as the correlation ID to your IIS logs you will need to edit the applicationHosts.config file (C:\Windows\System32\inetsrv\config\).

<site name="MyProject.Web" id="3" serverAutoStart="true">
  <application path="/" applicationPool="MyProject.WebAppPool">
    <virtualDirectory path="/" physicalPath="C:\path\MyProject.Web" />
  </application>
  <bindings>
    <binding protocol="http" bindingInformation="*:80:myproject.local" />
    <binding protocol="https" bindingInformation="*:443:myproject.local" sslFlags="1" />
  </bindings>
  <logFile>
    <customFields>
      <add logFieldName="X-Correlation-ID" sourceName="X-Correlation-ID" sourceType="ResponseHeader" />
    </customFields>
  </logFile>
</site>

This may of course be done as part of a deployment process using for instance PowerShell: Add-WebConfigurationProperty.

Add-WebConfigurationProperty -PSPath 'MACHINE/WEBROOT/APPHOST'  -Filter "system.applicationHost/sites/site[@name='MyProject.Web']/logFile/customFields" -Name '.' -Value @{logFieldName='X-Correlation-ID';sourceName='X-Correlation-ID';sourceType='ResponseHeader'}

Your IIS logs will then contain an extra column called X-Correlation-ID. Note that the name of the file will automatically change once you add extra information. So instead of getting files called for instance u_ex201012.log they will now be named u_ex201012_x.log.

Exceptions: Adding a correlation ID to all of your exception

To add this ID to your exception messages, please read the article Enriching your exceptions with information from Episerver for a simple way of setting up exception enrichment. Afterwards it is just a matter of adding the correlation ID from the items collection.

private static void EnrichUnsafe(Exception e)
{
  // ...
  e.Data["Correlation_ID"] = HttpContext.Current.Items[HttpHeaders.CorrelationId] ?? string.Empty;

As pointed out in the referenced article, be careful of what you’re doing in these methods, as causing additional exceptions here is not a favourable thing.