使用 Tracing 进行诊断

2019 年 8 月 14 日

为了有效地开发系统并在生产环境中运行它们，需要了解它们在运行时的行为。虽然传统的日志记录可以提供一些这种可见性，但异步软件（例如使用 Tokio 运行时的应用程序）引入了新的挑战。

tracing 是一系列库的集合，它们提供了一个框架，用于检测 Rust 程序以收集结构化、上下文感知、事件驱动的诊断信息。请注意，tracing 最初以名称 tokio-trace 发布；更名是为了反映虽然它是 Tokio 项目的一部分，但使用 tracing 不需要 tokio 运行时。

为什么我们需要另一个日志库？

Rust 已经拥有一个强大的日志生态系统，该生态系统围绕 log crate 的日志外观（facade）构建，并广泛使用了 env_logger 和 fern 等库。这就引出了合理的问题——为什么 tracing 是必要的，它提供了哪些现有库不具备的优势？为了回答这些问题，我们需要考虑异步系统中诊断所带来的挑战。

在同步代码中，我们可以简单地在程序执行时记录各个消息，并期望它们按顺序打印出来。程序员可以相当容易地解释日志，因为日志记录是按顺序输出的。例如，在同步系统中，如果我看到一组如下所示的日志消息：

DEBUG server: accepted connection from 106.42.126.8:56975
DEBUG server::http: received request
 WARN server::http: invalid request headers
DEBUG server: closing connection

我可以推断出 IP 地址为 106.42.126.8 的客户端的请求失败了，并且来自该客户端的连接随后被服务器关闭。 上下文 由之前的消息暗示：由于同步服务器必须先处理完每个请求，然后才能接受下一个连接，因此我们可以确定，在“接受连接...”消息之后和“关闭连接”消息之前发生的任何日志记录都与该连接相关。

然而，在像 Tokio 这样的异步系统中，解释传统的日志消息通常可能非常具有挑战性。异步系统中的单个线程可能正在执行任意数量的任务，并在它们之间切换，因为 IO 资源变得可用，并且应用程序可能由许多此类并发运行的工作线程组成。在这样的环境中，我们不能再依赖日志消息的顺序来确定上下文或因果关系。一个任务可能会记录一些消息并让出（yield），从而允许执行器轮询另一个任务，该任务记录其自身不相关的消息。来自并发运行线程的日志消息可能会交错打印出来。为了理解异步系统，上下文和因果关系必须显式记录，而不是由顺序暗示。

如果上面示例中的日志行是由异步应用程序发出的，则服务器任务可能继续接受新连接，而先前接受的连接正在由其他任务处理；多个请求可能由工作线程并发处理。我们可能会看到这样的情况：

DEBUG server: accepted connection from 106.42.126.8:56975
DEBUG server: closing connection
DEBUG server::http: received request
DEBUG server: accepted connection from 11.103.8.9:49123
DEBUG server::http: received request
DEBUG server: accepted connection from 102.12.37.105:51342
 WARN server::http: invalid request headers
TRACE server: closing connection

我们不再知道带有无效标头的请求是从 106.42.126.8 收到的。由于多个连接正在并发处理，因此无效标头可能是在我们等待从该客户端接收更多数据的同时在另一个连接上发送的。我们能做些什么来理解这种混乱呢？

传统的日志记录通常捕获关于程序的静态上下文——例如事件记录在哪个文件、模块或函数中——但这对于我们理解程序的运行时行为用处有限。相反，对异步代码的可见性需要跟踪事件发生的动态运行时上下文的诊断信息。

应用级 Tracing

tracing 不仅仅是一个日志库：它实现了作用域化、上下文化和结构化的诊断检测。这允许用户随着时间的推移跟踪应用程序中的逻辑上下文，即使实际的执行流程在这些上下文之间移动。

Span（跨度）

为了记录执行流程，tracing 引入了 span（跨度） 的概念。与表示时间点的日志行不同，span 模拟了一段时间，具有开始和结束。当程序开始在上下文中执行或执行一个工作单元时，它进入一个 span，当它停止在该上下文中执行时，它退出该 span。

在 span 进入和退出之间发生的任何事件都被认为发生在span 内。同样，span 可以嵌套：当一个线程在一个 span 内部进入另一个 span 时，它同时处于两个 span 中，新进入的 span 被视为子 span，外部 span 被视为父 span。然后，我们可以构建一个嵌套 span 树，并在程序的各个部分跟踪它们。

tracing 还支持事件，它们模拟瞬时的时间点。事件类似于传统的日志消息，但也存在于 span 树中。当我们记录一个事件时，我们可以精确定位它发生的上下文。

结构

通过将结构化数据附加到 span，我们可以对上下文进行建模。 tracing 检测点记录类型化的键值数据，称为字段，而不是简单地记录非结构化的、人类可读的消息。例如，在 HTTP 服务器中，表示已接受连接的 span 可能会记录客户端的 IP 地址、请求的路径、请求方法、标头等字段。如果我们重新审视上面的示例，并添加 span，我们可能会看到这样的情况：

DEBUG server{client.addr=106.42.126.8:56975}: accepted connection
DEBUG server{client.addr=82.5.70.2:53121}: closing connection
DEBUG server{client.addr=89.56.1.12:55601} request{path="/posts/tracing" method=GET}: received request
DEBUG server{client.addr=111.103.8.9:49123}: accepted connection
DEBUG server{client.addr=106.42.126.8:56975} request{path="/" method=PUT}: received request
DEBUG server{client.addr=113.12.37.105:51342}: accepted connection
 WARN server{client.addr=106.42.126.8:56975} request{path="/" method=PUT}: invalid request headers
TRACE server{client.addr=106.42.126.8:56975} request{path="/" method=PUT}: closing connection

请注意，事件是如何使用 span 注释的，这些 span 记录了客户端 IP 地址以及请求的路径和方法。尽管多个事件同时发生在不同的上下文中，但我们现在可以跟踪来自 106.42.126.8 的请求在系统中的流程，并确定是包含无效标头的请求生成了警告。

这种机器可读的结构化数据还使我们能够以比简单地将其格式化为供人阅读更复杂的方式使用诊断数据。例如，我们也可以通过计算接收到不同路径或 HTTP 方法的请求数量来使用上述数据。通过查看 span 树的结构以及键值数据，我们甚至可以执行诸如仅在请求以错误结束时才记录请求的整个生命周期之类的操作。

一个实际的例子

为了演示这种诊断的价值，让我们看一个例子。在此示例中，我们使用 tower 编写了一个小型 HTTP 服务，该服务实现了“字符重复即服务”。该服务接收由单个 ASCII 字符组成的路径的请求，并使用该字符重复多次响应，重复次数等于 Content-Length 标头的值。

我们使用 tracing 检测了示例服务，并使用 tracing-subscriber crate 实现了管理端点，该端点允许我们更改过滤器配置，该配置确定在运行时启用哪些 tracing 检测。负载生成器在后台运行，不断向演示服务发送随机字母字符的请求。

使用 log 和 env_logger crate 检测的示例服务版本，我们得到如下输出：

...
[DEBUG load_log] accepted connection from [::1]:55257
[DEBUG load_log] received request for path "/z"
[DEBUG load_log] accepted connection from [::1]:55258
[DEBUG load_log] received request for path "/Z"
[ERROR load_log] error received from server! status: 500
[DEBUG load_log] accepted connection from [::1]:55259
[DEBUG load_log] accepted connection from [::1]:55260
[DEBUG load_log] received request for path "/H"
[DEBUG load_log] accepted connection from [::1]:55261
[DEBUG load_log] received request for path "/S"
[DEBUG load_log] received request for path "/C"
[DEBUG load_log] accepted connection from [::1]:55262
[DEBUG load_log] received request for path "/x"
[DEBUG load_log] accepted connection from [::1]:55263
[DEBUG load_log] accepted connection from [::1]:55264
[WARN  load_log] path "/" not found; returning 404
[DEBUG load_log] accepted connection from [::1]:55265
[ERROR load_log] error received from server! status: 404
[DEBUG load_log] received request for path "/Q"
[DEBUG load_log] accepted connection from [::1]:55266
[DEBUG load_log] received request for path "/l"
...

由于服务处于负载状态，这些消息滚动得非常快。我在这里只包含了一小部分输出样本。

虽然错误确实显示在日志中，但很难将它们与任何可能帮助我们确定其原因的上下文联系起来。对于 404 错误，我们很幸运，服务器记录的警告行的添加者想到了在人类可读的日志消息中包含路径，但对于 500 错误，我们就茫然无措了。

现在，让我们切换到使用 tracing 检测的演示应用程序版本

...
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60891}: load: accepted connection
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60890}: load: accepted connection
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60891}:request{req.method=GET req.path="/I"}: load: received request. req.headers={"content-length": "18", "host": "[::1]:3000"} req.version=HTTP/1.1
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60890}:request{req.method=GET req.path="/T"}: load: received request. req.headers={"content-length": "4", "host": "[::1]:3000"} req.version=HTTP/1.1
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60892}: load: accepted connection
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60892}:request{req.method=GET req.path="/x"}: load: received request. req.headers={"content-length": "6", "host": "[::1]:3000"} req.version=HTTP/1.1
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60893}: load: accepted connection
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60895}:request{req.method=GET req.path="/"}: load: received request. req.headers={"content-length": "13", "host": "[::1]:3000"} req.version=HTTP/1.1
 WARN server{name=serve local=[::1]:3000}:conn{remote=[::1]:60895}:request{req.method=GET req.path="/"}: load: rsp.status=404
ERROR gen: error received from server! status=404
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60893}:request{req.method=GET req.path="/a"}: load: received request. req.headers={"content-length": "11", "host": "[::1]:3000"} req.version=HTTP/1.1
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60894}: load: accepted connection
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60894}:request{req.method=GET req.path="/V"}: load: received request. req.headers={"content-length": "12", "host": "[::1]:3000"} req.version=HTTP/1.1
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60896}: load: accepted connection
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60998}: load: accepted connection
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60996}:request{req.method=GET req.path="/z"}: load: received request. req.headers={"content-length": "17", "host": "[::1]:3000"} req.version=HTTP/1.1
ERROR gen: error received from server! status=500
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60987}: load: accepted connection
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60911}: load: accepted connection
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60911}:request{req.method=GET req.path="/m"}: load: received request. req.headers={"content-length": "7", "host": "[::1]:3000"} req.version=HTTP/1.1
DEBUG server{name=serve local=[::1]:3000}:conn{remote=[::1]:60912}: load: accepted connection
...

请注意，除了打印各个事件之外，还打印了它们发生的 span 上下文。特别是，每个连接和请求都会创建自己的 span。但是，这些事件记录得非常频繁，因此日志仍然滚动得非常快。

如果我们向演示应用程序的管理端点发送请求，我们可以重新加载过滤器配置，仅查看负载生成器记录的事件

:; curl -X PUT localhost:3001/filter -d "gen=debug"

这些过滤器的指定语法类似于 env_logger crate 的语法。

日志滚动的速度显着减慢，我们看到如下输出：

...
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: error received from server! status=404
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: error received from server! status=500
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: error received from server! status=500
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: error received from server! status=500
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: error received from server! status=500
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: error received from server! status=404
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: error received from server! status=500
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: error received from server! status=404
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: error received from server! status=404
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: error received from server! status=500
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: error received from server! status=404
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: error received from server! status=500
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: error received from server! status=404
...

查看负载生成器输出的 request span，我们开始注意到一个模式。 req.path 字段的值始终为 "/" 或 "/z"。

我们可以再次重新加载过滤器配置，仅当我们在具有字段 req.path 且值为 "/" 的 span 内时，才将详细程度设置为最大

:; curl -X PUT localhost:3001/filter -d "[{req.path=\"/\"}]=trace"

[] 表示我们希望过滤 tracing span 而不是静态目标，{} 表示我们想要匹配 span 字段。

...
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: sending request...
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: tower_buffer::service: sending request to buffer worker
DEBUG request{req.method=GET req.path="/"}: load: received request. req.headers={"content-length": "21", "host": "[::1]:3000"} req.version=HTTP/1.1
TRACE request{req.method=GET req.path="/"}: load: handling request...
TRACE request{req.method=GET req.path="/"}: load: rsp.error=path must be a single ASCII character
 WARN request{req.method=GET req.path="/"}: load: rsp.status=404
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: error received from server! status=404
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: response complete. rsp.body=path must be a single ASCII character
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: sending request...
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: tower_buffer::service: sending request to buffer worker
DEBUG request{req.method=GET req.path="/"}: load: received request. req.headers={"content-length": "18", "host": "[::1]:3000"} req.version=HTTP/1.1
TRACE request{req.method=GET req.path="/"}: load: handling request...
TRACE request{req.method=GET req.path="/"}: load: rsp.error=path must be a single ASCII character
 WARN request{req.method=GET req.path="/"}: load: rsp.status=404
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: error received from server! status=404
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: response complete. rsp.body=path must be a single ASCII character
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: gen: sending request...
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/"}: tower_buffer::service: sending request to buffer worker
DEBUG request{req.method=GET req.path="/"}: load: received request. req.headers={"content-length": "2", "host": "[::1]:3000"} req.version=HTTP/1.1
...

现在我们明白了发生了什么。该服务不支持对 / 的请求，并且非常正确地响应了 404。但是那些 500 错误呢？我们记得它们似乎只在请求的路径为“/z”时才会发生...

:; curl -X PUT localhost:3001/filter -d "[{req.path=\"/z\"}]=trace"

...
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: sending request...
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: tower_buffer::service: sending request to buffer worker
DEBUG request{req.method=GET req.path="/z"}: load: received request. req.headers={"content-length": "0", "host": "[::1]:3000"} req.version=HTTP/1.1
TRACE request{req.method=GET req.path="/z"}: load: handling request...
TRACE request{req.method=GET req.path="/z"}: load: error=i don't like this letter. letter="z"
TRACE request{req.method=GET req.path="/z"}: load: rsp.error=unknown internal error
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: error received from server! status=500
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: response complete. rsp.body=unknown internal error
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: sending request...
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: tower_buffer::service: sending request to buffer worker
DEBUG request{req.method=GET req.path="/z"}: load: received request. req.headers={"content-length": "16", "host": "[::1]:3000"} req.version=HTTP/1.1
TRACE request{req.method=GET req.path="/z"}: load: handling request...
TRACE request{req.method=GET req.path="/z"}: load: error=i don't like this letter. letter="z"
TRACE request{req.method=GET req.path="/z"}: load: rsp.error=unknown internal error
ERROR load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: error received from server! status=500
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: response complete. rsp.body=unknown internal error
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: gen: sending request...
TRACE load_gen{remote.addr=[::1]:3000}:request{req.method=GET req.path="/z"}: tower_buffer::service: sending request to buffer worker
DEBUG request{req.method=GET req.path="/z"}: load: received request. req.headers={"content-length": "24", "host": "[::1]:3000"} req.version=HTTP/1.1
TRACE request{req.method=GET req.path="/z"}: load: handling request...
TRACE request{req.method=GET req.path="/z"}: load: error=i don't like this letter. letter="z"
TRACE request{req.method=GET req.path="/z"}: load: rsp.error=unknown internal error
...

我们现在可以跟踪对 /z 的请求的整个生命周期，忽略同时发生的其他所有事情。并且，查看记录的事件，我们看到服务记录了“我不喜欢这个字母”并返回了一个内部错误。我们找到了（虽然确实是完全虚构的）错误！

这种动态过滤只有通过上下文感知的结构化诊断检测才有可能实现。因为嵌套 span 和事件使我们能够构建相关上下文的树，所以我们可以根据逻辑或因果关联（例如，它们在处理同一请求时发生）而不是时间关联（它们在时间上彼此靠近发生）来解释诊断信息。

如果您有兴趣查看生成这些日志的代码，或以交互方式体验此演示，可以在此处查看示例。

Tracing 入门

tracing 在 crates.io 上可用

tracing = "0.1.5"

开始使用 tracing 的最简单方法是在函数上使用 tracing::instrument 属性。此属性将检测该函数，以在调用该函数时创建并进入一个新的 span，并将该函数的参数记录为该 span 上的字段。例如：

use tracing::instrument;

#[instrument]
pub async fn connect_to(remote: SocketAddr) -> io::Result<TcpStream> {
    // ...
}

tracing 还提供了一组类似函数的宏，用于构造 span 和事件。 log crate 的用户应注意，tracing 的 trace!、debug!、info!、warn! 和 error! 宏是 log 中类似名称宏的超集，并且应该是可直接替换的

use log::info;

info!("hello world!");

use tracing::info;

info!("hello world!");

然而，更惯用的风格是使用这些宏来记录结构化数据，而不是非结构化消息。例如：

use tracing::trace;

let bytes_read = ...;
let num_processed = ...;

// ...

trace!(bytes_read, messages = num_processed);

Subscriber 实现收集和记录跟踪数据，类似于传统日志记录中的 logger。应用程序必须设置一个默认的 subscriber。

Subscriber 接口是 tracing 的主要扩展点；用于记录和处理跟踪数据的不同方法和策略可以表示为 Subscriber 实现。目前，tracing-fmt crate 提供了一个 Subscriber 实现，该实现将跟踪数据记录到控制台，并且更多实现即将推出。

更多 API 文档可在 docs.rs 上找到，示例在 tracing github 仓库中提供。

构建生态系统

tracing 生态系统以 tracing crate 为中心，该 crate 提供了用于检测库和应用程序的 API，以及 tracing-core，它提供了将检测与 Subscriber 连接所需的最小、稳定的功能内核。然而，这只是冰山一角。 tokio-rs/tracing 仓库包含许多额外的 crate，它们的稳定性各不相同。这些 crate 包括：

与其他库的兼容性层，例如 tracing-tower 和 tracing-log。
Subscriber 实现，例如 tracing-fmt。
tracing-subscriber crate，它提供了用于实现和组合 Subscriber 的实用程序。

中心 crate 的稳定版本已发布到 crates.io，并且 tracing 已经被 Linkerd 2 和 Vector 等项目采用。然而，未来还有很多工作要做，包括：

与分布式跟踪系统集成，例如 OpenTelemetry 或 Jaeger。
在 Tokio 运行时中构建更丰富的检测。
与更多库和框架集成。
编写 Subscriber 以实现更多收集跟踪数据的方式，例如指标、性能分析等。
帮助稳定实验性 crate。

欢迎在所有这些领域做出贡献。我们都期待看到社区将基于 tracing 提供的平台构建什么！

如果您有兴趣，请查看 GitHub 上的 tracing 仓库或加入 Gitter 聊天频道！

—Eliza Weisman