Rust in Everything
基于 tracing-appender 0.2.5

用了 non_blocking,一行日志都没有

主线位置:事件主线的最后一步。fmt::Layer 把一行拼好交给 writer,NonBlocking 的 writer 不写盘,只把这行塞进一个通道;真正的写入在后台线程里。守卫没了,后台线程就没了,事件主线照常走完,最后一步落了空。

flowchart TB
  ev["info! 走完主线"] --> fl["fmt 拼好一行"]
  fl --> nb["NonBlocking::write"]
  nb --> q{"通道"}
  q -->|"满了,lossy"| drop1["丢弃,计数加一"]
  q -->|"后台线程已退出"| drop2["丢弃,计数加一"]
  q --> wk["后台线程写出"]
  g["WorkerGuard drop"] --> sd["发 Shutdown"]
  sd --> wk
  wk --> exitnode["线程退出"]

tracing-appender 0.2.5 的 non_blocking 把任意 io::Write 搬到一个专门的线程上写,调用方只付一次入队的开销。它返回两样东西:NonBlocking(实现了 MakeWriter,交给 fmt)和 WorkerGuard。所有坑都出在后者。

复现

tracing = "=0.1.44"
tracing-subscriber = "=0.3.23"
tracing-appender = "=0.2.5"
fn main() {
  let (writer, _) = tracing_appender::non_blocking(std::io::stdout());
  let counter = writer.error_counter();
  tracing_subscriber::fmt().with_ansi(false).without_time().with_writer(writer).init();
  for i in 0..3 {
    tracing::info!(i, "hello");
  }
  eprintln!("dropped_lines = {}", counter.dropped_lines());
}

M2 Max、rustc 1.99.0、--release,连跑 20 次,每次的输出都只有这一行(来自 eprintln!):

dropped_lines = 3

三条事件一条都没出来,没有 panic,没有错误。只把 _ 改成 _guard:

 INFO guard_named: hello i=0
 INFO guard_named: hello i=1
 INFO guard_named: hello i=2
dropped_lines = 0

跑 3 次,三行日志都在;dropped_lines = 0 那一行的位置每次不同,有一次夹在 i=0 和 i=1 之间。它是主线程直接写 stderr 的,日志是后台线程稍后写的,两者谁先谁后不确定,这本身就说明了「非阻塞」的意思。

编译这段代码,cargo build 没有警告,cargo clippy 加上 -W let_underscore_drop -W clippy::let_underscore_must_use -W clippy::pedantic 也没有。WorkerGuard 确实标了 #[must_use],但 must_use 只管「表达式的值没被用掉」,元组被解构进 let 模式就算用掉了;let_underscore_* 这几个 lint 只认整个右边是 let _ = ... 的写法,不看元组里的 _。

为什么

_ 不是变量名,是「不绑定」的模式:元组里对应的那个值没有地方存,这条 let 语句结束时就被 drop。_guard 是一个普通变量(下划线开头只是不报「未使用」警告),活到作用域结束。crate 文档专门写了这一点:「Note that the WorkerGuard returned by non_blocking must be assigned to a binding that is not _, as _ will result in the WorkerGuard being dropped immediately.」

守卫 drop 时做的事在 impl Drop for WorkerGuard:

impl Drop for WorkerGuard {
    fn drop(&mut self) {
        match self
            .sender
            .send_timeout(Msg::Shutdown, Duration::from_millis(100))
        {
            Ok(_) => {
                // Attempt to wait for `Worker` to flush all messages before dropping. This happens
                // when the `Worker` calls `recv()` on a zero-capacity channel. Use `send_timeout`
                // so that drop is not blocked indefinitely.
                // TODO: Make timeout configurable.
                let _ = self.shutdown.send_timeout((), Duration::from_millis(1000));
            }
            Err(SendTimeoutError::Disconnected(_)) => (),
            Err(SendTimeoutError::Timeout(e)) => println!(
                "Failed to send shutdown signal to logging worker. Error: {:?}",
                e
            ),
        }
    }
}

先往日志通道里发一个 Msg::Shutdown,它排在已经入队的行后面;再在一个容量为 0 的 shutdown 通道上等后台线程来接。后台线程的循环在 worker_thread:

                loop {
                    match self.work() {
                        Ok(WorkerState::Continue) | Ok(WorkerState::Empty) => {}
                        Ok(WorkerState::Shutdown) | Ok(WorkerState::Disconnected) => {
                            let _ = self.shutdown.recv();
                            break;
                        }
                        Err(_) => {
                            // TODO: Expose a metric for IO Errors, or print to stderr
                        }
                    }
                }

work 一批批取行写出,取到 Shutdown 就 flush 并返回,线程在 shutdown.recv() 上和守卫会合后退出,持有的接收端随之释放。

此后 fmt 每写一行都调用 NonBlocking::write:

    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
        let buf_size = buf.len();
        if self.is_lossy {
            if self.channel.try_send(Msg::Line(buf.to_vec())).is_err() {
                self.error_counter.incr_saturating();
            }
        } else {
            return match self.channel.send(Msg::Line(buf.to_vec())) {
                Ok(_) => Ok(buf_size),
                Err(_) => Err(io::Error::from(io::ErrorKind::Other)),
            };
        }
        Ok(buf_size)
    }

默认是 lossy。接收端已经没了,try_send 返回错误,计数加一,然后照样返回 Ok。fmt 看不到任何错误,dropped_lines 是唯一的痕迹。复现程序里是 3。(如果某一行恰好在守卫 drop 之后、后台线程退出之前入队,它会留在通道里没人读,同样丢失,只是不计数;20 次里没有出现。)非 lossy 模式下 send 会返回 Err,fmt 默认把写入错误报到 stderr,至少有个声音。同样的复现换成 NonBlockingBuilder::default().lossy(false).finish(std::io::stdout()),跑 3 次输出相同:

[tracing-subscriber] Unable to write an event to the Writer for this Subscriber! Error: other error

[tracing-subscriber] Unable to write an event to the Writer for this Subscriber! Error: other error

[tracing-subscriber] Unable to write an event to the Writer for this Subscriber! Error: other error

📝NOTE
冷知识:守卫原本不等后台线程写完

0.1.1 及以前,WorkerGuard drop 时只往通道里发一个 Shutdown 就返回,不等后台线程。issue #1120「appender: WorkerGuard flush guarantee breach」报告:守卫明明活到 main 结束,日志文件却时有时无,「the messages to the log file are sometimes never written」;主线程睡 1 毫秒就好了。原因是 main 返回、进程退出时,后台线程可能还没来得及处理队列。PR #1125 改成现在的两段式:「The first shutdown signal is sent through the main message channel ... Then WorkerGuard sends a second signal on a second channel that is zero-capacity. This means It will only succeed a send() when a recv() is called on the other end.」上面 Drop 里的 shutdown.send_timeout 和 worker_thread 里的 shutdown.recv() 就是这次加的,连同那句「TODO: Make timeout configurable」。首次发布于 tracing-appender 0.1.2(CHANGELOG:「Fixed a race condition when logging on shutdown (#1125)」)。

守卫在,也可能丢

守卫保证的是「drop 时尽量等后台线程写完」,有三种情况它管不到。用一个每行要 20 ms 的慢 writer 看:

use std::io::{self, Write};
use std::time::{Duration, Instant};

// 一个慢 writer:每行 20 ms,模拟慢磁盘或网络
struct Slow;

impl Write for Slow {
  fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
    std::thread::sleep(Duration::from_millis(20));
    io::stdout().write_all(buf)?;
    Ok(buf.len())
  }
  fn flush(&mut self) -> io::Result<()> {
    io::stdout().flush()
  }
}

fn main() {
  let args: Vec<String> = std::env::args().collect();
  let how = args[1].as_str();
  let n: usize = args[2].parse().unwrap();
  let (writer, _guard) = tracing_appender::non_blocking(Slow);
  tracing_subscriber::fmt()
    .with_ansi(false)
    .without_time()
    .with_target(false)
    .with_writer(writer)
    .init();
  for i in 0..n {
    tracing::info!(i);
  }
  let start = Instant::now();
  match how {
    "exit" => std::process::exit(0),
    "return" => {
      drop(_guard);
      eprintln!("guard dropped after {} ms", start.elapsed().as_millis());
    }
    _ => unreachable!(),
  }
}

stdout 重定向到文件后数行数,exit 5 和 return 5 各跑 3 次(== 和 lines written: 两种行是外面的 shell 脚本打印的,wc -l 数 stdout 文件;guard dropped 那行是程序的 stderr):

== exit 5
lines written: 0
== return 5
guard dropped after 143 ms
lines written: 5

三次结果都一样。

std::process::exit 不跑析构。 守卫的 Drop 根本没执行,队列里的 5 行一行都没写出。WorkerGuard 的文档点名了这一种:「if the program terminates abruptly (such as through an uncaught panic or a std::process::exit), some spans or events may not be written」。panic 那一半指的是不跑析构的情况,比如 panic = "abort";main 里 panic 并展开时,守卫会照常 drop:同一个程序把 exit 换成 panic!("boom"),跑 3 次,panic 消息之后 5 行都写出来了。把守卫塞进 static、Box::leak 或 mem::forget 则和 exit 一样:它永远不会被 drop,退出时没有人等后台线程。

drop 最多等 1 秒。 return 5 时 drop 花了 143 ms,正好是写完 5 行的时间。等待的上限写死在上面的 send_timeout((), Duration::from_millis(1000)) 里,队列里积压超过 1 秒的活,超出的部分随进程退出一起消失,见文末动脑筋。

队列满了默认丢。 通道容量是 DEFAULT_BUFFERED_LINES_LIMIT = 128_000 行,NonBlockingBuilder 的默认值 是 is_lossy: true。把容量调到 8、writer 每行 1 ms,一口气发 1000 条:

use std::io::{self, Write};
use std::sync::atomic::{AtomicUsize, Ordering::Relaxed};
use std::time::{Duration, Instant};

use tracing_appender::non_blocking::NonBlockingBuilder;

static WRITTEN: AtomicUsize = AtomicUsize::new(0);

// 每行 1 ms 的 writer,只计数不输出
struct Slow;

impl Write for Slow {
  fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
    std::thread::sleep(Duration::from_millis(1));
    WRITTEN.fetch_add(1, Relaxed);
    Ok(buf.len())
  }
  fn flush(&mut self) -> io::Result<()> {
    Ok(())
  }
}

fn main() {
  let lossy = std::env::args().nth(1).unwrap() == "lossy";
  let (writer, guard) = NonBlockingBuilder::default()
    .buffered_lines_limit(8)
    .lossy(lossy)
    .finish(Slow);
  let counter = writer.error_counter();
  let sub = tracing_subscriber::fmt().with_writer(writer).finish();
  let start = Instant::now();
  tracing::subscriber::with_default(sub, || {
    for i in 0..1000 {
      tracing::info!(i);
    }
  });
  let emit_ms = start.elapsed().as_millis();
  drop(guard);
  println!(
    "lossy={lossy:<5} 发 1000 条用了 {emit_ms:>4} ms,写出 {:>4},dropped_lines = {}",
    WRITTEN.load(Relaxed),
    counter.dropped_lines()
  );
}

各跑 3 次:

lossy=true  发 1000 条用了    0 ms,写出    9,dropped_lines = 991
lossy=true  发 1000 条用了    0 ms,写出    9,dropped_lines = 991
lossy=true  发 1000 条用了    0 ms,写出    9,dropped_lines = 991
lossy=false 发 1000 条用了 1478 ms,写出 1000,dropped_lines = 0
lossy=false 发 1000 条用了 1473 ms,写出 1000,dropped_lines = 0
lossy=false 发 1000 条用了 1481 ms,写出 1000,dropped_lines = 0

lossy 时只写出 9 行:通道里能放 8 行,后台线程手上正在写 1 行,其余 991 行入队失败、被计数后丢掉,发事件的线程一点都没被拖慢。lossy(false) 一行不丢,代价是发事件的线程被 send 阻塞,1000 条花了将近 1.5 秒,写日志的速度变成了程序的速度。默认的 128000 行很少被一次填满,但磁盘卡住或 writer 很慢时,丢的就是最需要的那段。

修法

  • 守卫绑到一个有名字的变量上,放在 main 里,让它活到 main 结束:let (writer, _guard) = tracing_appender::non_blocking(...)。初始化写在单独函数里时,把守卫作为返回值交回 main,不要在函数里丢掉。
  • 需要提前退出时,不要直接 std::process::exit;先让守卫 drop(drop(guard) 或从 main 返回一个退出码),再退出。
  • 不能丢日志的程序用 NonBlockingBuilder::default().lossy(false),接受写日志反过来限速;能丢的话,定期或在退出前把 writer.error_counter().dropped_lines() 打出来,至少知道丢了多少。
  • 退出前积压可能超过 1 秒(慢的网络 writer、大量日志),守卫兜不住。要么换成同步 writer,要么在退出路径上自己等到队列清空再 drop。

怎么确认自己没踩

  • 搜 non_blocking(,看返回的元组第二项是不是 _。编译器和 clippy 都不会帮你找。
  • 程序启动后立刻打一条日志,再确认它真的出现在目标里;dropped_lines() 在启动后就大于 0,基本就是守卫没了。
  • 搜 process::exit 和 panic = "abort",确认它们之前守卫已经 drop。
❗IMPORTANT
动脑筋:积压 2 秒的活,守卫等多久、写出几行

还是上面那个每行 20 ms 的程序,运行 at_exit return 100:100 行入队后马上 drop 守卫,再从 main 返回。M2 Max、rustc 1.99.0、--release。stderr 上打印的等待时间大约是多少毫秒?stdout 里能有几行?

动脑筋答案

跑 3 次(同样由 shell 脚本数行数):

== return 100
guard dropped after 1001 ms
lines written: 36
== return 100
guard dropped after 1010 ms
lines written: 35
== return 100
guard dropped after 1010 ms
lines written: 35
  • 等了约 1000 ms:Shutdown 能立刻入队(通道远没满),然后在 shutdown.send_timeout((), 1000 ms) 上等后台线程来接。后台线程要先写完排在前面的 100 行才会取到 Shutdown,2 秒的活 1 秒干不完,send_timeout 超时,drop 返回。
  • 只写出 35、36 行,而不是 1000 / 20 = 50 行:thread::sleep(20 ms) 在这台机器上实际每次睡得更久(前面 5 行花了 143 ms,约 28 ms 一行),1 秒里写了 35 行左右。行数随调度略有浮动。
  • 剩下的 60 多行还在通道里,main 返回、进程退出,后台线程随之消失,没有任何提示:超时分支是 let _ =,不打印。

小结

  • non_blocking 返回的 WorkerGuard 一 drop,后台线程就退出;let (w, _) = ... 让它在这一行就被 drop,之后每一行都在 NonBlocking::write 里被静默丢弃,只有 error_counter().dropped_lines() 记了数。rustc 和 clippy 都不提示。
  • 守卫的 Drop 先发 Shutdown(排在已入队的行后面),再在容量为 0 的通道上最多等 1 秒,等后台线程写完前面的行。这个两段式来自 #1125,首次发布于 0.1.2。
  • std::process::exit、不展开的 panic、被泄漏的守卫都不会跑 Drop,队列里的行全丢;积压超过 1 秒时,超出部分也丢。
  • 默认队列 128000 行、lossy:满了就丢、计数,不阻塞调用方;lossy(false) 不丢,但会把调用方拖到 writer 的速度。

💬 关联讨论

发起讨论
加载中...