Serilog: Request Id implementation

Question

Lately I have configured Serilog to play nice with ASP.NET Core 2 MVC app and next task is to trace incoming request to web app on every layer of the system. So basically, we want to propagate some token (like RequestId generated by Serilog to lower layers of application).

"Serilog": {
    "Using": [ "Serilog.Sinks.Console", "Serilog.Sinks.RollingFile" ],
    "MinimumLevel": {
      "Default": "Debug",
      "Override": {
        "Microsoft": "Warning"
      }
    },
    "WriteTo": [
      {
        "Name": "RollingFile",
        "Args": {
          "pathFormat": "log-{Hour}.txt",
          "fileSizeLimitBytes": "",
          "retainedFileCountLimit": "",
          "outputTemplate": "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Application}] [{Level}] [{RequestId}] - {Message}{NewLine}{Exception}"
        }
      }
    ],
    "Enrich": [ "FromLogContext", "WithMachineName", "WithThreadId" ],
    "Properties": {
      "Application": "MultilayerApp"
    }
},

In logs we have nice input like

2018-01-19 14:06:01.165 +00:00 [App] [Warning] [0HLAV6PIMA9M0:00000001] - Accessing expired session, Key:"6e7f3ab5-db62-335d-1bc7-6824e5b918f5"

But my question is where in Serilog is implementation of RequestId enricher? Honestly I can't find it.

Answer 1

In ASP.NET Core, the RequestId that is exposed by some loggers is the value of TraceIdentifier on the HttpContext. This property can be used throughout the application to identify the current request.

For logging purposes, falling back to the HttpContext is not the way to go though. The Microsoft.Extensions.Logging abstractions support logging scopes which is a way to provide additional information to the loggers that apply within that scope.

There are two logging scopes that are opened by ASP.NET Core by default. One of those is the HostingLogScope that is opened at the beginning of every request (if at least critical logging is enabled).

Loggers can access the information by implementing the BeginScope method which gets the HostingLogScope object passed to it at the beginning of each request and simply iterating over the object until they find the property:

string requestId = null;
if (state is IEnumerable<KeyValuePair<string, object>> properties)
{
    foreach (var property in properties)
    {
        if (property.Key == "RequestId")
        {
            requestId = property.Value as string;
        }
    }
}

Serilog does pretty much the same but stores all properties in the log event. That’s why you don’t find an explicit reference to RequestId but it’s still there when you specify the logging string format to include it.