ducaale / xh

Friendly and fast tool for sending HTTP requests
MIT License
4.96k stars 90 forks source link

Add `--debug` option for logging and backtraces #371

Closed blyxxyz closed 2 weeks ago

blyxxyz commented 1 month ago

Add env_logger to be able to print the logs that our libraries already generate.

Add some logging to the application code. We'll probably want more log messages, and we might want to upgrade some of them from trace to debug.

Add a --debug flag that automatically enables env_logger as well as backtraces for anyhow and panics.

$ xh --debug :
[2024-06-05T13:54:40Z DEBUG xh] xh 0.22.0 -native-tls +rustls
[2024-06-05T13:54:40Z DEBUG xh] Cli {
        httpie_compat_mode: false,
        [...]
    }
[2024-06-05T13:54:40Z DEBUG xh] Complete URL: http://localhost/
[2024-06-05T13:54:40Z DEBUG xh] HTTP method: GET
[2024-06-05T13:54:40Z DEBUG reqwest::connect] starting new connection: http://localhost/
[2024-06-05T13:54:40Z DEBUG hyper_util::client::legacy::connect::dns] resolving host="localhost"
[...]
xh: error: error sending request for url (http://localhost/)

Caused by:
    0: client error (Connect)
    1: tcp connect error: Connection refused (os error 111)
    2: Connection refused (os error 111)

Stack backtrace:
   0: anyhow::error::<impl core::convert::From<E> for anyhow::Error>::from
             at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.82/src/error.rs:565:25
[...]

We could ask users to post --debug output when reporting bugs.

blyxxyz commented 2 weeks ago

How do you feel about logging a timestamp relative to startup?

[0.000245s DEBUG xh] Complete URL: https://httpbin.org/get
[0.000259s DEBUG xh] HTTP method: GET
[0.003718s DEBUG reqwest::connect] starting new connection: https://httpbin.org/
[0.003926s DEBUG hyper_util::client::legacy::connect::dns] resolving host="httpbin.org"
[0.028668s DEBUG hyper_util::client::legacy::connect::http] connecting to 3.213.1.197:443
[0.144769s DEBUG hyper_util::client::legacy::connect::http] connected to 3.213.1.197:443
[0.144841s DEBUG rustls::client::hs] No cached session for DnsName("httpbin.org")
[0.145032s DEBUG rustls::client::hs] Not resuming any session
[0.257458s DEBUG rustls::client::hs] ALPN protocol is Some(b"h2")
[0.257492s DEBUG rustls::client::hs] Using ciphersuite TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
[0.257511s DEBUG rustls::client::tls12::server_hello] Server supports tickets
[0.257559s DEBUG rustls::client::tls12] ECDHE curve is EcParameters { curve_type: NamedCurve, named_group: secp256r1 }
[0.257575s DEBUG rustls::client::tls12] Server DNS name is DnsName("httpbin.org")
[0.452195s DEBUG h2::client] binding client connection
[0.452274s DEBUG h2::client] client connection bound

Alternatively:

[220.895µs DEBUG xh] Complete URL: https://httpbin.org/get
[237.877µs DEBUG xh] HTTP method: GET
[39.082ms DEBUG reqwest::connect] starting new connection: https://httpbin.org/
[39.524ms DEBUG hyper_util::client::legacy::connect::dns] resolving host="httpbin.org"
[67.596ms DEBUG hyper_util::client::legacy::connect::http] connecting to 3.213.1.197:443
[200.555ms DEBUG hyper_util::client::legacy::connect::http] connected to 3.213.1.197:443
[200.664ms DEBUG rustls::client::hs] No cached session for DnsName("httpbin.org")
[...]
[646.214ms DEBUG h2::proto::settings] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 65535, max_frame_size: 16384 }
[1.049s DEBUG h2::codec::framed_read] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }

Seems better than including the date and everything but I'm on the fence about whether it's worth showing by default. And which style to use.

ducaale commented 2 weeks ago

Nice, the relative timestamp version looks much better! I think we can enable it by default in debug mode.

Regarding the style to use for the timestamp, the first version seems easier to scan, but I don't have any strong opinions. Would the latter work better for higher timestamp precision?

blyxxyz commented 2 weeks ago
blyxxyz commented 2 weeks ago

Timeout for the deflate test on ARM: https://github.com/ducaale/xh/actions/runs/9604382549/job/26489748373 If that happens again we should look into it. (It's probably not a second xz, but...)