connection_verbose does not log outgoing traffic in certain circumstances.

[DanielArmengod]

At least when the URL scheme is http, no log is made of the request or its body.

At least when the URL scheme is https, the request correctly appears in the program log.

Minimal example to reproduce, with dependencies env_logger or stderrlog:

fn main() {
    // stderrlog::new().verbosity(4).init().unwrap();   <- also tested with this logging backend (stderrlog), just in case.
    env_logger::init();  // RUST_LOG=trace
    let c = reqwest::blocking::ClientBuilder::new().connection_verbose(true).build().unwrap();
    c.get("https://ident.me").send().unwrap();
    c.get("http://ident.me").send().unwrap();
}

Output (abbreviated):

[2023-01-12T16:02:31Z DEBUG reqwest::connect] starting new connection: https://ident.me/
[2023-01-12T16:02:31Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE | WRITABLE
[2023-01-12T16:02:31Z TRACE reqwest::connect::verbose] 012eea0f write: b"GET / HTTP/1.1\r\naccept: */*\r\nhost: ident.me\r\n\r\n"
[2023-01-12T16:02:31Z TRACE reqwest::connect::verbose] 012eea0f read: b"HTTP/1.1 200 OK\r\nServer: nginx\r\nDate: Thu, 12 Jan 2023 16:02:31 GMT\r\nContent-Type: text/plain\r\nContent-Length: 14\r\nConnection: keep-alive\r\nAccess-Control-Allow-Origin: *\r\nCache-Control: no-cache, no-store, must-revalidate\r\n\r\n[ip redacted]"

[2023-01-12T16:02:31Z DEBUG reqwest::connect] starting new connection: http://ident.me/
[2023-01-12T16:02:31Z TRACE mio::poll] registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
[2023-01-12T16:02:31Z TRACE reqwest::connect::verbose] c850fa8a read: b"HTTP/1.1 200 OK\r\nServer: nginx\r\nDate: Thu, 12 Jan 2023 16:02:31 GMT\r\nContent-Type: text/plain\r\nContent-Length: 14\r\nConnection: keep-alive\r\nAccess-Control-Allow-Origin: *\r\nCache-Control: no-cache, no-store, must-revalidate\r\n\r\n[ip redacted]"

Output (full):

[2023-01-12T16:02:31Z TRACE reqwest::blocking::wait] (ThreadId(1)) park without timeout
[2023-01-12T16:02:31Z TRACE reqwest::blocking::client] (ThreadId(2)) start runtime::block_on
[2023-01-12T16:02:31Z TRACE reqwest::blocking::wait] wait at most 30s
[2023-01-12T16:02:31Z TRACE reqwest::blocking::wait] (ThreadId(1)) park timeout 29.999995688s
[2023-01-12T16:02:31Z DEBUG reqwest::connect] starting new connection: https://ident.me/
[2023-01-12T16:02:31Z TRACE mio::poll] registering event source with poller: token=Token(0), interests=READABLE | WRITABLE
[2023-01-12T16:02:31Z TRACE want] signal: Want
[2023-01-12T16:02:31Z TRACE want] signal found waiting giver, notifying
[2023-01-12T16:02:31Z TRACE want] poll_want: taker wants!
[2023-01-12T16:02:31Z TRACE reqwest::connect::verbose] 012eea0f write: b"GET / HTTP/1.1\r\naccept: */*\r\nhost: ident.me\r\n\r\n"
[2023-01-12T16:02:31Z TRACE reqwest::connect::verbose] 012eea0f read: b"HTTP/1.1 200 OK\r\nServer: nginx\r\nDate: Thu, 12 Jan 2023 16:02:31 GMT\r\nContent-Type: text/plain\r\nContent-Length: 14\r\nConnection: keep-alive\r\nAccess-Control-Allow-Origin: *\r\nCache-Control: no-cache, no-store, must-revalidate\r\n\r\n[ip redacted]"
[2023-01-12T16:02:31Z TRACE want] signal: Want
[2023-01-12T16:02:31Z TRACE want] signal: Want
[2023-01-12T16:02:31Z TRACE want] signal: Want
[2023-01-12T16:02:31Z TRACE reqwest::blocking::wait] wait at most 30s
[2023-01-12T16:02:31Z TRACE reqwest::blocking::wait] (ThreadId(1)) park timeout 29.99999773s
[2023-01-12T16:02:31Z DEBUG reqwest::connect] starting new connection: http://ident.me/
[2023-01-12T16:02:31Z TRACE mio::poll] registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
[2023-01-12T16:02:31Z TRACE want] signal: Want
[2023-01-12T16:02:31Z TRACE want] signal found waiting giver, notifying
[2023-01-12T16:02:31Z TRACE want] poll_want: taker wants!
[2023-01-12T16:02:31Z TRACE reqwest::connect::verbose] c850fa8a read: b"HTTP/1.1 200 OK\r\nServer: nginx\r\nDate: Thu, 12 Jan 2023 16:02:31 GMT\r\nContent-Type: text/plain\r\nContent-Length: 14\r\nConnection: keep-alive\r\nAccess-Control-Allow-Origin: *\r\nCache-Control: no-cache, no-store, must-revalidate\r\n\r\n[ip redacted]"
[2023-01-12T16:02:31Z TRACE want] signal: Want
[2023-01-12T16:02:31Z TRACE want] signal: Want
[2023-01-12T16:02:31Z TRACE want] signal: Want
[2023-01-12T16:02:31Z TRACE reqwest::blocking::client] closing runtime thread (ThreadId(2))
[2023-01-12T16:02:31Z TRACE reqwest::blocking::client] signaled close for runtime thread (ThreadId(2))
[2023-01-12T16:02:31Z TRACE reqwest::blocking::client] (ThreadId(2)) Receiver is shutdown
[2023-01-12T16:02:31Z TRACE reqwest::blocking::client] (ThreadId(2)) end runtime::block_on
[2023-01-12T16:02:31Z TRACE mio::poll] deregistering event source from poller
[2023-01-12T16:02:31Z TRACE want] signal: Closed
[2023-01-12T16:02:31Z TRACE mio::poll] deregistering event source from poller
[2023-01-12T16:02:31Z TRACE want] signal: Closed
[2023-01-12T16:02:31Z TRACE reqwest::blocking::client] (ThreadId(2)) finished
[2023-01-12T16:02:31Z TRACE reqwest::blocking::client] closed runtime thread (ThreadId(2))

Process finished with exit code 0

[seanmonstar]

Huh, interesting. The connect file has a bunch of conditional stuff, so that we can support native-tls, rustls, both, neither, and proxies. It's possible one of those conditions forgets to wrap the socket?