Trace 的内部
主线位置:三个时刻都在,结局主线的第二问「什么算结束」也在这里回答。五个回调各在哪个时刻被调用,axum 卷其余常用中间件已经实测过;本页讲它们背后的类型、
classify怎么接进来,以及 body 结束和出错时的判断。
flowchart TB callNode["Trace::call:make_span、make_classifier、on_request"] --> fut["ResponseFuture::poll:classify_response、on_response"] fut -->|Ready Err| f1[on_failure] fut -->|"Ready:classify_eos = None"| body1["ResponseBody:只调 on_body_chunk、on_eos"] fut -->|"RequiresEos:classify_eos = Some"| body2["ResponseBody:结束或出错时再分类"] body2 -->|trailers 判失败或 body 出错| f2[on_failure]
8 个类型参数
Trace 的定义:
pub struct Trace<
S,
M,
MakeSpan = DefaultMakeSpan,
OnRequest = DefaultOnRequest,
OnResponse = DefaultOnResponse,
OnBodyChunk = DefaultOnBodyChunk,
OnEos = DefaultOnEos,
OnFailure = DefaultOnFailure,
> {
pub(crate) inner: S,
pub(crate) make_classifier: M,
pub(crate) make_span: MakeSpan,
pub(crate) on_request: OnRequest,
// ...
}
除了内层 S,还有 7 个:M 是 MakeClassifier,其余 6 个是可替换的部件,每个都有默认值。.on_request(f) 这类方法不是改字段,而是换掉对应的类型参数,返回一个新类型的 Trace:
pub fn on_request<NewOnRequest>(
self,
new_on_request: NewOnRequest,
) -> Trace<S, M, MakeSpan, NewOnRequest, OnResponse, OnBodyChunk, OnEos, OnFailure> {
所以闭包可以直接塞进来,代价是类型名里会出现 {closure@src/main.rs:35:21: 35:57} 这样的东西。TraceLayer 是同样 7 个参数(没有 S)。new_for_http 和 new_for_grpc 只是把 M 分别定成 SharedClassifier<ServerErrorsAsFailures> 和 SharedClassifier<GrpcErrorsAsFailures>,crate 里给了两个别名 HttpMakeClassifier、GrpcMakeClassifier。
每个部件都是一个 trait,都给三种东西实现了:默认类型、闭包、()(什么都不做)。签名有一处不对称:
| trait | 方法接收者 | 何时调用 |
|---|---|---|
MakeSpan<B> | &mut self | call 时,每个请求一次 |
OnRequest<B> | &mut self | call 时 |
OnResponse<B> | self | 响应 future 完成时,最多一次 |
OnBodyChunk<B> | &mut self | 每个数据帧 |
OnEos | self | body 结束时,最多一次 |
OnFailure<FailureClass> | &mut self | 失败时 |
取 self 的两个在 Trace::call 里 clone 一份放进 ResponseFuture,用的时候 take() 出来消耗掉,所以 ResponseFuture 里那几个字段都是 Option。这也是为什么 Trace 的 Service 实现要求放进 future 的 OnResponse、OnBodyChunk、OnEos、OnFailure 和分类器都实现 Clone。
MakeSpan 与 include_headers
MakeSpan 有三种实现:一个现成的 Span(每次 clone,所有请求共用一个 span),一个 FnMut(&Request<B>) -> Span 闭包,和 DefaultMakeSpan。默认的那个造一个名叫 request 的 span,字段是 method、uri、version,打开 include_headers(true) 再加上 headers = ?request.headers(),用 Debug 打印全部请求头。Authorization 会不会出现在日志里,取决于这个 HeaderValue 有没有被 SetSensitiveRequestHeadersLayer 标记为敏感,标记要在 Trace 之前完成,也就是放在 Trace 外面。
DefaultMakeSpan 里有一个手写的 match self.level,五个分支各调一次 tracing::span!,源码注释解释:「tracing::span! required the level argument to be static」。事件那边的 event_dynamic_lvl! 宏做的是同一件事。默认级别:span 和 on_request / on_response / on_eos 是 DEBUG,on_failure 是 ERROR。tracing-subscriber 的 fmt 默认只开到 INFO,这时 span 本身是关着的,on_failure 的 ERROR 事件能打印出来,但前面不会带 request{method=... uri=...},OnEarlyDrop 一页的实验里能看到这一点。
0.7.0:事件显式挂到请求 span
Trace 在 call 里 span.enter() 之后才调 on_request 和内层的 call,ResponseFuture::poll、ResponseBody::poll_frame 开头也各 enter 一次,所以在回调里 tracing::info! 会落在请求 span 里面。0.7.0 之前默认回调就是靠这个「当前 span」。#690 改成显式指定父 span,比如 DefaultOnRequest:
event_dynamic_lvl!(parent: span, self.level, "started processing request");
CHANGELOG 的说法是「This fixes intermittent cases where events could appear without their request span attached」。自己写的闭包不受这个改动影响:回调的最后一个参数就是请求的 &Span,要显式挂就自己写 tracing::info!(parent: span, ...)。span 本身的进入、退出语义见 tracing 卷 Span 与 Entered。
什么算结束
ResponseBody::poll_frame 每拿到一帧,按帧的种类分支:
let result = ready!(this.inner.as_mut().poll_frame(cx));
let latency = this.start.elapsed();
*this.start = Instant::now();
match result {
Some(Ok(frame)) => {
// 数据帧:on_body_chunk
// trailers 帧:classify_eos(Some(&trailers)),失败就 on_failure;然后 on_eos
// ...
if this.inner.is_end_stream() {
// classify_eos(None),失败就 on_failure;然后 on_eos
}
Poll::Ready(Some(Ok(frame)))
}
Some(Err(err)) => {
if let Some((classify_eos, mut on_failure)) =
this.classify_eos.take().zip(this.on_failure.take())
{
let failure_class = classify_eos.classify_error(&err);
on_failure.on_failure(failure_class, latency, this.span);
}
Poll::Ready(Some(Err(err)))
}
None => {
// classify_eos(None),失败就 on_failure;然后 on_eos
}
}
「结束」有三种信号:poll_frame 返回 None;读到 trailers 帧(HTTP 里 trailers 一定是最后一帧);交出一帧之后内层的 is_end_stream() 为真。第三种是 0.7.0 的 #687 加的(第 83 行),注释写着原因:「the consumer may not poll again (e.g. when Content-Length is exact)」。body 的使用方知道长度已经够了时,可能不会再 poll 一次去拿那个 None;在此之前,这种 body 的 on_eos 可能永远等不到。on_eos 存在 Option 里,三种信号谁先到谁 take(),所以最多调一次。
还有一个更早的修复:0.6.7 的 #580(「Call on_eos for successful streams」)。在那之前,分类结果是 Ready 时 ResponseFuture::poll 造 body 时写的是 on_eos: None,也就是说用 new_for_http 时 on_eos 根本不会触发,只有 gRPC 这种 RequiresEos 的路径才有。
出错算不算失败
Some(Err(err)) 分支要同时拿到 classify_eos 和 on_failure 才会调 on_failure。classify_eos 只在分类器返回 RequiresEos 时才是 Some。于是同一个 body 错误,换个分类器结局就不同。下面同一个 handler 回两种 body,一个以 grpc-status: 13 的 trailers 结束,一个读到一半出错,分别套上 new_for_http 和 new_for_grpc:
tower-http = { version = "=0.7.1", features = ["trace"] }
tower = { version = "=0.5.3", features = ["util"] }
tokio = { version = "=1.54.1", features = ["macros", "rt", "time", "test-util"] }
http = "1"
http-body = "1"
http-body-util = "0.1"
bytes = "1"
futures = "0.3"
tracing = "0.1"
use bytes::Bytes;
use http::{HeaderMap, HeaderValue, Request, Response};
use http_body::Frame;
use http_body_util::{combinators::UnsyncBoxBody, BodyExt, Full, StreamBody};
use std::{convert::Infallible, time::Duration};
use tower::{service_fn, BoxError, Layer, ServiceExt};
use tower_http::{
classify::{GrpcFailureClass, ServerErrorsFailureClass},
trace::TraceLayer,
};
use tracing::Span;
type Body = UnsyncBoxBody<Bytes, BoxError>;
// 两种 body:一个以 grpc-status: 13 的 trailers 结束,一个读到一半出错
async fn handler(req: Request<Full<Bytes>>) -> Result<Response<Body>, Infallible> {
tokio::time::sleep(Duration::from_secs(1)).await;
let frames: Vec<Result<Frame<Bytes>, BoxError>> = if req.uri().path() == "/trailers" {
let mut t = HeaderMap::new();
t.insert("grpc-status", HeaderValue::from_static("13"));
vec![Ok(Frame::data(Bytes::from("msg"))), Ok(Frame::trailers(t))]
} else {
vec![Ok(Frame::data(Bytes::from("part"))), Err("disk gone".into())]
};
let mut res = Response::new(StreamBody::new(futures::stream::iter(frames)).boxed_unsync());
res.headers_mut().insert("content-type", HeaderValue::from_static("application/grpc"));
Ok(res)
}
#[tokio::main(flavor = "current_thread", start_paused = true)]
async fn main() {
macro_rules! callbacks {
($layer:expr, $class:ty) => {
$layer
.on_response(|r: &Response<Body>, l: Duration, _: &Span| println!(" on_response {} (latency < 10ms: {})", r.status(), l < Duration::from_millis(10)))
.on_body_chunk(|c: &Bytes, _: Duration, _: &Span| println!(" on_body_chunk {:?}", c))
.on_eos(|t: Option<&HeaderMap>, _: Duration, _: &Span| println!(" on_eos trailers={:?}", t.map(|t| t.get("grpc-status"))))
.on_failure(|f: $class, _: Duration, _: &Span| println!(" on_failure {f}"))
};
}
for path in ["/trailers", "/error"] {
println!("new_for_http {path}");
let svc = callbacks!(TraceLayer::new_for_http(), ServerErrorsFailureClass).layer(service_fn(handler));
let res = svc.oneshot(Request::get(path).body(Full::default()).unwrap()).await.unwrap();
let _ = res.into_body().collect().await;
println!("new_for_grpc {path}");
let svc = callbacks!(TraceLayer::new_for_grpc(), GrpcFailureClass).layer(service_fn(handler));
let res = svc.oneshot(Request::get(path).body(Full::default()).unwrap()).await.unwrap();
let _ = res.into_body().collect().await;
}
}
on_response 拿到的延迟是多少?注意 start_paused = true:tokio 的时钟是暂停的,sleep(1s) 会立刻「睡完」。平台 M2 Max、rustc 1.99.0。
先看回调的顺序:
new_for_http两个路径都没有on_failure:分类器在响应头阶段就给了Ready(Ok)(200 不是 5xx),classify_eos是None。/trailers照样调了on_eos并把 trailers 交给它,但没有人去解读grpc-status: 13;/error连on_eos都没有,body 出错不算结束。axum 卷那一节的/body-error是同一个现象。new_for_grpc头里没有grpc-status,返回RequiresEos。/trailers先on_failure Status: Internal(13 就是Internal)再on_eos,顺序和源码一致;/error的 body 错误经classify_error变成Error: disk gone,调了on_failure。
所以「body 中途出错会不会被 Trace 记成失败」没有统一答案:用 new_for_http 不会,用 new_for_grpc 或者任何返回 RequiresEos 的自定义分类器会。想让 HTTP 服务的 body 错误也进 on_failure,可以写一个总是返回 RequiresEos 的分类器,把状态码的判断推迟到 classify_eos。
动脑筋答案
new_for_http /trailers
on_response 200 OK (latency < 10ms: true)
on_body_chunk b"msg"
on_eos trailers=Some(Some("13"))
new_for_grpc /trailers
on_response 200 OK (latency < 10ms: true)
on_body_chunk b"msg"
on_failure Status: Internal
on_eos trailers=Some(Some("13"))
new_for_http /error
on_response 200 OK (latency < 10ms: true)
on_body_chunk b"part"
new_for_grpc /error
on_response 200 OK (latency < 10ms: true)
on_body_chunk b"part"
on_failure Error: disk gone
跑 3 次相同。延迟不到 10 毫秒,不是 1 秒。Trace::call 记开始时间用的是 std::time::Instant::now(),不是 tokio::time::Instant;tokio 的暂停时钟让 sleep 瞬间完成,标准库的时钟只走了真实流逝的那一点点。在 start_paused 的测试里断言 Trace 报出的延迟,永远拿不到虚拟时间。
延迟还有一个细节:ResponseBody 每拿到一帧就把 start 重置成 Instant::now(),所以 on_body_chunk 的 latency 是距离上一帧的时间;body 阶段的 on_failure 拿到的也是这个值,不是从请求开始算的总时长。on_eos 的 stream_duration 则是从响应头出来时算起的 body 总时长。
小结
Trace有 8 个类型参数:内层S、分类器M、6 个部件;.on_xxx(f)换掉对应的类型参数,闭包和()都能当部件。OnResponse、OnEos取self,最多调一次;其余取&mut self。- 默认 span 和三个普通事件是
DEBUG,on_failure是ERROR;0.7.0 起默认回调显式挂到请求 span;include_headers(true)会打印全部请求头。 - 什么算结束:
None、trailers、交出一帧后is_end_stream()为真(0.7.0 #687);0.6.7 之前new_for_http根本不调on_eos。 - body 出错只在分类器返回
RequiresEos时才算失败:new_for_http不记,new_for_grpc记。 - 延迟用标准库时钟,tokio 暂停时钟不影响它;body 阶段的延迟是距上一帧的时间。