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` 也随之结束

#[instrument]

如果想要将某个函数的整个函数体都设置为 span 的范围，最简单的方法就是为函数标记上 #[instrument]，此时 tracing 会自动为函数创建一个 span，span 名跟函数名相同，在输出的信息中还会自动带上函数参数。

use tracing::{info, instrument};
use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};

#[instrument]
fn foo(ans: i32) {
    info!("in foo");
}

fn main() {
    tracing_subscriber::registry().with(fmt::layer()).init();
    foo(42);
}

2022-04-10T02:44:12.885556Z  INFO foo{ans=42}: test_tracing: in foo

关于 #[instrument] 详细说明，请参见官方文档。

in_scope

对于没有内置 tracing 支持或者无法使用 #instrument 的函数，例如外部库的函数，我们可以使用 Span 结构体的 in_scope 方法，它可以将同步代码包裹在一个 span 中：

use tracing::info_span;

let json = info_span!("json.parse").in_scope(|| serde_json::from_slice(&buf))?;

在 async 中使用 span

需要注意，如果是在异步编程时使用，要避免以下使用方式:

async fn my_async_function() {
    let span = info_span!("my_async_function");

    // WARNING: 该 span 直到 drop 后才结束，因此在 .await 期间，span 依然处于工作中状态
    let _enter = span.enter();

    // 在这里 span 依然在记录，但是 .await 会让出当前任务的执行权，然后运行时会去运行其它任务，此时这个 span 可能会记录其它任务的执行信息，最终记录了不正确的 trace 信息
    some_other_async_function().await

    // ...
}

我们建议使用以下方式，简单又有效:

use tracing::{info, instrument};
use tokio::{io::AsyncWriteExt, net::TcpStream};
use std::io;

#[instrument]
async fn write(stream: &mut TcpStream) -> io::Result<usize> {
    let result = stream.write(b"hello world\n").await;
    info!("wrote to stream; success={:?}", result.is_ok());
    result
}

那有同学可能要问了，是不是我们无法在异步代码中使用 span.enter 了，答案是：是也不是。

是，你无法直接使用 span.enter 语法了，原因上面也说过，但是可以通过下面的方式来曲线使用：

use tracing::Instrument;

let my_future = async {
    // ...
};

my_future
    .instrument(tracing::info_span!("my_future"))
    .await

span 嵌套

tracing 的 span 不仅仅是上面展示的基本用法，它们还可以进行嵌套！

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

fn main() {
    tracing_subscriber::registry().with(fmt::layer()).init();

    let scope = span!(Level::DEBUG, "foo");
    let _enter = scope.enter();
    info!("Hello in foo scope");
    debug!("before entering bar scope"); 
    {
        let scope = span!(Level::DEBUG, "bar", ans = 42);
        let _enter = scope.enter();
        debug!("enter bar scope");
        info!("In bar scope");
        debug!("end bar scope");
    }
    debug!("end bar scope");
}

INFO foo: log_test: Hello in foo scope
DEBUG foo: log_test: before entering bar scope
DEBUG foo:bar{ans=42}: log_test: enter bar scope
INFO foo:bar{ans=42}: log_test: In bar scope
DEBUG foo:bar{ans=42}: log_test: end bar scope
DEBUG foo: log_test: end bar scope

在上面的日志中，foo:bar 不仅包含了 foo 和 bar span 名，还显示了它们之间的嵌套关系。

对宏进行配置

日志级别和目标

span! 和 event! 宏都需要设定相应的日志级别，而且它们支持可选的 target 或 parent 参数( 只能二者选其一 )，该参数用于描述事件发生的位置，如果父 span 没有设置，target 参数也没有提供，那这个位置默认分别是当前的 span 和 当前的模块。

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

fn main() {
    tracing_subscriber::registry().with(fmt::layer()).init();

    let s = span!(Level::TRACE, "my span");
    // 没进入 span，因此输出日志将不会带上 span 的信息
    event!(target: "app_events", Level::INFO, "something has happened 1!");

    // 进入 span ( 开始 )
    let _enter = s.enter();
    // 没有设置 target 和 parent
    // 这里的对象位置分别是当前的 span 名和模块名
    event!(Level::INFO, "something has happened 2!");
    // 设置了 target
    // 这里的对象位置分别是当前的 span 名和 target
    event!(target: "app_events",Level::INFO, "something has happened 3!");

    let span = span!(Level::TRACE, "my span 1");
    // 这里就更为复杂一些，留给大家作为思考题
    event!(parent: &span, Level::INFO, "something has happened 4!");
}

记录字段

我们可以通过语法 field_name = field_value 来输出结构化的日志

// 记录一个事件，带有两个字段:
//  - "answer", 值是 42
//  - "question", 值是 "life, the universe and everything"
event!(Level::INFO, answer = 42, question = "life, the universe, and everything");

// 日志输出 -> INFO test_tracing: answer=42 question="life, the universe, and everything"

捕获环境变量

还可以捕获环境中的变量:

let user = "ferris";

// 下面的简写方式
span!(Level::TRACE, "login", user);
// 等价于:
span!(Level::TRACE, "login", user = user);

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

fn main() {
    tracing_subscriber::registry().with(fmt::layer()).init();

    let user = "ferris";
    let s = span!(Level::TRACE, "login", user);
    let _enter = s.enter();

    info!(welcome="hello", user);
    // 下面一行将报错，原因是这种写法是格式化字符串的方式，必须使用 info!("hello {}", user)
    // info!("hello", user);
}

// 日志输出 -> INFO login{user="ferris"}: test_tracing: welcome="hello" user="ferris"

字段名的多种形式

字段名还可以包含 . :

let user = "ferris";
let email = "ferris@rust-lang.org";
event!(Level::TRACE, user, user.email = email);

// 还可以使用结构体
let user = User {
    name: "ferris",
    email: "ferris@rust-lang.org",
};

// 直接访问结构体字段，无需赋值即可使用
span!(Level::TRACE, "login", user.name, user.email);

// 字段名还可以使用字符串
event!(Level::TRACE, "guid:x-request-id" = "abcdef", "type" = "request");

// 日志输出 -> 
// TRACE test_tracing: user="ferris" user.email="ferris@rust-lang.org"
// TRACE test_tracing: user.name="ferris" user.email="ferris@rust-lang.org"
// TRACE test_tracing: guid:x-request-id="abcdef" type="request"

?

? 符号用于说明该字段将使用 fmt::Debug 来格式化。

 #[derive(Debug)]
struct MyStruct {
    field: &'static str,
}

let my_struct = MyStruct {
    field: "Hello world!",
};

// `my_struct` 将使用 Debug 的形式输出
event!(Level::TRACE, greeting = ?my_struct);
// 等价于:
event!(Level::TRACE, greeting = tracing::field::debug(&my_struct));

// 下面代码将报错, my_struct 没有实现 Display
// event!(Level::TRACE, greeting = my_struct);

// 日志输出 -> TRACE test_tracing: greeting=MyStruct { field: "Hello world!" }

%

% 说明字段将用 fmt::Display 来格式化。

// `my_struct.field` 将使用 `fmt::Display` 的格式化形式输出
event!(Level::TRACE, greeting = %my_struct.field);
// 等价于:
event!(Level::TRACE, greeting = tracing::field::display(&my_struct.field));

// 作为对比，大家可以看下 Debug 和正常的字段输出长什么样
event!(Level::TRACE, greeting = ?my_struct.field);
event!(Level::TRACE, greeting = my_struct.field);

// 下面代码将报错, my_struct 没有实现 Display
// event!(Level::TRACE, greeting = %my_struct);

2022-04-10T03:49:00.834330Z TRACE test_tracing: greeting=Hello world!
2022-04-10T03:49:00.834410Z TRACE test_tracing: greeting=Hello world!
2022-04-10T03:49:00.834422Z TRACE test_tracing: greeting="Hello world!"
2022-04-10T03:49:00.834433Z TRACE test_tracing: greeting="Hello world!"

Empty

字段还能标记为 Empty，用于说明该字段目前没有任何值，但是可以在后面进行记录。

use tracing::{trace_span, field};

let span = trace_span!("my_span", greeting = "hello world", parting = field::Empty);

// ...

// 现在，为 parting 记录一个值
span.record("parting", &"goodbye world!");

格式化字符串

除了以字段的方式记录信息，我们还可以使用格式化字符串的方式( 同 println! 、format! )。

注意，当字段跟格式化的方式混用时，必须把格式化放在最后，如下所示

let question = "the ultimate question of life, the universe, and everything";
let answer = 42;
event!(
    Level::DEBUG,
    question.answer = answer,
    question.tricky = true,
    "the answer to {} is {}.", question, answer
);

// 日志输出 -> DEBUG test_tracing: the answer to the ultimate question of life, the universe, and everything is 42. question.answer=42 question.tricky=true

文件输出

截至目前，我们上面的日志都是输出到控制台中。

针对文件输出，tracing 提供了一个专门的库 tracing-appender，大家可以查看官方文档了解更多。

一个综合例子

最后，再来看一个综合的例子，使用了 color-eyre 和 文件输出，前者用于为输出的日志加上更易读的颜色。

use color_eyre::{eyre::eyre, Result};
use tracing::{error, info, instrument};
use tracing_appender::{non_blocking, rolling};
use tracing_error::ErrorLayer;
use tracing_subscriber::{
    filter::EnvFilter, fmt, layer::SubscriberExt, util::SubscriberInitExt, Registry,
};

#[instrument]
fn return_err() -> Result<()> {
    Err(eyre!("Something went wrong"))
}

#[instrument]
fn call_return_err() {
    info!("going to log error");
    if let Err(err) = return_err() {
        // 推荐大家运行下，看看这里的输出效果
        error!(?err, "error");
    }
}

fn main() -> Result<()> {
    let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));
    // 输出到控制台中
    let formatting_layer = fmt::layer().pretty().with_writer(std::io::stderr);
    
    // 输出到文件中
    let file_appender = rolling::never("logs", "app.log");
    let (non_blocking_appender, _guard) = non_blocking(file_appender);
    let file_layer = fmt::layer()
        .with_ansi(false)
        .with_writer(non_blocking_appender);
        
    // 注册
    Registry::default()
        .with(env_filter)
        // ErrorLayer 可以让 color-eyre 获取到 span 的信息
        .with(ErrorLayer::default())
        .with(formatting_layer)
        .with(file_layer)
        .init();
    
    // 安裝 color-eyre 的 panic 处理句柄 
    color_eyre::install()?;

    call_return_err();

    Ok(())
}

总结 & 推荐

至此，tracing 的介绍就已结束，相信大家都看得出，它比上个章节的 log 及兄弟们要更加复杂一些，一方面是因为它能更好的支持异步编程环境，另一方面就是它还是一个分布式追踪的库，对于后者，我们将在后续的监控章节进行讲解。

如果你让我推荐使用哪个，那我的建议是:

• 对于简单的工程，例如用于 POC（ Proof of Concepts ） 目的，使用 log 即可
• 对于需要认真对待，例如生产级或优秀的开源项目，建议使用 tracing 的方式，一举解决日志和监控的后顾之忧

推荐几款学习编程的免费平台

免费在线开发平台（https://docs.ltpp.vip/LTPP/）

       探索编程世界的新天地，为学生和开发者精心打造的编程平台，现已盛大开启！这个平台汇集了近4000道精心设计的编程题目，覆盖了C、C++、JavaScript、TypeScript、Go、Rust、PHP、Java、Ruby、Python3以及C#等众多编程语言，为您的编程学习之旅提供了一个全面而丰富的实践环境。       
      在这里，您不仅可以查看自己的代码记录，还能轻松地在云端保存和运行代码，让编程变得更加便捷。平台还提供了私聊和群聊功能，让您可以与同行们无障碍交流，分享文件，共同进步。不仅如此，您还可以通过阅读文章、参与问答板块和在线商店，进一步拓展您的知识边界。
       为了提升您的编程技能，平台还设有每日一题、精选题单以及激动人心的编程竞赛，这些都是备考编程考试的绝佳资源。更令人兴奋的是，您还可以自定义系统UI，选择视频或图片作为背景，打造一个完全个性化的编码环境，让您的编程之旅既有趣又充满挑战。

免费公益服务器（https://docs.ltpp.vip/LTPP-SHARE/linux.html）

       作为开发者或学生，您是否经常因为搭建和维护编程环境而感到头疼？现在，您不必再为此烦恼，因为一款全新的免费公共服务器已经为您解决了所有问题。这款服务器内置了多种编程语言的编程环境，并且配备了功能强大的在线版VS Code，让您可以随时随地在线编写代码，无需进行任何复杂的配置。
随时随地，云端编码
       无论您身在何处，只要有网络连接，就可以通过浏览器访问这款公共服务器，开始您的编程之旅。这种云端编码的便利性，让您的学习或开发工作不再受限于特定的设备或环境。
丰富的编程语言支持
       服务器支持包括C、C++、JavaScript、TypeScript、Go、Rust、PHP、Java、Ruby、Python3以及C#等在内的多种主流编程语言，满足不同开发者和学生的需求。无论您是初学者还是资深开发者，都能找到适合自己的编程环境。
在线版VS Code，高效开发
       内置的在线版VS Code提供了与本地VS Code相似的编辑体验，包括代码高亮、智能提示、代码调试等功能，让您即使在云端也能享受到高效的开发体验。
数据隐私和安全提醒
       虽然服务器是免费的，但为了保护您的数据隐私和安全，我们建议您不要上传任何敏感或重要的数据。这款服务器更适合用于学习和实验，而非存储重要信息。

免费公益MYSQL（https://docs.ltpp.vip/LTPP-SHARE/mysql.html）

       作为一名开发者或学生，数据库环境的搭建和维护往往是一个复杂且耗时的过程。但不用担心，现在有一款免费的MySQL服务器，专为解决您的烦恼而设计，让数据库的使用变得简单而高效。
性能卓越，满足需求
       虽然它是免费的，但性能绝不打折。服务器提供了稳定且高效的数据库服务，能够满足大多数开发和学习场景的需求。
在线phpMyAdmin，管理更便捷
       内置的在线phpMyAdmin管理面板，提供了一个直观且功能强大的用户界面，让您可以轻松地查看、编辑和管理数据库。
数据隐私提醒，安全第一
       正如您所知，这是一项公共资源，因此我们强烈建议不要上传任何敏感或重要的数据。请将此服务器仅用于学习和实验目的，以确保您的数据安全。

免费在线WEB代码编辑器（https://docs.ltpp.vip/LTPP-WEB-IDE/）

       无论你是开发者还是学生，编程环境的搭建和管理可能会占用你宝贵的时间和精力。现在，有一款强大的免费在线代码编辑器，支持多种编程语言，让您可以随时随地编写和运行代码，提升编程效率，专注于创意和开发。
多语言支持，无缝切换
       这款在线代码编辑器支持包括C、C++、JavaScript、TypeScript、Go、Rust、PHP、Java、Ruby、Python3以及C#在内的多种编程语言，无论您的项目需要哪种语言，都能在这里找到支持。
在线运行，快速定位问题
       您可以在编写代码的同时，即时运行并查看结果，快速定位并解决问题，提高开发效率。
代码高亮与智能提示
       编辑器提供代码高亮和智能提示功能，帮助您更快地编写代码，减少错误，提升编码质量。

免费二维码生成器（https://docs.ltpp.vip/LTPP-QRCODE/）

       二维码（QR Code）是一种二维条码，能够存储更多信息，并且可以通过智能手机等设备快速扫描识别。它广泛应用于各种场景，如：
企业宣传
       企业可以通过二维码分享公司网站、产品信息、服务介绍等。
活动推广
       活动组织者可以创建二维码，参与者扫描后可以直接访问活动详情、报名链接或获取电子门票。
个人信息分享
       个人可以生成包含联系方式、社交媒体链接、个人简历等信息的二维码。
电子商务
       商家使用二维码进行商品追踪、促销活动、在线支付等。
教育
       教师可以创建二维码，学生扫描后可以直接访问学习资料或在线课程。
交通出行
       二维码用于公共交通的票务系统，乘客扫描二维码即可进出站或支付车费。        功能强大的二维码生成器通常具备用户界面友好，操作简单，即使是初学者也能快速上手和生成的二维码可以在各种设备和操作系统上扫描识别的特点。