让 .NET 的 Logger 结构化的打印 Scope

问题描述

在 Microsoft.Extensions.Logging 中使用 JsonConsoleFormatter 打印日志时，如果使用 BeginScope<TState>(state) 方法，输出的时候 Scope 会是一个字符串而非传入的 state 对象 JSON 序列化后的结果（即不是预期中的 JSON Object）。

示例代码如下

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

输出如下

{
  "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 }"
  ]
}

问题比较和追查

经过调研，发现 Activity 里面的 TraceId 和 SpanId 就能正常打印出结构来。

样例代码

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");

样例输出

{
  "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"
    }
  ]
}

跑到 Microsoft.Extensions.Logging 源代码仓库里一找，发现只要继承自 IReadOnlyList<KeyValuePair<string, object?>> 或者 IEnumerable<KeyValuePair<string, object?>> 就能解决这个问题。相关源代码见 LoggerFactoryScopeProvider.cs#L131。

问题解决

样例代码

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}";
    }
}

样例输出

{
  "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"
    }
  ]
}