用了 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
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。
还是上面那个每行 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 的速度。