在 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 会提供一个函式让使用者设定 Logger
fn 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 时 panic
• ignore_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 scope
DEBUG foo: log_test: before enter 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

以我的理解 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 work
INFO work{id=1}: log_test: loop 0
INFO work{id=2}: log_test: start work
INFO work{id=2}: log_test: loop 0
INFO work{id=1}: log_test: loop 1
INFO work{id=2}: log_test: loop 1
INFO work{id=1}: log_test: loop 2
INFO work{id=2}: log_test: loop 2
INFO work{id=1}: log_test: loop 3
INFO work{id=1}: log_test: loop 4
INFO work{id=2}: log_test: loop 3
INFO work{id=1}: log_test: end work
INFO work{id=2}: log_test: loop 4
INFO 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 看来会很适合