Add --debug option for logging and backtraces

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.

```console
$ 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.

Cargo.toml

@@ -47,6 +47,8 @@ time = "0.3.16"
 unicode-width = "0.1.9"
 url = "2.2.2"
 ruzstd = { version = "0.6", default-features = false, features = ["std"]}
+env_logger = { version = "0.11.3", default-features = false, features = ["color", "auto-color", "humantime"] }
+log = "0.4.21"
 
 [dependencies.reqwest]
 version = "0.12.3"

completions/_xh

@@ -62,6 +62,7 @@ none\:"Disable both coloring and formatting"))' \
 '--meta[Print only the response metadata. Shortcut for --print=m]' \
 '*-v[Print the whole request as well as the response]' \
 '*--verbose[Print the whole request as well as the response]' \
+'--debug[Print full error stack traces and debug log messages]' \
 '--all[Show any intermediary requests/responses while following redirects with --follow]' \
 '-q[Do not print to stdout or stderr]' \
 '--quiet[Do not print to stdout or stderr]' \
@@ -101,6 +102,7 @@ none\:"Disable both coloring and formatting"))' \
 '--no-body[]' \
 '--no-meta[]' \
 '--no-verbose[]' \
+'--no-debug[]' \
 '--no-all[]' \
 '--no-history-print[]' \
 '--no-quiet[]' \

completions/_xh.ps1

@@ -65,6 +65,7 @@ Register-ArgumentCompleter -Native -CommandName 'xh' -ScriptBlock {
             [CompletionResult]::new('--meta', 'meta', [CompletionResultType]::ParameterName, 'Print only the response metadata. Shortcut for --print=m')
             [CompletionResult]::new('-v', 'v', [CompletionResultType]::ParameterName, 'Print the whole request as well as the response')
             [CompletionResult]::new('--verbose', 'verbose', [CompletionResultType]::ParameterName, 'Print the whole request as well as the response')
+            [CompletionResult]::new('--debug', 'debug', [CompletionResultType]::ParameterName, 'Print full error stack traces and debug log messages')
             [CompletionResult]::new('--all', 'all', [CompletionResultType]::ParameterName, 'Show any intermediary requests/responses while following redirects with --follow')
             [CompletionResult]::new('-q', 'q', [CompletionResultType]::ParameterName, 'Do not print to stdout or stderr')
             [CompletionResult]::new('--quiet', 'quiet', [CompletionResultType]::ParameterName, 'Do not print to stdout or stderr')
@@ -104,6 +105,7 @@ Register-ArgumentCompleter -Native -CommandName 'xh' -ScriptBlock {
             [CompletionResult]::new('--no-body', 'no-body', [CompletionResultType]::ParameterName, 'no-body')
             [CompletionResult]::new('--no-meta', 'no-meta', [CompletionResultType]::ParameterName, 'no-meta')
             [CompletionResult]::new('--no-verbose', 'no-verbose', [CompletionResultType]::ParameterName, 'no-verbose')
+            [CompletionResult]::new('--no-debug', 'no-debug', [CompletionResultType]::ParameterName, 'no-debug')
             [CompletionResult]::new('--no-all', 'no-all', [CompletionResultType]::ParameterName, 'no-all')
             [CompletionResult]::new('--no-history-print', 'no-history-print', [CompletionResultType]::ParameterName, 'no-history-print')
             [CompletionResult]::new('--no-quiet', 'no-quiet', [CompletionResultType]::ParameterName, 'no-quiet')

completions/xh.bash

@@ -19,7 +19,7 @@ _xh() {
 
     case "${cmd}" in
         xh)
-            opts="-j -f -s -p -h -b -m -v -P -q -S -o -d -c -A -a -F -4 -6 -I -V --json --form --multipart --raw --pretty --format-options --style --response-charset --response-mime --print --headers --body --meta --verbose --all --history-print --quiet --stream --output --download --continue --session --session-read-only --auth-type --auth --bearer --ignore-netrc --offline --check-status --follow --max-redirects --timeout --proxy --verify --cert --cert-key --ssl --native-tls --default-scheme --https --http-version --resolve --interface --ipv4 --ipv6 --ignore-stdin --curl --curl-long --help --no-json --no-form --no-multipart --no-raw --no-pretty --no-format-options --no-style --no-response-charset --no-response-mime --no-print --no-headers --no-body --no-meta --no-verbose --no-all --no-history-print --no-quiet --no-stream --no-output --no-download --no-continue --no-session --no-session-read-only --no-auth-type --no-auth --no-bearer --no-ignore-netrc --no-offline --no-check-status --no-follow --no-max-redirects --no-timeout --no-proxy --no-verify --no-cert --no-cert-key --no-ssl --no-native-tls --no-default-scheme --no-https --no-http-version --no-resolve --no-interface --no-ipv4 --no-ipv6 --no-ignore-stdin --no-curl --no-curl-long --no-help --version <[METHOD] URL> [REQUEST_ITEM]..."
+            opts="-j -f -s -p -h -b -m -v -P -q -S -o -d -c -A -a -F -4 -6 -I -V --json --form --multipart --raw --pretty --format-options --style --response-charset --response-mime --print --headers --body --meta --verbose --debug --all --history-print --quiet --stream --output --download --continue --session --session-read-only --auth-type --auth --bearer --ignore-netrc --offline --check-status --follow --max-redirects --timeout --proxy --verify --cert --cert-key --ssl --native-tls --default-scheme --https --http-version --resolve --interface --ipv4 --ipv6 --ignore-stdin --curl --curl-long --help --no-json --no-form --no-multipart --no-raw --no-pretty --no-format-options --no-style --no-response-charset --no-response-mime --no-print --no-headers --no-body --no-meta --no-verbose --no-debug --no-all --no-history-print --no-quiet --no-stream --no-output --no-download --no-continue --no-session --no-session-read-only --no-auth-type --no-auth --no-bearer --no-ignore-netrc --no-offline --no-check-status --no-follow --no-max-redirects --no-timeout --no-proxy --no-verify --no-cert --no-cert-key --no-ssl --no-native-tls --no-default-scheme --no-https --no-http-version --no-resolve --no-interface --no-ipv4 --no-ipv6 --no-ignore-stdin --no-curl --no-curl-long --no-help --version <[METHOD] URL> [REQUEST_ITEM]..."
             if [[ ${cur} == -* || ${COMP_CWORD} -eq 1 ]] ; then
                 COMPREPLY=( $(compgen -W "${opts}" -- "${cur}") )
                 return 0

completions/xh.fish

@@ -30,6 +30,7 @@ complete -c xh -s h -l headers -d 'Print only the response headers. Shortcut for
 complete -c xh -s b -l body -d 'Print only the response body. Shortcut for --print=b'
 complete -c xh -s m -l meta -d 'Print only the response metadata. Shortcut for --print=m'
 complete -c xh -s v -l verbose -d 'Print the whole request as well as the response'
+complete -c xh -l debug -d 'Print full error stack traces and debug log messages'
 complete -c xh -l all -d 'Show any intermediary requests/responses while following redirects with --follow'
 complete -c xh -s q -l quiet -d 'Do not print to stdout or stderr'
 complete -c xh -s S -l stream -d 'Always stream the response body'
@@ -61,6 +62,7 @@ complete -c xh -l no-headers
 complete -c xh -l no-body
 complete -c xh -l no-meta
 complete -c xh -l no-verbose
+complete -c xh -l no-debug
 complete -c xh -l no-all
 complete -c xh -l no-history-print
 complete -c xh -l no-quiet

doc/man-template.roff

@@ -96,6 +96,9 @@ Location of the .netrc file.
 .TP
 .B NO_COLOR
 Disables output coloring. See <https://no-color.org>
+.TP
+.B RUST_LOG
+Configure low-level debug messages. See <https://docs.rs/env_logger/0.11.3/env_logger/#enabling-logging>
 
 .SH FILES
 .TP 4

doc/xh.1

@@ -1,4 +1,4 @@
-.TH XH 1 2024-04-12 0.22.0 "User Commands"
+.TH XH 1 2024-06-04 0.22.0 "User Commands"
 
 .SH NAME
 xh \- Friendly and fast tool for sending HTTP requests
@@ -169,6 +169,11 @@ Using verbose twice i.e. \-vv will print the response metadata as well.
 
 Equivalent to \-\-print=HhBb \-\-all.
 .TP 4
+\fB\-\-debug\fR
+Print full error stack traces and debug log messages.
+
+Logging can be configured in more detail using the `$RUST_LOG` environment variable. See https://docs.rs/env_logger/0.11.3/env_logger/#enabling\-logging.
+.TP 4
 \fB\-\-all\fR
 Show any intermediary requests/responses while following redirects with \-\-follow.
 .TP 4
@@ -371,6 +376,9 @@ Location of the .netrc file.
 .TP
 .B NO_COLOR
 Disables output coloring. See <https://no-color.org>
+.TP
+.B RUST_LOG
+Configure low-level debug messages. See <https://docs.rs/env_logger/0.11.3/env_logger/#enabling-logging>
 
 .SH FILES
 .TP 4

src/buffer.rs

@@ -287,9 +287,11 @@ mod imp {
 
 impl Buffer {
     pub fn new(download: bool, output: Option<&Path>, is_stdout_tty: bool) -> io::Result<Self> {
+        log::trace!("is_stdout_tty: {is_stdout_tty}");
         Ok(if download {
             Buffer::stderr()
         } else if let Some(output) = output {
+            log::trace!("creating file {output:?}");
             let file = std::fs::File::create(output)?;
             Buffer::file(file)
         } else if is_stdout_tty {

src/cli.rs

@@ -18,6 +18,7 @@ use reqwest::{tls, Method, Url};
 use serde::Deserialize;
 
 use crate::buffer::Buffer;
+use crate::redacted::SecretString;
 use crate::request_items::RequestItems;
 use crate::utils::config_dir;
 
@@ -155,6 +156,13 @@ Example: --print=Hb"
     #[clap(short = 'v', long, action = ArgAction::Count)]
     pub verbose: u8,
 
+    /// Print full error stack traces and debug log messages.
+    ///
+    /// Logging can be configured in more detail using the `$RUST_LOG` environment
+    /// variable. See https://docs.rs/env_logger/0.11.3/env_logger/#enabling-logging.
+    #[clap(long)]
+    pub debug: bool,
+
     /// Show any intermediary requests/responses while following redirects with --follow.
     #[clap(long)]
     pub all: bool,
@@ -219,11 +227,11 @@ Example: --print=Hb"
     ///
     /// TOKEN is expected if --auth-type=bearer.
     #[clap(short = 'a', long, value_name = "USER[:PASS] | TOKEN")]
-    pub auth: Option<String>,
+    pub auth: Option<SecretString>,
 
     /// Authenticate with a bearer token.
     #[clap(long, value_name = "TOKEN", hide = true)]
-    pub bearer: Option<String>,
+    pub bearer: Option<SecretString>,
 
     /// Do not use credentials from .netrc
     #[clap(long)]
@@ -618,6 +626,12 @@ impl Cli {
             .after_help(format!("Each option can be reset with a --no-OPTION argument.\n\nRun \"{} help\" for more complete documentation.", env!("CARGO_PKG_NAME")))
             .after_long_help("Each option can be reset with a --no-OPTION argument.")
     }
+
+    pub fn logger_config(&self) -> env_logger::Builder {
+        let default_level = if self.debug { "debug" } else { "off" };
+        let env = env_logger::Env::default().default_filter_or(default_level);
+        env_logger::Builder::from_env(env)
+    }
 }
 
 #[derive(Deserialize)]

src/main.rs

@@ -9,6 +9,7 @@ mod middleware;
 mod nested_json;
 mod netrc;
 mod printer;
+mod redacted;
 mod redirect;
 mod request_items;
 mod session;
@@ -60,6 +61,16 @@ fn get_user_agent() -> &'static str {
 
 fn main() {
     let args = Cli::parse();
+
+    if args.debug {
+        setup_backtraces();
+    }
+    args.logger_config().init();
+    // HTTPie also prints the language version, library versions, and OS version.
+    // But those are harder to access for us (and perhaps less likely to cause quirks).
+    log::debug!("xh {} {}", env!("CARGO_PKG_VERSION"), env!("XH_FEATURES"));
+    log::debug!("{args:#?}");
+
     let bin_name = args.bin_name.clone();
     let native_tls = args.native_tls;
 
@@ -93,13 +104,16 @@ fn run(args: Cli) -> Result<i32> {
         return Ok(0);
     }
 
+    // Maybe we can use log::warn!() for this instead?
+    // The output format is different though.
     let warn = {
         let bin_name = &args.bin_name;
         move |msg| eprintln!("{}: warning: {}", bin_name, msg)
     };
 
     let (mut headers, headers_to_unset) = args.request_items.headers()?;
     let url = url_with_query(args.url, &args.request_items.query()?);
+    log::debug!("Complete URL: {url}");
 
     let use_stdin = !(args.ignore_stdin || io::stdin().is_terminal() || test_pretend_term());
 
@@ -131,6 +145,7 @@ fn run(args: Cli) -> Result<i32> {
     };
 
     let method = args.method.unwrap_or_else(|| body.pick_method());
+    log::debug!("HTTP method: {method}");
 
     let mut client = Client::builder()
         .http1_title_case_headers()
@@ -317,6 +332,7 @@ fn run(args: Cli) -> Result<i32> {
                             None
                         })
                         .with_context(|| format!("Couldn't bind to {:?}", name_or_ip))?;
+                    log::debug!("Resolved {name_or_ip:?} to {ip_addr:?}");
                     client = client.local_address(ip_addr);
                 }
             }
@@ -327,6 +343,8 @@ fn run(args: Cli) -> Result<i32> {
         client = client.resolve(&resolve.domain, SocketAddr::new(resolve.addr, 0));
     }
 
+    log::trace!("Finalizing reqwest client");
+    log::trace!("{client:#?}");
     let client = client.build()?;
 
     let mut session = match &args.session {
@@ -484,6 +502,10 @@ fn run(args: Cli) -> Result<i32> {
             .insert(ACCEPT_ENCODING, HeaderValue::from_static("identity"));
     }
 
+    log::trace!("Built reqwest request");
+    // Note: Debug impl is incomplete?
+    log::trace!("{request:#?}");
+
     let buffer = Buffer::new(
         args.download,
         args.output.as_deref(),
@@ -607,3 +629,28 @@ fn run(args: Cli) -> Result<i32> {
 
     Ok(exit_code)
 }
+
+/// Configure backtraces for standard panics and anyhow using `$RUST_BACKTRACE`.
+///
+/// Note: they only check the environment variable once, so this won't take effect if
+/// we do it after a panic has already happened or an anyhow error has already been
+/// created.
+///
+/// It's possible for CLI parsing to create anyhow errors before we call this function
+/// but it looks like those errors are always fatal.
+///
+/// https://github.com/rust-lang/rust/issues/93346 will become the preferred way to
+/// configure panic backtraces.
+fn setup_backtraces() {
+    if std::env::var_os("RUST_BACKTRACE").is_some_and(|val| !val.is_empty()) {
+        // User knows best
+        return;
+    }
+
+    // SAFETY: No other threads are running at this time.
+    // (Will become unsafe in the 2024 edition.)
+    #[allow(unused_unsafe)]
+    unsafe {
+        std::env::set_var("RUST_BACKTRACE", "1");
+    }
+}

src/redacted.rs

@@ -0,0 +1,44 @@
+use std::ffi::OsString;
+use std::fmt::{self, Debug};
+use std::ops::Deref;
+use std::str::FromStr;
+
+/// A String that doesn't show up in Debug representations.
+///
+/// This is important for logging, where we maybe want to avoid outputting
+/// sensitive data.
+#[derive(Clone, PartialEq, Eq)]
+pub struct SecretString(String);
+
+impl FromStr for SecretString {
+    type Err = std::convert::Infallible;
+
+    fn from_str(s: &str) -> Result<Self, Self::Err> {
+        Ok(Self(s.to_owned()))
+    }
+}
+
+impl Deref for SecretString {
+    type Target = String;
+
+    fn deref(&self) -> &String {
+        &self.0
+    }
+}
+
+impl Debug for SecretString {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        // Uncomment this to see the string anyway:
+        // self.0.fmt(f);
+        // If that turns out to be frequently necessary we could
+        // make this configurable at runtime, e.g. by flipping an
+        // AtomicBool depending on an environment variable.
+        f.write_str("(redacted)")
+    }
+}
+
+impl From<SecretString> for OsString {
+    fn from(string: SecretString) -> OsString {
+        string.0.into()
+    }
+}