• 基于 Activity 来实现后台服务的日志追踪
  • 发布于 2个月前
  • 265 热度
    0 评论
背景
之前我们实现了一个 CorrelationContext 来实现后台服务的日志,现在我们改造成使用 Activity 来实现,这样就不必自己实现 CorrelationContext 并且可以更方便地和其他系统进行集成,HttpHandler 也无需自己实现了,.NET 框架会自动加上,可以借助 OpenTelemetry 更好的分析 tracing 分析

ActivityEnricher
在前面的示例里我们需要增加一个 Enricher 来在日志里添加 CorrelationId,同样我们也需要这样的一个东西来添加 Activity 里的 TraceId/SpanId 等,实现如下:
file sealed class ActivityEnricher : ILogEventEnricher
{
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        if (Activity.Current != null)
        {
            logEvent.AddPropertyIfAbsent(
                propertyFactory.CreateProperty(
                    nameof(Activity.TraceId),
                    Activity.Current.TraceId)
            );
            logEvent.AddPropertyIfAbsent(
                propertyFactory.CreateProperty(
                    nameof(Activity.SpanId),
                    Activity.Current.SpanId)
            );
            logEvent.AddPropertyIfAbsent(
                propertyFactory.CreateProperty(
                    "ActivityId",
                    Activity.Current.Id)
            );
        }
    }
}
ServiceScopeExtensions
之前的文章里我们自定义了一个扩展方法来实现手动注入 CorrelationId,同样的我们需要把 CorrelationId 替换为创建一个 Activity,实现如下:
file static class ServiceScopeExtensions
{
    public static readonly ActivitySource ActivitySource = new ActivitySource("ActivitySample");

    public static void ExecuteWithCorrelationScope(this IServiceProvider serviceProvider,
        Action<IServiceScope, string> action)
    {
        var scope = serviceProvider.CreateScope();
        var activity = ActivitySource.StartActivity();
        try
        {
            action.Invoke(scope, activity?.TraceId.ToString() ?? Guid.NewGuid().ToString());
        }
        finally
        {
            activity?.Stop();
            scope.Dispose();
        }
    }

    public static async Task ExecuteWithCorrelationScopeAsync(this IServiceProvider serviceProvider,
        Func<IServiceScope, string, Task> action)
    {
        var scope = serviceProvider.CreateScope();
        var activity = ActivitySource.StartActivity();
        try
        {
            await action.Invoke(scope, activity?.TraceId.ToString() ?? Guid.NewGuid().ToString());
        }
        finally
        {
            activity?.Stop();
            scope.Dispose();
        }
    }
}
可以看到主要就是创建了一个 activity, ActivitySource 是用来创建和区分 activity 的

Sample code
示例代码如下:
SerilogHelper.LogInit(configuration =>
{
    configuration.Enrich.With<ActivityEnricher>();
    configuration.WriteTo.Console(LogEventLevel.Information
        , "[{Timestamp:HH:mm:ss} {Level:u3}] {TraceId} {SpanId} {Message:lj}{NewLine}{Exception}"
    );
});

var serviceCollection = new ServiceCollection()
    .AddLogging(builder => builder.AddSerilog());
serviceCollection.AddHttpClient("test",
    client => { client.BaseAddress = new Uri("https://reservation.weihanli.xyz"); });
await using var provider = serviceCollection.BuildServiceProvider();

var logger = provider.GetRequiredService<ILoggerFactory>()
    .CreateLogger(typeof(CorrelationIdSampleV2));
logger.LogInformation("Hello 1234");
provider.ExecuteWithCorrelationScope((_, _) =>
{
    logger.LogInformation("Correlation 1-1");
     // 堆代码 duidaima.com
    // do something
    Thread.Sleep(100);
    logger.LogInformation("Correlation 1-2");
});

await provider.ExecuteWithCorrelationScopeAsync(async (scope, __) =>
{
    logger.LogInformation("Correlation 2-1");

    await Task.Delay(100);

    var httpClient = scope.ServiceProvider.GetRequiredService<IHttpClientFactory>()
        .CreateClient("test");
    using var response = await httpClient.GetAsync("/health");
    Console.WriteLine($"HttpRequestHeaders: {
        response.RequestMessage?.Headers.Select(_ => $"{{{{{_.Key}: {_.Value.StringJoin(",")}}}").StringJoin(Environment.NewLine)
    }");
    var responseText = await response.Content.ReadAsStringAsync();
    logger.LogInformation("ApiResponse: {responseStatus} {responseText}", response.StatusCode.ToString(),
        responseText);
    Console.WriteLine();

    logger.LogInformation("Correlation 2-2");
});

logger.LogInformation("Hello 4567");
这段代码基本和之前的代码差不多,相比之前更为简单,主要就是 log 配置变了,http handler 也没有了,然后为了说明 Http request 中的 TraceId 打印了 Http request 的 headers

Custom ActivityListener
有了 activity 之后我们需要定义一个 ActivityListener 来监听我们的 activity,出于性能考虑如果一个 ActivitySource 在创建 Activity 的时候,如果没有 listener 在监听,就会返回 null,我们需要返回的 activity 不为 null 所以我们需要监听一下我们的 ActivitySource,出于简单和示例的考虑我们直接监听了所有的 ActivitySource,并且记录处理的数据,自定义 ActivityListerner 代码如下:
using var activityListener = new ActivityListener();
activityListener.ShouldListenTo = _ => true;
activityListener.ActivityStarted = activity =>
{
    Console.WriteLine($"activity {activity.DisplayName} started, activityId: {activity.Id}, traceId: {activity.TraceId}");
};
activityListener.ActivityStopped = activity =>
{
    Console.WriteLine($"activity {activity.DisplayName} stopped, activityId: {activity.Id}, traceId: {activity.TraceId}");
};
activityListener.Sample = (ref ActivityCreationOptions<ActivityContext> _) => ActivitySamplingResult.AllData;
ActivitySource.AddActivityListener(activityListener);
执行我们的示例代码,输出结果如下图所示:

从输出结果来看和我们之前的示例差别不大,注意观察打印出来的 http request header 可以看到有一个 traceparent 的 header,其实对应 Http request 对应 activity 的 Id。

Activity.Id/traceparent 默认使用 W3C 标准的格式,可以参考文档 https://www.w3.org/TR/trace-context/#traceparent-header,.NET 里的 ActivityContext 实现了这个标准
00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01
前面两位 00 代表一个 version,目前固定使用 00
0af7651916cd43dd8448eb211c80319c 代表着 traceId,同一个 TraceContext/ActivityContext 里的所有 activity 应该相同
b7ad6b7169203331 代表当前 Activity 的 spanId,如果是 traceparent header 则是代表 parent 的 spanId

最后的两个 01 代表 trace 的标志,目前只定义了一个值,如果是 01 代表被采样成功会被记录下来,00 代表没有被采样,tracing 系统里不会有这个值

OpenTelemetry integration
前面我们自己通过 ActivityListener 实现 activity 的监听,我们也可以通过集成 OpenTelemetry 来更好地呈现和分析以及集成其他的项目,我们可以创建一个 OpenTelemetry 里的 Tracer,示例如下:
using var tracerProvider = Sdk.CreateTracerProviderBuilder()
    .ConfigureResource(x => x.AddService("BalabalaSample"))
    .AddSource("System.*")
    .AddSource(ServiceScopeExtensions.ActivitySource.Name)
    .AddConsoleExporter()
    .Build();
备注:需要引用 nuget package: OpenTelemetry.Exporter.Console
再来运行我们的示例代码,输出结果如下:

输出结果是不是好看了很多,我们也可以导出到 zipkin, jaeger 等可视化更好的系统中,这里我们使用了默认的 Http 的 activity 我们也可以集成 open telemetry 的 httpClient 扩展,需要安装一下 OpenTelemetry.Instrumentation.Http nuget 包, tracerProvider 的创建修改为下面的示例
using var tracerProvider = Sdk.CreateTracerProviderBuilder()
    .ConfigureResource(x => x.AddService("BalabalaSample"))
    .AddSource(ServiceScopeExtensions.ActivitySource.Name)
    .AddHttpClientInstrumentation()
    .AddConsoleExporter()
    .Build();
我们再来运行一下示例,输出结果如下:

可以看到 http request 有了更多的信息,这是 open telemetry 通过 http client 的 diagnostic source 发出的信息来在对应的 activity 里增加了更多的信息,实现可以参考:
https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/src/OpenTelemetry.Instrumentation.Http/Implementation/HttpHandlerDiagnosticListener.cs
小结:
上面的示例比较简单,仅作参考。前面写死的 ActivitySource 也可以添加到依赖注入里,通过依赖注入来获取 ActivitySource,如果是 asp.net core 应用,你可能需要封装一下不能直接注入 ActivitySource 不然可能会发现拿到的 ActivitySource 并不是自己想要的,我们也可以通过 OpenTelemetry 来集成更多的组件,也可以让 tracing 数据更加好的呈现,也可以为 activity 添加更多的 tag 来进一步丰富 activity 的内容以帮助更好的分析和解决问题,如果你为自己的 library 添加 tracing 支持,推荐使用 ActivitySource 来代替 DiagosticSource,也更加方便和 OpenTelemetry 进行集成,DiagnosticSource 还需要再转换一下!

好的,就这样啦~
用户评论