一条日志都没有
主线位置:事件主线的第四道门和最后一步。
__is_enabled和Event::dispatch都调用dispatcher::get_default;它在当前线程和全局都找不到 subscriber 时返回NoSubscriber,事件到这里就结束了,前面几道门放没放行都一样。
flowchart TB
ev["info!(..)"] --> gd["get_default"]
gd --> tls{"本线程有线程默认?"}
tls -->|有| scoped["线程默认"]
tls -->|没有| glob{"全局默认设了?"}
glob -->|是| global["全局默认"]
glob -->|否| none["NoSubscriber:丢弃"]
get_default 怎么在线程默认和全局默认之间选,在 Dispatch:全局与线程局部 里讲过,那一页也已经用一个自己写的 subscriber 试过 let _ 和线程隔离。这一页用 fmt 重现三种「一行都没有」的写法,第三种放到 tokio 的多线程运行时里。
本页的实验都在 M2 Max、rustc 1.99.0、--release 下运行,依赖:
tracing = "=0.1.44"
tracing-subscriber = "=0.3.23"
tokio = { version = "=1.54.1", features = ["full"] }
原因一:根本没装
tracing 是门面,宏只负责把事件交给当前的 dispatcher。没有人装 subscriber 时,当前的 dispatcher 是 NONE,指向零大小的 NoSubscriber,它对一切都说「不感兴趣」。连 error! 也一样:
fn main() {
tracing::error!("没有 subscriber 时的 error");
println!("has_been_set = {}", tracing::dispatcher::has_been_set());
tracing_subscriber::fmt().with_ansi(false).without_time().init();
tracing::error!("装上之后的 error");
}
连跑 3 次输出相同:
has_been_set = false
ERROR no_sub: 装上之后的 error
第一条 error! 没有任何输出,也没有警告。它不会被缓存起来,装上 subscriber 之后也不会补打。所以 init 要放在 main 的第一行,配置加载、参数解析这些可能打日志的步骤都在它后面。
这种情况常见于:只依赖了 tracing 没依赖 tracing-subscriber;库的示例或测试里没有初始化;初始化代码在某个分支里没走到。还有一种:项目里用的是 log 的 logger(比如 env_logger),依赖库却用 tracing 打日志。tracing 的 log feature 只在从来没设过 dispatcher 时把事件转给 log(见 和 log 互通),没开这个 feature 时这些日志直接消失。
原因二:let _ = set_default(..)
set_default 返回一个 DefaultGuard,守卫活多久,线程默认就设多久;守卫 drop 时把之前的值换回去。let _ = expr 不绑定变量,守卫在这条语句结束时就 drop 了:
fn main() {
let sub = tracing_subscriber::fmt().with_ansi(false).without_time().finish();
let _ = tracing::subscriber::set_default(sub);
tracing::info!("let _ 之后");
let sub = tracing_subscriber::fmt().with_ansi(false).without_time().finish();
let _guard = tracing::subscriber::set_default(sub);
tracing::info!("let _guard 之后");
}
连跑 3 次输出相同:
INFO let_underscore: let _guard 之后
_ 和 _guard 只差几个字符:前者是「不绑定」,后者是一个名字以下划线开头的普通变量,活到作用域结束。
为什么会有人写 let _ =?因为不写的时候编译器叫你这么写。直接把 set_default(sub); 当一条语句,rustc 1.99.0 报:
warning: unused return value of `tracing::subscriber::set_default` that must be used
--> src/bin/must_use.rs:3:3
|
3 | tracing::subscriber::set_default(sub);
| ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
|
= note: Dropping the guard unregisters the subscriber.
= note: `#[warn(unused_must_use)]` (part of `#[warn(unused)]`) on by default
help: use `let _ = ...` to ignore the resulting value
|
3 | let _ = tracing::subscriber::set_default(sub);
| +++++++
note 说的是对的,help 给的是 rustc 对所有 must_use 返回值的通用建议,照着改了警告消失,subscriber 照样没装上。
PR #685「Add must_use attribute to set_default」给 tracing 的 set_default 加上了 #[must_use = "Dropping the guard unregisters the subscriber."],说明只有一句:「This makes the user aware of if the guard is dropped immediately and thus, the tracing does not work.」tracing 0.1.14 的 CHANGELOG 记作「Added #[must_use] attribute to the guard returned by subscriber::set_default (#685)」。随后的 PR #686 给 tracing-core 的 dispatcher::set_default 补上同样的属性,随 tracing-core 0.1.11 发布。在此之前,set_default(sub); 一行连警告都没有;加了之后挡住了「完全忘记绑定」,却挡不住 let _ =。
原因三:set_default 只管当前线程
线程默认存在线程局部的 CURRENT_STATE 里,换一个线程就看不到了。tokio 的多线程运行时里,#[tokio::main] 的 main future 在主线程上被 block_on,tokio::spawn 出去的任务却在工作线程上被 poll(见 tokio 卷的 多线程调度器):
#[tokio::main(flavor = "multi_thread", worker_threads = 2)]
async fn main() {
let sub = tracing_subscriber::fmt()
.with_ansi(false)
.without_time()
.with_thread_names(true)
.finish();
let _guard = tracing::subscriber::set_default(sub);
tracing::info!("main 里的 future");
let mut handles = Vec::new();
for i in 0..4 {
handles.push(tokio::spawn(async move {
let thread = std::thread::current();
println!("task {i} 跑在 {}", thread.name().unwrap_or("?"));
tracing::info!(i, "spawn 出去的任务");
}));
}
for h in handles {
h.await.unwrap();
}
tracing::info!("main 结束");
}
连跑 3 次,3 次输出相同(四个任务的先后顺序取决于调度,这 3 次恰好一样):
INFO main tokio_set_default: main 里的 future
task 0 跑在 tokio-rt-worker
task 3 跑在 tokio-rt-worker
task 2 跑在 tokio-rt-worker
task 1 跑在 tokio-rt-worker
INFO main tokio_set_default: main 结束
println! 证明四个任务都跑了,跑在 tokio-rt-worker 线程上;它们的 info! 一条都没有。只在主线程上的两条打了出来,所以这个问题很难第一眼看出来:「有日志」,只是少了一大半。spawn_blocking 的阻塞线程池同理。
两种改法:
- 用全局默认:
fmt().init()(或set_global_default),所有线程都看得到。绝大多数程序应该这样做。 - 确实要线程默认(比如测试里),用
WithSubscriber把 dispatcher 绑在 future 上。with_current_subscriber在调用的那一刻取当前默认,WithDispatch每次 poll 前用set_default设上、poll 完守卫 drop(机制见 Instrument 与异步):
use tracing::instrument::WithSubscriber;
#[tokio::main(flavor = "multi_thread", worker_threads = 2)]
async fn main() {
let sub = tracing_subscriber::fmt()
.with_ansi(false)
.without_time()
.with_thread_names(true)
.finish();
let _guard = tracing::subscriber::set_default(sub);
let mut handles = Vec::new();
for i in 0..2 {
let fut = async move { tracing::info!(i, "spawn 出去的任务") };
// 在 main 线程上取当前默认 dispatcher,绑到 future 上
handles.push(tokio::spawn(fut.with_current_subscriber()));
}
for h in handles {
h.await.unwrap();
}
}
连跑 3 次输出相同(两行的先后取决于调度,没有保证):
INFO tokio-rt-worker tokio_fix: spawn 出去的任务 i=1
INFO tokio-rt-worker tokio_fix: spawn 出去的任务 i=0
with_current_subscriber 必须在 spawn 之前、在设了线程默认的那个线程上调用;写进任务内部就晚了,那时已经在工作线程上,取到的还是 NoSubscriber。把上面的任务改成 tokio::spawn(async { async { info!(..) }.with_current_subscriber().await }),连跑 3 次,info! 一次都没有输出。
M2 Max、rustc 1.99.0、--release:
#[tokio::main(flavor = "current_thread")]
async fn main() {
let sub = tracing_subscriber::fmt()
.with_ansi(false)
.without_time()
.with_thread_names(true)
.finish();
let _guard = tracing::subscriber::set_default(sub);
let h = tokio::spawn(async { tracing::info!("spawn 出去的任务") });
h.await.unwrap();
}
怎么确认自己没踩
- 在第一条日志之前打印
tracing::dispatcher::has_been_set()。false就是原因一:从来没人设过 dispatcher。注意它只增不减,设过又撤掉的线程默认也会让它变成true(见 Dispatch:全局与线程局部)。 - 搜
let _ =后面跟着set_default的地方,全部改成let _guard =。 - 搜
set_default和with_default:除了测试,生产代码里出现它们,就要问一句「之后的日志是不是都在这个线程上」。用fmt().with_thread_names(true)打一下线程名,缺的日志是不是都来自别的线程,一眼可见。 - 日志有、但少了
debug!:那是过滤,不是 dispatcher 的问题,见 RUST_LOG 设了不生效 和 release 构建里 debug! 全部消失。
动脑筋答案
连跑 3 次输出相同:
INFO main tokio_current: spawn 出去的任务
- 有,线程名是
main。单线程运行时没有工作线程,spawn出去的任务和mainfuture 都在调用block_on的那个线程上被 poll,所以主线程的线程默认对它们也有效。 - 这也是为什么同样的代码在
#[tokio::test](默认就是current_thread)里一切正常,搬到#[tokio::main](默认多线程)里日志就少了一半。
小结
- 没有 subscriber 时事件交给
NoSubscriber,连error!也不打,init之前的日志不会补打。 let _ = set_default(..)当场 drop 守卫;rustc 的must_use提示(tracing 0.1.14 起)恰好建议了这个写法。要写let _guard =。set_default是线程局部的。tokio 多线程运行时里 spawn 出去的任务在工作线程上跑,看不到它;单线程运行时看得到。- 生产代码用全局默认;需要线程默认时,用
with_current_subscriber()在 spawn 前把 dispatcher 绑到 future 上。 - 排查:
has_been_set()看有没有人设过,with_thread_names(true)看缺的日志来自哪个线程。