Add --debug option for logging and backtraces

[blyxxyz]

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.

[ducaale]

Looks good! Sorry for taking so long to review this

[blyxxyz]

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]

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]

• Added a timestamp to the logs (first format, it makes it a bit harder to see the scale of the digits but I think it's overall clearer)
• Replaced warn() by log::warn!()
• Implemented Support silencing warnings via double -q flag #179
• Re-did ca629c8 by turning it into a warning instead (I hadn't noticed your fix)
• Moved the logging tests to a separate file (if this setup looks good we can split it up more, cli.rs is getting unwieldy)

[blyxxyz]

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...)

[ducaale]

Approved 🎉

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...)

Haha, tests on ARM tend to hang more often, and it might be related to rust-cross. Either way, I'm patiently waiting for the day GitHub's ARM runner becomes generally available.