tracing does not cover the entire request lifetime

[Geal]

Version warp 0.3.2

Platform Linux 5.13.0-7620-generic

Description

when using tracing with warp, and the tracing filters, the generated tracing span ends before the entire response body is sent

It is reproducible with this code sample: https://gist.github.com/Geal/68bb703d2c307e64bc415c60b6e75107 (derived from https://github.com/seanmonstar/warp/blob/master/examples/tracing.rs)

With this route:

    let goodbye = warp::path("goodbye")
        .and(warp::get())
        .and_then(|| async {
            println!("in goodbye");
            let chunks: Vec<Result<_, std::io::Error>> = vec![Ok("hello"), Ok(" "), Ok("world")];

            let stream = futures_util::stream::iter(chunks).map(|chunk| {
                println!("sending chunk");
                chunk
            });

            let body = Body::wrap_stream(stream);
            println!("will return body");
            Ok::<Box<dyn Reply>, Infallible>(Box::new(Response::new(body)))
        })
        .with(warp::trace::named("goodbye"));

I'd expect to see:

in goodbye
will return body
sending chunk
sending chunk
sending chunk
*then the last trace log*

Here is what I see instead:

2021-12-02T18:13:05.969237Z  INFO Server::run{addr=127.0.0.1:3030}: warp::server: listening on http://127.0.0.1:3030
2021-12-02T18:13:22.131648Z DEBUG request{method=GET path=/goodbye version=HTTP/1.1 remote.addr=127.0.0.1:43980}: warp::filters::trace: received request
2021-12-02T18:13:22.131692Z  INFO request{method=GET path=/goodbye version=HTTP/1.1 remote.addr=127.0.0.1:43980}: warp::filters::trace: processing request
2021-12-02T18:13:22.131725Z  INFO request{method=GET path=/goodbye version=HTTP/1.1 remote.addr=127.0.0.1:43980}:context{hello}: warp::filters::trace: processing request
2021-12-02T18:13:22.131810Z  WARN request{method=GET path=/goodbye version=HTTP/1.1 remote.addr=127.0.0.1:43980}:context{hello}: warp::filters::trace: unable to serve request (client error) status=404 error=Rejection(NotFound)
2021-12-02T18:13:22.131862Z  INFO request{method=GET path=/goodbye version=HTTP/1.1 remote.addr=127.0.0.1:43980}:context{goodbye}: warp::filters::trace: processing request
2021-12-02T18:13:22.131892Z DEBUG request{method=GET path=/goodbye version=HTTP/1.1 remote.addr=127.0.0.1:43980}:context{hello}: warp::filters::trace: close time.busy=73.6µs time.idle=98.6µs
in goodbye
will return body
2021-12-02T18:13:22.131940Z  INFO request{method=GET path=/goodbye version=HTTP/1.1 remote.addr=127.0.0.1:43980}:context{goodbye}: warp::filters::trace: finished processing with success status=200
2021-12-02T18:13:22.131979Z DEBUG request{method=GET path=/goodbye version=HTTP/1.1 remote.addr=127.0.0.1:43980}:context{goodbye}: warp::filters::trace: close time.busy=85.0µs time.idle=43.1µs
2021-12-02T18:13:22.132004Z  INFO request{method=GET path=/goodbye version=HTTP/1.1 remote.addr=127.0.0.1:43980}: warp::filters::trace: finished processing with success status=200
2021-12-02T18:13:22.132026Z  INFO request{method=GET path=/goodbye version=HTTP/1.1 remote.addr=127.0.0.1:43980}: warp::filters::trace: close time.busy=301µs time.idle=109µs
sending chunk
sending chunk
sending chunk

So the trace ends before the chunks are sent.

[Geal]

I have tried to fix this from inside warp but I am hitting a wall. The trick I could use was to convert the response body to a stream, instrument that stream with the span I want, then create a response from it. Unfortunately, that will convert every response to a chunked one, definitely not something we need here.

From what I understand, warp makes a service, which receives a Request and returns a Response, and anything outside of that (reading parsing the request, serializing and writing the response) is hyper's job instead. So I guess it could be fixed by hyper's tracing integration, if it could create a span that is valid for the entire life of a HTTP transaction