Rust in Everything
基于 tracing 0.1.44

release 构建里 debug! 全部消失

主线位置:事件主线的第一道门 STATIC_MAX_LEVEL。它是编译期常量,挡住的事件连代码都不生成,后面几道门和 subscriber 的配置都碰不到它们。

flowchart TB
  dep["某个依赖开了 release_max_level_info"] --> unify["feature 合并"]
  unify --> one["整个程序只有一份 tracing"]
  one --> smax["release 下 STATIC_MAX_LEVEL = INFO"]
  smax --> gone["所有 debug! trace! 被删掉"]
  gone --> envf["RUST_LOG=debug 也没用"]
  tree["cargo tree -e features -i tracing"] -.->|找出是谁| dep

dev 构建里一切正常,换成 --release,所有 debug! 都不见了;subscriber 明明设成了 TRACE,RUST_LOG=debug 也没用。你的 Cargo.toml 里没写任何级别 feature。这种情况先查 STATIC_MAX_LEVEL。

现象

一个三个包的 workspace:app 依赖 mid,mid 依赖 quiet-dep,只有 quiet-dep 给 tracing 开了 release_max_level_info。

# quiet-dep/Cargo.toml
[dependencies]
tracing = { version = "=0.1.44", features = ["release_max_level_info"] }
# mid/Cargo.toml:不直接依赖 tracing
[dependencies]
quiet-dep = { path = "../quiet-dep" }
# app/Cargo.toml
[dependencies]
mid = { path = "../mid" }
tracing = "=0.1.44"
tracing-subscriber = { version = "=0.3.23", default-features = false, features = ["fmt", "std"] }

quiet-dep 的 work() 打一条 info!,mid::run() 调它。app 的 main:

use tracing::level_filters::STATIC_MAX_LEVEL;
use tracing::{Level, debug, info};

fn main() {
  tracing_subscriber::fmt()
    .with_max_level(Level::TRACE)
    .with_ansi(false)
    .without_time()
    .init();

  let profile = if cfg!(debug_assertions) { "dev" } else { "release" };
  info!(profile, %STATIC_MAX_LEVEL, "start");
  debug!(user_id = 42, "cache miss");
  mid::run();
}

M2 Max、rustc 1.99.0,cargo run -p app 和 cargo run -p app --release 各跑 3 次,输出相同。dev:

 INFO app: start profile="dev" STATIC_MAX_LEVEL=trace
DEBUG app: cache miss user_id=42
 INFO quiet_dep: quiet-dep working

release:

 INFO app: start profile="release" STATIC_MAX_LEVEL=info
 INFO quiet_dep: quiet-dep working

app 自己的 debug! 没了,而 app 从没写过 release_max_level_info。subscriber 设成了 TRACE,没有任何作用。

为什么是整个程序

两件事叠在一起:

  1. feature 在依赖图里合并。 整个程序里 tracing 0.1.44 只编译一份,它的 feature 是所有依赖者要求的并集。quiet-dep 要了 release_max_level_info,app 用的那份 tracing 也就有了。
  2. STATIC_MAX_LEVEL 是编译期常量。 STATIC_MAX_LEVEL 由 get_max_level_inner 根据 feature 算出。每个 debug! 展开后的第一个判断就是 Level::DEBUG <= STATIC_MAX_LEVEL,两边都是常量,结果为 false 时整段代码在编译期被删掉,Metadata 都不会进二进制。运行时的 EnvFilter、with_max_level 根本见不到这些事件。

release_max_level_* 只在 not(debug_assertions) 时生效,所以 dev 构建看不出问题。这条 if 链和三条规则(只在 release 生效、release 组整组优先于 max_level_*、同组取最严)在 级别过滤的几道门 里有完整的源码和实验,本页不重复。

tracing 的模块文档把这组 feature 写成给「a crate」用的配置,没有提醒库不要开。log 0.4.34 的文档对它自己的同名 feature 写得更直接:「Libraries should avoid using the max level features because they're global and can't be changed once they're set」。tracing 的这组 feature 是一样的情况。

找出是谁开的

cargo tree 的 -e features 把 feature 也画成节点,-i tracing 倒过来看「谁依赖 tracing」。在 workspace 根目录(M2 Max、cargo 随 rustc 1.99.0,路径缩短为 ./):

$ cargo tree -e features -i tracing -p app
tracing v0.1.44
├── tracing feature "attributes"
│   └── tracing feature "default"
│       ├── app v0.1.0 (./app)
│       │   └── app feature "default" (command-line)
│       └── quiet-dep v0.1.0 (./quiet-dep)
│           └── quiet-dep feature "default"
│               └── mid v0.1.0 (./mid)
│                   └── mid feature "default"
│                       └── app v0.1.0 (./app) (*)
├── tracing feature "default" (*)
├── tracing feature "release_max_level_info"
│   └── quiet-dep v0.1.0 (./quiet-dep) (*)
├── tracing feature "std"
│   └── tracing feature "default" (*)
└── tracing feature "tracing-attributes"
    └── tracing feature "attributes" (*)

找 tracing feature "release_max_level_..."(或 "max_level_...")那一项,它下面列的就是开这个 feature 的包,这里是 quiet-dep。(*) 表示这个包的依赖链上面已经画过:quiet-dep 是经 mid 被 app 引进来的。

只想看最终启用了哪些 feature,用 -f 打印 feature 列表:

$ cargo tree -p app -i tracing -f '{p} {f}' --depth 0
tracing v0.1.44 attributes,default,release_max_level_info,std,tracing-attributes
❗IMPORTANT

动脑筋:在 app 里开一个更宽的级别,能不能抵消?

app/Cargo.toml 加两个 feature,分别试:

[features]
rel_trace = ["tracing/release_max_level_trace"]
max_trace = ["tracing/max_level_trace"]

cargo run -p app --release --features rel_trace 和 --features max_trace,STATIC_MAX_LEVEL 各是多少?cache miss 那行回来了吗?

修法

feature 只能加不能减,下游没有办法关掉上游开的 feature,也不能用更宽的级别覆盖它(见下面的动脑筋答案)。能做的:

  • 让开 feature 的那个库去掉它。 级别上限应该由最终的二进制决定;库要在 release 里省掉日志开销,应该交给应用去开,而不是自己写进 [dependencies]。
  • 在它改之前用 [patch] 换掉它。 把那个库拷到本地或 fork,删掉 tracing 的 release_max_level_*,在 workspace 根的 Cargo.toml 里 [patch.crates-io] quiet-dep = { path = "..." }。
  • 如果是你自己的库,改成让应用决定:库里不写这些 feature;应用想在 release 里删掉 debug!,就在应用自己的 Cargo.toml 里开 release_max_level_info。

怎么确认自己没踩

看 EnvFilter 的警告。 用 EnvFilter 的程序其实已经被提醒过了。把上面 app 的 subscriber 换成 EnvFilter::from_default_env()(tracing-subscriber 加 env-filter feature),RUST_LOG=debug 跑 release(3 次输出相同;没开 tracing-subscriber 的 ansi feature,所以警告不带颜色):

warning: some trace filter directives would enable traces that are disabled statically
note: `debug` would enable the DEBUG level for all targets
note: the static max level is `info`
help: to enable DEBUG logging, remove the `max_level_info` feature from the `tracing` crate
 INFO app: start

前四行是 Builder::from_directives 用 eprintln! 打到 stderr 的:任何一条指令的级别比 STATIC_MAX_LEVEL 宽,就打这段(见 EnvFilter)。它只在构造 EnvFilter 时打一次,夹在启动输出里很容易漏看。最后的 help 行要小心:它按 STATIC_MAX_LEVEL 查一张写死的表(INFO 对应 "max_level_info"),不区分 max_level_* 和 release_max_level_*,这里真正要去掉的是 release_max_level_info。前面用 with_max_level(Level::TRACE) 的那个程序就没有这段警告。

启动时打一行 STATIC_MAX_LEVEL,像前面 start 那行。release 构建里看到 info,就知道 debug! 已经不在二进制里了。

CI 里检查 tracing 的 feature 列表:

cargo tree -p app -i tracing -f '{f}' --depth 0 | grep -q max_level

在上面那个 workspace 里退出码是 0(找到了),在一个没开级别 feature 的 crate 里是 1。这一条同时匹配 max_level_* 和 release_max_level_*;应用自己有意开了某一个的话,把模式写成别的那些。

动脑筋答案

各跑 1 次(结果由 feature 在编译期决定,不随运行变化):

== release +rel_trace
 INFO app: start profile="release" STATIC_MAX_LEVEL=info
 INFO quiet_dep: quiet-dep working
== release +max_trace
 INFO app: start profile="release" STATIC_MAX_LEVEL=info
 INFO quiet_dep: quiet-dep working

两种都还是 info,cache miss 没回来。

  • rel_trace:两个 release_max_level_* 同时开,get_max_level_inner 的 if 链从 off 往 trace 排,release_max_level_info 的分支在前面,先命中,取更严的那个。
  • max_trace:release 构建里所有 release_max_level_* 的分支排在所有 max_level_* 前面,release_max_level_info 先命中,max_level_trace 轮不到。

小结

  • 症状:dev 构建正常,release 构建里 debug! / trace! 全部消失,subscriber 和 RUST_LOG 怎么设都没用。
  • 原因:某个依赖开了 tracing/release_max_level_*。feature 在依赖图里合并,整个程序共享一份 tracing,STATIC_MAX_LEVEL 在 release 下变成那个级别,被挡住的事件在编译期就被删掉。
  • 用 EnvFilter 时,RUST_LOG 比静态上限宽会在 stderr 打一段「disabled statically」警告,但 help 行写的 feature 名不分 release_。
  • cargo tree -e features -i tracing 里 tracing feature "release_max_level_..." 下面列的就是开它的包;cargo tree -i tracing -f '{f}' --depth 0 只打印最终的 feature 列表。
  • 下游无法抵消:再开 release_max_level_trace 或 max_level_trace 都不行。只能让那个库去掉它,或用 [patch] 换掉。
  • 库不应该开这组 feature,级别上限交给应用决定。

💬 关联讨论

发起讨论
加载中...