cargo test 不捕获 tracing 的日志

主线位置：事件主线的最后一步，fmt::Layer 向 MakeWriter 要一个 writer 并 write_all。libtest 能不能把这一行收进某个测试的输出，只取决于这个 writer 走不走 print!。

flowchart TB
  ev["fmt 拼好一行"] --> mw{"MakeWriter 是谁"}
  mw -->|"默认 io::stdout"| raw["直接写 fd 1"]
  raw --> screen["总是出现在终端"]
  mw -->|TestWriter| pr["print!"]
  pr --> cap{"本线程有捕获缓冲"}
  cap -->|有| buf["进该测试的缓冲"]
  buf --> fail["测试失败时才显示"]
  cap -->|"没有或 --nocapture"| screen

cargo test 默认捕获每个测试的输出：通过的测试什么都不显示，失败的测试在 ---- 名字 stdout ---- 下面把它打印过的东西列出来。println! 是这样，tracing::info! 却不一定。

现象

两个都会通过的测试：

[dev-dependencies]
tracing = "=0.1.44"
tracing-subscriber = "=0.3.23"

// 两个都会通过的测试，一个用 println!，一个用 fmt().init() 打日志
#[test]
fn uses_println() {
  println!("println from a passing test");
}

#[test]
fn uses_fmt_init() {
  tracing_subscriber::fmt().with_ansi(false).without_time().init();
  tracing::info!("tracing event from a passing test");
}

M2 Max、rustc 1.99.0，cargo test --test plain_init（dev 构建），跑 3 次输出相同（去掉了 cargo 自己的 Compiling、Running 行）：

running 2 tests
test uses_println ... ok
 INFO plain_init: tracing event from a passing test
test uses_fmt_init ... ok

test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

println! 的那行被收起来了，通过的测试不显示；tracing 的那行直接混进了测试列表。测试一多、并行一跑，各测试的日志交错在一起，分不清哪行是谁的。反过来，测试失败时它的 stdout 段里却没有它的日志：

#[test]
fn fails_with_default_writer() {
  let _ = tracing_subscriber::fmt().with_ansi(false).without_time().try_init();
  tracing::info!("event from the failing test");
  panic!("boom");
}

running 1 test
 INFO fail_default: event from the failing test
test fails_with_default_writer ... FAILED

failures:

---- fails_with_default_writer stdout ----

thread 'fails_with_default_writer' (1627885) panicked at tests/fail_default.rs:7:3:
boom
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

（跑 3 次，除线程号外相同；截到 stdout 段为止。）日志在测试开始时就打到了终端，---- ... stdout ---- 下面只有 panic 信息。

为什么

libtest 的捕获不是重定向文件描述符。std 的 io/stdio.rs 里有一个线程局部的 OUTPUT_CAPTURE，注释是「Used by the test crate to capture the output of the print macros and panics」。libtest 在每个测试线程上把它设成一块缓冲；print! / println! / eprint! / eprintln! 最后都走到 print_to，先看本线程有没有这块缓冲，有就写进去。直接拿 io::stdout() 调 write_all 不经过 print_to，所以不被捕获。

fmt 的默认 writer 正是后者：SubscriberBuilder 的类型参数默认值是 W = fn() -> io::Stdout，也就是每条事件调一次 io::stdout 拿 writer，再 write_all（fmt 的 MakeWriter 一节）。

修法：with_test_writer

SubscriberBuilder::with_test_writer（fmt::Layer 上也有一个 同名方法）把 writer 换成 TestWriter，它的 io::Write 绕回到宏上：

impl io::Write for TestWriter {
    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
        let out_str = String::from_utf8_lossy(buf);
        if self.use_stderr {
            eprint!("{}", out_str)
        } else {
            print!("{}", out_str)
        }
        Ok(buf.len())
    }
    // ...
}

一个会通过、一个会失败的测试，共用一个 init：

fn init() {
  // 每个测试都可能先到，用 try_init，失败（已经装过）就算了
  let _ = tracing_subscriber::fmt()
    .with_ansi(false)
    .without_time()
    .with_test_writer()
    .try_init();
}

#[test]
fn passes() {
  init();
  tracing::info!("event from the passing test");
}

#[test]
fn fails() {
  init();
  tracing::info!("event from the failing test");
  assert_eq!(1 + 1, 3);
}

cargo test --test test_writer，跑 3 次，只有 test ... ok 这几行的顺序不同。其中一次（这个文件里还有一个下面要讲的 stderr_writer 测试）：

running 3 tests
test passes ... ok
test stderr_writer ... ok
test fails ... FAILED

failures:

---- fails stdout ----
 INFO test_writer: event from the failing test

thread 'fails' (1597997) panicked at tests/test_writer.rs:22:3:
assertion `left == right` failed
  left: 2
 right: 3
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace


failures:
    fails

test result: FAILED. 2 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

通过的测试一行都没有；失败的测试，日志和 panic 信息排在一起。subscriber 是全局的，两个测试共用它，可每行日志仍然进了发出它的那个线程的缓冲：捕获是按线程挑缓冲的，与 subscriber 装在哪无关。

TestWriter::with_stderr() 在 0.3.23 里不起作用

0.3.20 起有 TestWriter::with_stderr()，用来让 TestWriter 走 eprint!。但 fmt 每条事件都通过 MakeWriter 现做一个 writer，而 MakeWriter for TestWriter 是：

impl<'a> MakeWriter<'a> for TestWriter {
    type Writer = Self;

    fn make_writer(&'a self) -> Self::Writer {
        Self::default()
    }
}

返回的是 Self::default()，use_stderr 永远是 false，with_stderr() 设的值被扔掉了。上面那个文件里的第三个测试：

use tracing_subscriber::fmt::TestWriter;

#[test]
fn stderr_writer() {
  // 只在本线程生效的 subscriber，写给 TestWriter::with_stderr()
  let sub = tracing_subscriber::fmt()
    .with_ansi(false)
    .without_time()
    .with_writer(TestWriter::with_stderr())
    .finish();
  tracing::subscriber::with_default(sub, || {
    tracing::info!("where do I go?");
  });
}

不加 --nocapture 时 print! 和 eprint! 都被捕获，看不出差别（上面它是 ok，什么都没显示），差别要到 --nocapture 下才有，见文末动脑筋。截至本卷对照的本地仓库 main（2026-10-09 的提交）这三行仍然没变。

每个测试都 init

libtest 在一个进程里并行跑测试，全局 subscriber 只能设一次，每个测试都 fmt().with_test_writer().init() 必有一个测试 panic，哪一个取决于谁先跑。panic 原文、源码和修法在 Unable to install global subscriber 与 failed to set global default subscriber。在测试里能用的有两种写法，区别在子线程：

use std::sync::Once;

static INIT: Once = Once::new();

fn init_global() {
  INIT.call_once(|| {
    tracing_subscriber::fmt().with_ansi(false).without_time().with_test_writer().init();
  });
}

fn work() {
  tracing::info!("on the test thread");
  std::thread::spawn(|| tracing::info!("on a spawned thread")).join().unwrap();
}

#[test]
fn global_once() {
  init_global();
  work();
  panic!("show me the logs");
}

#[test]
fn thread_default() {
  let sub = tracing_subscriber::fmt().with_ansi(false).without_time().with_test_writer().finish();
  let _guard = tracing::subscriber::set_default(sub);
  work();
  panic!("show me the logs");
}

两个测试都故意失败，好看到各自捕获了什么。单独跑 cargo test --test threads thread_default，3 次相同：

---- thread_default stdout ----
 INFO threads: on the test thread

thread 'thread_default' (1600539) panicked at tests/threads.rs:28:3:
show me the logs

（只截了 stdout 段。）子线程那行没有了：set_default 装的是线程默认，只对当前线程有效（Dispatch：全局与线程局部），新线程上没有 subscriber。两个一起跑 cargo test --test threads，3 次相同（只截两个 stdout 段）：

---- global_once stdout ----
 INFO threads: on the test thread
 INFO threads: on a spawned thread

thread 'global_once' (N) panicked at tests/threads.rs:20:3:
show me the logs

---- thread_default stdout ----
 INFO threads: on the test thread
 INFO threads: on a spawned thread

thread 'thread_default' (N) panicked at tests/threads.rs:28:3:
show me the logs

（线程号换成了 N。）

• global_once：全局 subscriber 对所有线程有效，子线程的那行也在，而且进的是这个测试的缓冲：std::thread::spawn 出来的线程继承父线程的输出捕获。
• thread_default 这次也有子线程那行，因为 global_once 已经装了全局 subscriber，子线程找不到线程默认时落到了全局的那个上。同一个测试，单独跑和一起跑结果不同；如果 thread_default 的子线程比 global_once 的 init 先跑，这行又会消失。

所以：测试里会起线程（包括 tokio 的多线程运行时），用 Once（或 let _ = try_init()）装一个全局的 with_test_writer()；所有逻辑都在测试线程上、而且各测试要不同的配置，用 set_default 加守卫。同一个测试二进制里最好只用一种，免得结果取决于运行顺序。

怎么确认自己没踩

• cargo test 全部通过时还能看到 tracing 的日志行，说明 writer 没走 print!：检查测试里装 subscriber 的地方有没有 with_test_writer()（或 .with_writer(TestWriter::new())）。

• 有自定义 writer 的（写文件、写 io::stderr()），在测试里同样不被捕获，这是预期的；要捕获就得让它最终调 print! / eprint!。

• 想让测试日志走 stderr，0.3.23 里 TestWriter::with_stderr() 做不到，自己写一个在 write 里 eprint! 的 writer，用闭包当 MakeWriter：

  Copy

  use std::io;
  
  // 走 eprint! 的 writer，给测试用
  struct TestStderr;
  
  impl io::Write for TestStderr {
    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
      eprint!("{}", String::from_utf8_lossy(buf));
      Ok(buf.len())
    }
    fn flush(&mut self) -> io::Result<()> {
      Ok(())
    }
  }
  
  #[test]
  fn custom_stderr() {
    let sub = tracing_subscriber::fmt().with_ansi(false).without_time().with_writer(|| TestStderr).finish();
    tracing::subscriber::with_default(sub, || tracing::info!("custom stderr writer"));
  }
  

  不加 --nocapture 时它通过且什么都不显示（被捕获了）；加 --nocapture、只看 stderr，那一行 INFO fail_default: custom stderr writer 出现在 stderr 上。

• 测试里多个测试都装 subscriber 的，单独跑一个和全部一起跑各试一次，输出不同就说明线程默认和全局默认混用了。

cargo test --test test_writer stderr_writer -- --nocapture 2>/dev/null   # 只看 stdout
cargo test --test test_writer stderr_writer -- --nocapture 2>&1 >/dev/null # 只看 stderr

动脑筋答案

只看 stdout，3 次相同：

running 1 test
 INFO test_writer: where do I go?
test stderr_writer ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 2 filtered out; finished in 0.00s

只看 stderr：除了 cargo 自己的 Finished、Running 两行，什么都没有。

• --nocapture 让 libtest 不设捕获缓冲，print! 和 eprint! 分别写到真正的 stdout 和 stderr，这时才看得出 writer 走的是哪个宏。
• 日志在 stdout：with_stderr() 造的 TestWriter 只是 with_writer 收下的那个「工厂」，每条事件用的 writer 是 make_writer 返回的 Self::default()，use_stderr 为 false，走的是 print!。
• 在 zsh 里这样写要小心：zsh 的 MULTIOS 选项下 2>&1 >/dev/null | ... 会让 stdout 同时进管道和 /dev/null，看起来像是 stderr 里也有。

小结

• libtest 的输出捕获靠 std 里线程局部的 OUTPUT_CAPTURE，只有 print! 一族宏会查它；fmt 默认的 writer 直接写 io::stdout()，所以通过的测试也刷屏、失败的测试段里反而没有日志。
• 测试里用 with_test_writer()：TestWriter 的 write 调 print!，日志进发出它的那个线程的缓冲，只在测试失败时显示。它来自 #638 / #938，首次发布于 0.2.12。
• 0.3.23 的 TestWriter::with_stderr() 不生效：MakeWriter 每次返回 Self::default()，丢了 use_stderr；不加 --nocapture 时本来也看不出差别。
• 每个测试都 init 会 panic。Once / try_init 装全局的，子线程的日志也能收到；set_default 加守卫只管当前线程，子线程的日志要么丢，要么落到别的测试装的全局 subscriber 上。