Span::record 没有效果
主线位置:span 主线中段。span 创建之后补字段走
Span::record→Subscriber::record;字段名在调用点的FieldSet里查不到,这一步在 tracing 门面里就结束了,subscriber 收不到任何回调。
flowchart TB
rec["span.record(name, v)"] --> meta{"有 meta 吗"}
meta -->|否| nothing["什么也不做"]
meta -->|有| look{"name 在 FieldSet 里"}
look -->|否| nothing
look -->|是| sub["Subscriber::record"]
sub --> fmtnode["fmt 追加到字段串"]
现象
record 之后,日志里就是没有这个字段,没有报错,没有 panic:
tracing = "=0.1.44"
tracing-subscriber = { version = "=0.3.23", default-features = false, features = ["fmt", "std"] }
use tracing::{Span, field, info, info_span, instrument};
// 1. 没声明 status
fn undeclared() {
let span = info_span!("req", id = 1);
let _g = span.enter();
span.record("status", 200);
info!(has_status = span.has_field("status"), "done");
}
// 2. 用 field::Empty 先占名字
fn declared() {
let span = info_span!("req", id = 2, status = field::Empty);
let _g = span.enter();
span.record("status", 200);
info!(has_status = span.has_field("status"), "done");
}
// 3. #[instrument] 里只写名字,等于 field::Empty
#[instrument(fields(status))]
fn handler(id: u32) {
Span::current().record("status", 200);
info!("done");
}
// 4. Span::current() 是内层函数自己的 span
#[instrument(fields(status = field::Empty))]
fn outer(id: u32) {
set_status();
info!("done");
}
#[instrument]
fn set_status() {
Span::current().record("status", 200);
}
// 5. 修法:在外层拿到自己的 span,再交给内层
#[instrument(fields(status = field::Empty))]
fn outer_fixed(id: u32) {
let span = Span::current();
set_status_on(&span);
info!("done");
}
#[instrument(skip(span))]
fn set_status_on(span: &Span) {
span.record("status", 200);
}
fn main() {
tracing_subscriber::fmt()
.with_ansi(false)
.without_time()
.with_target(false)
.init();
undeclared();
declared();
handler(3);
outer(4);
outer_fixed(5);
}
M2 Max、rustc 1.99.0、--release,跑 3 次输出相同:
INFO req{id=1}: done has_status=false
INFO req{id=2 status=200}: done has_status=true
INFO handler{id=3 status=200}: done
INFO outer{id=4}: done
INFO outer_fixed{id=5 status=200}: done
第 1 行和第 4 行是这个坑的两种形态:
undeclared:span 创建时没写status,record("status", 200)被丢掉。outer:outer声明了status = Empty,但record是在set_status里对Span::current()调的。set_status有自己的#[instrument],那一刻的当前 span 是set_status,它没有status字段,于是又被丢掉了。
从哪来
pub fn record<Q: field::AsField + ?Sized, V: field::Value>(
&self,
field: &Q,
value: V,
) -> &Self {
if let Some(meta) = self.meta {
if let Some(field) = field.as_field(meta) {
self.record_all(
&meta
.fields()
.value_set(&[(&field, Some(&value as &dyn field::Value))]),
);
}
}
self
}
传字符串时,AsField for str 是 metadata.fields().field(&self),在调用点的 FieldSet 里按名字查。FieldSet 是宏在编译期写进 static 元数据的名字数组(见 字段:Field、Value 与 Visit),创建之后加不了名字。查不到就是 None,if let 不进去,函数返回 &Self,没有任何错误值可以检查。文档在这个方法上也写了:「You won't get any error, but the assignment will have no effect!」
所以「声明」必须发生在创建 span 的那个宏里。不知道值的字段用 field::Empty 占位:名字进了 FieldSet,但创建时不交给 subscriber(fmt 不打印它),之后 record 才有地方填。Span::record 的其余行为(重复 record、空 span)见 Span 与 Entered。
#[instrument(fields(x))] 和 span! 里的 x 不一样
#[instrument(fields(status))] 只写名字,展开成 status = ::tracing::field::Empty,所以上面的 handler 能用。这条规则在 ToTokens for Field,注释承认它和宏的语法不一致:
} else if self.kind == FieldKind::Value {
// XXX(eliza): I don't like that fields without values produce
// empty fields rather than local variable shorthand...but,
// we've released a version where field names without values in
// `instrument` produce empty field values, so changing it now
// is a breaking change. agh.
let name = &self.name;
tokens.extend(quote!(#name = ::tracing::field::Empty))
在 info_span! 里只写名字,意思是「取同名的局部变量」(见 宏展开)。照 #[instrument] 的习惯写:
use tracing::info_span;
fn main() {
let span = info_span!("req", id = 1, status);
span.record("status", 200);
}
rustc 1.99.0:
error[E0425]: cannot find value `status` in this scope
--> src/bin/err_shorthand.rs:4:40
|
4 | let span = info_span!("req", id = 1, status);
| ^^^^^^ not found in this scope
这种至少编译不过。麻烦的是作用域里恰好有一个同名变量:在上面的 info_span! 前加一行 let status = 0;,再进入 span 打一条 info!("done"),编译通过,输出是 INFO req{id=1 status=0 status=200}: done。字段在创建时就带上了那个变量的值,record 又追加了一个(为什么是追加,见下面的动脑筋)。两处的写法要分开记:#[instrument] 里 fields(x) 等于 x = Empty;span! 里要写全 x = field::Empty。
修法
- 创建时声明:
info_span!("req", status = field::Empty),或#[instrument(fields(status = field::Empty))](fields(status)也行,但写全更不容易和span!搞混)。 - 别在内层函数里对
Span::current()记外层的字段。在外层把 span 拿到手(let span = Span::current();),传给内层,像上面的outer_fixed;或者让内层返回值,由外层record。 - 想一次填多个字段用
record_all!。它对没声明的名字同样什么都不做(见 字段:Field、Value 与 Visit)。
依赖同上。status 创建时就有值,retry 是 Empty:
use tracing::{field, info, info_span};
fn main() {
tracing_subscriber::fmt()
.with_ansi(false)
.without_time()
.with_target(false)
.init();
let span = info_span!("req", status = 0, retry = field::Empty);
let _g = span.enter();
span.record("status", 200);
span.record("retry", 1);
span.record("retry", 2);
info!("done");
}
done 这一行的 span 部分,req{...} 花括号里是什么?
怎么确认自己没踩
record 没有返回值可查,但 Span::has_field 用的是同一个查找:上面第 1 行的 has_status=false 就是它。在不确定的地方加一句 debug_assert!(span.has_field("status"))。在 dev 构建里,上面 undeclared 那种写法加上这句断言,运行时 panic,信息是断言里写的那句话;--release 下断言被编译掉,程序照常结束。
注意被过滤掉的 span 上 has_field 也是 false:没开 log feature 时,过滤掉的 span 是 Span::none(),没有 meta。用 with_max_level(Level::WARN) 建一个 info_span!("off", status = field::Empty),打印出来是 is_disabled=true has_field=false。所以断言要在 subscriber 会启用这个 span 的配置下跑(比如测试里装一个 TRACE 级别的 subscriber)。
Span::current() 那种情况,has_field 同样能查出来:在 set_status 里断言,当前 span 没有 status,断言失败,正好指出 record 记错了对象。
动脑筋答案
M2 Max、rustc 1.99.0、--release,跑 3 次输出相同:
INFO req{status=0 status=200 retry=1 retry=2}: done
两个字段都出现了两次,旧值没有被替换。fmt 的 on_record 在 span 的 Extensions 里找到已经格式化好的字段串,调 add_fields:
fn add_fields(
&self,
current: &'writer mut FormattedFields<Self>,
fields: &span::Record<'_>,
) -> fmt::Result {
if !current.fields.is_empty() {
current.fields.push(' ');
}
self.format_fields(current.as_writer(), fields)
}
它只往字符串后面加一个空格再追加新字段,不解析已有的内容,也就无从替换。Empty 字段在创建时不出现,所以第一次 record 看起来像「填上」,第二次就露馅了。这是 fmt 的行为,Span::record 本身只是把值交给 subscriber;别的 subscriber(比如按字段名存 map 的)可以选择覆盖。用 fmt 时,一个字段只 record 一次。
小结
Span::record按名字在调用点的FieldSet里查,查不到就静默返回,不报错、不调 subscriber。- 要在创建后才填的字段,创建时写
field::Empty占名字。#[instrument(fields(x))]就是x = Empty;span!里只写x是取同名局部变量,两者不同。 Span::current()是「此刻」的当前 span;被调函数有自己的#[instrument]时,它拿到的是内层 span。外层的字段要用外层的 span 句柄去记。span.has_field(...)和record用同一个查找,可以放进debug_assert!做检查。- 用
fmt时同一字段record两次,两个值都会出现在输出里。