Rust in Everything
基于 tracing 0.1.44

跨 .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()。

📝NOTE
没有蠢问题

问: 只有 .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 前结束。

💬 关联讨论

发起讨论
加载中...