Make .NET Logger Print Scope as Structured Data

Problem Description #

When using JsonConsoleFormatter in Microsoft.Extensions.Logging to print logs, if you use the BeginScope<TState>(state) method, the Scope in the output will be a string rather than the result of JSON-serializing the state object passed in (that is, it is not the expected JSON Object).

The sample code is as follows:

csharp

using (logger.BeginScope(new { SessionId = "123", TraceId = "456", SpanId = "789" }))
{
    logger.LogInformation("Hello {name}!", "World");
}

The output is as follows:

json

{
  "Timestamp": "2024-05-30T13:38:39.108Z",
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "main",
  "Message": "Hello World!",
  "State": {
    "Message": "Hello World!",
    "name": "World",
    "{OriginalFormat}": "Hello {name}!"
  },
  "Scopes": [
    "{ SessionId = 123, TraceId = 456, SpanId = 789 }"
  ]
}

Comparing and Investigating the Issue #

After some investigation, I found that the TraceId and SpanId in Activity can be printed with the correct structure.

Sample code:

csharp

var loggerFactory = LoggerFactory.Create(builder =>
{
    builder.ClearProviders();
    builder.AddJsonConsole(options => {
        // ...
    });

    builder.Configure(options =>
    {
        options.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.SpanId;
    });
});

var logger = loggerFactory.CreateLogger("main");

var activitySource = new ActivitySource(
    Assembly.GetExecutingAssembly().FullName ?? typeof(Program).FullName ?? nameof(Program));
ActivitySource.AddActivityListener(new ActivityListener()
{
    ShouldListenTo = _ => true,
    Sample = (ref ActivityCreationOptions<ActivityContext> options) => ActivitySamplingResult.AllData,
});

var activity = activitySource.StartActivity(ActivityKind.Internal, name: "main");

logger.LogInformation("Hello {name}!", "World");

Sample output:

json

{
  "Timestamp": "2024-05-30T13:45:28.480Z",
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "main",
  "Message": "Hello World!",
  "State": {
    "Message": "Hello World!",
    "name": "World",
    "{OriginalFormat}": "Hello {name}!"
  },
  "Scopes": [
    {
      "Message": "SpanId:a9563a12d6c1c82d, TraceId:62031742f61da3361b63ef75c11c0be8",
      "SpanId": "a9563a12d6c1c82d",
      "TraceId": "62031742f61da3361b63ef75c11c0be8"
    }
  ]
}

After searching the Microsoft.Extensions.Logging source code repository, I found that this issue can be solved as long as the type inherits from IReadOnlyList<KeyValuePair<string, object?>> or IEnumerable<KeyValuePair<string, object?>>. For the relevant source code, see LoggerFactoryScopeProvider.cs#L131.

Solution #

Sample code:

csharp

var logger = loggerFactory.CreateLogger("main");

using (logger.BeginScope(new TracingContext(SessionId: "123", TraceId: "456", SpanId: "789")))
{
    logger.LogInformation("Hello {name}!", "World");
}

public record class TracingContext(string SessionId, string TraceId, string SpanId)
    : IEnumerable<KeyValuePair<string, object?>>
{
    public IEnumerator<KeyValuePair<string, object?>> GetEnumerator()
    {
        yield return new(nameof(SessionId), SessionId);
        yield return new(nameof(TraceId), TraceId);
        yield return new(nameof(SpanId), SpanId);
    }

    IEnumerator IEnumerable.GetEnumerator()
    {
        return GetEnumerator();
    }

    public override string ToString()
    {
        return $"{nameof(SessionId)}: {SessionId}, {nameof(TraceId)}: {TraceId}, {nameof(SpanId)}: {SpanId}";
    }
}

Sample output:

json

{
  "Timestamp": "2024-05-30T13:53:05.767Z",
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "main",
  "Message": "Hello World!",
  "State": {
    "Message": "Hello World!",
    "name": "World",
    "{OriginalFormat}": "Hello {name}!"
  },
  "Scopes": [
    {
      "Message": "SessionId:123, TraceId:456, SpanId:789",
      "SessionId": "123",
      "TraceId": "456",
      "SpanId": "789"
    }
  ]
}