在 Rust 中使用 log： log / slog / tracing

最近在写一些 side project 时碰到了一些 bug ，这个时候除了用 println! 大法外，如果有好好的写 log 或许也会比较容易知道发生了什么事，这篇就来整理一下我用过的 Rust 的 log 框架

log

这个其实在之前的文章中就有提到了，不过那个时候几乎没有介绍，这次就来好好的介绍一下， log 是 Rust 的社群所约定的一个 log 的标準，想输出 log 的人使用 log 的 API ，而应用程式只要使用实作了 log 中的 trait 的 Logger就能显示 log

这边是最基本的使用方式与 Logger 的实作：

use log::{info, LevelFilter, Log, Metadata, Record};struct Logger;impl Log for Logger {    // 提供让使用者侦测有没有启用 log 的 API    fn enabled(&self, _meta: &Metadata) -> bool {        true    }    // 实际输出 log 的部份    fn log(&self, record: &Record) {        eprintln!("{}: {}", record.level(), record.args());    }    // 清空缓冲区    fn flush(&self) {}}// 一般 Logger 会提供一个函式让使用者设定 Loggerfn init_log() {    static LOGGER: Logger = Logger;    log::set_max_level(LevelFilter::Trace);    log::set_logger(&LOGGER).unwrap();}fn main() {    init_log();    info!("Hello world")}

而我自己喜欢用的两个 logger ，分别是：

pretty_env_logger: 这个提供了 env_logger 有的功能，同时输出又比 env_logger 预设的要来的好看，不过它其实只是修改了 env_logger 预设的样式而已fern: 一个弹性颇高的 logger ，可以设定同时输出到萤幕跟档案之类的

不过 log 就只能输出文字讯息而已，如果要输出变数的内容就要自己用 format string 把它加入讯息中：

let foo = 1;info!("foo = {}", foo);

如果变数不多，这好像也不是什么大问题，但假如多的话呢？而且还有另一个情况，现在有些情况下会希望输出的 log 是方便程式处理的格式，比如 json ，但 log 这样输出的方法就只能是文字讯息而已，如果能把变数内容加到 json 中，对于要处理的程式而言就更方便了

目前 log 有打算要支援 structured logging (issue) ，不过什么时候才会支援就不知道了

slog

slog 是个 structured logging 的框架，让你可以依自己的需求组合出自己的 logger ，另外也有提供相容于 log 的功能，不过如果使用来自 log 的 macro 就没办法使用 structured logging 的功能了

此外因为可以自己组合 logger 的关係，在使用上也是比较複杂的，比如这边简单弄一个输出成 json 的 logger ：

use slog::Drain;use std::sync::Mutex;fn main() {    let root = slog::Logger::root(        Mutex::new(slog_json::Json::default(std::io::stderr())).fuse(),        // 让每行 log 都会带有版本号的资讯， slog::o! 代表的是包装成 `OwnedKV`        slog::o!("version" => env!("CARGO_PKG_VERSION")),    );    // 输出 Hello world ，同时带一组 key value 为 "foo" => 1    slog::info!(&root, "Hello world"; "foo" => 1);}

这边其实还有很多的小细节，比如我们还用到了 Mutex ，另外还有 fuse 跟 Drain 又是什么之类的，首先先从 Drain 这个 trait 开始，它是 slog 输出 log 的目标，所以 log 要输出到档案，要用什么样的格式，基本上最后都是要在这个 trait 的实作中决定， slog 有提供一个空白实作的 Discard 用来当作完全不输出的 Drain ，同时也是一个很好的实作範例：

#[derive(Debug, Copy, Clone)]pub struct Discard;impl Drain for Discard {    type Ok = ();    // Never 是 slog 用来代表不可能会有错误的一个型态，这边就不管了    type Err = Never;    fn log(&self, _: &Record, _: &OwnedKVList) -> result::Result<(), Never> {        Ok(())    }    // 这边就跟 log::Logger 一样，可以用来检查要不要输出这个 log    #[inline]    fn is_enabled(&self, _1: Level) -> bool {        false    }}

其中的 log 就是输出的部份， slog 的 Record 基本上有 log 的 Record 所有的资讯，只是还多了一个 key value pair 的部份，以上面来说就是 foo 的那部份，另外还有 OwnedKVList 则是在建立 logger 时传进的 key value pair ，以上面来说则是 version 的部份

另外上面也可以看到 Drain 的 log 是可以回传 Err 代表自己没办法正常输出 log 的，但 slog 要求传入 logger 的 Drain 必须要处理掉 Err ，因此就有 fuse 跟另一个函式可以用了：

fuse: 它会包装你提供的 Drain ，并在回传 Err 时 panicignore_res: 忽略 Drain 回传的错误

最后则是 Mutex 的部份，因为 slog 要求 logger 必须能支援多执行绪，如果你的 Drain 并不支援的话，这边就有两种做法，一种是用 Mutex 包装， Drain 也有实作由 Mutex 包装的 Drain ，它会在要输出 log 时锁上，另一个则是使用 slog-async 这个 crate ，它用 channel 把 log 送到另一个执行绪来输出

这边再来组一个比较複杂的 logger 吧，我们把 json 输出到档案，然后输出好看的 log 到 stderr ：

use slog::{Drain, Duplicate};use std::fs::File;fn main() {    let log_file = File::create("test.log").unwrap();    let json_drain = slog_json::Json::default(log_file).fuse();    let decorator = slog_term::TermDecorator::new().build();    let drain = slog_term::CompactFormat::new(decorator).build().fuse();    let drain = slog_async::Async::new(Duplicate::new(drain, json_drain).fuse())        .build()        .fuse();    let root = slog::Logger::root(drain, slog::o!());    slog::info!(&root, "Hello world"; "foo" => 1);}

这边用 slog-term 输出好看的 log ，然后用 slog::Duplicate 来同时输出到两个不同的 Drain ，像这样就可以客制化自己需要的 logger

最后你可能会注意到 slog 都需要传入 logger 的 instance ，那是因为它可以有子 logger ，比如：

use slog::Drain;fn main() {    let decorator = slog_term::TermDecorator::new().build();    let drain = slog_term::CompactFormat::new(decorator).build().fuse();    let drain = slog_async::Async::new(drain).build().fuse();    let root = slog::Logger::root(drain, slog::o!("logger" => "root"));    let child = root.new(slog::o!("logger" => "child"));    slog::info!(&root, "Hello world");    slog::info!(&child, "Using child");}

像这样可以比如帮不同的元件设定不同的 logger ，让它们显示自己来自哪个元件，不过大部份的函式库用的应该都是社群标準的 log ，这时候能个整合原本的 log 就变的很重要了：

use slog::Drain;fn main() {    let decorator = slog_term::TermDecorator::new().build();    let drain = slog_term::FullFormat::new(decorator).build().fuse();    let drain = slog_async::Async::new(drain).build().fuse();    let logger = slog::Logger::root(drain, slog::o!("version" => env!("CARGO_PKG_VERSION")));    // 设定全域的 slog    let _scope_guard = slog_scope::set_global_logger(logger);    // 把 log 导到 slog    slog_stdlog::init().unwrap();    log::info!("standard logging redirected to slog");}

这边用到了两个 crate ，分别是 slog-scope 与 slog-stdlog ，第一个是让使用者可以从这个 crate 取得 logger 或是设定 logger ，而 stdlog 则是把 log 导到由 scope 设定的 logger 去，执行上面的範例应该就会看到 log 的输出被导向给 slog 处理了

tracing

不过随着 async/await 的出现， slog 这样的 structured log 好像又不太够用了，像在多执行绪或是有 async/await 的情况下，工作是可以交错执行的，自然 log 的输出也会交错，在底下又使用到了只用 log 输出 log 的第三方函式库的话，交错输出的 log 反而只是让 debug 变的更困难罢了，不过 slog-scope 还是有办法处理多执行绪的情况的：

use rayon::prelude::*;use slog::Drain;use std::{thread, time::Duration};fn thrid_party() {    log::info!("start process");    thread::sleep(Duration::from_secs(1));    log::info!("end process");}fn main() {    let decorator = slog_term::TermDecorator::new().build();    let drain = slog_term::FullFormat::new(decorator).build().fuse();    let drain = slog_async::Async::new(drain).build().fuse();    let root = slog::Logger::root(drain, slog::o!("version" => env!("CARGO_PKG_VERSION")));    let _guard = slog_scope::set_global_logger(root);    slog_stdlog::init().unwrap();    let data = vec![1, 2, 3, 4, 5, 6];    data.into_par_iter().for_each(|n| {        slog_scope::scope(&slog_scope::logger().new(slog::o!("data" => n)), || {            thrid_party();        });    });}

像这样就可以帮只用 log 的函式加上目前在处理的资料，或是任务的 id 等等，不过 slog 就没办法用这种方式支援 async/await 了， slog 的 scope 目前是以 thread local variable 来实作的，但 async/await 的程式可能是在同一个 thread 中去切换程式执行的流程，这时候的 scope 就不会正确了，这时候 Rust 社群中就我所知大概是最早就在做 async 的执行环境的 tokio 就出了一个 tracing 的 log 框架，这边先来看个範例:

use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};fn main() {    tracing_subscriber::registry()        .with(fmt::layer())        .init();        // 注意这边是呼叫 `log` 的 macro ，而不是 `tracing` 的    log::info!("Hello world");        let foo = 42;    tracing::info!(foo, "Hello from tracing");}

没意外的话你应该会看见两条 log ，一条是从 log 来的，另一条才是 tracing 来的，从这边你可以注意到，其实 tracing 预设就已经支援整合 log 了，至于它跟 log 或 slog 有什么不同呢？这边来用它最重要的功能 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 enter 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");}

像这样它可以用来划分程式的区域，而区域的名字，与放在里面的资讯都会被加入 log 中，像这样：

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

以我的理解 span 的第一个参数应该要能控制这个 span 输出的等级才是，但不知道这边为什么不行，如果有人知道希望可以告诉我

而这个功能也可以用在 future 或是 async fn 上，比如使用 instrument 这个 macro 来自动建立函式的 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);}

它输出的 log 会像这样：

INFO foo{ans=42}: log_test: in foo

这个东西也可以用在 async function 上，不过要另外安装 tracing-futures 就是了，这边跑两个 async function 来展示吧：

use std::time::Duration;use tracing::{info,  instrument, Level};use tracing_subscriber::{fmt, filter::LevelFilter, layer::SubscriberExt, util::SubscriberInitExt};// 可以用 skip 让 tracing 不要印出某些参数#[instrument(skip(delay))]async fn work(id: i32, delay: u64) {    info!("start work");    for i in 0..5 {        info!("loop {}", i);        smol::Timer::after(Duration::from_secs(delay)).await;    }    info!("end work");}fn main() {    tracing_subscriber::registry().with(LevelFilter::from_level(Level::INFO)).with(fmt::layer()).init();    smol::block_on(async {        let task = smol::spawn(work(1, 2));        let task2 = smol::spawn(work(2, 3));        task.await;        task2.await;    });}

这边用 smol 这个比较小的 async runtime 来展示在 async fn 的 log ，虽然 log 会交错在一起，但每行都会有函式相关的资讯，这样就不会搞混了

INFO work{id=1}: log_test: start workINFO work{id=1}: log_test: loop 0INFO work{id=2}: log_test: start workINFO work{id=2}: log_test: loop 0INFO work{id=1}: log_test: loop 1INFO work{id=2}: log_test: loop 1INFO work{id=1}: log_test: loop 2INFO work{id=2}: log_test: loop 2INFO work{id=1}: log_test: loop 3INFO work{id=1}: log_test: loop 4INFO work{id=2}: log_test: loop 3INFO work{id=1}: log_test: end workINFO work{id=2}: log_test: loop 4INFO work{id=2}: log_test: end work

最后来弄一个複杂一点的设定吧，这次除了 tracing 系列的还会用到 color-eyre ，这边同样的让 log 同时输出到画面上与档案中

color-eyre 是个提供可以让任何的 error 包装成它的 Report 与 panic 时显示 backtrace 的 crate ，建议去看它的範例

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() {        // 推荐实际跑一次，看看这边是怎么输出的，你会发现 tracing 搭配 color-eyre 是多么的强大        error!(?err, "error");    }}fn main() -> Result<()> {    let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));    // 这边是输出到画面的 subscriber    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 handler ，不过这次的程式没有 panic    color_eyre::install()?;    call_return_err();    Ok(())}

结语

这段是个人的想法，就请参考就好， Rust 的 log 的生态系看来暂时会分成使用 log 与 tracing 的两大派吧 ， slog 如果是应用程式可能会用，但如果是用在函式库的话，因为同时会限制到使用怎么使用函式库，所以函式库的作者可能比较不会去用，毕竟会变成需要传入 logger ，目前看来，如果需要简单的 log 功能就用 log 吧，如果需要複杂的功能， tracing 看来会很适合