跨 .await 持有 span.enter(),日志挂到别的 span 上
主线位置:span 主线的「进入 / 退出」放进异步代码以后出的错。
enter把 span 压进线程的 span 栈,守卫 drop 才出栈;守卫跨过.await时,任务让出了线程,span 却还在栈顶,事件主线上别的任务查「当前 span」就查到了它。
flowchart TB enter["span.enter()"] --> push["压进线程 span 栈"] push --> aw[".await 返回 Pending"] aw --> keep["守卫还在 future 里"] keep --> other["同线程跑别的任务"] other --> wrong["它的日志挂到这个 span"] aw -.->|正确写法| ins["Instrumented 每次 poll 后退出"]
这个坑没有报错,只有错的输出。机制在 Instrument 与异步 一页逐步拆过,本页只讲怎么认出它、为什么工具不拦、怎么改、怎么查。
现象
两个任务各建一个 span、enter、打一条日志、yield_now 让出、再打一条;第三个任务自己没有 span。全部跑在 current_thread 运行时上:
tracing = "=0.1.44"
tracing-subscriber = "=0.3.23"
tokio = { version = "=1.54.1", features = ["macros", "rt"] }
use tracing::{Instrument, info, info_span};
// 错误写法:守卫跨 .await
async fn wrong(id: u32) {
let span = info_span!("task", id);
let _g = span.enter();
info!(who = id, "start");
tokio::task::yield_now().await;
info!(who = id, "after yield");
}
// 正确写法:span 交给 Instrumented,每次 poll 进出
async fn right(id: u32) {
async {
info!(who = id, "start");
tokio::task::yield_now().await;
info!(who = id, "after yield");
}
.instrument(info_span!("task", id))
.await
}
// 旁观者:自己没有任何 span
async fn bystander() {
info!(who = "c", "no span here");
}
#[tokio::main(flavor = "current_thread")]
async fn main() {
tracing_subscriber::fmt()
.with_ansi(false)
.without_time()
.with_target(false)
.init();
info!("--- enter() 跨 .await");
let tasks = [
tokio::spawn(wrong(1)),
tokio::spawn(wrong(2)),
tokio::spawn(bystander()),
];
for t in tasks {
t.await.unwrap();
}
info!("--- .instrument()");
let tasks = [
tokio::spawn(right(1)),
tokio::spawn(right(2)),
tokio::spawn(bystander()),
];
for t in tasks {
t.await.unwrap();
}
info!("--- 结束");
}
M2 Max、rustc 1.99.0、--release,跑 5 次输出相同:
INFO --- enter() 跨 .await
INFO task{id=1}: start who=1
INFO task{id=1}:task{id=2}: start who=2
INFO task{id=1}:task{id=2}: no span here who="c"
INFO task{id=1}:task{id=2}: after yield who=2
INFO task{id=1}: after yield who=1
INFO --- .instrument()
INFO task{id=1}: start who=1
INFO task{id=2}: start who=2
INFO no span here who="c"
INFO task{id=2}: after yield who=2
INFO task{id=1}: after yield who=1
INFO --- 结束
who 是真正的发出者,行首的 span 链是 fmt 认定的上下文。错误写法下有三处不对:
task{id=2}被记成task{id=1}的子 span。父 span 在new_span时就定了,之后改不回来。- 旁观者
who="c"的事件被挂到两个和它无关的 span 下。 - 任务 2 的每一行都多了
task{id=1}:前缀。
在日志里认这个坑,看的就是这种「span 链里出现了别的请求的 span」:两个请求的 id 叠在一行里,或者一个不该有 span 的后台任务带着某个请求的 span。多线程运行时上症状更散,任务恢复时可能换了线程,守卫在另一个线程上 drop,原线程的栈里一直留着这个 span(Registry 的 span 栈按线程存)。
为什么会这样
Span::enter 返回 Entered 守卫,span 进入的时长等于守卫活着的时长。同步代码里这和词法作用域一致;async fn 里不是。.await 返回 Pending 时函数「暂停」,局部变量(包括 _g)留在 future 的状态里,没有 drop,所以也没有 exit。线程接着 poll 下一个任务,那个任务里的 info_span! 和 info! 去问「当前 span」,得到的是栈顶上这个不属于它的 span。
enter 的文档在 「In Asynchronous Code」 一节写了这件事:
/// **Warning**: in asynchronous code that uses [async/await syntax][syntax],
/// `Span::enter` should be used very carefully or avoided entirely. Holding
/// the drop guard returned by `Span::enter` across `.await` points will
/// result in incorrect traces. For example,
逐个时刻的 span 栈变化见 Instrument 与异步 里的表。
编译器和 clippy 默认都不拦
编译器:Entered 是 Send 的(原因见 Span 与 Entered),上面的 wrong 放进 tokio::spawn 照样编译。只有拥有 span 的 EnteredSpan(entered() 的返回值)带了一个 PhantomNotSend 字段,在要求 Send 的 tokio::spawn 里跨 .await 持有它会编译失败:
use tracing::info_span;
#[tokio::main]
async fn main() {
// 借用版守卫 Entered 跨 .await:能编译
tokio::spawn(async {
let span = info_span!("a");
let _g = span.enter();
tokio::task::yield_now().await;
})
.await
.unwrap();
// 拥有版守卫 EnteredSpan 跨 .await:编译不过
tokio::spawn(async {
let _g = info_span!("b").entered();
tokio::task::yield_now().await;
})
.await
.unwrap();
}
rustc 1.99.0 只对第二个任务报错(registry 路径缩短为 ~/.cargo/registry/...):
error: future cannot be sent between threads safely
--> src/bin/not_send.rs:15:3
|
15 | / tokio::spawn(async {
16 | | let _g = info_span!("b").entered();
17 | | tokio::task::yield_now().await;
18 | | })
| |____^ future created by async block is not `Send`
|
= help: within `{async block@src/bin/not_send.rs:15:16: 15:21}`, the trait `Send` is not implemented for `*mut ()`
note: future is not `Send` as this value is used across an await
--> src/bin/not_send.rs:17:30
|
16 | let _g = info_span!("b").entered();
| -- has type `EnteredSpan` which is not `Send`
17 | tokio::task::yield_now().await;
| ^^^^^ await occurs here, with `_g` maybe used later
note: required by a bound in `tokio::spawn`
--> ~/.cargo/registry/.../tokio-1.54.1/src/task/spawn.rs:176:21
|
174 | pub fn spawn<F>(future: F) -> JoinHandle<F::Output>
| ----- required by a bound in this function
175 | where
176 | F: Future + Send + 'static,
| ^^^^ required by this bound in `spawn`
*mut () 就是 PhantomNotSend 里的 PhantomData<*mut ()>。这条报错只出现在要求 Send 的地方;current_thread 运行时的 block_on 或 spawn_local 里持有 EnteredSpan,照样能编译,照样会错。
clippy:clippy 有 await_holding_lock、await_holding_refcell_ref,但没有针对 span 守卫的 lint。clippy 0.1.99(随 rustc 1.99.0)对上面的 wrong 不加参数跑 cargo clippy,退出码 0,没有警告。照命名习惯猜一个 -W clippy::await_holding_span_guard:
warning[E0602]: unknown lint: `clippy::await_holding_span_guard`
|
= help: did you mean: `clippy::await_holding_lock`
= note: requested on the command line with `-W clippy::await_holding_span_guard`
= note: `#[warn(unknown_lints)]` on by default
能用的是通用的 await_holding_invalid_type:它默认就是 warn,但要检查的类型列表来自 clippy.toml 的 await-holding-invalid-types,cargo clippy --explain await_holding_invalid_type 写明默认值是 (default: []),所以不配置就什么也查不出来。
修法
把 span 交给 future,而不是在 future 里进入它:
async fn right(id: u32) {
async {
// ...
}
.instrument(info_span!("task", id))
.await
}
Instrumented::poll 在每次 poll 里 enter、poll 返回就 drop 守卫,守卫从不跨 .await。上面输出的后半段就是这个写法:旁观者不在任何 span 里,两个 task 也不再互相嵌套。整个函数都要在 span 里时,直接给 async fn 加 #[tracing::instrument],它生成的就是 .instrument(span)(见 展开成什么)。要把 span 带进 tokio::spawn 的任务,在 spawn 之前写 .instrument(...) 或 .in_current_span()。
问: 只有 .await 之前那一小段同步代码需要在 span 里,也必须改成 .instrument 吗?
答: 不必。问题只在守卫跨过 .await;在 .await 之前结束它就行:放进一个块里,或者 drop(g),或者用 span.in_scope(|| ...)。下面两种写法用同一份 clippy.toml 跑 cargo clippy,没有警告,运行输出分别是 INFO a: sync part 和 INFO b: sync part:
async fn scoped() {
let span = info_span!("a");
{
let _g = span.enter();
info!("sync part");
}
work().await;
}
async fn dropped() {
let span = info_span!("b");
let g = span.enter();
info!("sync part");
drop(g);
work().await;
}
.await 之后的代码就不在 span 里了;之后也要在 span 里,就该用 .instrument。
怎么确认自己没踩
在 crate 根目录(或 workspace 根目录)放一个 clippy.toml,两个守卫都列上:
await-holding-invalid-types = [
{ path = "tracing::span::Entered", reason = "用 Instrument::instrument 代替" },
{ path = "tracing::span::EnteredSpan", reason = "用 Instrument::instrument 代替" },
]
不需要额外参数,cargo clippy 对上面的复现程序报出 wrong 里的守卫:
warning: holding a disallowed type across an await point `tracing::span::Entered`
--> src/bin/hold_across_await.rs:6:7
|
6 | let _g = span.enter();
| ^^
|
= note: 用 Instrument::instrument 代替
= help: for further information visit https://rust-lang.github.io/rust-clippy/rust-1.99.0/index.html#await_holding_invalid_type
= note: `#[warn(clippy::await_holding_invalid_type)]` on by default
对 info_span!("b").entered() 跨 .await 的写法,报的是 holding a disallowed type across an await point `tracing::span::EnteredSpan`。只列 Entered 查不到它。想让 CI 失败,用 cargo clippy -- -D clippy::await_holding_invalid_type。
tracing 0.1.44 的文档里还没有这条建议。#3463(「docs: recommend configuring await-holding-invalid-types lint」)2026-04-01 合进 main,把同样的配置写进了 Span::enter 的文档;它在 tag tracing-0.1.44 之后,截至 2026-10 还没有随任何 tracing 版本发布。
小结
- 症状:日志的 span 链里出现别的任务的 span,新 span 认错父,没有 span 的任务带上了别人的 span。没有任何报错。
- 原因:
enter()的守卫留在 future 里,.await让出线程时没有exit,同一线程上的下一个任务继承了它。 Entered是Send,编译器不拦;EnteredSpan不是Send,只在tokio::spawn这类要求Send的地方报「future cannot be sent between threads safely」。- clippy 没有
await_holding_span_guard;在clippy.toml的await-holding-invalid-types里列出tracing::span::Entered和tracing::span::EnteredSpan,await_holding_invalid_type就会报。 - 修法:
.instrument(span)或#[instrument];只有同步片段要在 span 里时,让守卫在.await前结束。