Rust in Everything
基于 tracing-subscriber 0.3.23

文件要 DEBUG、终端要 INFO,结果两边一样

主线位置:事件主线的第三、四道门。全局过滤器在 register_callsite 说 never、在 enabled 说 false,整个栈到此为止,哪一层都轮不到 on_event;每层过滤只在被包的那一层的 on_event 前起作用。

flowchart TB
  ev["debug! 到达"] --> where{"过滤器怎么装的"}
  where -->|".with(filter)"| g["全局:整个栈短路"]
  g --> none["终端、文件都没有"]
  where -->|"layer.with_filter"| p["每层:各查各的位"]
  p --> fileok["文件层收到"]
  p --> termno["终端层跳过"]
  where -->|"两者都有"| both["全局先说 never"]
  both --> none

想要的效果:终端只看 INFO,日志文件多记 DEBUG。写出来却是两边一模一样,要么文件里也没有 DEBUG,要么终端里也刷满 DEBUG。全局过滤和每层过滤的实现在 过滤:全局与每层 里拆过,这一页只讲怎么踩上、怎么改、怎么查。

复现

一个终端层(stdout)、一个文件层(真的写文件),三种装法,外加一种常见的「在 fmt() 上再加一层」:

tracing = "=0.1.44"
tracing-subscriber = { version = "=0.3.23", features = ["env-filter"] }
use std::fs::{self, File};

use tracing_subscriber::filter::LevelFilter;
use tracing_subscriber::prelude::*;
use tracing_subscriber::{EnvFilter, fmt};

fn emit() {
  tracing::info!("server started");
  tracing::debug!("cache warmed");
}

fn file(path: &str) -> File {
  File::create(path).unwrap()
}

fn show(path: &str) {
  print!("-- {path}:\n{}", fs::read_to_string(path).unwrap());
}

fn main() {
  let case = std::env::args().nth(1).unwrap();
  let path = format!("{case}.log");
  println!("== {case}");
  match case.as_str() {
    // 过滤器用 .with 叠上去:全局
    "global" => {
      let sub = tracing_subscriber::registry()
        .with(EnvFilter::new("info"))
        .with(fmt::layer().with_ansi(false).without_time())
        .with(fmt::layer().with_ansi(false).without_time().with_writer(file(&path)));
      tracing::subscriber::with_default(sub, emit);
    }
    // 全局 INFO,文件层再加自己的 DEBUG
    "global-plus-layer" => {
      let sub = tracing_subscriber::registry()
        .with(EnvFilter::new("info"))
        .with(fmt::layer().with_ansi(false).without_time())
        .with(
          fmt::layer()
            .with_ansi(false)
            .without_time()
            .with_writer(file(&path))
            .with_filter(LevelFilter::DEBUG),
        );
      tracing::subscriber::with_default(sub, emit);
    }
    // 每层过滤
    "per-layer" => {
      let sub = tracing_subscriber::registry()
        .with(fmt::layer().with_ansi(false).without_time().with_filter(EnvFilter::new("info")))
        .with(
          fmt::layer()
            .with_ansi(false)
            .without_time()
            .with_writer(file(&path))
            .with_filter(LevelFilter::DEBUG),
        );
      tracing::subscriber::with_default(sub, emit);
    }
    // 在 fmt() 造好的 subscriber 上再加一个带过滤的层
    "fmt-plus-filtered" => {
      let sub = tracing_subscriber::fmt()
        .with_ansi(false)
        .without_time()
        .with_env_filter("info")
        .finish()
        .with(
          fmt::layer()
            .with_ansi(false)
            .without_time()
            .with_writer(file(&path))
            .with_filter(LevelFilter::DEBUG),
        );
      tracing::subscriber::with_default(sub, emit);
    }
    _ => unreachable!(),
  }
  show(&path);
}

M2 Max、rustc 1.99.0、--release,四种各跑 3 次,除线程号外输出相同:

== global
 INFO two_outputs: server started
-- global.log:
 INFO two_outputs: server started
== global-plus-layer
 INFO two_outputs: server started
-- global-plus-layer.log:
 INFO two_outputs: server started
== per-layer
 INFO two_outputs: server started
-- per-layer.log:
 INFO two_outputs: server started
DEBUG two_outputs: cache warmed
== fmt-plus-filtered

thread 'main' (1605750) panicked at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.23/src/registry/mod.rs:149:9:
tracing_subscriber::fmt::Subscriber<tracing_subscriber::fmt::format::DefaultFields, tracing_subscriber::fmt::format::Format<tracing_subscriber::fmt::format::Full, ()>, tracing_subscriber::filter::env::EnvFilter> does not currently support filters
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
  • global:文件里没有 DEBUG。把 "info" 改成 "debug",终端也会多出 DEBUG。一个全局过滤器只有一个答案。
  • global-plus-layer:文件层自己加了 with_filter(LevelFilter::DEBUG),仍然没有 DEBUG。这是最容易让人以为「每层过滤不生效」的写法。
  • per-layer:两层各拿到自己要的。
  • fmt-plus-filtered:根本跑不起来,panic 发生在组装 subscriber 的 .with(..) 里。

为什么

全局过滤器是一层。 EnvFilter、LevelFilter 都实现了 Layer,.with(filter) 把它叠进栈里。Layered::enabled 从外往里问,问到它说 false 就整体返回 false,宏不构造事件,所有层都看不到。它放在 .with 链的哪个位置都一样。fmt().with_env_filter(..) 和 fmt().with_max_level(..) 也是这一种:SubscriberBuilder::finish 把过滤器叠在最外层。

全局 INFO 加单层 DEBUG 是「与」。 debug! 的调用点注册时,文件层的 Filtered 记下「要」,但内层的全局 EnvFilter 回答 never,Layered 短路并清掉每层过滤记下的意见,调用点缓存成 never。每层过滤只能在全局放行的范围内再收窄。逐步推导和实测在 过滤:全局与每层 的「动脑筋答案」。

fmt() 的产物不能承载每层过滤。 Layer::with_filter 返回的 Filtered 被叠上去时要向内层领一个 FilterId,调的是 LookupSpan::register_filter。只有 Registry::register_filter 真正分配,Layered 往里转发;LookupSpan 的默认实现直接 panic:

    fn register_filter(&mut self) -> FilterId {
        panic!(
            "{} does not currently support filters",
            std::any::type_name::<Self>()
        )
    }

fmt::Subscriber 是包着 Layered 的新类型,它的 LookupSpan 实现 只转发了 span_data,没有转发 register_filter,于是落到默认实现。panic 消息里那一长串类型名就是 std::any::type_name::<Self>()。

📝NOTE
没有蠢问题

问: 既然 fmt::Subscriber 里面就是一个 Registry,为什么不把 register_filter 也转发进去,让 fmt().finish().with(layer.with_filter(..)) 能用?

答: 转发了也得不到想要的结果。fmt() 的过滤器在 fmt::Subscriber 内部的最外层,是全局过滤;新加的层在它外面,它说 never 时整个栈照样短路,新层的 DEBUG 还是收不到,和 global-plus-layer 一样。想让各层级别不同,起点就该是 registry(),而不是已经带着全局过滤器的 fmt()。panic 至少让这个组合在启动时就暴露,而不是安静地丢日志。

修法

从 registry() 开始,每一个需要过滤的层都用 with_filter,栈里不留全局过滤器:

use tracing_subscriber::filter::LevelFilter;
use tracing_subscriber::prelude::*;
use tracing_subscriber::{EnvFilter, fmt};

let file_writer = std::fs::File::create("app.log").unwrap();
tracing_subscriber::registry()
  .with(fmt::layer().with_filter(EnvFilter::from_default_env()))
  .with(fmt::layer().with_ansi(false).with_writer(file_writer).with_filter(LevelFilter::DEBUG))
  .init();
  • EnvFilter 既能当全局过滤也能当每层过滤,RUST_LOG 照样只管终端那一层。
  • 文件层什么级别都要时,可以只给终端加 with_filter,文件层不加。但不要为了「省一个」把文件的 DEBUG 写成全局的 .with(LevelFilter::DEBUG):那等于给终端也放开了 DEBUG,终端那层的 with_filter 还得照写。
  • 已经有 fmt().with_env_filter(..) 的代码,要加第二个出口,就把它拆成 registry().with(fmt::layer().with_filter(..)),不要在 fmt() 的结果上接 .with(..)。

只想按级别把同一行分到不同出口(比如 WARN 以上另抄一份),不需要第二个层,用 MakeWriterExt 的 with_max_level / or_else / and,见 fmt 的「组合子」一节。

怎么确认自己没踩

  • 读初始化代码:.with( 后面直接跟 EnvFilter、LevelFilter、Targets、filter_fn(..) 的,都是全局过滤;fmt().with_env_filter / with_max_level 也是。栈里只要有一个全局过滤器,所有层的上限就是它。

  • 启动时故意打一条比终端级别低的事件(比如 debug!("logging ready")),确认它出现在文件里、没出现在终端。只看 LevelFilter::current() 不够:global-plus-layer 那种装法下,在 with_default 里打印它:

    let sub = tracing_subscriber::registry()
      .with(EnvFilter::new("info"))
      .with(fmt::layer().with_ansi(false).without_time())
      .with(fmt::layer().with_ansi(false).without_time().with_filter(LevelFilter::DEBUG));
    tracing::subscriber::with_default(sub, || {
      println!("LevelFilter::current() = {}", LevelFilter::current());
    });
    
    LevelFilter::current() = debug
    

    (跑 3 次相同。)每层过滤的 DEBUG 提示参与了取最大值,第二道门放行 debug!,可文件里还是没有 DEBUG,挡住它的是第三道门的 Interest 缓存。

  • does not currently support filters 的 panic 里,类型名开头是 tracing_subscriber::fmt::Subscriber 就是上面第四种;开头是别的类型,说明那个根 subscriber 不是 Registry,同样要换成 registry() 起步。

小结

  • .with(filter) 和 fmt().with_env_filter(..) 是全局过滤,说「不」时整个栈都看不到,放在链的哪里都一样。
  • 每层不同级别要用 layer.with_filter(filter),而且栈里不能再有比它更严的全局过滤:两者叠加是「与」,单层的 DEBUG 收不到被全局 INFO 挡掉的事件。
  • 每层过滤要向根 subscriber 领 FilterId,只有 Registry 能发;在 fmt().finish() 上加 with_filter 的层,组装时 panic「does not currently support filters」。
  • 检查办法是启动时打一条低级别事件看它落在哪,而不是看 LevelFilter::current()。

💬 关联讨论

发起讨论
加载中...