Rust使用 tracing 记录日志

使用 tracing 记录日志

严格来说，tracing 并不是一个日志库，而是一个分布式跟踪的 SDK，用于采集监控数据的。

随着微服务的流行，现在一个产品有多个系统组成是非常常见的，这种情况下，一条用户请求可能会横跨几个甚至几十个服务。此时再用传统的日志方式去跟踪这条用户请求就变得较为困难，这就是分布式追踪在现代化监控系统中这么炽手可热的原因。

关于分布式追踪，在后面的监控章节进行详细介绍，大家只要知道：分布式追踪的核心就是在请求的开始生成一个 trace_id，然后将该 trace_id 一直往后透穿，请求经过的每个服务都会使用该 trace_id 记录相关信息，最终将整个请求形成一个完整的链路予以记录下来。

那么后面当要查询这次请求的相关信息时，只要使用 trace_id 就可以获取整个请求链路的所有信息了，非常简单好用。看到这里，相信大家也明白为什么这个库的名称叫 tracing 了吧？

至于为何把它归到日志库的范畴呢？因为 tracing 支持 log 门面库的 API，因此，它既可以作为分布式追踪的 SDK 来使用，也可以作为日志库来使用。

在分布式追踪中，trace_id 都是由 SDK 自动生成和往后透穿，对于用户的使用来说是完全透明的。如果你要手动用日志的方式来实现请求链路的追踪，那么就必须考虑 trace_id 的手动生成、透传，以及不同语言之间的协议规范等问题

一个简单例子

开始之前，需要先将 tracing 添加到项目的 Cargo.toml 中:

[dependencies]
tracing = "0.1"

注意，在写作本文时，0.2 版本已经快要出来了，所以具体使用的版本请大家以阅读时为准。

下面的例子中将同时使用 log 和 tracing :

use log;
use tracing_subscriber::{
   fmt, layer::SubscriberExt, util::SubscriberInitExt};

fn main() {
   
    // 只有注册 subscriber 后， 才能在控制台上看到日志输出
    tracing_subscriber::registry()
        .with(fmt::layer())
        .init();
    
    // 调用 `log` 包的 `info!`
    log::info!("Hello world");
    
    let foo = 42;
    // 调用 `tracing` 包的 `info!`
    tracing::info!(foo, "Hello from tracing");
}

可以看出，门面库的排场还是有的，tracing 在 API 上明显是使用了 log 的规范。

运行后，输出如下日志:

2022-04-09T14:34:28.965952Z  INFO test_tracing: Hello world    
2022-04-09T14:34:28.966011Z  INFO test_tracing: Hello from tracing foo=42

还可以看出，log 的日志格式跟 tracing 一模一样，结合上一章节的知识，相信聪明的同学已经明白了这是为什么。

那么 tracing 跟 log 的具体日志实现框架有何区别呢？别急，我们再来接着看。

异步编程中的挑战

除了分布式追踪，在异步编程中使用传统的日志也是存在一些问题的，最大的挑战就在于异步任务的执行没有确定的顺序，那么输出的日志也将没有确定的顺序并混在一起，无法按照我们想要的逻辑顺序串联起来。

归根到底，在于日志只能针对某个时间点进行记录，缺乏上下文信息，而线程间的执行顺序又是不确定的，因此日志就有些无能为力。而 tracing 为了解决这个问题，引入了 span 的概念( 这个概念也来自于分布式追踪 )，一个 span 代表了一个时间段，拥有开始和结束时间，在此期间的所有类型数据、结构化数据、文本数据都可以记录其中。

大家发现了吗？ span 是可以拥有上下文信息的，这样就能帮我们把信息按照所需的逻辑性串联起来了。

核心概念

tracing 中最重要的三个概念是 Span、Event 和 Collector，下面我们来一一简单介绍下。

Span

相比起日志只能记录在某个时间点发生的事件，span 最大的意义就在于它可以记录一个过程，也就是在某一段时间内发生的事件流。既然是记录时间段，那自然有开始和结束:

use tracing::{
   span, Level};
fn main() {
   
    let span = span!(Level::TRACE, "my_span");

    // `enter` 返回一个 RAII ，当其被 drop 时，将自动结束该 span
    let enter = span.enter();
    // 这里开始进入 `my_span` 的上下文
    // 下面执行一些任务，并记录一些信息到 `my_span` 中
    // ...
} // 这里 enter 将被 drop，`my_span` 也随之结束

Event 事件

Event 代表了某个时间点发生的事件，这方面它跟日志类似，但是不同的是，Event 还可以产生在 span 的上下文中。

use tracing::{
   event, span, Level};
use tracing_subscriber::{
   fmt, layer::SubscriberExt, util::SubscriberInitExt};

fn main() {
   
    tracing_subscriber::registry().with(fmt::layer()).init();
    // 在 span 的上下文之外记录一次 event 事件
    event!(Level::INFO, "something happened");

    let span = span!(Level::INFO, "my_span");
    let _guard = span.enter();

    // 在 "my_span" 的上下文中记录一次 event
    event!(Level::DEBUG, "something happened inside my_span");
}

2022-04-09T14:51:38.382987Z  INFO test_tracing: something happened
2022-04-09T14:51:38.383111Z DEBUG my_span: test_tracing: something happened inside my_span

虽然 event 在哪里都可以使用，但是最好只在 span 的上下文中使用：用于代表一个时间点发生的事件，例如记录 HTTP 请求返回的状态码，从队列中获取一个对象，等等。

Collector 收集器

当 Span 或 Event 发生时，它们会被实现了 Collect 特征的收集器所记录或聚合。这个过程是通过通知的方式实现的：当 Event 发生或者 Span 开始/结束时，会调用 Collect 特征的相应方法通知 Collector。

tracing-subscriber

我们前面提到只有使用了 tracing-subscriber 后，日志才能输出到控制台中。

之前大家可能还不理解，现在应该明白了，它是一个 Collector，可以将记录的日志收集后，再输出到控制台中。

使用方法

span! 宏

span! 宏可以用于创建一个 Span 结构体，然后通过调用结构体的 enter 方法来开始，再通过超出作用域时的 drop 来结束。

use tracing::{
   span, Level};
fn main() {
   
    let span = span!(Level::TRACE, "my_span");

    // `enter` 返回一个 RAII ，当其被 drop 时，将自动结束该 span
    let enter = span.enter();
    // 这里开始进入 `my_span` 的上下文
    // 下面执行一些任务，并记录一些信息到 `my_span` 中
    // ...
} // 这里 enter 将被 drop，`my_span` 也随之结束