Cookies Used! Some utilities (google analitics, adsense) on this site used cookies

定制 tracing 的日志格式

rust / tracing / log

2025-03-12 19:01

之前一段时间我有提到说，我在试着用 tracing 这个库来记 log 了，今天我们稍微深入一下，试试看定制一下日志的输出格式。

问题

书接上文，上次我们配好了 tracing 的文件日志，默认的文件日志是这个样子的：

2025-01-19 14:05:30.784444  INFO main tr1x::log: D:\src\rs\tr1x\src\log.rs:39: log initialized
2025-01-19 14:11:14.418989  INFO main tr1x::log: D:\src\rs\tr1x\src\log.rs:39: log initialized
2025-01-19 14:11:14.419848  INFO main tr1xbin: src/main.rs:3: Hello, world!
2025-01-19 14:38:30.656538  INFO main tr1x::log: D:\src\rs\tr1x\src\log.rs:39: log initialized
2025-01-19 14:38:30.657229  INFO main tr1xbin: src/main.rs:3: Hello, world!
2025-01-19 17:14:14.326008  INFO main tr1x::log: D:\src\rs\tr1x\src\log.rs:39: log initialized
2025-01-19 17:14:14.326644  INFO main tr1xbin: src/main.rs:25: Value Before: 1
2025-01-19 17:14:14.327224  INFO main tr1xbin: src/main.rs:27: Value After: 2
2025-01-19 17:14:59.527942  INFO main tr1x::log: D:\src\rs\tr1x\src\log.rs:39: log initialized
2025-01-19 17:36:59.523256  INFO main tr1x::log: D:\src\rs\tr1x\src\log.rs:39: log initialized
2025-01-19 17:37:55.362689  INFO main tr1x::log: D:\src\rs\tr1x\src\log.rs:39: log initialized
2025-01-19 17:47:30.236674  INFO main tr1x::log: D:\src\rs\tr1x\src\log.rs:39: log initialized
2025-01-19 17:48:03.914635  INFO main tr1x::log: D:\src\rs\tr1x\src\log.rs:39: log initialized
2025-01-19 17:48:03.915937  INFO main tr1xbin: src/main.rs:11: test vec: [1, 2, 3, 4]
2025-01-19 17:48:03.916841  INFO main tr1xbin: src/main.rs:11: test vec: [1, 2, 3, 4, 4]

如果要求不高，这个日志格式基本上也没有什么毛病可以挑，不过大家应该也都猜到了，这个日志格式一定有戳到我的点，不然我也不会想着把它换掉。是的，我在简单使用之后发现一个问题，尽管这个日志格式完整记录了我想要的内容，但是如果是在复杂的文件系统或工程中，这个源码路径会变得非常长，这就比较影响阅读日志了，但是我还是想保留这部分信息，因为能对应到代码位置对于除错还是比较重要的。

所以摆在我们的问题是：如何限制文件日志中，源码路径的输出长度？

解决

最早这个问题其实我没放在眼里，我觉得这个交给 AI 帮我写一段就好了，不过后来跟多个 AI 多次沟通后，AI 的代码越写越长，编译的错误也越来越多，我也越来越放心：看来大模型还是不能替换掉我。

有一说一，AI 还是给了我一点研究方向，不然我一点头绪也没有：解决我这个问题，我需要自己实现一个 FormatEvent。实现 FormatEvent 实际上只需要实现一个方法，说起来不难，不过对 rust 有些了解的朋友都知道 rust 简单问题搞复杂的能力，没错，我们只需要实现这个方法：

struct MyFormatter;

impl<S, N> FormatEvent<S, N> for MyFormatter
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'a> FormatFields<'a> + 'static,
{
    fn format_event(
        &self,
        ctx: &FmtContext<'_, S, N>,
        mut writer: format::Writer<'_>,
        event: &Event<'_>,
    ) -> fmt::Result {
        ...
    }
}

不熟悉 rust 的朋友看到估计会眼前一黑，没事，睁开眼，上面这段完全照抄自官方文档。我们不需要完全搞懂这个方法的细节，依样画葫芦就行，为什么要抄官方文档？其实是因为 AI 生成的代码从 format_event 的参数就开始错了，所以我们要用官方文档中的正确版本替换掉 AI 生成的错误版本，后面的内容，我们可以抄一抄 AI 的，如果只是记录源码的路径、行号，AI 生成的代码是正确的，这些信息 event.metadata() 中都有：

// 获取文件路径
let file = event.metadata().file().unwrap_or("");

const MAX_FILE_LENGTH: usize = 17;
let file_short = if file.len() > MAX_FILE_LENGTH {
    &file[file.len() - MAX_FILE_LENGTH..]
} else {
    file
};

// 获取行号
let line = event
    .metadata()
    .line()
    .map_or("".to_string(), |line| line.to_string());

我的想法是如果文件路径太长，我就只取最后 17 个字符，前面再补上三个点，这样可以把输出路径控制在 20 个字符，接下来就可以输出日志了：

// 格式化输出
if file_short.len() < MAX_FILE_LENGTH {
    write!(
        writer,
        "{}{:>20}:{:4}{}",
        DIVIDER, file_short, line, DIVIDER
    )?;
} else {
    write!(
        writer,
        "{}...{}:{:4}{}",
        DIVIDER, file_short, line, DIVIDER
    )?;
}

ctx.format_fields(writer.by_ref(), event)?;
writeln!(writer)

{:4} 是为了对齐行号，行号小于四位仍会保留四个字符的宽度。我认为基本覆盖了大部分场景，如果行号超过 10000，会有对不齐的问题，不过这种情况代码也太长了，是不是应该考虑拆分一下源码？

有了这个，我们就可以在 layer 中使用我们自己的格式了：

let file_layer = tracing_subscriber::fmt::Layer::new()
    .compact()
    .with_span_events(event_kind.clone())
    .with_timer(timer.clone())
    .with_file(true)
    .with_line_number(true)
    .with_thread_names(true)
    .with_ansi(false)
    .event_format(MyFormatter)
    .with_writer(file_appender)
    .with_filter(log_level.clone());

试了以后我们发现，源码路径、行号和原始日志的问题解决了，但是时间、日志等级、线程名都没有了，聋子治成了哑巴，而且这也是关键信息，可不能丢掉。于是我又向 AI 问了一卦，AI 几次折腾未果后，给我的建议是自己把这些内容输出到日志。

我觉得不太在理，我只是想格式化一下源码路径的显示方式，怎么就需要全部自己上手了，但是因为对 tracing_subscriber 也没有那么了解，目前看上去也是原始的日志已经不输出了，那就先这么来，不要再纠结了，修改后的初始化代码长这个样子：

use time::format_description::BorrowedFormatItem;
use tracing::Subscriber;
use tracing_subscriber::fmt::format::FmtSpan;
use tracing_subscriber::fmt::time::FormatTime;
use tracing_subscriber::fmt::{self, FormatEvent, FormatFields};
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::registry::LookupSpan;
use tracing_subscriber::util::SubscriberInitExt;
use tracing_subscriber::Layer;

struct CustomFormatter<'a> {
    timer: fmt::time::OffsetTime<Vec<BorrowedFormatItem<'a>>>,
}

impl<'b, S, N> FormatEvent<S, N> for CustomFormatter<'b>
where
    S: Subscriber + for<'a> LookupSpan<'a>,
    N: for<'a> FormatFields<'a> + 'static,
{
    fn format_event(
        &self,
        ctx: &fmt::FmtContext<'_, S, N>,
        mut writer: fmt::format::Writer<'_>,
        event: &tracing::Event<'_>,
    ) -> std::fmt::Result {
        const DIVIDER: &str = "|";

        self.timer.format_time(&mut writer)?;
        let meta = event.metadata();

        write!(
            writer,
            "{}{:>5}{}{}",
            DIVIDER,
            meta.level(),
            DIVIDER,
            std::thread::current().name().unwrap_or("")
        )?;

        // 获取文件路径
        let file = event.metadata().file().unwrap_or("");

        const MAX_FILE_LENGTH: usize = 17;
        let file_short = if file.len() > MAX_FILE_LENGTH {
            &file[file.len() - MAX_FILE_LENGTH..]
        } else {
            file
        };

        // 获取行号
        let line = event
            .metadata()
            .line()
            .map_or("".to_string(), |line| line.to_string());

        // 格式化输出
        if file_short.len() < MAX_FILE_LENGTH {
            write!(
                writer,
                "{}{:>20}:{:4}{}",
                DIVIDER, file_short, line, DIVIDER
            )?;
        } else {
            write!(
                writer,
                "{}...{}:{:4}{}",
                DIVIDER, file_short, line, DIVIDER
            )?;
        }

        ctx.format_fields(writer.by_ref(), event)?;
        writeln!(writer)
    }
}

pub fn init(config: &crate::Config) {
    let debug = &config.debug;
    let name = &config.name;

    let timer_fmt = time::format_description::parse(
        "[year]-[month padding:zero]-[day padding:zero] [hour]:[minute]:[second].[subsecond digits:6]",
    )
    .expect("Failed to parse time format");

    let time_offset =
        time::UtcOffset::current_local_offset().unwrap_or_else(|_| time::UtcOffset::UTC);
    let timer = fmt::time::OffsetTime::new(time_offset, timer_fmt);

    let log_level = if *debug {
        tracing_subscriber::filter::LevelFilter::TRACE
    } else {
        tracing_subscriber::filter::LevelFilter::INFO
    };

    let log_file_name = format!("{}.log", name);

    let file_appender = tracing_appender::rolling::daily("logs", &log_file_name);
    let event_kind = FmtSpan::ACTIVE | FmtSpan::CLOSE;
    let file_layer = tracing_subscriber::fmt::Layer::new()
        .compact()
        .with_span_events(event_kind.clone())
        .with_file(true)
        .with_line_number(true)
        .with_thread_names(true)
        .with_ansi(false)
        .event_format(CustomFormatter {
            timer: timer.clone(),
        })
        .with_writer(file_appender)
        .with_filter(log_level.clone());

    let console_layer = tracing_subscriber::fmt::Layer::new()
        .pretty()
        .with_span_events(event_kind)
        .with_timer(timer)
        .with_file(true)
        .with_line_number(true)
        .with_thread_names(true)
        .with_filter(log_level);

    tracing_subscriber::Registry::default()
        .with(file_layer)
        .with(console_layer)
        .init();

    tracing::info!("{} log initialized", name);
}

时间的长度固定，等级固定五字符右对齐，同一线程的日志就非常整齐了：

2025-03-16 10:11:48.445297| INFO|main|...s\tr1x\src\log.rs:126 |tr1xbin log initialized
2025-03-16 10:11:48.446125| INFO|main|...x\src\reloader.rs:46  |reloading: test
2025-03-16 10:11:48.447331| INFO|main|         src\main.rs:13  |test vec: [1, 2, 3, 4]
2025-03-16 10:11:48.447848| INFO|main|...x\src\reloader.rs:48  |reloaded: test
2025-03-16 10:11:48.448151| INFO|main|...x\src\reloader.rs:46  |reloading: test
2025-03-16 10:11:48.448497| INFO|main|         src\main.rs:13  |test vec: [1, 2, 3, 4, 5, 4]
2025-03-16 10:11:48.449050| INFO|main|...x\src\reloader.rs:48  |reloaded: test
2025-03-16 10:11:48.449688| INFO|main|         src\main.rs:23  |enter
2025-03-16 10:11:48.450094| INFO|main|         src\main.rs:25  |This is a test log message.
2025-03-16 10:11:48.450734| INFO|main|         src\main.rs:23  |exit
2025-03-16 10:11:48.450987| INFO|main|         src\main.rs:23  |close time.busy=1.03ms time.idle=276µs

总结

原本感觉是一个简单的日志格式定制问题，但是最后花了不少时间。其实我觉得这个问题应该是日志库提供配置解决，可是没想到最后是用代码来实现的，另一个点是我之前定义时间格式是传递一个 timer 给 layer，但是在 CustomFormatter 中，我还没有办法取出这个 timer，于是只能在 CustomFormatter 中自己保存一份。另外时间不一致的问题也没有解决，不过我大概猜测是因为，tracing_subscriber 中也和我一样是直接用 now 来获取时间并记录的。其实应该用事件的生成时间，或者 log 的调用时间。但是目前看来 event 中是没有保存生成时间的，而且我也没什么办法在创建 event 时记录这个时间。

rust 的程序或代码总是会给人这样的感觉，看上去很精妙，文档「看上去」也很详尽。但是用起来非常吃力和费劲，而且总让人感觉缺东少西。可能也是和我本人的水平有关，高手看起来都是小菜一碟，分分钟的事情。