Rust使用 tracing 输出自定义的 Rust 日志

使用 tracing 输出自定义的 Rust 日志

在 tracing 包出来前，Rust 的日志也就 log 有一战之力，但是 log 的功能相对来说还是简单一些。在大名鼎鼎的 tokio 开发团队推出 tracing 后，我现在坚定的认为 tracing 就是未来！

截至目前，rust编译器团队、GraphQL 都在使用 tracing，而且 tokio 在密谋一件大事：基于 tracing 开发一套终端交互式 debug 工具: console！

基于这种坚定的信仰，我们决定将公司之前使用的 log 包替换成 tracing ，但是有一个问题：后者提供的 JSON logger 总感觉不是那个味儿。这意味着，对于程序员来说，最快乐的时光又要到来了：定制自己的开发工具。

好了，闲话少说，下面我们一起来看看该如何构建自己的 logger，以及深入了解 tracing 的一些原理，当然你也可以只选择来凑个热闹，总之，开始吧！

打地基(1)

首先，使用 cargo new --bin test-tracing 创建一个新的二进制类型( binary )的项目。

然后引入以下依赖：

# in cargo.toml

[dependencies]
serde_json = "1"
tracing = "0.1"
tracing-subscriber = "0.3"

其中 tracing-subscriber 用于订阅正在发生的日志、监控事件，然后可以对它们进行进一步的处理。serde_json 可以帮我们更好的处理格式化的 JSON，毕竟咱们要解决的问题就来自于 JSON logger。

下面来实现一个基本功能：设置自定义的 logger，并使用 info! 来打印一行日志。

// in examples/figure_0/main.rs

use tracing::info;
use tracing_subscriber::prelude::*;

mod custom_layer;
use custom_layer::CustomLayer;

fn main() {
   
    // 设置 `tracing-subscriber` 对 tracing 数据的处理方式
    tracing_subscriber::registry().with(CustomLayer).init();

    // 打印一条简单的日志。用 `tracing` 的行话来说，`info!` 将创建一个事件
    info!(a_bool = true, answer = 42, message = "first example");
}

大家会发现，上面引入了一个模块 custom_layer， 下面从该模块开始，来实现我们的自定义 logger。首先，tracing-subscriber 提供了一个特征 Layer 专门用于处理 tracing 的各种事件( span, event )。

// in examples/figure_0/custom_layer.rs

use tracing_subscriber::Layer;

pub struct CustomLayer;

impl<S> Layer<S> for CustomLayer where S: tracing::Subscriber {
   }

由于还没有填入任何代码，运行该示例比你打的水漂还无力 - 毫无效果。

捕获事件

在 tracing 中，当 info!、error! 等日志宏被调用时，就会产生一个相应的事件 Event。

而我们首先，就要为之前的 Layer 特征实现 on_event 方法。

// in examples/figure_0/custom_layer.rs

where
    S: tracing::Subscriber,
{
    fn on_event(
        &self,
        event: &tracing::Event<'_>,
        _ctx: tracing_subscriber::layer::Context<'_, S>,
    ) {
        println!("Got event!");
        println!("  level={:?}", event.metadata().level());
        println!("  target={:?}", event.metadata().target());
        println!("  name={:?}", event.metadata().name());
        for field in event.fields() {
            println!("  field={}", field.name());
        }
    }
}

从代码中可以看出，我们打印了事件中包含的事件名、日志等级以及事件发生的代码路径。运行后，可以看到以下输出:

$ cargo run --example figure_1

Got event!
  level=Level(Info)
  target="figure_1"
  name="event examples/figure_1/main.rs:10"
  field=a_bool
  field=answer
  field=message

但是奇怪的是，我们无法通过 API 来获取到具体的 field 值。还有就是，上面的输出还不是 JSON 格式。

现在问题来了，要创建自己的 logger，不能获取 filed 显然是不靠谱的。

访问者模式

在设计上，tracing 作出了一个选择：永远不会自动存储产生的事件数据( spans, events )。如果我们要获取这些数据，就必须自己手动存储。

解决办法就是使用访问者模式(Visitor Pattern)：手动实现 Visit 特征去获取事件中的值。Visit 为每个 tracing 可以处理的类型都提供了对应的 record_X 方法。

// in examples/figure_2/custom_layer.rs

struct PrintlnVisitor;

impl tracing::field::Visit for PrintlnVisitor {
   
    fn record_f64(&mut self, field: &tracing::field::Field, value: f64) {
   
        println!("  field={} value={}", field.name(), value)
    }

    fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
   
        println!("  field={} value={}", field.name(), value)
    }

    fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
   
        println!("  field={} value={}", field.name(), value)
    }

    fn record_bool(&mut self, field: &tracing::field::Field, value: bool) {
   
        println!("  field={} value={}", field.name(), value)
    }

    fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
   
        println!("  field={} value={}", field.name(), value)
    }

    fn record_error(
        &mut self,
        field: &tracing::field::Field,
        value: &(dyn std::error::Error + 'static),
    ) {
   
        println!("  field={} value={}", field.name(), value)
    }

    fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
   
        println!("  field={} value={:?}", field.name(), value)
    }
}

然后在之前的 on_event 中来使用这个新的访问者： event.record(&mut visitor) 可以访问其中的所有值。

// in examples/figure_2/custom_layer.rs

fn on_event(
    &self,
    event: &tracing::Event<'_>,
    _ctx: tracing_subscriber::layer::Context<'_, S>,
) {
   
    println!("Got event!");
    println!("  level={:?}"