Rust in Everything
基于 tracing 0.1.44

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 字段,于是又被丢掉了。

从哪来

Span::record:

    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)。
❗IMPORTANT
动脑筋:同一个字段记两次,打印出来是什么?

依赖同上。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 两次,两个值都会出现在输出里。

💬 关联讨论

发起讨论
加载中...