Rust in Everything
基于 tower-http 0.7.1

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 selfcall 时,每个请求一次
OnRequest<B>&mut selfcall 时
OnResponse<B>self响应 future 完成时,最多一次
OnBodyChunk<B>&mut self每个数据帧
OnEosselfbody 结束时,最多一次
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;
  }
}
❗IMPORTANT
动脑筋:handler 先睡 1 秒再返回,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 阶段的延迟是距上一帧的时间。

💬 关联讨论

发起讨论
加载中...