Rust in Everything
基于 tracing-attributes 0.1.31

本站的 #[instrument]

主线位置:span 主线的起点和事件主线的交汇。#[instrument] 在函数第一次被 poll 时建一个 span,函数体里的每条事件都带着这个 span 的名字和字段输出;err 在返回处再补一条事件。

flowchart TB
  req["POST /api/..."] --> inner["dioxus 生成的 handler"]
  inner --> extract["解出参数"]
  extract --> userfn["本站函数"]
  userfn --> span["建 span:name 和 fields"]
  span --> body["函数体里的事件"]
  body --> ret{"返回 Err?"}
  ret -->|是| errev["err:ERROR 事件"]
  ret -->|否| done["无事件"]
  done --> encode["编码响应"]
  errev --> encode

本页的站点源码链接都指向本站仓库的提交 89a61b1。#[instrument] 展开成什么、每个参数怎么解析,在 展开成什么 和 参数 里讲过;这一页只看本站怎么用、用出来在生产配置下是什么样子。生产配置是 dioxus-logger 装的那个 subscriber,见 subscriber 的初始化。

三处用法

本站源码里一共三处 #[tracing::instrument],都在服务端:

函数位置skipfields怎么挂
auth_callback_internalcrates/app/src/server/mod.rs 第 252 行code、pkce_cookieprovider = %provider、code_len、state_match直接写;函数本身带 #[cfg(feature = "server")]
post_commentcrates/modules/comments/src/server.rs 第 75 行contentblog_id = %blog_id、content_lencfg_attr(feature = "server", ...),下面跟 #[post]
search_querycrates/modules/search/src/server.rs 第 57 行qq_len、kind = ?kind、limit = ?limit、hits = Empty同上

三处都写了 name = "server::..."、level = "info" 和 err,没有 ret。OAuth 回调那一处:

#[cfg(feature = "accounts")]
#[cfg(feature = "server")]
#[tracing::instrument(
  name = "server::auth_callback",
  level = "info",
  skip(code, pkce_cookie),
  fields(
    provider = %provider,
    code_len = code.len(),
    state_match = received_state == pkce_cookie.state,
  ),
  err
)]
pub async fn auth_callback_internal(
  code: String,
  provider: String,
  received_state: String,
  pkce_cookie: app_core::auth::PkceCookiePayload,
) -> Result<(String, String), app_core::error::AppError> {

搜索那一处:

#[cfg_attr(
  feature = "server",
  tracing::instrument(
    name = "server::search_query",
    level = "info",
    skip(q),
    fields(q_len = q.len(), kind = ?kind, limit = ?limit, hits = tracing::field::Empty),
    err
  )
)]
#[post("/api/search/query")]
pub async fn search_query(
  q: String,
  kind: Option<String>,
  limit: Option<u32>,
) -> Result<SearchResponse, ServerFnError> {

和 #[post] 的先后

post_comment 和 search_query 是 server 函数,同一个函数上有两个属性宏。属性宏从上往下展开:cfg_attr 在开了 server feature 时变成 #[tracing::instrument(...)],它先拿到整个函数(连同下面那行 #[post(...)]),改写函数体后原样保留其余属性;然后 #[post] 拿到的是已经改写过的函数。

dioxus-fullstack-macro 0.7.9 的 #[post] 把这个函数克隆一份(function_on_server),在 #[cfg(feature = "server")] 块里原样放出来,再生成一个 __inner__function__ 作为 axum handler:

    let mut function_on_server = function.clone();
    function_on_server
        .sig
        .inputs
        .extend(route.server_args.clone());
            // On the server, we expand the tokens and submit the function to inventory
            #[cfg(feature = "server")] {
                #function_on_server

                #[allow(clippy::unused_unit)]
                fn __inner__function__ #impl_generics(
                    // ...
                ) -> /* ... */ {
                    Box::pin(async move {
                         match (/* ... */).extract_axum(___state.0, ___request, #unpack_closure).await {
                            Ok(/* ... */) => {
                                // Call the user function
                                let res = #fn_on_server_name #ty_generics(/* ... */).await;

                                // Encode the response Into a `Result<T, E>`
                                let encoded = (&&&&&&ServerFnDecoder::<#out_ty>::new()).make_axum_response(res);
                                // ...

所以 span 包住的只是本站写的函数体:从请求里解出参数在 span 之前,把返回值编码成响应在 span 之后。err 看到的是函数体返回的 Result,不是 HTTP 状态码。请求路由和 handler 怎么来的见 axum 卷的 dioxus 生成的 Router。本站没有挂 tower-http 的 TraceLayer(源码里搜不到),这三个 span 之外没有按请求建的 span。

客户端构建(不开 server)时,#[post] 生成的函数只有发请求的那一支,本站写的函数体不会出现在客户端代码里。cfg_attr 让 #[instrument] 在客户端构建里根本不展开。auth_callback_internal 不是 server 函数,整个函数只在服务端编译,直接写 #[tracing::instrument] 就行。

skip 和长度字段

三处 skip 的都是内容本身:OAuth 的授权码 code、评论正文 content、搜索词 q,再用 fields 记它们的长度。skip 只是不让参数被自动记成字段,fields 的表达式照样能用这个参数,所以 skip(code) 和 code_len = code.len() 能同时写(参数 的「skip 与 skip_all」)。源码注释写明了用意:评论「避免评论原文泄漏到日志」,搜索「避免把整段查询文本进日志」。

pkce_cookie 的类型 PkceCookiePayload 派生了 Debug,字段有 provider、state、verifier(PKCE 的 code_verifier 原文)、issued_at_secs。不 skip 它也能编译,整个结构体会按 Debug 打进 span 字段。

没有被 skip 的参数仍按 展开成什么 的规则自动记录。auth_callback_internal 的 received_state 不在 skip 里,类型 String 在 TYPES_FOR_VALUE 里,按 Value 记录,subscriber 收到的是 record_str;fmt 的 DefaultVisitor::record_str 对 message 以外的字符串字段用 Debug 写,所以输出带引号,OAuth 的 state 原文会进日志。provider 也没有 skip,但 fields 里有同名的 provider = %provider,expand.rs 第 210 行那段逻辑让同名参数不再自动记录,改由 fields 那一项按 Display 记,不带引号。post_comment 的 blog_id、search_query 的 kind、limit 是同样的情形。

把三处属性原样搬进一个小程序,函数体换成桩,用生产里真正生效的 subscriber(dioxus_logger::initialize_default(),RUST_LOG=info,--release,NO_COLOR=1):

dioxus-logger = "=0.7.9"
dioxus-cli-config = "=0.7.9"
tracing = "=0.1.44"
tracing-subscriber = { version = "=0.3.23", features = ["env-filter", "fmt"] }
tokio = { version = "=1.54.1", features = ["rt", "macros"] }
// 把本站三处 #[tracing::instrument] 原样搬过来,函数体换成桩
use std::fmt;

#[allow(dead_code)]
#[derive(Debug)]
struct PkceCookiePayload {
  provider: String,
  state: String,
  verifier: Option<String>,
  issued_at_secs: u64,
}

#[derive(Debug)]
struct AppError(String);
impl fmt::Display for AppError {
  fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
    write!(f, "{}", self.0)
  }
}

#[tracing::instrument(
  name = "server::auth_callback",
  level = "info",
  skip(code, pkce_cookie),
  fields(
    provider = %provider,
    code_len = code.len(),
    state_match = received_state == pkce_cookie.state,
  ),
  err
)]
async fn auth_callback_internal(
  code: String,
  provider: String,
  received_state: String,
  pkce_cookie: PkceCookiePayload,
) -> Result<(String, String), AppError> {
  tracing::debug!(code_len = code.len(), "auth callback received");
  if code == "expired" {
    return Err(AppError("oauth: token exchange failed".into()));
  }
  tracing::info!(user = %"alice", "auth callback login success");
  Ok(("欢迎回来, alice!".into(), "jwt".into()))
}

#[tracing::instrument(
  name = "server::post_comment",
  level = "info",
  skip(content),
  fields(blog_id = %blog_id, content_len = content.len()),
  err
)]
async fn post_comment(blog_id: String, content: String) -> Result<Vec<String>, AppError> {
  if content.is_empty() {
    return Err(AppError("评论不能为空".into()));
  }
  tracing::warn!(user = %"bob", blog_id = %blog_id, score = 0.97, "moderation: comment BLOCKED");
  Err(AppError("评论被审核拒绝:spam".into()))
}

#[tracing::instrument(
  name = "server::search_query",
  level = "info",
  skip(q),
  fields(q_len = q.len(), kind = ?kind, limit = ?limit, hits = tracing::field::Empty),
  err
)]
async fn search_query(q: String, kind: Option<String>, limit: Option<u32>) -> Result<usize, AppError> {
  let hits = 3;
  tracing::Span::current().record("hits", hits);
  Ok(hits)
}

async fn calls() {
  let cookie = PkceCookiePayload {
    provider: "github".into(),
    state: "s3cr3t-state".into(),
    verifier: Some("v".into()),
    issued_at_secs: 0,
  };
  println!("-- auth_callback ok");
  let _ = auth_callback_internal("code-123".into(), "github".into(), "s3cr3t-state".into(), cookie).await;
  let cookie = PkceCookiePayload {
    provider: "github".into(),
    state: "s3cr3t-state".into(),
    verifier: None,
    issued_at_secs: 0,
  };
  println!("-- auth_callback err");
  let _ = auth_callback_internal("expired".into(), "github".into(), "other".into(), cookie).await;
  println!("-- post_comment blocked");
  let _ = post_comment("rust-intro".into(), "buy now".into()).await;
  println!("-- search_query ok");
  let _ = search_query("tokio 调度".into(), Some("blog".into()), None).await;
}

#[tokio::main(flavor = "current_thread")]
async fn main() {
  if std::env::args().any(|a| a == "--close") {
    // 对照:同样的过滤,再打开 span 关闭事件
    let sub = tracing_subscriber::fmt()
      .with_env_filter("info")
      .with_span_events(tracing_subscriber::fmt::format::FmtSpan::CLOSE)
      .with_ansi(false)
      .without_time()
      .finish();
    let _g = tracing::subscriber::set_default(sub);
    calls().await;
  } else {
    // 和生产一样:只有 dioxus-logger 装的 subscriber
    dioxus_logger::initialize_default();
    calls().await;
  }
}

不带参数跑 3 次,除时间戳外相同:

-- auth_callback ok
2026-10-23T20:37:24.289196Z  INFO server::auth_callback{received_state="s3cr3t-state" provider=github code_len=8 state_match=true}: instrument_site: auth callback login success user=alice
-- auth_callback err
2026-10-23T20:37:24.289213Z ERROR server::auth_callback{received_state="other" provider=github code_len=7 state_match=false}: instrument_site: error=oauth: token exchange failed
-- post_comment blocked
2026-10-23T20:37:24.289223Z  WARN server::post_comment{blog_id=rust-intro content_len=7}: instrument_site: moderation: comment BLOCKED user=bob blog_id=rust-intro score=0.97
2026-10-23T20:37:24.289230Z ERROR server::post_comment{blog_id=rust-intro content_len=7}: instrument_site: error=评论被审核拒绝:spam
-- search_query ok
  • span 部分写成 名字{字段}:,排在 target 之前(fmt 的「Full 格式」)。span 名里的 :: 只是名字的一部分,server::auth_callback 不是 target;事件的 target 是模块路径,实验里是 instrument_site,在本站分别是 app::server、module_comments::server、module_search::server。
  • 字段顺序是先自动记录的参数(received_state),再是 fields 里的各项。received_state 带引号,provider 不带:前者是 record_str,fmt 给字符串字段加引号;后者被同名的 %provider 取代,走 Display。
  • code、pkce_cookie、content、q 都没有出现,出现的是它们的长度和 state_match。
  • auth callback received 是 debug!,RUST_LOG=info 下被过滤掉。

fields 里的表达式

code_len = code.len()、state_match = received_state == pkce_cookie.state 这些表达式在建 span 时求值一次。async fn 的 span 在函数第一次被 poll 时、函数体被搬进 async move 块之前建好,这时参数还能被借用(展开成什么 的「async fn」一节)。之后函数体里 code、pkce_cookie 被移走也不影响已经记下的值。

state_match 记的是 OAuth 回调里 URL 的 state 和 cookie 里的 state 是否相等,它是 CSRF 校验的结果;上面的错误那一行里 state_match=false,一眼就能看出失败是不是出在这一步。kind = ?kind 和 limit = ?limit 是 Option,按 Debug 写成 Some("blog")、None。

hits:先占位,再 record

search_query 的 fields 里有 hits = tracing::field::Empty,函数体末尾在 server.rs 第 95 行填上:

    tracing::Span::current().record("hits", hits.len());

Span::record 只能填创建时声明过的字段,所以要先用 Empty 占位(见 参数 的「fields:追加字段」和 Span::record 没有效果)。这里用的是 Span::current():async fn 被 Instrumented 包着,每次 poll 都进入这个 span(Instrument 与异步),函数体里又没有别的 span,当前 span 就是 server::search_query。fmt::Layer 的 on_record 把新值追加到这个 span 已经格式化好的字段串后面。

问题在于之后没有任何事件。上面的输出里,-- search_query ok 后面一行都没有:成功的搜索不打事件,err 只在 Err 时触发,没有 ret。hits 被追加进 span 的字段串,span 关闭时连同字段串一起释放,生产配置下不会出现在任何一行里。函数上方的注释写的是「返回 hit 数通过 ret 自动拿到」,属性里并没有 ret。

打开 span 关闭事件就能看到它。带 --close 跑(用 set_default 换成一个 FmtSpan::CLOSE 的 subscriber),3 次相同:

-- auth_callback ok
 INFO server::auth_callback{received_state="s3cr3t-state" provider=github code_len=8 state_match=true}: instrument_site: auth callback login success user=alice
 INFO server::auth_callback{received_state="s3cr3t-state" provider=github code_len=8 state_match=true}: instrument_site: close
-- auth_callback err
ERROR server::auth_callback{received_state="other" provider=github code_len=7 state_match=false}: instrument_site: error=oauth: token exchange failed
 INFO server::auth_callback{received_state="other" provider=github code_len=7 state_match=false}: instrument_site: close
-- post_comment blocked
 WARN server::post_comment{blog_id=rust-intro content_len=7}: instrument_site: moderation: comment BLOCKED user=bob blog_id=rust-intro score=0.97
ERROR server::post_comment{blog_id=rust-intro content_len=7}: instrument_site: error=评论被审核拒绝:spam
 INFO server::post_comment{blog_id=rust-intro content_len=7}: instrument_site: close
-- search_query ok
 INFO server::search_query{q_len=12 kind=Some("blog") limit=None hits=3}: instrument_site: close

最后一行有了 hits=3。q_len=12 是 "tokio 调度" 的字节数(String::len),不是字符数。close 后面没有 time.busy / time.idle,是因为这个对照用了 without_time():它同时把 span 的计时也关掉了(FmtSpanConfig::without_time 把 fmt_timing 设成 false)。

📝NOTE
没有蠢问题

问: 三处函数上方的注释都说 #[tracing::instrument]「自动记录入口 + 退出 + elapsed」,生产日志里为什么从来看不到入口和退出?

答: #[instrument] 只建 span、进出 span,本身不发入口和退出事件。「进入」「关闭」能不能变成一行输出,由 fmt::Layer 的 with_span_events 决定,默认是 FmtSpan::NONE(fmt 的「with_span_events」)。生效的 dioxus-logger 配置没有调用它,本站自己那段(也没调用)又没生效。所以 span 只体现为函数体里事件前面的 名字{字段}:,没有事件的调用(比如成功的搜索)在日志里什么都不留。上面 --close 的对照就是打开 CLOSE 之后的样子,busy / idle 就是 elapsed。

err

err 在函数返回 Err(e) 时发一条 ERROR 级别的事件,字段是 error = %e(默认 Display,见 参数 的「err 与 ret」)。事件在 span 里发出,所以带着 span 前缀。三个函数的错误类型 AppError、ServerFnError 都实现了 Display,err 不需要改成 err(Debug)。

err 不分错误的种类。函数体里每一个 ? 都会经过它:post_comment 里 require_session_verified().await? 的未登录、validate_comment(&content).map_err(ServerFnError::new)? 的校验失败、审核拒绝,都会变成一行 ERROR。审核拒绝时函数体里已经先打了一条 WARN(comments/src/server.rs 第 118 行),上面的输出里一次拒绝就是一条 WARN 加一条 ERROR。要改级别可以写 err(level = "warn"),这是 tracing-attributes 0.1.31 支持的写法。

❗IMPORTANT
动脑筋:生产配置下,一次成功的 search_query 调用会在日志里留下几行?

提示:看函数体里有没有事件,err 什么时候触发,有没有 ret,subscriber 有没有打开 span 事件。

动脑筋答案

0 行。上面不带参数那次运行里,-- search_query ok 后面没有任何输出:

-- search_query ok
  • 函数体里没有 info! 之类的事件;
  • err 只在返回 Err 时发事件;
  • 属性里没有 ret;
  • dioxus-logger 的 fmt::Layer 没有打开 with_span_events,span 的创建和关闭不产生输出。

hits=3 记进了 span,但没有一行把它带出来。

小结

  • 三处 #[tracing::instrument] 都是 name = "server::..."、level = "info"、err;两处 server 函数用 cfg_attr(feature = "server", ...) 写在 #[post] 之上,先展开,#[post] 再把改写过的函数放进服务端的 handler,span 只包住本站的函数体。
  • skip 掉授权码、评论正文、搜索词,用 fields 记长度;没 skip 的 received_state 照样进日志(字符串字段带引号);和参数同名的 fields 项取代参数,按 % 或 ? 记。
  • fields 的表达式在建 span 时求值一次,异步函数是在第一次 poll 时。
  • hits = Empty 加 Span::current().record 能填上值,但成功路径没有事件,生产配置又没开 span 事件,hits 从不出现在日志里。注释里的 ret 和「入口 + 退出 + elapsed」在当前配置下都不成立。
  • err 把每一个 Err 都变成一行 ERROR,包括未登录、校验失败这类预期内的错误。

💬 关联讨论

发起讨论
加载中...