本站的 #[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],都在服务端:
| 函数 | 位置 | skip | fields | 怎么挂 |
|---|---|---|---|---|
auth_callback_internal | crates/app/src/server/mod.rs 第 252 行 | code、pkce_cookie | provider = %provider、code_len、state_match | 直接写;函数本身带 #[cfg(feature = "server")] |
post_comment | crates/modules/comments/src/server.rs 第 75 行 | content | blog_id = %blog_id、content_len | cfg_attr(feature = "server", ...),下面跟 #[post] |
search_query | crates/modules/search/src/server.rs 第 57 行 | q | q_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)。
问: 三处函数上方的注释都说 #[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 支持的写法。
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,包括未登录、校验失败这类预期内的错误。