connection_verbose does not emit the response headers and body

[ogarcia]

Given the following code:

#[tokio::main]
async fn main() {
    env_logger::init();  // RUST_LOG=trace
    let client = reqwest::Client::builder()
        .connection_verbose(true)
        .build()
        .expect("Client::new()");
    let _ = client.get("https://eu.httpbin.org/get")
        .send()
        .await;
}

If executed with reqwest v0.11.27 it outputs the response haeaders and body log correctly:

% RUST_LOG=trace cargo run
[2024-05-06T06:57:18Z DEBUG reqwest::connect] starting new connection: https://eu.httpbin.org/
[2024-05-06T06:57:19Z TRACE reqwest::connect::verbose] 7e642c23 write: b"GET /get HTTP/1.1\r\naccept: */*\r\nhost: eu.httpbin.org\r\n\r\n"
[2024-05-06T06:57:19Z TRACE reqwest::connect::verbose] 7e642c23 read: b"HTTP/1.1 200 OK\r\nDate: Mon, 06 May 2024 06:57:19 GMT\r\nContent-Type: application/json\r\nContent-Length: 228\r\nConnection: keep-alive\r\nServer: gunicorn/19.9.0\r\nAccess-Control-Allow-Origin: *\r\nAccess-Control-Allow-Credentials: true\r\n\r\n"
[2024-05-06T06:57:19Z TRACE reqwest::connect::verbose] 7e642c23 read: b"{\n  \"args\": {}, \n  \"headers\": {\n    \"Accept\": \"*/*\", \n    \"Host\": \"eu.httpbin.org\", \n    \"X-Amzn-Trace-Id\": \"Root=1-66387f4f-25a929b24f3cb1f5250ce27f\"\n  }, \n  \"origin\": \"91.116.229.190\", \n  \"url\": \"https://eu.httpbin.org/get\"\n}\n"

But if run it with 0.12 it doesn't:

[2024-05-06T06:56:30Z TRACE hyper_util::client::legacy::pool] checkout waiting for idle connection: ("https", eu.httpbin.org)
[2024-05-06T06:56:30Z DEBUG reqwest::connect] starting new connection: https://eu.httpbin.org/
[2024-05-06T06:56:30Z TRACE hyper_util::client::legacy::connect::http] Http::connect; scheme=Some("https"), host=Some("eu.httpbin.org"), port=None
[2024-05-06T06:56:30Z DEBUG hyper_util::client::legacy::connect::dns] resolving host="eu.httpbin.org"
[2024-05-06T06:56:30Z DEBUG hyper_util::client::legacy::connect::http] connecting to 3.211.223.136:443
[2024-05-06T06:56:30Z DEBUG hyper_util::client::legacy::connect::http] connected to 3.211.223.136:443
[2024-05-06T06:56:30Z TRACE hyper_util::client::legacy::client] http1 handshake complete, spawning background dispatcher task
[2024-05-06T06:56:30Z TRACE hyper_util::client::legacy::pool] checkout dropped for ("https", eu.httpbin.org)
[2024-05-06T06:56:30Z TRACE reqwest::connect::verbose] 52085a80 write: b"GET /get HTTP/1.1\r\naccept: */*\r\nhost: eu.httpbin.org\r\n\r\n"
[2024-05-06T06:56:30Z TRACE reqwest::connect::verbose] TODO: verbose poll_read
[2024-05-06T06:56:30Z TRACE reqwest::connect::verbose] TODO: verbose poll_read
[2024-05-06T06:56:30Z TRACE hyper_util::client::legacy::pool] put; add idle connection for ("https", eu.httpbin.org)
[2024-05-06T06:56:30Z DEBUG hyper_util::client::legacy::pool] pooling idle connection for ("https", eu.httpbin.org)

The truth is that I don't know if those two TODO lines it emits refer to this.

[seanmonstar]

Oh yes, that got left behind in the upgrade, as the TODO reveals. Woops!

Looking in the source, the problem is that hyper's ReadBuf/ReadBufCursor don't currently have a way to inspect what was just read. We'd need to propose a method in the hyper repo to do that.

[ogarcia]

Any news on this? If it is necessary to open a bug in the upstream I can open it myself without problems (although I am not very clear about what is missing).

[seanmonstar]

Hm, actually, this probably can be done without upstream support. Does #2454 work for you?

[ogarcia]

Yes, perfectly. Using the same code as in my initial comment, it outputs the log without problems:

[2024-10-23T07:12:06Z DEBUG reqwest::connect] starting new connection: https://eu.httpbin.org/
[2024-10-23T07:12:06Z TRACE reqwest::connect::verbose] 841544ce write: b"GET /get HTTP/1.1\r\naccept: */*\r\nhost: eu.httpbin.org\r\n\r\n"
[2024-10-23T07:12:06Z TRACE reqwest::connect::verbose] 841544ce read: b"HTTP/1.1 200 OK\r\nDate: Wed, 23 Oct 2024 07:12:06 GMT\r\nContent-Type: application/json\r\nContent-Length: 226\r\nConnection: keep-alive\r\nServer: gunicorn/19.9.0\r\nAccess-Control-Allow-Origin: *\r\nAccess-Control-Allow-Credentials: true\r\n\r\n"
[2024-10-23T07:12:06Z TRACE reqwest::connect::verbose] 841544ce read: b"{\n  \"args\": {}, \n  \"headers\": {\n    \"Accept\": \"*/*\", \n    \"Host\": \"eu.httpbin.org\", \n    \"X-Amzn-Trace-Id\": \"Root=1-6718a1c6-2a53d0bf675d86b05ad82229\"\n  }, \n  \"origin\": \"91.117.96.45\", \n  \"url\": \"https://eu.httpbin.org/get\"\n}\n"