最近拜读了 Artech 大佬的新文章 《几个Caller-特性的妙用》，可以说是受益匪浅。不过，对我而言，最大的收获当属这篇文章里的第二主角，即 ActivitySource 和 Activity，这组 API 可以认为是微软针对 OpenTelemetry 规范的一种实现，即：每一个 Activity 都对应着一个 Span 。在以前的博客 《Envoy 集成 Jaeger 实现分布式链路追踪》 中，我曾经向大家介绍过 OpenTelemetry 规范，并最终结合 Envoy 和 Jeager 实现了非侵入式的、网关层的分布式链路追踪，正所谓“温故而知新”，在这个过程中我意识到其中还有值得去挖掘的东西。譬如，可观测性的三大支柱分别是 Logging、Tracing 和 Metrics 。可当我们接入了 Jeager 、Zipkin 等等的链路追踪系统，我们会发现它和平用到日志系统如 NLog、Serilog、ELK …等等都相去甚远，好像这两者间存在着一种天然的割裂感，你不得不在了解了服务间的调用关系以后，再一头扎进各种各样的日志文件里。幸运的是，经过数日的探索，我有了一点小小的收获。因此，今天这篇博客我想和大家分享的是，分布式链路追踪系统如何和日志系统进行整合。
.NET 中的分布式追踪
微软的 官方文档 中，有一个独立的章节来介绍分布式追踪。如果你观察得足够仔细，就会发现官方将其归类为 诊断和检测。我个人认为，这是我们日常开发中经常被忽略的一个东西。早年开发 Windows 桌面程序的时候，每当程序出现异常的时候，经验丰富的前辈总会让你去看一下 Windows 日志。其实，这个 Windows 日志就是 .NET Framework 时代的一种诊断工具。由此我们就可以知道， Diagnostics 就是一种帮助你记录应用程序运行期间的关键性操作及其执行时长的机制，我承认，这听起来和现在流行的 APM 差不多，至少从宏观上来看这个观点是成立的，因为 APM 的核心功能之一就是检测应用程序的关键事件。从 .NET Core 开始，Diagnostics 这个命名空间从 Microsoft 变为了 System 。如下图所示，整个诊断的核心建立在 Activity 这个类，以及 IObservable<T> 和 IObserver<T> 这组观察者模式的 API 上，其基本原理是：通过一系列活动来产生一系列事件，而关心这些事件的订阅者则可以通过这些事件来判断应用程序当前的状态。
一个最典型的场景是，当我们调用一个由 ASP.NET Core 托管的 Web 服务的时候，它可以在日志中输出本次请求的时长，这背后的功臣其实 DiagnosticsSource 和 DiagnosticsListener，我们来看下面的例子：
// 定义观察者：MyDiagnosticObserver
public class MyDiagnosticObserver : IObserver<KeyValuePair<string, object>>
{
//...
public void OnCompleted()
{
}
public void OnError(Exception error)
{
_logger.LogError(error.Message);
}
public void OnNext(KeyValuePair<string, object> pair)
{
_logger.LogInformation($"{pair.Key}, {pair.Value}");
}
}
// 订阅 Microsoft.AspNetCore 主题
var listener = new DiagnosticListener("Microsoft.AspNetCore");
var observer = new MyDiagnosticObserver();
listener.Subscribe(observer);
此时，我们可以注意到，微软在请求开始、请求结束的地方做了埋点，因此，对于上面我们提出的问题，如果想要计算本次请求的时长，其实只需要用这两个时间戳相减。诚然，这个问题的解决方案还有很多，可最为重要的一件事情是，我们可以换一种角度来审视这一切。截止到目前为止，ASP.NET Core、EntityFramework Core 等等都已经对 Diagnostics 支持，这使得我们可以利用这些诊断信息来排查应用程序的性能问题或者跟踪调用链。
ActivitySource 与 Activity
OK，现在让我们把目光聚焦在 Activity、ActivitySource 以及 AcitivityListener 这条线索上来，我们上面提到诊断信息可以运用于调用链的跟踪，其实就是指这部分内容。目前，分布式追踪普遍使用的术语叫做 Span，由于 .NET 中的 Activity 比 Span 出现地更早，当时 Span 的概念还不为人所知，所以，微软就一直沿用了这个术语。我个人猜测，这极有可能是为了和后来出现的 Span<T> 类型区分开来。总而言之，这里的 Activity 和 Span 是等价的，它本身具有像 SpanId、TraceId、ParentSpanId 等等表示树状节点的信息，可以携带像 Baggage、Tags 等等键值对信息，或者是事件信息。下面是 Activity 的一个基本用法：
// 1.定义活动源
var _activitySource = new ActivitySource("MyTrace")
// 2.定义活动监听器
ActivitySource.AddActivityListener(new ActivityListener() {
ShouldListenTo = _ => true,
Sample = (ref ActivityCreationOptions<ActivityContext> options) => ActivitySamplingResult.AllData,
ActivityStopped = activity =>
{
logger.LogInformation($"{activity.DisplayName},ParentSpanId={activity.ParentSpanId},TraceId={activity.TraceId},SpanId={activity.SpanId},Duration={activity.Duration}");
var stringBuilder = new StringBuilder();
foreach (var kv in activity.TagObjects)
{
stringBuilder.AppendLine($"{kv.Key}={kv.Value}");
}
if (stringBuilder.Length > 0)
logger.LogInformation($"TagObjects:{stringBuilder.ToString()}");
}
};)
如你所见，我们定义了一个活动源 MyTrace ，同时为其指定了一个监听器，这使得我们可以这些活动的信息。有道是：万事俱备，只欠东风，接下来，我们来考虑如何产生活动。假设一件事情需要三个步骤来完成，如果每一个步骤对应一个活动，那么我们可以像下面这样子来编写代码：
public async Task<string> InvokeAsync()
{
using (_activitySource.StartActivity())
{
return await RunStep1Async();
}
}
// Step1
private async Task<string> RunStep1Async()
{
using (var activity = _activitySource.StartActivity())
{
await Task.Delay(100);
activity.AddTag("Description", "This is Step1");
_logger.LogInformation("Step1 is running");
return await RunStep2Async();
}
}
// Step2
private async Task<string> RunStep2Async()
{
using (var activity = _activitySource.StartActivity())
{
await Task.Delay(200);
activity.AddTag("Description", "This is Step2");
_logger.LogInformation("Step2 is running");
return await RunStep3Async();
}
}
// Step3
private async Task<string> RunStep3Async()
{
using (var activity = _activitySource.StartActivity())
{
await Task.Delay(300);
activity.AddTag("Description", "This is Step3");
_logger.LogInformation("Step3 is running");
return "Hi, I am always here";
}
}
此时，会发生什么呢？可以注意到，每一个步骤对应了一个 Activity 或者说是一个 Span，它本身有一个唯一的 SpanId，并且都拥有相同的 TraceId，这显然符合我们的调用链，即：Step1 -> Step2 -> Step3。当然，因为这些调用存在是层级关系，所以，你会注意到第一个活动的 SpanId 就是第二个活动的 ParentSpanId，以此类推。话说到这种程度，我想，大家都能理解，这可不就是 Span 吗？
.NET 与 OpenTelemetry
在此前的文章中，博主曾非常粗浅提到过 OpenTelemetry 规范，它由微软和谷歌共同发起，终极目标是：实现 Metrics、Tracing、Logging 的融合及大一统，作为 APM 的数据采集终极解决方案。不得不说，这是一个非常宏伟的理想，毕竟跟随着 Logstash、Filebeat、Fluentd 这一路走过来，日志收集的方案一直是层出不穷，有时候我会觉得这一切混乱无比。坦白讲，我不愿意接触 K8S 的一大理由，就是不想再去学习一套配置语法。可是话说回来，虽然 OpenTelemetry 还没有发布正式版，可这丝毫不影响我们在 .NET 中提前体验一番，我们继续使用上面的例子来进行说明：
Sdk.CreateTracerProviderBuilder()
.SetResourceBuilder(ResourceBuilder.CreateDefault().AddService("Program"))
.AddSource("MyTrace")
.AddConsoleExporter()
.AddJaegerExporter(options =>
{
options.AgentHost = "<You Agent Host>";
options.AgentPort = 6831;
})
.Build();
通过上面这段代码，我们就可以收集这些活动到 Jeager，平时我们使用 Jeager 更多的是分析跨服务、跨进程的调用链，其实它一样可以运用到进程内，如果我们能把打通进程内外，那么，整个链路追踪就从逻辑上就实现了闭环。当我们在一个微服务的体系中排查问题的时候，经常遇到的一个困境就是，我必须从头到尾、一个点一个点的排查，无论我是否需要知道上下游的业务细节，那一刻无数冗余的信息都如排山倒海一般拥挤过来。不知道大家是不是和我有类似的感受，即：有时候我们拆分了微服务出来，好像拆分了，又好像没有。
除了上面这种半自动化采集的方式，OpenTelemetry 的 .NET SDK 里同样提供了自动化采集的方式，主要针对 HttpClient 和 ASP.NET Core 的诊断信息：
services.AddOpenTelemetryTracing(builder =>
{
builder
.AddConsoleExporter()
.AddSource(serviceName)
.SetResourceBuilder(ResourceBuilder.CreateDefault().AddService(serviceName))
.AddHttpClientInstrumentation() // HttpClient 诊断信息采集
.AddAspNetCoreInstrumentation(); // ASP.NET Core 诊断信息采集
});
这意味着，当你访问一个接口或者是通过 HttpClient 调用第三方接口时，OpenTelemetry 可以自动将其采集到指定的目标，如果大家对 OpenTelemetry 感兴趣的话，可以参照官方文档做更进一步的探索！
分布式追踪和日志整合
好了，到现在为止，关于 Activity、ActivitySource 以及 AcitivityListener 这条故事线的探索已经全部完成，甚至它可以结合 OpenTelemetry 为分布式链路追踪带来一点新思路。可是，大家对这一切真的就没有一点疑问吗？对博主而言，我真正困惑的点是，即使有一天 OpenTelemetry 可以统一 Metrics、Tracing、Logging ，可至少在现在这个阶段，我们使用得最多的还是 NLog、Serilog 这些方案。此时，当务之急是如何让新旧两个体系完美地整合在一起。所以，接下来我们来聊聊分布式追踪和日志的整合，这里以 NLog 为例。
NLog.DiagnosticSource
NLog.DiagnosticSource 是一个 NLog 的扩展库，它可以利用 System.Diagnostics.Activity.Current 将一个活动的信息渲染到日志中，譬如，这里最重要的一个参数是 TraceId，如果我们的日志中有这个参数，我们就可以在 ELK 中精确地查询出上下文相关的一组日志，而不是通过时间或者关键字去做模糊匹配。如下图所示，我们可以在 NLog.config 这个配置文件中使用诊断数据中的字段，这里以 TraceId 和 SpannId 为例：
<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xsi:schemaLocation="NLog NLog.xsd"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<extensions>
<add assembly="NLog.DiagnosticSource"/>
</extensions>
<targets>
<target xsi:type="File" name="file" fileName="${basedir}/logs/${shortdate}.log">
<layout xsi:type="JsonLayout" includeAllProperties="true">
<attribute name="time" layout="${longdate}" />
<attribute name="level" layout="${level:upperCase=true}" />
<attribute name="message" layout="${message}" />
<attribute name="exception" layout="${exception:format=ToString}" />
<attribute name="traceId" layout="${activity:property=TraceId}" />
<attribute name="spanId" layout="${activity:property=SpanId}" />
</layout>
</target>
</targets>
<rules>
<logger name="*" minlevel="Trace" writeTo="file" />
</rules>
</nlog>
在此情形下，上下文相关的日志将会有相同的 TraceId。显然，这对于我们排查问题非常有用，你可以通过 Jeager 获得 TraceId ，然后再通过 TraceId 查询日志，我觉得这样就很好！
更多关于 NLog.DiagnosticSource 使用的细节，请大家可以参考其官方文档。
自定义 LayoutRenderer
当然，微软的东西好像天生就是一种原罪，很多时候，你可能根本不会用这个听都没听说过的 Acitivity ，你可能更愿意使用自己生成的 TraceId，在这种情况下，NLog.DiagnosticSource 这个库就不再适用啦，因此，在最后的这点篇幅里，我想分享一下 Nlog 里自定义的 LayoutRenderer 的实现。提到这个话题的时候，我其实是蛮感慨的。因为我以前特意研究过 NLog 里的 LayoutRenderer 、Serilog 里的 Sink，原因是上家公司的日志不支持全文索引，当时的想法是把日志写到 Elasticsearch 里面，所以，花了一点时间去了解这些东西。无独有偶，在生成 TraceId 这个问题上，我已经见过了好几种做法，有的在客户端生成，有的在服务器端生成，有的在网关层生成，可以说是莫衷一是。由此可见，这个自定义的 TraceId 其实是挺普遍的一个需求。
以博主以前写的博客 《Envoy 集成 Jaeger 实现分布式链路追踪》 为例，我的这个 TraceId 是在网关层生成的，此时的做法是通过一个中间件来实现：
public async Task InvokeAsync(HttpContext context) {
if (context.Request.Headers.ContainsKey("x-b3-traceid")) {
CallContext.SetData("TraceId", context.Request.Headers["x-b3-traceid"]);
} else {
CallContext.SetData("TraceId", Guid.NewGuid().ToString("N"));
}
await _next(context);
}
其中，CallContext 是一个基于 AsyncLocal<T> 的辅助类，用于在异步代码间共享数据。如果你经历过 .NET Framework 时代，应该会知道这个 CallContext 的作用：
public static class CallContext
{
private static ConcurrentDictionary<string, AsyncLocal<object>> _states
= new ConcurrentDictionary<string, AsyncLocal<object>>();
public static void SetData<T>(string name, T data) =>
_states.GetOrAdd(name, _ => new AsyncLocal<object>()).Value = data;
public static T GetData<T>(string name) =>
_states.TryGetValue(name, out AsyncLocal<object> data) ? (T)data.Value : default(T);
}
现在，这个 TraceId 已经被存放到 CallContext 里面啦，我们只要从某个地方将其读取出来即可，为此，我们需要实现下面的自定义 LayoutRenderer ：
[LayoutRenderer("my-trace-id")]
public class MyTraceIdLayoutRenderer : LayoutRenderer
{
protected override void Append(StringBuilder builder, LogEventInfo logEvent)
{
if (Activity.Current != null) {
builder.Append(Activity.Current.TraceId.ToString());
} else {
var traceId = CallContext.GetData<string>("traceid");
builder.Append(traceId);
}
}
}
此时，我们可以在 NLog.config 中使用这个新的模板，至此我们就实现了分布式链路追踪与日志的整合：
<layout xsi:type="JsonLayout" includeAllProperties="true">
<attribute name="time" layout="${longdate}" />
<attribute name="level" layout="${level:upperCase=true}"/>
<attribute name="message" layout="${message}" />
<attribute name="exception" layout="${exception:format=ToString}" />
<attribute name="traceId" layout="${my-trace-id}" />
</layout>
当然，在使用这个新模板前，按照 NLog 官方的说法，你最好是全局注册一下先：
ConfigurationItemFactory.Default.LayoutRenderers
.RegisterDefinition("my-trace-id", typeof(MyTraceIdLayoutRenderer));
本文小结
本文的灵感来自于 Artech 大佬的新文章 《几个Caller-特性的妙用》 一文，可是对于我来说， Activity、ActivitySource 以及 AcitivityListener 这条故事线好像更重要一点。正所谓：“温故而知新”，在这个过程中我发现了 Activity 和 Span 在功能上的相似性，进而接触到了 OpenTelemetry ，当我们尝试把这两个事物结合在一起的时候，就会发现它完全可以运用到进程内的链路追踪。如果说，年初时候写的 《Envoy 集成 Jaeger 实现分布式链路追踪》 一文中的做法更符合云原生的理念，那么，此时此刻，这种在应用程序里接入 SDK 的做法是否就显得落后呢？我想，或许各有千秋，就像我有时候会觉得，在代码里创建一个个的 Activity 显得多此一举，我更愿意通过 AOP 的方式让这些细节不可感知，可仔细想想知道这个想法太过天真，因为只要你在意这些 Activity 的层级关系，这个过程就一定是会被使用者感知到的。在这个基础上，我们把 TraceId 写入到日志文件里，这样我们排查问题就有了一个清晰的流程：首先，通过 Jeager 或者 Zipkin 搞清楚调用链路，等拿到 TraceId 以后再去查询相关的日志，如果能避免在无关的事情/信息上浪费时间，何乐而不为呢？