Rust日志记录 - Rust入门秘籍

tracing简要说明

tracing可以记录结构化的日志，可以按区间(span)记录日志，例如一个函数可以作为一个区间单元，也可以自行指定何时进入(span.enter())区间单元
tracing有TRACE DEBUG INFO WARN ERROR共5个日志级别，其中TRACE是最详细的级别
tracing crate提供了最基本的核心功能：
- span：区间单元，具有区间的起始时间和区间的结束位置，是一个有时间跨度的区间
- span!()创建一个span区间，span.enter()表示进入span区间，drop span的时候退出span区间
- event: 每一次事件，都是一条记录，也可以看作是一条日志
- event!()记录某个指定日志级别的日志信息，event!(Level::INFO, "something happened!");
- trace!() debug!() info!() warn!() error!()，是event!()的语法糖，可以无需再指定日志级别
记录日志时，可以记录结构化数据，以key=value的方式提供和记录。例如：trace!(num = 33, "hello world")，将记录为"num = 33 hello worl"。支持哪些格式，参考https://docs.rs/tracing/latest/tracing/index.html#recording-fields
tracing crate自身不会记录日志，它只是发出event!()或类似宏记录的日志，发出日志后，还需要通过tracing subscriber来收集
在可执行程序(例如main函数)中，需要初始化subscriber，而在其它地方(如库或函数中)，只需使用那些宏来发出日志即可。发日志和收集记录日志分开，使得日志的处理逻辑非常简洁
初始化subscriber的时候，可筛选收集到的日志(例如指定过滤哪些级别的日志)、格式化收集到的日志(例如修改时间格式)、指定日志的输出位置，等等
默认清空下，subscribe的默认输出位置是标准输出，但可以在初始化时改变目标位置。如果需要写入文件，可使用tracing_appender crate
- 需注意，使用tracing_appender时，因为是先缓冲日志信息，而不是直接写入文件。他要求必须在main()函数中使用Guard，否则guard被丢弃将不会写入任何信息到文件

示例

Cargo.toml：

[package]
name = "log"
version = "0.1.0"
edition = "2021"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[dependencies]
chrono = "0.4.19"
tracing = "0.1.29"
tracing-appender = "0.2.0"
tracing-subscriber = { version = "0.3.3" }

src/main.rs：

use chrono::Local;
use std::io;
use tracing::*;
use tracing_subscriber::fmt::format::Writer;
use tracing_subscriber::{self, fmt::time::FormatTime};

// 用来格式化日志的输出时间格式
struct LocalTimer;

impl FormatTime for LocalTimer {
    fn format_time(&self, w: &mut Writer<'_>) -> std::fmt::Result {
        write!(w, "{}", Local::now().format("%FT%T%.3f"))
    }
}

// 通过instrument属性，直接让整个函数或方法进入span区间，且适用于异步函数async fn fn_name(){}
// 参考：https://docs.rs/tracing/latest/tracing/attr.instrument.html
// #[tracing::instrument(level = "info")]
#[instrument]
fn test_trace(n: i32) {
    // #[instrument]属性表示函数整体在一个span区间内，因此函数内的每一个event信息中都会额外带有函数参数
    // 在函数中，只需发出日志即可
    event!(Level::TRACE, answer = 42, "trace2: test_trace");
    trace!(answer = 42, "trace1: test_trace");
    info!(answer = 42, "info1: test_trace");
}

// 在可执行程序中，需初始化tracing subscriber来收集、筛选并按照指定格式来记录日志
fn main() {
    // 直接初始化，采用默认的Subscriber，默认只输出INFO、WARN、ERROR级别的日志
    // tracing_subscriber::fmt::init();

    // 使用tracing_appender，指定日志的输出目标位置
    // 参考: https://docs.rs/tracing-appender/0.2.0/tracing_appender/
    // 如果不是在main函数中，guard必须返回到main()函数中，否则不输出任何信息到日志文件
    let file_appender = tracing_appender::rolling::daily("/tmp", "tracing.log");
    let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender);

    // 设置日志输出时的格式，例如，是否包含日志级别、是否包含日志来源位置、设置日志的时间格式
    // 参考: https://docs.rs/tracing-subscriber/0.3.3/tracing_subscriber/fmt/struct.SubscriberBuilder.html#method.with_timer
    let format = tracing_subscriber::fmt::format()
        .with_level(true)
        .with_target(true)
        .with_timer(LocalTimer);

    // 初始化并设置日志格式(定制和筛选日志)
    tracing_subscriber::fmt()
        .with_max_level(Level::TRACE)
        .with_writer(io::stdout) // 写入标准输出
        .with_writer(non_blocking) // 写入文件，将覆盖上面的标准输出
        .with_ansi(false)  // 如果日志是写入文件，应将ansi的颜色输出功能关掉
        .event_format(format)
        .init();  // 初始化并将SubScriber设置为全局SubScriber

    test_trace(33);
    trace!("tracing-trace");
    debug!("tracing-debug");
    info!("tracing-info");
    warn!("tracing-warn");
    error!("tracing-error");
}

输出(上面设置了输出到文件/tmp/tracing.log)：

// 其中出现的log，是target
2021-12-01T15:09:55.797 TRACE test_trace{n=33}: log: trace1: test_trace answer=42
2021-12-01T15:09:55.797 TRACE test_trace{n=33}: log: trace2: test_trace answer=42
2021-12-01T15:09:55.797 TRACE log: tracing-trace
2021-12-01T15:09:55.797 DEBUG log: tracing-debug
2021-12-01T15:09:55.797  INFO log: tracing-info
2021-12-01T15:09:55.797  WARN log: tracing-warn
2021-12-01T15:09:55.797 ERROR log: tracing-error

不同区域使用不同日志

有时候有需求区分不同的日志，或者不同区域使用不同格式的日志。例如：

#![allow(unused)]
fn main() {
// 先创建一个SubScriber，准备作为默认的全局SubScriber
// finish()将完成SubScriber的构建，返回一个SubScriber
let default_logger = tracing_subscriber::fmt().with_max_level(Level::DEBUG).finish();

// 这段代码不记录任何日志，因为还未开启全局SubScriber
{
    info!("nothing will log");
}

// 从此开始，将default_logger设置为全局SubScriber
default_logger.init(); 

// 创建一个无颜色显示的且只记录ERROR级别的SubScriber
let tmp_logger = tracing_subscriber::fmt()
    .with_ansi(false)
    .with_max_level(Level::ERROR)
    .finish();
// 使用with_default，可将某段代码使用指定的SubScriber而非全局的SubScriber进行日志记录
tracing::subscriber::with_default(tmp_logger, || {
    error!("log with tmp_logger, only log ERROR logs");
});
info!("log with Global logger");
}

因为init()方法会调用set_global_default()，使得指定的Subscriber被设置为所有线程的全局Subscriber，所有的日志记录都会被该全局Subscriber给接收。如果想要在某个局部位置改变日志记录的目标(Subscriber)，甚至在某个位置丢弃所有日志记录，可以参考如下方式：

#![allow(unused)]
fn main() {
// 设置全局Subscriber，从WARN级别开始记录
tracing_subscriber::fmt()
    .with_max_level(tracing::Level::WARN)
    .init();

// 创建一个不调用init()方法的Subscriber，从TRACE级别开始记录
let sc = tracing_subscriber::fmt()
    .with_max_level(Level::TRACE)
    .finish();
// 指定局部范围的Subscriber
tracing::subscriber::with_default(sc, || {
    // 即便全局Subscriber是WARN级别的，但这条记录仍然会被记录
    tracing::info!("This will be logged to stdout");
});

// NoSubscriber是不记录任何日志记录的Subscriber，它会丢弃所有数据
let sc = tracing::subscriber::NoSubscriber::default();
tracing::subscriber::with_default(sc, || {
    // 不会被记录
    tracing::info!("This will be logged to stdout");
});
}

不同crate使用不同级别的日志

有时候我们自己想设置日志级别为debug来调试我们自己的程序，但这也会把其它所引用依赖的crate中的debug的日志输出出来。特别是有些时候其它crate的输出内容非常非常多，这很不友好。

通过开启tracing-subscriber的env-filter特性，可以按crate来设置不同日志级别。

tracing-subscriber = { version = "0.3", features = ["env-filter"] }

然后设置：

#![allow(unused)]
fn main() {
tracing_subscriber::fmt()
        .with_env_filter(EnvFilter::from_default_env())
        .with_target(false)
        .with_file(true)
        .with_line_number(true)
        .with_ansi(false)
        .init();
}

使用EnvFilter::from_default_env()后，将读取RUST_LOG环境变量来设置日志级别。

可以是简单的格式，也可以是复杂的格式。假设我们自己的crate名叫crate_a，引用了一个名为crate_b的包。示例如下：

# 我们自己的以及所依赖的所有crate的日志级别都设置为debug
RUST_LOG=debug cargo run --release

# 关闭其它所有crate的输出，只设置自己的crate的级别为debug
RUST_LOG=none,crate_a=debug cargo run --release

# 默认级别为info，但我们自己的crate为debug
RUST_LOG=info,crate_a=debug cargo run --release

# 默认级别为debug，但关闭crate_b的日志
RUST_LOG=debug,crate_b=off cargo run --release

修改日志记录的时区

默认情况下，tracing-subscriber记录的时间是UTC时间，而不会主动输出为本机设置的时区对应的时间。但是对于东八区的我们来说，希望记录的是东八区的时间。

前面示例中提供了一种修改为本地时间的方式，并且是基于chrono crate而不是默认的time crate来设置tracing-subscriber的日志时间的时区和格式：

use tracing_subscriber::{
    self,
    fmt::{format::Writer, time::FormatTime},
};

// 用来格式化日志的输出时间格式
struct LocalTimer;

impl FormatTime for LocalTimer {
    fn format_time(&self, w: &mut Writer<'_>) -> std::fmt::Result {
        write!(w, "{}", chrono::Local::now().format("%FT%T%.3f"))
    }
}

fn main() {
    tracing_subscriber::fmt().with_timer(LocalTimer).init();

    tracing::info!("hello world");
}

但注意，使用chrono::Local::now()的效率相对会差一些，因为每次获取时间都要探测本机的时区。因此可改进为使用Offset的方式，明确指定时区，无需探测：

#![allow(unused)]
fn main() {
struct LocalTimer;

const fn east8() -> Option<chrono::FixedOffset> {
    chrono::FixedOffset::east_opt(8 * 3600)
}

impl FormatTime for LocalTimer {
    fn format_time(&self, w: &mut Writer<'_>) -> std::fmt::Result {
        let now = chrono::Utc::now().with_timezone(&east8().unwrap());
        write!(w, "{}", now.format("%FT%T%.3f"))
    }
}
}

当然，还有其它一些方式设置tracing-subscriber日志时间的时区和格式。例如可以通过它的fmt::time::OffsetTime指定时区，不过它使用的是time crate，因此如果记录非UTC时区，则先设置Cargo.toml：

tracing-subscriber = {version = "0.3", features = ["time"]}
time = { version = "0.3", features = ["macros"] }

然后设置日志时间的时区和格式：

use time::macros::{format_description, offset};
use tracing_subscriber::fmt::time::OffsetTime;

fn main() {
    let time_fmt = format_description!("[year]-[month]-[day]T[hour]:[minute]:[second].[subsecond digits:3]");
    let timer = OffsetTime::new(offset!(+8), time_fmt);
    tracing_subscriber::fmt().with_timer(timer).init();

    tracing::info!("offset: {}, hello world", offset);
}

Rust入门秘籍

博客

tracing简要说明

示例

不同区域使用不同日志

不同crate使用不同级别的日志

修改日志记录的时区