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.
This commit is contained in:
Jan Verbeek 2024-06-03 21:45:07 +02:00
parent 0d873a00d9
commit 41ab47f32f
17 changed files with 235 additions and 5 deletions

30
Cargo.lock generated
View File

@ -494,6 +494,28 @@ dependencies = [
"encoding_rs",
]
[[package]]
name = "env_filter"
version = "0.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "a009aa4810eb158359dda09d0c87378e4bbb89b5a801f016885a4707ba24f7ea"
dependencies = [
"log",
]
[[package]]
name = "env_logger"
version = "0.11.3"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "38b35839ba51819680ba087cd351788c9a3c476841207e0b8cee0b04722343b9"
dependencies = [
"anstream",
"anstyle",
"env_filter",
"humantime",
"log",
]
[[package]]
name = "equivalent"
version = "1.0.1"
@ -746,6 +768,12 @@ version = "1.0.3"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "df3b46402a9d5adb4c86a0cf463f42e19994e3ee891101b1841f30a545cb49a9"
[[package]]
name = "humantime"
version = "2.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4"
[[package]]
name = "hyper"
version = "1.2.0"
@ -2434,6 +2462,7 @@ dependencies = [
"dirs",
"encoding_rs",
"encoding_rs_io",
"env_logger",
"flate2",
"form_urlencoded",
"http-body-util",
@ -2442,6 +2471,7 @@ dependencies = [
"indicatif",
"indoc",
"jsonxf",
"log",
"memchr",
"mime",
"mime2ext",

View File

@ -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"

View File

@ -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[]' \

View File

@ -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')

View File

@ -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

View File

@ -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

View File

@ -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

View File

@ -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

View File

@ -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 {

View File

@ -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)]

View File

@ -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,6 +104,8 @@ 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)
@ -100,6 +113,7 @@ fn run(args: Cli) -> Result<i32> {
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");
}
}

44
src/redacted.rs Normal file
View File

@ -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()
}
}

View File

@ -36,6 +36,9 @@ impl Middleware for RedirectFollower {
self.max_redirects
));
}
log::info!("Following redirect to {}", next_request.url());
log::trace!("Remaining redirects: {}", remaining_redirects);
log::trace!("{next_request:#?}");
self.print(&mut ctx, &mut response, &mut next_request)?;
request = clone_request(&mut next_request)?;
response = self.next(&mut ctx, next_request)?;
@ -58,6 +61,7 @@ fn get_next_request(mut request: Request, response: &Response) -> Option<Request
match response.status() {
StatusCode::MOVED_PERMANENTLY | StatusCode::FOUND | StatusCode::SEE_OTHER => {
let next_url = get_next_url(&request)?;
log::trace!("Preparing redirect to {next_url}");
let prev_url = request.url();
if is_cross_domain_redirect(&next_url, prev_url) {
remove_sensitive_headers(request.headers_mut());
@ -74,6 +78,7 @@ fn get_next_request(mut request: Request, response: &Response) -> Option<Request
}
StatusCode::TEMPORARY_REDIRECT | StatusCode::PERMANENT_REDIRECT => {
let next_url = get_next_url(&request)?;
log::trace!("Preparing redirect to {next_url}");
let prev_url = request.url();
if is_cross_domain_redirect(&next_url, prev_url) {
remove_sensitive_headers(request.headers_mut());
@ -93,6 +98,7 @@ fn is_cross_domain_redirect(next: &Url, previous: &Url) -> bool {
// See https://github.com/seanmonstar/reqwest/blob/bbeb1ede4e8098481c3de6f2cafb8ecca1db4ede/src/redirect.rs#L234-L246
fn remove_sensitive_headers(headers: &mut HeaderMap) {
log::debug!("Removing sensitive headers for cross-domain redirect");
headers.remove(AUTHORIZATION);
headers.remove(COOKIE);
headers.remove("cookie2");
@ -102,6 +108,7 @@ fn remove_sensitive_headers(headers: &mut HeaderMap) {
// See https://github.com/seanmonstar/reqwest/blob/bbeb1ede4e8098481c3de6f2cafb8ecca1db4ede/src/async_impl/client.rs#L1503-L1510
fn remove_content_headers(headers: &mut HeaderMap) {
log::debug!("Removing content headers for redirect that strips body");
headers.remove(TRANSFER_ENCODING);
headers.remove(CONTENT_ENCODING);
headers.remove(CONTENT_TYPE);

View File

@ -177,11 +177,13 @@ impl Session {
path
};
log::debug!("Checking for session in {path:?}");
let content = match fs::read_to_string(&path) {
Ok(content) => serde_json::from_str::<Content>(&content)?.migrate(),
Err(err) if err.kind() == io::ErrorKind::NotFound => Content::default(),
Err(err) => return Err(err.into()),
};
log::debug!("Loaded session from {path:?}");
Ok(Session {
url,
@ -347,6 +349,7 @@ impl Session {
fs::create_dir_all(parent_path)?;
}
let mut session_file = fs::File::create(&self.path)?;
log::debug!("Persisting session to {:?}", self.path);
let formatter = serde_json::ser::PrettyFormatter::with_indent(b" ");
let mut ser = serde_json::Serializer::with_formatter(&mut session_file, formatter);
self.content.serialize(&mut ser)?;

View File

@ -133,6 +133,12 @@ pub fn translate(args: Cli) -> Result<Command> {
// Far from an exact match, but it does print the request headers
cmd.opt("-v", "--verbose");
}
if args.debug {
// Again not an exact match but it's something
// This actually overrides --verbose
cmd.arg("--trace");
cmd.arg("-");
}
if args.stream == Some(true) {
// curl sorta streams by default, but its buffer stops it from
// showing up right away

View File

@ -46,7 +46,9 @@ pub fn clone_request(request: &mut Request) -> Result<Request> {
/// Whether to make some things more deterministic for the benefit of tests
pub fn test_mode() -> bool {
// In integration tests the binary isn't compiled with cfg(test), so we
// use an environment variable
// use an environment variable.
// This isn't called very often currently but we could cache it using an
// atomic integer.
cfg!(test) || var_os("XH_TEST_MODE").is_some()
}

View File

@ -3610,3 +3610,59 @@ fn multiple_format_options_are_merged() {
"#});
}
#[test]
fn logs_are_printed_in_debug_mode() {
get_command()
.arg("--debug")
.arg("--offline")
.arg(":")
.env_remove("RUST_LOG")
.assert()
.stderr(contains("DEBUG xh] Cli {"))
.success();
}
#[test]
fn logs_are_not_printed_outside_debug_mode() {
get_command()
.arg("--offline")
.arg(":")
.env_remove("RUST_LOG")
.assert()
.stderr("")
.success();
}
#[test]
fn backtrace_is_printed_in_debug_mode() {
let mut server = server::http(|_req| async move {
panic!("test crash");
});
server.disable_hit_checks();
get_command()
.arg("--debug")
.arg(server.base_url())
.env_remove("RUST_BACKTRACE")
.env_remove("RUST_LIB_BACKTRACE")
.assert()
.stderr(contains("Stack backtrace:"))
.failure();
}
#[test]
fn backtrace_is_not_printed_outside_debug_mode() {
let mut server = server::http(|_req| async move {
panic!("test crash");
});
server.disable_hit_checks();
let cmd = get_command()
.arg(server.base_url())
.env_remove("RUST_BACKTRACE")
.env_remove("RUST_LIB_BACKTRACE")
.assert()
.failure();
assert!(!std::str::from_utf8(&cmd.get_output().stderr)
.unwrap()
.contains("Stack backtrace:"));
}