Rust in Everything
基于 tracing-subscriber 0.3.23

RUST_LOG 设了不生效

主线位置：事件主线的第二、三道门。EnvFilter 在 register_callsite 时用指令比对每个调用点的 target 和级别，定下 Interest；指令写错了，调用点在这里就被判成 never，后面的 fmt 什么都收不到。

flowchart TB
  env["RUST_LOG 字符串"] --> split["按逗号切分"]
  split --> parse["Directive::parse"]
  parse -->|"段首有空格"| bad["解析失败或 target 带空格"]
  parse --> tables["指令表"]
  tables -->|"一条都没有"| def["加默认指令"]
  tables -->|"至少一条"| nodef["不加默认指令"]
  nodef --> match["target 前缀比对"]
  match -->|"my-app 对 my_app"| miss["全部 never"]

EnvFilter 怎么解析指令、默认指令什么时候加、各个构造函数的区别，在 EnvFilter 里有完整的表和实验。这一页从现象出发：三种「设了 RUST_LOG 却和没设一样，甚至更糟」的写法，各用一个最小程序复现。

本页的实验都在 M2 Max、rustc 1.99.0、--release 下运行，依赖：

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

复现：一个叫 my-app 的包

Cargo.toml 里 name = "my-app"，src/main.rs：

use tracing_subscriber::EnvFilter;

fn main() {
  let filter = EnvFilter::from_default_env();
  eprintln!("filter = {filter}");
  tracing_subscriber::fmt()
    .with_env_filter(filter)
    .with_ansi(false)
    .without_time()
    .init();
  tracing::error!("error event");
  tracing::info!("info event");
  tracing::debug!("debug event");
}

eprintln! 打印的是 EnvFilter 的 Display，也就是它实际解析出来的指令。七种 RUST_LOG 各跑一次，stdout、stderr 合在一起，连跑 3 遍输出相同：

$ ./my-app
filter = error
ERROR my_app: error event
$ RUST_LOG="my-app=debug" ./my-app
filter = my-app=debug
$ RUST_LOG="my_app=debug" ./my-app
filter = my_app=debug
ERROR my_app: error event
 INFO my_app: info event
DEBUG my_app: debug event
$ RUST_LOG="info,my_app=debug" ./my-app
filter = my_app=debug,info
ERROR my_app: error event
 INFO my_app: info event
DEBUG my_app: debug event
$ RUST_LOG="info, my_app=debug" ./my-app
ignoring ` my_app=debug`: error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5
filter = info
ERROR my_app: error event
 INFO my_app: info event
$ RUST_LOG="info, my_app" ./my-app
filter =  my_app=trace,info
ERROR my_app: error event
 INFO my_app: info event
$ RUST_LOG="info,my-app=debug" ./my-app
filter = my-app=debug,info
ERROR my_app: error event
 INFO my_app: info event

坑一：my-app=debug，连 ERROR 都没了

不设 RUST_LOG 时还有一行 ERROR；设成 my-app=debug 想看更多，结果一行都没有了。两件事叠在一起。

target 是 my_app。 事件的 target 默认是 module_path!()，而模块路径里的 crate 名是 Cargo 把包名里的 - 换成 _ 之后的名字，所以输出里的 target 是 my_app。my-app=debug 本身是一条合法指令（filter = my-app=debug 说明它被原样接受了，解析器允许 target 里有 -），只是它永远匹配不上：Directive::cares_about 比的是前缀，

        if let Some(ref target) = self.target {
            if !meta.target().starts_with(&target[..]) {
                return false;
            }
        }

"my_app".starts_with("my-app") 为假。

有了指令，就不再加默认指令。 from_default_env 是 builder().with_default_directive(ERROR).from_env_lossy()，这个 ERROR 只在 Builder::from_directives 收到的指令一条都没有时才加：

        if !has_dynamics && filter.statics.is_empty() {
            if let Some(ref default) = self.default_directive {
                filter = filter.add_directive(default.clone());
            }
        }

my-app=debug 是一条静态指令，statics 不空，默认指令不加。剩下的唯一一条指令谁都不关心，于是所有调用点都是 never，包括 error!。默认指令不是「其余 target 的兜底级别」，这一点在 EnvFilter 的「构造：坏指令和默认指令」一节讲过。

对比最后一行 info,my-app=debug：裸级别 info 是一条自己写的兜底指令，所以 ERROR 和 INFO 都在，DEBUG 依然没有，因为 my-app=debug 还是没匹配上。只看到 INFO 的人很容易以为 my-app=debug 生效了、只是代码里没走到 debug!。

坑二：逗号后面的空格

RUST_LOG="info, my_app=debug" 是很自然的写法，结果 stderr 多了一行 ignoring ...，DEBUG 没了。错误信息说的是「级别解析失败」，可 debug 明明是合法的级别。

Builder::parse_lossy 只按 , 切分，不去空白，第二段是 my_app=debug（带前导空格）。Directive::parse 遍历的是 trim 过的字符串，切片用的却是原串：

        for (i, c) in from.trim().char_indices() {
            state = match (state, c) {
                // ...
                (Start, _) => LevelOrTarget { start: i },
                (LevelOrTarget { start }, '=') => {
                    cur.target = Some(from[start..i].to_owned());
                    Level { level_start: i + 1 }
                }

trim 后的 my_app=debug 里 = 的下标是 6，原串 my_app=debug 里下标 6 是 p、7 才是 =。于是 target 成了 my_ap，级别从下标 7 开始取，是 =debug，LevelFilter::from_str 失败。

  • lossy 的构造（from_default_env、EnvFilter::new）打印 ignoring 后丢掉这一段，剩下 info。
  • 没有 = 的 info, my_app 走另一个分支，from[start..] 取到的是 my_app，解析成功，target 带着前导空格（filter = my_app=trace,info 里有两个空格）。它不报错，也永远匹配不上任何 target。
  • 严格的构造（try_new、try_from_default_env）整个返回 Err，见下一个坑。

修法只有一个：RUST_LOG 里不写空格。

📝NOTE
冷知识：这个坑 2023 年就有人报过，至今没合

issue #2452「EnvFilter does not trim white spaces in each directive before parsing it」报告于 2023 年 1 月，当时是 tracing-subscriber 0.3.16：「For example, RUST_LOG='info, app=debug' doesn't work with EnvFilter, but it works with env_logger」，并指出「env_logger trims white spaces」。随后的 PR #2496「Trim whitespace around commas before parsing EnvFilter directives」做的正是「After splitting a directive line on commas, it now trims them before parsing to Directives」，理由是「This is backwards-compatible cause before it just didn't allow any whitespace」。issue 和 PR 截至 0.3.23 都还开着，上面 parse_lossy 里的 split(',') 后面仍然没有 trim。

当时的 Directive::parse 还是正则实现（0.3.19 及以前，^...$ 锚定、target 只允许 [\w:-]+），带空格的一段整个匹配不上；0.3.20 换成状态机（见 EnvFilter 的「指令语法」）后加了 .trim()，却没让切片也用 trim 后的串，于是报错从「无效指令」变成了上面这句关于级别的话，info, my_app 这种写法也从报错变成了静默接受。

坑三：空的 RUST_LOG= 和 try_from_default_env

很多示例这样写「读 RUST_LOG，读不到就用 info」：

EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"))

它对「没设」和「写错」都有效，对「设成空字符串」无效。同一个包里的 src/bin/fallback.rs，try 模式用上面的写法，另一种模式用 builder 的默认指令：

use tracing_subscriber::EnvFilter;
use tracing_subscriber::filter::LevelFilter;

fn main() {
  let filter = match std::env::args().nth(1).as_deref() {
    // 常见写法：读不到就退回 info
    Some("try") => EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info")),
    // 改法：默认指令交给 builder
    _ => EnvFilter::builder()
      .with_default_directive(LevelFilter::INFO.into())
      .from_env_lossy(),
  };
  eprintln!("filter = {filter}");
  tracing_subscriber::fmt()
    .with_env_filter(filter)
    .with_ansi(false)
    .without_time()
    .init();
  tracing::error!("error event");
  tracing::info!("info event");
}

连跑 3 遍输出相同：

$ ./fallback try
filter = info
ERROR fallback: error event
 INFO fallback: info event
$ RUST_LOG= ./fallback try
filter = 
$ RUST_LOG="info, fallback=debug" ./fallback try
filter = info
ERROR fallback: error event
 INFO fallback: info event
$ ./fallback builder
filter = info
ERROR fallback: error event
 INFO fallback: info event
$ RUST_LOG= ./fallback builder
filter = info
ERROR fallback: error event
 INFO fallback: info event
$ RUST_LOG="info, fallback=debug" ./fallback builder
ignoring ` fallback=debug`: error parsing level filter: expected one of "off", "error", "warn", "info", "debug", "trace", or a number 0-5
filter = info
ERROR fallback: error event
 INFO fallback: info event

RUST_LOG= ./fallback try 一行日志都没有，filter = 后面是空的。try_from_default_env 是 builder().try_from_env()：try_from_env 只在变量不存在时返回 Err；变量存在但为空，交给 Builder::parse，它对空串返回 Ok(self.from_directives(empty))，而 builder() 没有设默认指令，结果是一个零条指令的 EnvFilter，Ok 了，unwrap_or_else 不起作用。

try 模式下第三种情形也值得看：带空格的 RUST_LOG 让严格解析返回 Err，unwrap_or_else 默默换成了 info，stderr 上什么都没有。和 builder 模式的输出对比，后者至少打印了一行 ignoring。

改法是把默认值交给 builder：EnvFilter::builder().with_default_directive(LevelFilter::INFO.into()).from_env_lossy()。变量不存在、为空、或者所有段都被丢掉时，它都用 info；有坏的段会在 stderr 说出来。要「写错就启动失败」，用 .from_env()?（同样带默认指令），它对空串也用默认指令，对坏指令返回 Err。

❗IMPORTANT
动脑筋：RUST_LOG="warn,my_app=debug" 和 RUST_LOG="my_app=debug,warn" 在 my-app 上的输出一样吗？

还是上面的 src/main.rs，M2 Max、rustc 1.99.0、--release。两种写法各打几行、filter = 那一行各是什么？答案在本页末尾。

修法

现象原因怎么改
设了 RUST_LOG 后一行都没有，filter = 里有 -target 里的 - 应该是 _写 my_app=debug；不确定就打印一次 module_path!()
只有自己的 crate 有日志，依赖的 WARN/ERROR 不见了有指令就不加默认指令自己写兜底：RUST_LOG=warn,my_app=debug
stderr 有 ignoring 开头的行，或者 filter = 里某个 target 前面有空格逗号后有空格去掉空格
RUST_LOG= 时一行都没有try_from_default_env 对空串返回空过滤器builder().with_default_directive(..).from_env_lossy()
写错的 RUST_LOG 被静默换成默认值unwrap_or_else 吞掉了 Err至少把 Err 打出来；或用 lossy 版本

怎么确认自己没踩

  • 启动时把过滤器的 Display 打一行（上面的 eprintln!("filter = {filter}")）。它显示的是解析后真正生效的指令：没有你写的那条、多了空格、只剩默认值，都一眼可见。
  • 打印一次 module_path!()，确认 target 的写法；用 fmt 的默认格式时，每行日志里也印着 target。
  • 看 stderr 有没有 ignoring 开头的行。lossy 构造在丢弃一段指令时只说这一次，而且不经过 tracing，日志收集系统如果只收 stdout 就看不到。
  • 带空格、写错 target 的 RUST_LOG 都不会让程序启动失败。需要严格时用 EnvFilter::builder().with_default_directive(..).from_env() 并处理它的 Err。

动脑筋答案

连跑 3 次输出相同：

$ RUST_LOG="warn,my_app=debug" ./my-app
filter = my_app=debug,warn
ERROR my_app: error event
 INFO my_app: info event
DEBUG my_app: debug event
$ RUST_LOG="my_app=debug,warn" ./my-app
filter = my_app=debug,warn
ERROR my_app: error event
 INFO my_app: info event
DEBUG my_app: debug event
  • 一样。EnvFilter 不按书写顺序匹配，而是把指令按具体程度排序，带 target 的 my_app=debug 排在裸级别 warn 前面，Display 也按这个顺序打印，所以两种写法的 filter = 那一行完全相同。
  • my_app 的事件匹配到更具体的 my_app=debug，三行都打；warn 只管其他 target（这里没有）。顺序无关这一点在 EnvFilter 的第一个实验里也能看到。

小结

  • target 默认是 module_path!()，包名里的 - 在这里是 _；my-app=debug 是合法指令，只是谁都匹配不上。
  • 默认指令只在一条指令都没有时才加；RUST_LOG 里写了任何一条，就要自己写兜底的裸级别，否则连 ERROR 都没了。
  • RUST_LOG 里逗号后不能有空格：0.3.23 的 Directive::parse 用 trim 后的下标切原串，带值的一段被丢弃并报一个误导的级别错误，不带值的一段带着空格被静默接受；issue #2452 至今未修。
  • try_from_default_env() 对空的 RUST_LOG= 返回 Ok(空过滤器)，unwrap_or_else 的兜底不会触发；用 builder 的 with_default_directive 加 from_env_lossy。
  • 启动时打印过滤器的 Display，看 stderr 的 ignoring 行。

💬 关联讨论

发起讨论
加载中...