Skip to content

Body streams with precise content-length headers don't trigger on_eos #625

New issue
New issue
Open
Open
Body streams with precise content-length headers don't trigger on_eos#625
@Firstyear

Description

@Firstyear
Firstyear
opened on Dec 18, 2025
  • I have looked for existing issues (including closed) about this

Bug Report

When using the TraceLayer example per https://docs.rs/tower-http/latest/tower_http/trace/index.html#customization with axum, a streaming body response that sends a content-length header fails to trigger on_eos. (On End Of Stream)

Version

v0.6.8

Platform

Darwin maxixe.dev.blackhats.net.au 24.6.0 Darwin Kernel Version 24.6.0: Wed Nov 5 21:33:58 PST 2025; root:xnu-11417.140.69.705.2~1/RELEASE_ARM64_T6000 arm64

Crates

v0.6.8

Description

The construction is similar to:

#[axum::debug_handler]
async fn get_view(
    extract::State(state): extract::State<Arc<AppState>>,
    extract::OriginalUri(req_uri): extract::OriginalUri,
) -> Response {
    let req_path = req_uri.path();

    let mut dest_url = state.target.clone();
    dest_url.set_path(req_path);

    let client_response = state.client.get(dest_url).send().await.expect("Oh no!");

    let status = client_response.status();
    let headers = client_response.headers().clone();
    let stream = client_response.bytes_stream();
    let body = Body::from_stream(stream);
    (status, headers, body).into_response()
}

Where AppState client is reqwest 12 client. What happens is after adding extra tracing to https://github.com/tower-rs/tower-http/blob/main/tower-http/src/trace/body.rs#L53 frames are chunked and sent. However the None branch https://github.com/tower-rs/tower-http/blob/main/tower-http/src/trace/body.rs#L85 or match frame.into_trailers() https://github.com/tower-rs/tower-http/blob/main/tower-http/src/trace/body.rs#L63 are never hit.

This is because when you send a precise content-length header, the client ceases to request more bytes. As a result, this causes the fall through to https://github.com/tower-rs/tower-http/blob/main/tower-http/src/trace/body.rs#L85 to never trigger.

If you omit the content-length header, or adjust it by 1 extra byte, this will trigger and on_eos fires.

Expected Behaviour

on_eos to fire, even if content-length is provided.

Reproducer

Cargo.toml

[package]
name = "eos-repro"
version = "0.1.0"
edition = "2024"

[dependencies]


tracing = "0.1"
tracing-subscriber = "0.3"
tokio = { version = "1", features = ["full", "tracing"] }
axum = { version = "0.8", features = [ "http1", "tokio", "macros" ] }
axum-server = "0.7"
url = "2"
reqwest = { version = "0.12", features = ["stream"] }
tower-http = { version = "0.6", features = ["trace"] }
http = "1"

src/main.rs

use axum::{
    Router,
    body::{Body, Bytes},
    extract,
    response::{IntoResponse, Response},
    routing::get,
};
use http::{HeaderMap, Request};
use std::net::SocketAddr;
use std::str::FromStr;
use std::sync::Arc;
use std::time::Duration;
use tower_http::trace::TraceLayer;
use tracing::*;
use url::Url;

pub const ALLOW_REDIRECTS: usize = 4;

struct AppState {
    client: reqwest::Client,
    target: Url,
}

#[axum::debug_handler]
async fn get_view(
    extract::State(state): extract::State<Arc<AppState>>,
    extract::OriginalUri(req_uri): extract::OriginalUri,
) -> Response {
    let req_path = req_uri.path();

    let mut dest_url = state.target.clone();
    dest_url.set_path(req_path);

    let client_response = state.client.get(dest_url).send().await.expect("Oh no!");

    let status = client_response.status();

    // ======================================
    // !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
    // comment/ uncomment this and adjust into_response to add/remove the content-length header!!!
    let headers = client_response.headers().clone();
    let stream = client_response.bytes_stream();
    let body = Body::from_stream(stream);
    (status, headers, body).into_response()
    // (status, body).into_response()
}

#[tokio::main]
async fn main() {
    tracing_subscriber::fmt::init();

    info!("Lets go!");

    // let timeout = std::time::Duration::from_secs(7200);
    let client = reqwest::ClientBuilder::new()
        .no_gzip()
        .no_brotli()
        .no_deflate()
        .no_proxy()
        // .timeout(timeout)
        .redirect(reqwest::redirect::Policy::limited(ALLOW_REDIRECTS))
        .build()
        .expect("Unable to build client");

    let target = Url::parse("http://cdn.opensuse.org").expect("Invalid base url");

    let app_state = Arc::new(AppState { client, target });

    let app = Router::new()
        .route("/{*req_path}", get(get_view))
        .layer(
            TraceLayer::new_for_http()
                .make_span_with(|request: &Request<_>| tracing::debug_span!("http-request"))
                .on_request(|request: &Request<_>, _span: &Span| {
                    tracing::debug!("started {} {}", request.method(), request.uri().path())
                })
                .on_response(|response: &Response<_>, latency: Duration, _span: &Span| {
                    tracing::debug!("response generated in {:?}", latency)
                })
                .on_body_chunk(|chunk: &Bytes, latency: Duration, _span: &Span| {
                    tracing::debug!("sending {} bytes", chunk.len())
                })
                .on_eos(
                    |trailers: Option<&HeaderMap>, stream_duration: Duration, _span: &Span| {
                        tracing::debug!("stream closed after {:?}", stream_duration)
                    },
                )
                .on_failure(|error: _, latency: Duration, _span: &Span| {
                    tracing::debug!("something went wrong")
                }),
        )
        .with_state(app_state.clone());

    let svc = app.into_make_service();

    let addr = SocketAddr::from_str("127.0.0.1:8080").expect("Invalid Localhost Address");

    axum_server::bind(addr).serve(svc).await;
}

Command to execute:

curl -v http://127.0.0.1:8080/distribution/leap/15.6/iso/openSUSE-Leap-15.6-DVD-aarch64-Current.iso.sha256

Output

With content-length disabled:

2025-12-18T08:12:28.218862Z DEBUG http-request: eos_repro: started GET /distribution/leap/15.6/iso/openSUSE-Leap-15.6-DVD-aarch64-Current.iso.sha256
2025-12-18T08:12:28.219242Z TRACE http-request: hyper_util::client::legacy::pool: checkout waiting for idle connection: ("http", cdn.opensuse.org)
2025-12-18T08:12:28.219275Z DEBUG http-request: reqwest::connect: starting new connection: http://cdn.opensuse.org/
2025-12-18T08:12:28.219298Z TRACE http-request: hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("http"), host=Some("cdn.opensuse.org"), port=None
2025-12-18T08:12:28.238128Z DEBUG http-request: hyper_util::client::legacy::connect::http: connecting to [2a04:4e42:49::347]:80
2025-12-18T08:12:28.243366Z DEBUG http-request: hyper_util::client::legacy::connect::http: connected to [2a04:4e42:49::347]:80
2025-12-18T08:12:28.243472Z TRACE http-request: hyper_util::client::legacy::client: http1 handshake complete, spawning background dispatcher task
2025-12-18T08:12:28.243516Z TRACE http-request: hyper_util::client::legacy::client: waiting for connection to be ready
2025-12-18T08:12:28.243591Z TRACE http-request: hyper_util::client::legacy::client: connection is ready
2025-12-18T08:12:28.243620Z TRACE http-request: hyper_util::client::legacy::pool: checkout dropped for ("http", cdn.opensuse.org)
2025-12-18T08:12:28.840679Z TRACE http-request: hyper_util::client::legacy::pool: put; add idle connection for ("http", cdn.opensuse.org)
2025-12-18T08:12:28.840818Z DEBUG http-request: hyper_util::client::legacy::pool: pooling idle connection for ("http", cdn.opensuse.org)
2025-12-18T08:12:28.840944Z TRACE http-request: reqwest::retry: shouldn't retry!
2025-12-18T08:12:28.841471Z TRACE http-request: hyper_util::client::legacy::pool: take? ("http", cdn.opensuse.org): expiration = Some(90s)
2025-12-18T08:12:28.841528Z DEBUG http-request: hyper_util::client::legacy::pool: reuse idle connection for ("http", cdn.opensuse.org)
2025-12-18T08:12:29.437011Z TRACE http-request: hyper_util::client::legacy::pool: put; add idle connection for ("http", cdn.opensuse.org)
2025-12-18T08:12:29.437266Z DEBUG http-request: hyper_util::client::legacy::pool: pooling idle connection for ("http", cdn.opensuse.org)
2025-12-18T08:12:29.437368Z TRACE http-request: reqwest::retry: shouldn't retry!
2025-12-18T08:12:29.438869Z DEBUG http-request: eos_repro: response generated in 1.220045458s
2025-12-18T08:12:29.439060Z DEBUG http-request: eos_repro: sending 118 bytes
2025-12-18T08:12:29.439101Z DEBUG http-request: eos_repro: stream closed after 175.5µs

With content-length enabled

2025-12-18T08:13:02.691807Z DEBUG http-request: eos_repro: started GET /distribution/leap/15.6/iso/openSUSE-Leap-15.6-DVD-aarch64-Current.iso.sha256
2025-12-18T08:13:02.692492Z TRACE http-request: hyper_util::client::legacy::pool: checkout waiting for idle connection: ("http", cdn.opensuse.org)
2025-12-18T08:13:02.692551Z DEBUG http-request: reqwest::connect: starting new connection: http://cdn.opensuse.org/
2025-12-18T08:13:02.692592Z TRACE http-request: hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("http"), host=Some("cdn.opensuse.org"), port=None
2025-12-18T08:13:02.704557Z DEBUG http-request: hyper_util::client::legacy::connect::http: connecting to [2a04:4e42:49::347]:80
2025-12-18T08:13:02.713966Z DEBUG http-request: hyper_util::client::legacy::connect::http: connected to [2a04:4e42:49::347]:80
2025-12-18T08:13:02.714096Z TRACE http-request: hyper_util::client::legacy::client: http1 handshake complete, spawning background dispatcher task
2025-12-18T08:13:02.714120Z TRACE http-request: hyper_util::client::legacy::client: waiting for connection to be ready
2025-12-18T08:13:02.714159Z TRACE http-request: hyper_util::client::legacy::client: connection is ready
2025-12-18T08:13:02.714178Z TRACE http-request: hyper_util::client::legacy::pool: checkout dropped for ("http", cdn.opensuse.org)
2025-12-18T08:13:02.725872Z TRACE http-request: hyper_util::client::legacy::pool: put; add idle connection for ("http", cdn.opensuse.org)
2025-12-18T08:13:02.725910Z DEBUG http-request: hyper_util::client::legacy::pool: pooling idle connection for ("http", cdn.opensuse.org)
2025-12-18T08:13:02.725942Z TRACE http-request: reqwest::retry: shouldn't retry!
2025-12-18T08:13:02.726194Z TRACE http-request: hyper_util::client::legacy::pool: take? ("http", cdn.opensuse.org): expiration = Some(90s)
2025-12-18T08:13:02.726216Z DEBUG http-request: hyper_util::client::legacy::pool: reuse idle connection for ("http", cdn.opensuse.org)
2025-12-18T08:13:02.738975Z TRACE http-request: hyper_util::client::legacy::pool: put; add idle connection for ("http", cdn.opensuse.org)
2025-12-18T08:13:02.739010Z DEBUG http-request: hyper_util::client::legacy::pool: pooling idle connection for ("http", cdn.opensuse.org)
2025-12-18T08:13:02.739030Z TRACE http-request: reqwest::retry: shouldn't retry!
2025-12-18T08:13:02.739105Z DEBUG http-request: eos_repro: response generated in 47.446125ms
2025-12-18T08:13:02.739166Z DEBUG http-request: eos_repro: sending 118 bytes
/// !! NOTE: No log message for  'stream closed'

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions