From 9eb21936c7168491902da9233a105904ee922dea Mon Sep 17 00:00:00 2001 From: Jacob Page Date: Thu, 18 Jun 2026 12:48:07 -0700 Subject: [PATCH 01/10] feat: global --debug HTTP request/response logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add a `--debug transport` mode that dumps raw HTTP requests and responses to stderr for diagnostics, with no per-command wiring. The `--debug` flag was already parsed into `Middleware.debug` but never consumed. This wires it up: - `flags::debug_component_enabled` parses the comma-separated component pattern (`*`, `transport`, `*,-auth`) — the first consumer of the syntax. - A process-global default `TransportLogger` (mirroring `set_default_user_agent`) is published when `--debug` selects `transport`; every `HttpClient` built afterward inherits it as its default logger, so handlers get a curl-style trace automatically. An explicit `HttpClientBuilder::logger` still overrides. - `TransportLogEvent` gains optional `headers`/`body`; the transport send paths capture request headers+body, and response buffering/logging is centralized so JSON/decode responses are dumped in full. Raw byte-download and streaming responses log size only. Raw/multipart/if-match paths now log responses too. - `StderrTransportLogger` renders the trace and redacts sensitive headers (authorization, proxy-authorization, cookie, set-cookie, x-api-key) by default. `CliConfig::with_redacted_debug_headers` adds CLI-specific secret-bearing headers (additive, case-insensitive). - `transport::debug_log_reqwest_request`/`debug_log_reqwest_response` feed the same global sink from bare `reqwest` / progenitor clients that cannot use `HttpClient`. docs/concepts.md documents the feature and the gaps that would let more bare-reqwest call sites migrate onto HttpClient. Co-Authored-By: Claude Opus 4.8 --- docs/concepts.md | 14 +- src/cli.rs | 79 ++++++ src/flags.rs | 65 ++++- src/lib.rs | 7 +- src/transport/client.rs | 456 ++++++++++++++++++++++++---------- src/transport/debug_logger.rs | 266 ++++++++++++++++++++ src/transport/mod.rs | 5 +- tests/foundation.rs | 122 ++++++++- 8 files changed, 861 insertions(+), 153 deletions(-) create mode 100644 src/transport/debug_logger.rs diff --git a/docs/concepts.md b/docs/concepts.md index 6270c7b..d4bbbc1 100644 --- a/docs/concepts.md +++ b/docs/concepts.md @@ -270,7 +270,7 @@ populate middleware: | `--schema` | `schema` | `false` | Renders command schema instead of running business logic. | | `--reason` | `reason` | empty | Reason passed to authorization. | | `--timeout` | `timeout` | `0s` | Command deadline (e.g. `60s`, `5m`); default `0s` = no timeout. | -| `--debug` | `debug` | empty | Enables debug behavior for integrations that use it. | +| `--debug` | `debug` | empty | Enables debug components (comma-separated patterns: `*`, `transport`, `*,-auth`). `transport` dumps HTTP requests/responses to stderr. See [HTTP debug logging](#http-debug-logging). | | `--search` | `search` | empty | Searches command and guide documentation before command execution. | Applications can add additional global flags through `CliConfig::register_flags` and copy parsed @@ -589,6 +589,18 @@ The transport module provides a `reqwest`-based HTTP client with: Auth injectors include bearer token, provider bearer, cookie, basic auth, API key, client credentials, and no-op injectors. +### HTTP debug logging + +The global `--debug` flag drives transport diagnostics through the `transport` component (`--debug`, `--debug transport`, or `--debug '*'`; `--debug '*,-transport'` keeps everything else but silences HTTP).`flags::debug_component_enabled` parses the comma-separated pattern. + +When `transport` is selected the engine publishes a process-wide `StderrTransportLogger` via `transport::set_default_transport_logger`. Every `HttpClient` built afterward inherits it as its default logger (mirroring `set_default_user_agent`), so command handlers get a curl-style request/response trace on stderr with **no per-command wiring**. A client that sets its own logger with `HttpClientBuilder::logger` still overrides the default. The logger is installed once, before the command handler runs, and shared by every client the handler builds, so all of a command's HTTP requests are logged. + +Sensitive headers (`authorization`, `proxy-authorization`, `cookie`, `set-cookie`, `x-api-key`) are redacted by default. A CLI with its own secret-bearing headers — e.g. a custom API-key header an auth injector adds — registers them with `CliConfig::with_redacted_debug_headers`; matching is case-insensitive and additive (the built-in set is always redacted). Request and JSON/decode response bodies are printed in full; raw byte-download and streaming responses report only their size to avoid dumping large payloads. + +For code that talks to `reqwest` directly and cannot use `HttpClient` (bare clients, or progenitor-generated clients that wrap their own `reqwest::Client`), `transport::debug_log_reqwest_request` and `transport::debug_log_reqwest_response` emit to the same global logger, so a single `--debug`-controlled trace can still cover those call sites. + +Adopting `HttpClient` for a generated client is not always possible; a typed progenitor client should attach the helpers above through its own request/response hook instead. Other engine gaps that would let more bare-`reqwest` call sites migrate onto `HttpClient`: a per-request dynamic header hook (e.g. a generated `x-request-id`), an absolute-URL/no-auth request method (pre-signed uploads), an arbitrary-method escape hatch returning the raw response, and surfacing `x-request-id` from error responses into `transport::Error`. + ## Contributor Model The intended contributor workflow is: diff --git a/src/cli.rs b/src/cli.rs index 0d50de7..a3bb55e 100644 --- a/src/cli.rs +++ b/src/cli.rs @@ -214,6 +214,12 @@ pub struct CliConfig { /// the engine derives `name/version` from this config. See /// [`CliConfig::user_agent_string`]. pub user_agent: Option, + /// Extra HTTP header names to redact in `--debug transport` output, on top + /// of the built-in sensitive set (`authorization`, `proxy-authorization`, + /// `cookie`, `set-cookie`, `x-api-key`). Set CLI-specific secret-bearing + /// headers here — e.g. a custom API-key header an auth injector adds. + /// Populate via [`CliConfig::with_redacted_debug_headers`]. + pub redacted_debug_headers: Vec, /// Optional authorization gatekeeper injected into middleware. pub authz: Option>, /// Optional audit recorder injected into middleware. @@ -351,6 +357,24 @@ impl CliConfig { self } + /// Adds HTTP header names to redact in `--debug transport` output, on top of + /// the built-in sensitive set. + /// + /// Use this for CLI-specific secret-bearing headers that are not standard + /// auth headers — for example a custom API-key header that an + /// [`AuthInjector`](crate::transport::AuthInjector) sets. Matching is + /// case-insensitive and additive: the built-in set is always redacted. + /// Calls accumulate. + #[must_use] + pub fn with_redacted_debug_headers( + mut self, + names: impl IntoIterator>, + ) -> Self { + self.redacted_debug_headers + .extend(names.into_iter().map(Into::into)); + self + } + /// Returns the outbound User-Agent string the CLI presents on HTTP requests. /// /// Resolution order: @@ -1403,6 +1427,7 @@ impl Cli { }; let mut middleware = self.middleware.clone(); apply_global_flags(&mut middleware, &flags, command_timeout); + install_debug_transport_logger(&flags.debug, &self.config.redacted_debug_headers); if let Err(err) = self.apply_config_flags(&matches, &mut middleware) { return self.finish_run(render_cli_error(&middleware, &err, &self.config.app_id)); } @@ -1490,6 +1515,7 @@ impl Cli { } }; apply_global_flags(&mut middleware, &flags, command_timeout); + install_debug_transport_logger(&flags.debug, &self.config.redacted_debug_headers); if let Err(err) = self.apply_config_flags(&matches, &mut middleware) { return self.finish_run(render_cli_error(&middleware, &err, &self.config.app_id)); } @@ -2081,6 +2107,29 @@ fn apply_global_flags(middleware: &mut Middleware, flags: &GlobalFlags, timeout: middleware.search = flags.search.clone(); } +/// Installs (or clears) the process-wide transport debug logger from the parsed +/// `--debug` pattern. +/// +/// When `--debug` selects the `transport` component the engine publishes a +/// [`StderrTransportLogger`](crate::transport::StderrTransportLogger) — extended +/// with any [`CliConfig::with_redacted_debug_headers`] entries — which every +/// [`HttpClient`](crate::transport::HttpClient) built afterward picks up +/// automatically, with no per-command wiring. The logger is reset to a noop when +/// `transport` is not selected so the explicit setting always reflects the +/// current invocation rather than a stale process-global from an earlier one. +fn install_debug_transport_logger(debug: &str, extra_redacted: &[String]) { + let logger: Arc = + if crate::debug_component_enabled(debug, "transport") { + Arc::new( + crate::transport::StderrTransportLogger::new() + .with_redacted_headers(extra_redacted.iter().cloned()), + ) + } else { + Arc::new(crate::transport::NoopTransportLogger) + }; + crate::transport::set_default_transport_logger(logger); +} + async fn run_with_timeout( timeout: Option, timeout_label: &str, @@ -3002,6 +3051,36 @@ mod user_agent_tests { "uatest/4.5.6" ); } + + #[test] + fn install_debug_transport_logger_tracks_the_debug_pattern() { + let _guard = crate::transport::client::TRANSPORT_LOGGER_TEST_LOCK + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner); + let _restore = crate::transport::client::RestoreDefaultTransportLogger; + + // `transport` selected -> a real stderr logger is published. + install_debug_transport_logger("transport", &[]); + assert!( + format!("{:?}", crate::transport::default_transport_logger()) + .starts_with("StderrTransportLogger") + ); + + // Wildcard with transport excluded -> back to the noop. + install_debug_transport_logger("*,-transport", &[]); + assert_eq!( + format!("{:?}", crate::transport::default_transport_logger()), + "NoopTransportLogger" + ); + + // Empty pattern -> noop. + install_debug_transport_logger("transport", &[]); + install_debug_transport_logger("", &[]); + assert_eq!( + format!("{:?}", crate::transport::default_transport_logger()), + "NoopTransportLogger" + ); + } } #[cfg(test)] diff --git a/src/flags.rs b/src/flags.rs index 068a157..ff033b4 100644 --- a/src/flags.rs +++ b/src/flags.rs @@ -482,6 +482,49 @@ fn collect_flag_names(command: &Command, visit: &mut impl FnMut(&Arg, String)) { } } +/// Reports whether a `--debug` pattern enables a named component. +/// +/// The pattern is a comma-separated list of tokens applied left to right, so +/// later tokens override earlier ones: +/// +/// - `*` enables every component; `-*` disables every component. +/// - `name` enables that component; `-name` disables it. +/// - whitespace around tokens is ignored and matching is case-insensitive. +/// +/// An empty pattern enables nothing. Tokens that name other components are +/// ignored for the queried `component`. +/// +/// # Examples +/// +/// ``` +/// use cli_engine::debug_component_enabled; +/// +/// assert!(debug_component_enabled("*", "transport")); +/// assert!(debug_component_enabled("transport", "transport")); +/// assert!(!debug_component_enabled("*,-transport", "transport")); +/// assert!(debug_component_enabled("*,-auth", "transport")); +/// assert!(!debug_component_enabled("", "transport")); +/// ``` +#[must_use] +pub fn debug_component_enabled(pattern: &str, component: &str) -> bool { + let component = component.trim().to_ascii_lowercase(); + let mut enabled = false; + for raw in pattern.split(',') { + let token = raw.trim(); + if token.is_empty() { + continue; + } + let (negated, name) = token + .strip_prefix('-') + .map_or((false, token), |rest| (true, rest)); + let name = name.trim().to_ascii_lowercase(); + if name == "*" || name == component { + enabled = !negated; + } + } + enabled +} + fn arg_requires_value(arg: &Arg) -> bool { match arg.get_action() { ArgAction::Set | ArgAction::Append => arg @@ -502,7 +545,27 @@ fn arg_requires_value(arg: &Arg) -> bool { #[cfg(test)] mod tests { - use super::{output_env_var, resolve_default_output_format}; + use super::{debug_component_enabled, output_env_var, resolve_default_output_format}; + + #[test] + fn debug_component_matcher_handles_wildcards_and_negation() { + // Empty pattern enables nothing. + assert!(!debug_component_enabled("", "transport")); + // Wildcard enables everything. + assert!(debug_component_enabled("*", "transport")); + assert!(debug_component_enabled("*", "auth")); + // Bare name enables only that component. + assert!(debug_component_enabled("transport", "transport")); + assert!(!debug_component_enabled("transport", "auth")); + // Negation after a wildcard removes one component but keeps the rest. + assert!(!debug_component_enabled("*,-transport", "transport")); + assert!(debug_component_enabled("*,-auth", "transport")); + // `-*` disables everything; later tokens still win. + assert!(!debug_component_enabled("*,-*", "transport")); + assert!(debug_component_enabled("-*,transport", "transport")); + // Whitespace and case are ignored. + assert!(debug_component_enabled(" Transport , -auth ", "transport")); + } #[test] fn default_output_format_follows_env_override_then_tty() { diff --git a/src/lib.rs b/src/lib.rs index 520437d..dd3b999 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -129,9 +129,10 @@ pub use error::{ CliCoreError, DetailedError, ExitCoder, Result, exit_code_for_error, exit_code_for_exit_coder, }; pub use flags::{ - GlobalFlags, app_id_env_prefix, default_output_format, derive_bool_flags, derive_value_flags, - extract_command_path, extract_output_format, extract_search_query, global_flags_from_matches, - has_true_schema_flag, output_env_var, register_global_flags, resolve_default_output_format, + GlobalFlags, app_id_env_prefix, debug_component_enabled, default_output_format, + derive_bool_flags, derive_value_flags, extract_command_path, extract_output_format, + extract_search_query, global_flags_from_matches, has_true_schema_flag, output_env_var, + register_global_flags, resolve_default_output_format, }; pub use guide::{GuideEntry, parse_guides, parse_guides_from_markdown}; pub use middleware::{ diff --git a/src/transport/client.rs b/src/transport/client.rs index 9fff60d..9e55512 100644 --- a/src/transport/client.rs +++ b/src/transport/client.rs @@ -69,6 +69,101 @@ impl Drop for RestoreDefaultUserAgent { } } +static DEFAULT_TRANSPORT_LOGGER: OnceLock>> = OnceLock::new(); + +fn default_transport_logger_lock() -> &'static RwLock> { + DEFAULT_TRANSPORT_LOGGER.get_or_init(|| RwLock::new(Arc::new(NoopTransportLogger))) +} + +/// Sets the process-wide default transport logger for outbound HTTP traffic. +/// +/// Applies to subsequently created [`HttpClient`] values (those that do not set +/// their own via [`HttpClientBuilder::logger`]) and to the free +/// [`super::debug_log_reqwest_request`] / [`super::debug_log_reqwest_response`] +/// helpers used by code that talks to `reqwest` directly. +/// +/// The CLI installs a logger from this setter when `--debug` selects the +/// `transport` component, so command handlers get request/response diagnostics +/// without any per-command wiring. A per-client logger still overrides it for +/// that client. +pub fn set_default_transport_logger(logger: Arc) { + if let Ok(mut current) = default_transport_logger_lock().write() { + *current = logger; + } +} + +/// Returns the process-wide default transport logger set via +/// [`set_default_transport_logger`], or a [`NoopTransportLogger`] when none was +/// set. +#[must_use] +pub fn default_transport_logger() -> Arc { + default_transport_logger_lock() + .read() + .map_or_else(|_| no_op_logger(), |logger| logger.clone()) +} + +fn no_op_logger() -> Arc { + Arc::new(NoopTransportLogger) +} + +/// Logs a `reqwest::Request` to the process-wide default transport logger. +/// +/// This is the bridge for code that talks to `reqwest` directly — bare clients +/// or progenitor-generated clients that cannot use [`HttpClient`] — so a single +/// `--debug`-controlled trace can still cover them. Captures the request method, +/// URL, headers, and in-memory body. Pairs with [`debug_log_reqwest_response`]. +/// It is a no-op unless a logger has been installed via +/// [`set_default_transport_logger`]. +pub fn debug_log_reqwest_request(request: &reqwest::Request) { + default_transport_logger().debug(&TransportLogEvent { + message: "http request", + fields: BTreeMap::from([ + ("method".to_owned(), request.method().as_str().to_owned()), + ("url".to_owned(), request.url().as_str().to_owned()), + ]), + headers: Some(header_pairs(request.headers())), + body: request + .body() + .and_then(reqwest::Body::as_bytes) + .map(<[u8]>::to_vec), + }); +} + +/// Logs an HTTP response (status, headers, body) to the process-wide default +/// transport logger. +/// +/// Companion to [`debug_log_reqwest_request`] for `reqwest`-direct call sites. +/// The caller passes the already-read response body. It is a no-op unless a +/// logger has been installed via [`set_default_transport_logger`]. +pub fn debug_log_reqwest_response(status: StatusCode, headers: &header::HeaderMap, body: &[u8]) { + default_transport_logger().debug(&TransportLogEvent { + message: "http response", + fields: BTreeMap::from([("status".to_owned(), status.as_u16().to_string())]), + headers: Some(header_pairs(headers)), + body: Some(body.to_vec()), + }); +} + +/// Serializes unit tests that mutate the process-wide default transport logger +/// so they cannot observe one another's writes. Integration tests in +/// `tests/foundation.rs` run in a separate binary and use their own lock. +#[cfg(test)] +pub(crate) static TRANSPORT_LOGGER_TEST_LOCK: std::sync::Mutex<()> = std::sync::Mutex::new(()); + +/// Restores the process-wide default transport logger to the noop on drop, so a +/// panicking assertion in a test that installs a logger cannot leak it into +/// later tests. Declare it after acquiring [`TRANSPORT_LOGGER_TEST_LOCK`] so the +/// reset runs while the lock is still held. +#[cfg(test)] +pub(crate) struct RestoreDefaultTransportLogger; + +#[cfg(test)] +impl Drop for RestoreDefaultTransportLogger { + fn drop(&mut self) { + set_default_transport_logger(no_op_logger()); + } +} + #[derive(serde::Deserialize)] struct GraphQlError { message: String, @@ -82,12 +177,24 @@ struct GraphQlEnvelope { } /// Structured debug event emitted by [`TransportLogger`]. -#[derive(Clone, Debug)] +/// +/// `message` and `fields` are the stable breadcrumb surface (method, url, +/// status, retry attempt). `headers` and `body` carry the raw, un-redacted +/// request or response payload when one is available; loggers that print these +/// (such as [`StderrTransportLogger`](super::StderrTransportLogger)) are +/// responsible for redacting sensitive headers. +#[derive(Clone, Debug, Default)] pub struct TransportLogEvent { /// Event name such as `http request` or `retrying request`. pub message: &'static str, /// Stable event fields. pub fields: BTreeMap, + /// Raw header name/value pairs for the request or response, when known. + pub headers: Option>, + /// Raw request or response body bytes, when captured. Streaming and + /// byte-download responses omit this and report a `body_bytes` field + /// instead to avoid buffering large payloads into the log. + pub body: Option>, } /// Debug logger interface for transport events. @@ -139,7 +246,7 @@ impl HttpClientBuilder { auth, user_agent: default_user_agent(), default_headers: BTreeMap::new(), - logger: Arc::new(NoopTransportLogger), + logger: default_transport_logger(), } } @@ -281,7 +388,7 @@ impl HttpClient { .and_then(|value| value.to_str().ok()) .unwrap_or_default() .to_owned(); - let value = decode_json_response(response, "GET", path).await?; + let value = self.decode_json_response(response, "GET", path).await?; Ok((value, etag)) } @@ -294,7 +401,7 @@ impl HttpClient { .and_then(|value| value.to_str().ok()) .unwrap_or_default() .to_owned(); - ensure_success_response(response, "GET", path).await?; + self.ensure_success_response(response, "GET", path).await?; Ok(etag) } @@ -306,7 +413,7 @@ impl HttpClient { etag: &str, ) -> Result { let response = self.send_put_if_match(path, body, etag).await?; - decode_json_response(response, "PUT", path).await + self.decode_json_response(response, "PUT", path).await } /// Sends PUT with `If-Match` and checks only for success. @@ -317,19 +424,20 @@ impl HttpClient { etag: &str, ) -> Result<()> { let response = self.send_put_if_match(path, body, etag).await?; - ensure_success_response(response, "PUT", path).await + self.ensure_success_response(response, "PUT", path).await } /// Streams a raw GET response body into a writer. pub async fn get_raw(&self, path: &str, writer: &mut dyn Write) -> Result<()> { let response = self.send_get_raw_status_only_retry(path).await?; - if response.status().is_client_error() || response.status().is_server_error() { - return Err(parse_error_response(response, "GET", path).await.into()); + let (status, bytes) = self + .read_and_log_response(response, "GET", path, false) + .await?; + if status.is_client_error() || status.is_server_error() { + return Err( + parse_error_body(status, &String::from_utf8_lossy(&bytes), "GET", path).into(), + ); } - let bytes = response - .bytes() - .await - .map_err(|err| CliCoreError::message(format!("transport: stream response: {err}")))?; writer.write_all(&bytes)?; Ok(()) } @@ -337,14 +445,15 @@ impl HttpClient { /// Sends GET and returns the raw response body as bytes. pub async fn get_bytes(&self, path: &str) -> Result> { let response = self.send_get_raw_status_only_retry(path).await?; - if response.status().is_client_error() || response.status().is_server_error() { - return Err(parse_error_response(response, "GET", path).await.into()); + let (status, bytes) = self + .read_and_log_response(response, "GET", path, false) + .await?; + if status.is_client_error() || status.is_server_error() { + return Err( + parse_error_body(status, &String::from_utf8_lossy(&bytes), "GET", path).into(), + ); } - let bytes = response - .bytes() - .await - .map_err(|err| CliCoreError::message(format!("transport: stream response: {err}")))?; - Ok(bytes.to_vec()) + Ok(bytes) } /// Sends POST and streams the raw response body into a writer. @@ -355,13 +464,14 @@ impl HttpClient { writer: &mut dyn Write, ) -> Result<()> { let response = self.send_post_raw_once(path, body).await?; - if response.status().is_client_error() || response.status().is_server_error() { - return Err(parse_error_response(response, "POST", path).await.into()); + let (status, bytes) = self + .read_and_log_response(response, "POST", path, false) + .await?; + if status.is_client_error() || status.is_server_error() { + return Err( + parse_error_body(status, &String::from_utf8_lossy(&bytes), "POST", path).into(), + ); } - let bytes = response - .bytes() - .await - .map_err(|err| CliCoreError::message(format!("transport: stream response: {err}")))?; writer.write_all(&bytes)?; Ok(()) } @@ -388,7 +498,8 @@ impl HttpClient { ) -> Result { let method_text = method.as_str().to_owned(); let response = self.send_raw_once(method, path, content_type, body).await?; - decode_json_response(response, &method_text, path).await + self.decode_json_response(response, &method_text, path) + .await } /// Sends a raw-body request and checks only for success. @@ -413,7 +524,8 @@ impl HttpClient { ) -> Result<()> { let method_text = method.as_str().to_owned(); let response = self.send_raw_once(method, path, content_type, body).await?; - ensure_success_response(response, &method_text, path).await + self.ensure_success_response(response, &method_text, path) + .await } /// Sends a multipart file upload and decodes a JSON response. @@ -604,7 +716,8 @@ impl HttpClient { ) -> Result { let method_text = method.as_str().to_owned(); let response = self.send_with_retry(method, path, body).await?; - decode_json_response(response, &method_text, path).await + self.decode_json_response(response, &method_text, path) + .await } async fn post_graphql_response_envelope( @@ -644,25 +757,11 @@ impl HttpClient { .build() .map_err(|err| CliCoreError::message(format!("transport: create request: {err}")))?; self.inject_auth(&mut request).await?; - let url = format!("{}{}", self.base_url, path); - self.log_debug( - "http request", - [("method", "PUT".to_owned()), ("url", url.clone())], - ); - let response = self - .base + self.log_request(&request); + self.base .execute(request) .await - .map_err(|err| CliCoreError::message(format!("transport: PUT {path}: {err}")))?; - self.log_debug( - "http response", - [ - ("status", response.status().as_u16().to_string()), - ("method", "PUT".to_owned()), - ("url", url), - ], - ); - Ok(response) + .map_err(|err| CliCoreError::message(format!("transport: PUT {path}: {err}"))) } async fn send_multipart( @@ -671,7 +770,7 @@ impl HttpClient { form: reqwest::multipart::Form, ) -> Result { let response = self.send_multipart_response(path, form).await?; - decode_json_response(response, "POST", path).await + self.decode_json_response(response, "POST", path).await } async fn send_multipart_without_response( @@ -680,7 +779,7 @@ impl HttpClient { form: reqwest::multipart::Form, ) -> Result<()> { let response = self.send_multipart_response(path, form).await?; - ensure_success_response(response, "POST", path).await + self.ensure_success_response(response, "POST", path).await } async fn send_multipart_response( @@ -691,7 +790,7 @@ impl HttpClient { let url = format!("{}{}", self.base_url, path); let mut builder = self .base - .post(url.clone()) + .post(url) .header(header::USER_AGENT, self.user_agent.clone()) .multipart(form); for (key, value) in &self.default_headers { @@ -701,7 +800,7 @@ impl HttpClient { .build() .map_err(|err| CliCoreError::message(format!("transport: create request: {err}")))?; self.inject_auth(&mut request).await?; - self.log_debug("http multipart request", [("url", url)]); + self.log_request(&request); self.base .execute(request) .await @@ -716,7 +815,8 @@ impl HttpClient { ) -> Result<()> { let method_text = method.as_str().to_owned(); let response = self.send_with_retry(method, path, body).await?; - ensure_success_response(response, &method_text, path).await + self.ensure_success_response(response, &method_text, path) + .await } async fn send_raw_once( @@ -745,13 +845,7 @@ impl HttpClient { .build() .map_err(|err| CliCoreError::message(format!("transport: create request: {err}")))?; self.inject_auth(&mut request).await?; - self.log_debug( - "http request", - [ - ("method", method_text.clone()), - ("url", format!("{}{}", self.base_url, path)), - ], - ); + self.log_request(&request); self.base .execute(request) .await @@ -768,13 +862,13 @@ impl HttpClient { match self.send_get_raw_once(path).await { Ok(response) => { - if response.status() == StatusCode::TOO_MANY_REQUESTS - || response.status().is_server_error() - { + let status = response.status(); + if status == StatusCode::TOO_MANY_REQUESTS || status.is_server_error() { + self.log_response("GET", path, status, response.headers(), None, None); last_err = Some(CliCoreError::message(format!( "transport: GET {}: status {}", path, - response.status().as_u16() + status.as_u16() ))); continue; } @@ -790,7 +884,7 @@ impl HttpClient { let url = format!("{}{}", self.base_url, path); let mut builder = self .base - .get(url.clone()) + .get(url) .header(header::USER_AGENT, self.user_agent.clone()); for (key, value) in &self.default_headers { builder = builder.header(key, value); @@ -799,7 +893,7 @@ impl HttpClient { .build() .map_err(|err| CliCoreError::message(format!("transport: create request: {err}")))?; self.inject_auth(&mut request).await?; - self.log_debug("http raw request", [("url", url)]); + self.log_request(&request); self.base .execute(request) .await @@ -816,10 +910,7 @@ impl HttpClient { .build() .map_err(|err| CliCoreError::message(format!("transport: create request: {err}")))?; self.inject_auth(&mut request).await?; - self.log_debug( - "http post raw request", - [("url", format!("{}{}", self.base_url, path))], - ); + self.log_request(&request); self.base .execute(request) .await @@ -849,8 +940,10 @@ impl HttpClient { match self.send_once(method.clone(), path, body).await { Ok(response) => { if retryable_status(method.clone(), response.status()) { - last_err = - Some(retryable_status_error(response, method.as_str(), path).await); + last_err = Some( + self.retryable_status_error(response, method.as_str(), path) + .await, + ); continue; } return Ok(response); @@ -881,13 +974,13 @@ impl HttpClient { match self.send_once(Method::GET, path, Option::<&()>::None).await { Ok(response) => { - if response.status() == StatusCode::TOO_MANY_REQUESTS - || response.status().is_server_error() - { + let status = response.status(); + if status == StatusCode::TOO_MANY_REQUESTS || status.is_server_error() { + self.log_response("GET", path, status, response.headers(), None, None); last_err = Some(CliCoreError::message(format!( "transport: GET {}: status {}", path, - response.status().as_u16() + status.as_u16() ))); continue; } @@ -911,25 +1004,11 @@ impl HttpClient { .map_err(|err| CliCoreError::message(format!("transport: create request: {err}")))?; self.inject_auth(&mut request).await?; let method_text = method.as_str().to_owned(); - self.log_debug( - "http request", - [ - ("method", method_text.clone()), - ("url", format!("{}{}", self.base_url, path)), - ], - ); - let response = self.base.execute(request).await.map_err(|err| { - CliCoreError::message(format!("transport: {method_text} {path}: {err}")) - })?; - self.log_debug( - "http response", - [ - ("status", response.status().as_u16().to_string()), - ("method", method_text), - ("url", format!("{}{}", self.base_url, path)), - ], - ); - Ok(response) + self.log_request(&request); + self.base + .execute(request) + .await + .map_err(|err| CliCoreError::message(format!("transport: {method_text} {path}: {err}"))) } fn build_request( @@ -967,48 +1046,171 @@ impl HttpClient { .into_iter() .map(|(key, value)| (key.to_owned(), value)) .collect(), + headers: None, + body: None, + }); + } + + /// Emits an `http request` event capturing the built request's headers and + /// in-memory body. Streaming bodies (e.g. multipart) report no body. + fn log_request(&self, request: &reqwest::Request) { + self.logger.debug(&TransportLogEvent { + message: "http request", + fields: BTreeMap::from([ + ("method".to_owned(), request.method().as_str().to_owned()), + ("url".to_owned(), request.url().as_str().to_owned()), + ]), + headers: Some(header_pairs(request.headers())), + body: request + .body() + .and_then(reqwest::Body::as_bytes) + .map(<[u8]>::to_vec), }); } + /// Emits an `http response` event. When `body` is `None`, `body_bytes` + /// records the payload size instead (used for raw/byte-download paths so + /// large responses are not buffered into the log). + fn log_response( + &self, + method: &str, + path: &str, + status: StatusCode, + headers: &header::HeaderMap, + body: Option<&[u8]>, + body_bytes: Option, + ) { + let mut fields = BTreeMap::from([ + ("status".to_owned(), status.as_u16().to_string()), + ("method".to_owned(), method.to_owned()), + ("url".to_owned(), format!("{}{}", self.base_url, path)), + ]); + if let Some(len) = body_bytes { + fields.insert("body_bytes".to_owned(), len.to_string()); + } + self.logger.debug(&TransportLogEvent { + message: "http response", + fields, + headers: Some(header_pairs(headers)), + body: body.map(<[u8]>::to_vec), + }); + } + + /// Reads a response body once, emits the `http response` event, and returns + /// the status and buffered bytes. `include_body` controls whether the body + /// is attached to the log or only its size is reported. + async fn read_and_log_response( + &self, + response: reqwest::Response, + method: &str, + path: &str, + include_body: bool, + ) -> Result<(StatusCode, Vec)> { + let status = response.status(); + let headers = response.headers().clone(); + let body = response + .bytes() + .await + .map_err(|err| CliCoreError::message(format!("transport: decode response: {err}")))?; + if include_body { + self.log_response(method, path, status, &headers, Some(&body), None); + } else { + self.log_response(method, path, status, &headers, None, Some(body.len())); + } + Ok((status, body.to_vec())) + } + async fn inject_auth(&self, request: &mut reqwest::Request) -> Result<()> { self.auth .inject(request) .await .map_err(|err| CliCoreError::message(format!("transport: auth inject: {err}"))) } -} -async fn decode_json_response( - response: reqwest::Response, - method: &str, - path: &str, -) -> Result { - if response.status().is_client_error() || response.status().is_server_error() { - return Err(parse_error_response(response, method, path).await.into()); + async fn decode_json_response( + &self, + response: reqwest::Response, + method: &str, + path: &str, + ) -> Result { + let (status, body) = self + .read_and_log_response(response, method, path, true) + .await?; + if status.is_client_error() || status.is_server_error() { + return Err( + parse_error_body(status, &String::from_utf8_lossy(&body), method, path).into(), + ); + } + if status == StatusCode::NO_CONTENT { + return Ok(T::default()); + } + if body.trim_ascii() == b"null" { + return Ok(T::default()); + } + serde_json::from_slice::(&body) + .map_err(|err| CliCoreError::message(format!("transport: decode response: {err}"))) } - if response.status() == StatusCode::NO_CONTENT { - return Ok(T::default()); + + async fn ensure_success_response( + &self, + response: reqwest::Response, + method: &str, + path: &str, + ) -> Result<()> { + let (status, body) = self + .read_and_log_response(response, method, path, true) + .await?; + if status.is_client_error() || status.is_server_error() { + return Err( + parse_error_body(status, &String::from_utf8_lossy(&body), method, path).into(), + ); + } + Ok(()) } - let body = response - .bytes() - .await - .map_err(|err| CliCoreError::message(format!("transport: decode response: {err}")))?; - if body.trim_ascii() == b"null" { - return Ok(T::default()); + + async fn retryable_status_error( + &self, + response: reqwest::Response, + method: &str, + path: &str, + ) -> CliCoreError { + let status = response.status(); + let headers = response.headers().clone(); + match response.bytes().await { + Ok(body) => { + self.log_response(method, path, status, &headers, Some(&body), None); + CliCoreError::message(format!( + "transport: {method} {path}: status {}: {}", + status.as_u16(), + String::from_utf8_lossy(&body) + )) + } + Err(err) => { + self.log_response(method, path, status, &headers, None, None); + CliCoreError::message(format!( + "transport: {method} {path}: status {} (body read failed: {err})", + status.as_u16() + )) + } + } } - serde_json::from_slice::(&body) - .map_err(|err| CliCoreError::message(format!("transport: decode response: {err}"))) } -async fn ensure_success_response( - response: reqwest::Response, - method: &str, - path: &str, -) -> Result<()> { - if response.status().is_client_error() || response.status().is_server_error() { - return Err(parse_error_response(response, method, path).await.into()); - } - Ok(()) +/// Converts a `reqwest` header map into owned name/value pairs for logging. +/// +/// Header values that are not valid UTF-8 are rendered as a byte-count +/// placeholder rather than dropped, so the trace still shows the header exists. +fn header_pairs(headers: &header::HeaderMap) -> Vec<(String, String)> { + headers + .iter() + .map(|(name, value)| { + let value = value.to_str().map_or_else( + |_| format!("<{} non-utf8 bytes>", value.as_bytes().len()), + str::to_owned, + ); + (name.as_str().to_owned(), value) + }) + .collect() } /// Converts a non-success HTTP response into the shared transport error shape. @@ -1042,22 +1244,6 @@ fn retryable_status(method: Method, status: StatusCode) -> bool { status == StatusCode::TOO_MANY_REQUESTS || (status.is_server_error() && is_idempotent(&method)) } -async fn retryable_status_error( - response: reqwest::Response, - method: &str, - path: &str, -) -> CliCoreError { - let status = response.status().as_u16(); - match response.text().await { - Ok(body) => CliCoreError::message(format!( - "transport: {method} {path}: status {status}: {body}" - )), - Err(err) => CliCoreError::message(format!( - "transport: {method} {path}: status {status} (body read failed: {err})" - )), - } -} - fn is_idempotent(method: &Method) -> bool { matches!(*method, Method::GET | Method::HEAD | Method::DELETE) } diff --git a/src/transport/debug_logger.rs b/src/transport/debug_logger.rs new file mode 100644 index 0000000..f8b5317 --- /dev/null +++ b/src/transport/debug_logger.rs @@ -0,0 +1,266 @@ +//! Stderr sink for transport debug events. +//! +//! [`StderrTransportLogger`] renders [`TransportLogEvent`]s as a curl-style +//! request/response trace on stderr. It is the logger the CLI installs when +//! `--debug` selects the `transport` component. Sensitive headers are redacted +//! so the output is safe to paste into a ticket. + +use std::io::Write; + +use super::client::{TransportLogEvent, TransportLogger}; + +/// Header names whose values are replaced with `` in the dump. +const SENSITIVE_HEADERS: &[&str] = &[ + "authorization", + "proxy-authorization", + "cookie", + "set-cookie", + "x-api-key", +]; + +const REDACTED: &str = ""; + +/// Transport logger that prints a redacted, curl-style HTTP trace to stderr. +/// +/// Outbound requests are prefixed with `>` and responses with `<`: +/// +/// ```text +/// > POST https://api.example.com/v3/repos +/// > authorization: +/// > content-type: application/json +/// > +/// > {"name":"foo"} +/// +/// < 200 POST https://api.example.com/v3/repos +/// < content-type: application/json +/// < +/// < {"id":"repo-1"} +/// ``` +/// +/// Bodies are printed for JSON/decode paths; raw byte-download responses report +/// only their size. Sensitive header values (`authorization`, +/// `proxy-authorization`, `cookie`, `set-cookie`, `x-api-key`) are redacted. +#[derive(Clone, Debug, Default)] +pub struct StderrTransportLogger { + /// Extra header names to redact, in addition to the built-in set. Stored + /// lowercased; matching is case-insensitive. + extra_redacted: Vec, +} + +impl StderrTransportLogger { + /// Creates a stderr transport logger that redacts the built-in sensitive + /// header set. + #[must_use] + pub fn new() -> Self { + Self::default() + } + + /// Adds header names to redact on top of the built-in set. + /// + /// Use this for CLI-specific secret-bearing headers that are not standard + /// auth headers — for example a custom API-key header an auth injector sets. + /// Names are matched case-insensitively. Additive only: the built-in set + /// (`authorization`, `proxy-authorization`, `cookie`, `set-cookie`, + /// `x-api-key`) is always redacted. + #[must_use] + pub fn with_redacted_headers( + mut self, + names: impl IntoIterator>, + ) -> Self { + self.extra_redacted.extend( + names + .into_iter() + .map(|name| name.into().to_ascii_lowercase()), + ); + self + } + + fn is_sensitive(&self, name: &str) -> bool { + SENSITIVE_HEADERS + .iter() + .any(|candidate| name.eq_ignore_ascii_case(candidate)) + || self + .extra_redacted + .iter() + .any(|candidate| name.eq_ignore_ascii_case(candidate)) + } + + /// Renders a single transport event into its stderr representation. + /// + /// Kept private (not `pub`) so unit tests can assert on the formatted text + /// without capturing the process stderr stream. + fn format_event(&self, event: &TransportLogEvent) -> String { + match event.message { + "http request" => { + let method = field(event, "method").unwrap_or("?"); + let url = field(event, "url").unwrap_or("?"); + let mut out = format!("> {method} {url}\n"); + self.append_headers(&mut out, ">", event); + append_body(&mut out, ">", event); + out + } + "http response" => { + let status = field(event, "status").unwrap_or("?"); + let method = field(event, "method").unwrap_or(""); + let url = field(event, "url").unwrap_or(""); + let mut out = format!("< {status} {method} {url}\n"); + self.append_headers(&mut out, "<", event); + append_body(&mut out, "<", event); + out + } + "retrying request" => { + let attempt = field(event, "attempt").unwrap_or("?"); + let backoff = field(event, "backoff").unwrap_or("?"); + format!("* retrying (attempt {attempt}, backoff {backoff})\n") + } + other => { + let mut out = format!("* {other}"); + for (key, value) in &event.fields { + out.push_str(&format!(" {key}={value}")); + } + out.push('\n'); + out + } + } + } + + fn append_headers(&self, out: &mut String, prefix: &str, event: &TransportLogEvent) { + if let Some(headers) = &event.headers { + for (name, value) in headers { + let shown = if self.is_sensitive(name) { + REDACTED + } else { + value + }; + out.push_str(&format!("{prefix} {name}: {shown}\n")); + } + } + } +} + +impl TransportLogger for StderrTransportLogger { + fn debug(&self, event: &TransportLogEvent) { + let rendered = self.format_event(event); + if rendered.is_empty() { + return; + } + // Write directly to a locked stderr handle (not `eprintln!`) so the + // whole event lands as one contiguous block under concurrency. + // Diagnostics are best-effort, so a failed write is dropped rather than + // allowed to break the command. + let mut stderr = std::io::stderr().lock(); + drop(stderr.write_all(rendered.as_bytes())); + } +} + +fn field<'event>(event: &'event TransportLogEvent, key: &str) -> Option<&'event str> { + event.fields.get(key).map(String::as_str) +} + +fn append_body(out: &mut String, prefix: &str, event: &TransportLogEvent) { + if let Some(body) = &event.body { + if body.is_empty() { + return; + } + out.push_str(&format!("{prefix}\n")); + for line in String::from_utf8_lossy(body).lines() { + out.push_str(&format!("{prefix} {line}\n")); + } + } else if let Some(size) = field(event, "body_bytes") + && size != "0" + { + out.push_str(&format!("{prefix} [body: {size} bytes not captured]\n")); + } +} + +#[cfg(test)] +mod tests { + use std::collections::BTreeMap; + + use super::{REDACTED, StderrTransportLogger}; + use crate::transport::client::TransportLogEvent; + + fn fields(pairs: &[(&str, &str)]) -> BTreeMap { + pairs + .iter() + .map(|(key, value)| ((*key).to_owned(), (*value).to_owned())) + .collect() + } + + #[test] + fn request_event_redacts_sensitive_headers_and_prints_body() { + let event = TransportLogEvent { + message: "http request", + fields: fields(&[("method", "POST"), ("url", "https://api.example.com/repos")]), + headers: Some(vec![ + ("authorization".to_owned(), "Bearer super-secret".to_owned()), + ("content-type".to_owned(), "application/json".to_owned()), + ]), + body: Some(br#"{"name":"foo"}"#.to_vec()), + }; + let rendered = StderrTransportLogger::new().format_event(&event); + assert!(rendered.contains("> POST https://api.example.com/repos")); + assert!(rendered.contains(&format!("> authorization: {REDACTED}"))); + assert!(!rendered.contains("super-secret")); + assert!(rendered.contains("> content-type: application/json")); + assert!(rendered.contains(r#"> {"name":"foo"}"#)); + } + + #[test] + fn response_event_with_size_only_reports_byte_count() { + let event = TransportLogEvent { + message: "http response", + fields: fields(&[ + ("status", "200"), + ("method", "GET"), + ("url", "https://api.example.com/blob"), + ("body_bytes", "2048"), + ]), + headers: Some(vec![("set-cookie".to_owned(), "session=abc123".to_owned())]), + body: None, + }; + let rendered = StderrTransportLogger::new().format_event(&event); + assert!(rendered.contains("< 200 GET https://api.example.com/blob")); + assert!(rendered.contains(&format!("< set-cookie: {REDACTED}"))); + assert!(!rendered.contains("abc123")); + assert!(rendered.contains("< [body: 2048 bytes not captured]")); + } + + #[test] + fn extra_redacted_headers_are_redacted_case_insensitively() { + let event = TransportLogEvent { + message: "http request", + fields: fields(&[("method", "GET"), ("url", "https://api.example.com/m")]), + headers: Some(vec![ + ("x-litellm-api-key".to_owned(), "sk-leak-me".to_owned()), + ("content-type".to_owned(), "application/json".to_owned()), + ]), + body: None, + }; + // Configured with mixed case to prove matching ignores case. + let logger = StderrTransportLogger::new().with_redacted_headers(["X-LiteLLM-API-Key"]); + let rendered = logger.format_event(&event); + assert!(rendered.contains(&format!("> x-litellm-api-key: {REDACTED}"))); + assert!(!rendered.contains("sk-leak-me")); + // Non-configured headers are untouched. + assert!(rendered.contains("> content-type: application/json")); + + // Without configuring it, the same header is shown verbatim. + let plain = StderrTransportLogger::new().format_event(&event); + assert!(plain.contains("> x-litellm-api-key: sk-leak-me")); + } + + #[test] + fn retry_event_renders_a_note_line() { + let event = TransportLogEvent { + message: "retrying request", + fields: fields(&[("attempt", "2"), ("backoff", "500ms")]), + headers: None, + body: None, + }; + assert_eq!( + StderrTransportLogger::new().format_event(&event), + "* retrying (attempt 2, backoff 500ms)\n" + ); + } +} diff --git a/src/transport/mod.rs b/src/transport/mod.rs index ec2215d..7b73d3b 100644 --- a/src/transport/mod.rs +++ b/src/transport/mod.rs @@ -14,13 +14,16 @@ use crate::DetailedError; /// HTTP client implementation. pub mod client; +mod debug_logger; /// Request auth injectors. pub mod injector; pub use client::{ HttpClient, HttpClientBuilder, NoopTransportLogger, TransportLogEvent, TransportLogger, - set_default_user_agent, + debug_log_reqwest_request, debug_log_reqwest_response, default_transport_logger, + set_default_transport_logger, set_default_user_agent, }; +pub use debug_logger::StderrTransportLogger; pub use injector::{ ApiKeyInjector, AuthInjector, BasicAuthInjector, BearerTokenInjector, ClientCredentialsInjector, CookieInjector, NoopInjector, ProviderBearerInjector, TokenFunc, diff --git a/tests/foundation.rs b/tests/foundation.rs index 15a0150..fc4f54b 100644 --- a/tests/foundation.rs +++ b/tests/foundation.rs @@ -5319,6 +5319,22 @@ async fn http_client_custom_logger_observes_request_response_and_retry_preserves assert_eq!(events[1].fields["status"], "429"); assert_eq!(events[2].fields["attempt"], "2"); assert_eq!(events[4].fields["status"], "200"); + // Response events now carry the buffered body bytes. + assert_eq!(events[1].body.as_deref(), Some(b"slow down".as_slice())); + assert_eq!( + events[4].body.as_deref(), + Some(br#"{"ok":true}"#.as_slice()) + ); + // The successful response captures its headers (content-type from the server). + assert!( + events[4] + .headers + .as_ref() + .expect("response event should capture headers") + .iter() + .any(|(name, value)| name.eq_ignore_ascii_case("content-type") + && value.contains("application/json")) + ); } #[tokio::test] @@ -5396,26 +5412,108 @@ async fn http_client_custom_logger_observes_raw_if_match_and_multipart_events_pr .await .expect("multipart without response should skip decode"); + // Raw, if-match, and multipart paths now emit unified `http request` / + // `http response` events, and the raw/download/post-raw paths log the + // response too (size only, never the body bytes). assert_eq!( logger.messages(), vec![ - "http request", - "http raw request", - "http raw request", - "http post raw request", - "http request", - "http response", - "http multipart request", + "http request", // OPTIONS /raw + "http response", // 200 /raw + "http request", // GET /download (429) + "http response", // 429 + "http request", // GET /download (200) + "http response", // 200 download (size only) + "http request", // POST /post-raw + "http response", // 200 post raw (size only) + "http request", // PUT /match + "http response", // 200 /match + "http request", // POST /upload (multipart) + "http response", // 200 /upload ] ); let events = logger.events(); assert_eq!(events[0].fields["method"], "OPTIONS"); assert!(events[0].fields["url"].ends_with("/raw")); - assert!(events[1].fields["url"].ends_with("/download")); - assert!(events[3].fields["url"].ends_with("/post-raw")); - assert_eq!(events[4].fields["method"], "PUT"); - assert_eq!(events[5].fields["status"], "200"); - assert!(events[6].fields["url"].ends_with("/upload")); + assert!(events[2].fields["url"].ends_with("/download")); + assert_eq!(events[3].fields["status"], "429"); + // Download response logs its size, not the body bytes. + assert_eq!(events[5].fields["body_bytes"], "download".len().to_string()); + assert!(events[5].body.is_none()); + assert!(events[6].fields["url"].ends_with("/post-raw")); + assert_eq!(events[8].fields["method"], "PUT"); + assert_eq!(events[9].fields["status"], "200"); + assert!(events[10].fields["url"].ends_with("/upload")); + // Request events carry captured headers (e.g. the user-agent). + assert!( + events[0] + .headers + .as_ref() + .expect("request event should capture headers") + .iter() + .any(|(name, _)| name.eq_ignore_ascii_case("user-agent")) + ); +} + +#[tokio::test] +async fn http_client_picks_up_process_global_default_logger() { + // The `--debug` feature works by publishing a process-global default logger + // that every HttpClient built afterward inherits without per-command wiring. + // This proves a client built WITHOUT `.logger(...)` records to that global. + struct ResetLogger; + impl Drop for ResetLogger { + fn drop(&mut self) { + transport::set_default_transport_logger(Arc::new(transport::NoopTransportLogger)); + } + } + let _reset = ResetLogger; + + let logger = Arc::new(RecordingTransportLogger::default()); + transport::set_default_transport_logger(logger.clone()); + + let server = TestServer::new(|request| { + assert!(request.contains("GET /global-logger-probe HTTP/1.1")); + http_response( + 200, + &[("Content-Type", "application/json")], + r#"{"ok":true}"#, + ) + }); + // Built with the default logger (no `.logger(...)`): it must inherit the + // process-global default installed above. + let client = HttpClient::new(server.base_url(), Arc::new(NoopInjector)); + let value: serde_json::Value = client + .get("/global-logger-probe") + .await + .expect("request should succeed"); + assert_eq!(value, json!({"ok": true})); + + // Filter by our unique path so concurrent tests sharing the global logger + // during this window cannot perturb the assertions. + let events = logger.events(); + let probe: Vec<_> = events + .iter() + .filter(|event| { + event + .fields + .get("url") + .is_some_and(|url| url.ends_with("/global-logger-probe")) + }) + .collect(); + assert!( + probe.iter().any(|event| event.message == "http request"), + "global logger should record the request" + ); + let response = probe + .iter() + .find(|event| event.message == "http response") + .expect("global logger should record the response"); + assert_eq!(response.fields["status"], "200"); + assert_eq!( + response.body.as_deref(), + Some(br#"{"ok":true}"#.as_slice()), + "response event should carry the buffered body" + ); } #[tokio::test] From 024d8ebb9c7994f0ae06907f1508e6e26df375b4 Mon Sep 17 00:00:00 2001 From: Jacob Page Date: Thu, 18 Jun 2026 12:58:56 -0700 Subject: [PATCH 02/10] fix: address Copilot review on --debug transport logging - set_default_transport_logger / default_transport_logger now recover a poisoned RwLock (PoisonError::into_inner) instead of silently no-oping, so a panic elsewhere can't leave a stale logger installed. - StderrTransportLogger renders status-only responses (from the reqwest-direct helper) as `< 204` without trailing spaces; added a regression test. - Replaced `drop(write_all(..))` with `.ok()` (plain `let _ =` would trip the crate's `let_underscore_drop` lint). - Serialized the process-global-logger integration test behind a new TRANSPORT_LOGGER_TEST_LOCK so its install/assert/reset window is isolated. - Fixed a missing space in docs/concepts.md. Co-Authored-By: Claude Opus 4.8 --- docs/concepts.md | 2 +- src/transport/client.rs | 19 +++++++++--------- src/transport/debug_logger.rs | 36 +++++++++++++++++++++++++++++------ tests/foundation.rs | 9 +++++++++ 4 files changed, 50 insertions(+), 16 deletions(-) diff --git a/docs/concepts.md b/docs/concepts.md index d4bbbc1..319fcb8 100644 --- a/docs/concepts.md +++ b/docs/concepts.md @@ -591,7 +591,7 @@ credentials, and no-op injectors. ### HTTP debug logging -The global `--debug` flag drives transport diagnostics through the `transport` component (`--debug`, `--debug transport`, or `--debug '*'`; `--debug '*,-transport'` keeps everything else but silences HTTP).`flags::debug_component_enabled` parses the comma-separated pattern. +The global `--debug` flag drives transport diagnostics through the `transport` component (`--debug`, `--debug transport`, or `--debug '*'`; `--debug '*,-transport'` keeps everything else but silences HTTP). `flags::debug_component_enabled` parses the comma-separated pattern. When `transport` is selected the engine publishes a process-wide `StderrTransportLogger` via `transport::set_default_transport_logger`. Every `HttpClient` built afterward inherits it as its default logger (mirroring `set_default_user_agent`), so command handlers get a curl-style request/response trace on stderr with **no per-command wiring**. A client that sets its own logger with `HttpClientBuilder::logger` still overrides the default. The logger is installed once, before the command handler runs, and shared by every client the handler builds, so all of a command's HTTP requests are logged. diff --git a/src/transport/client.rs b/src/transport/client.rs index 9e55512..f4c180a 100644 --- a/src/transport/client.rs +++ b/src/transport/client.rs @@ -87,9 +87,13 @@ fn default_transport_logger_lock() -> &'static RwLock> /// without any per-command wiring. A per-client logger still overrides it for /// that client. pub fn set_default_transport_logger(logger: Arc) { - if let Ok(mut current) = default_transport_logger_lock().write() { - *current = logger; - } + // Recover from a poisoned lock (a panic while a writer held it) instead of + // silently doing nothing, which would leave a stale logger installed and + // make `--debug transport` appear ineffective. + let mut current = default_transport_logger_lock() + .write() + .unwrap_or_else(std::sync::PoisonError::into_inner); + *current = logger; } /// Returns the process-wide default transport logger set via @@ -99,11 +103,8 @@ pub fn set_default_transport_logger(logger: Arc) { pub fn default_transport_logger() -> Arc { default_transport_logger_lock() .read() - .map_or_else(|_| no_op_logger(), |logger| logger.clone()) -} - -fn no_op_logger() -> Arc { - Arc::new(NoopTransportLogger) + .unwrap_or_else(std::sync::PoisonError::into_inner) + .clone() } /// Logs a `reqwest::Request` to the process-wide default transport logger. @@ -160,7 +161,7 @@ pub(crate) struct RestoreDefaultTransportLogger; #[cfg(test)] impl Drop for RestoreDefaultTransportLogger { fn drop(&mut self) { - set_default_transport_logger(no_op_logger()); + set_default_transport_logger(Arc::new(NoopTransportLogger)); } } diff --git a/src/transport/debug_logger.rs b/src/transport/debug_logger.rs index f8b5317..d75ba04 100644 --- a/src/transport/debug_logger.rs +++ b/src/transport/debug_logger.rs @@ -100,10 +100,16 @@ impl StderrTransportLogger { out } "http response" => { + // Method/url are absent on responses logged via the + // reqwest-direct helper, so omit them rather than rendering + // trailing spaces (`< 200 `). let status = field(event, "status").unwrap_or("?"); - let method = field(event, "method").unwrap_or(""); - let url = field(event, "url").unwrap_or(""); - let mut out = format!("< {status} {method} {url}\n"); + let suffix = match (field(event, "method"), field(event, "url")) { + (Some(method), Some(url)) => format!(" {method} {url}"), + (Some(value), None) | (None, Some(value)) => format!(" {value}"), + (None, None) => String::new(), + }; + let mut out = format!("< {status}{suffix}\n"); self.append_headers(&mut out, "<", event); append_body(&mut out, "<", event); out @@ -146,10 +152,11 @@ impl TransportLogger for StderrTransportLogger { } // Write directly to a locked stderr handle (not `eprintln!`) so the // whole event lands as one contiguous block under concurrency. - // Diagnostics are best-effort, so a failed write is dropped rather than - // allowed to break the command. + // Diagnostics are best-effort: ignore write failures rather than break + // the command. (`let _ =` would trip the crate's `let_underscore_drop` + // lint, so use `.ok()` to discard the result.) let mut stderr = std::io::stderr().lock(); - drop(stderr.write_all(rendered.as_bytes())); + stderr.write_all(rendered.as_bytes()).ok(); } } @@ -226,6 +233,23 @@ mod tests { assert!(rendered.contains("< [body: 2048 bytes not captured]")); } + #[test] + fn status_only_response_has_no_trailing_space() { + // The reqwest-direct helper logs responses with only a status (no + // method/url); the line must not render as `< 200 `. + let event = TransportLogEvent { + message: "http response", + fields: fields(&[("status", "204")]), + headers: Some(vec![("content-length".to_owned(), "0".to_owned())]), + body: None, + }; + let rendered = StderrTransportLogger::new().format_event(&event); + assert!( + rendered.starts_with("< 204\n"), + "status-only response should be `< 204` with no trailing space, got: {rendered:?}" + ); + } + #[test] fn extra_redacted_headers_are_redacted_case_insensitively() { let event = TransportLogEvent { diff --git a/tests/foundation.rs b/tests/foundation.rs index fc4f54b..087d849 100644 --- a/tests/foundation.rs +++ b/tests/foundation.rs @@ -150,6 +150,11 @@ impl RecordingTransportLogger { static USER_AGENT_TEST_LOCK: Mutex<()> = Mutex::const_new(()); +/// Serializes tests in this binary that mutate the process-wide default +/// transport logger, so an install/assert/reset window in one test cannot be +/// disturbed by another test resetting the global concurrently. +static TRANSPORT_LOGGER_TEST_LOCK: Mutex<()> = Mutex::const_new(()); + /// Restores the process-wide default User-Agent to the builtin on drop, so a /// panicking assertion in a test that publishes a config-derived UA cannot leak /// it into later tests. Hold alongside (declared after) the `USER_AGENT_TEST_LOCK` @@ -5460,6 +5465,10 @@ async fn http_client_picks_up_process_global_default_logger() { // The `--debug` feature works by publishing a process-global default logger // that every HttpClient built afterward inherits without per-command wiring. // This proves a client built WITHOUT `.logger(...)` records to that global. + // + // Hold the logger lock so the install/assert/reset window is isolated from + // any other test that mutates the same process-global. + let _logger_guard = TRANSPORT_LOGGER_TEST_LOCK.lock().await; struct ResetLogger; impl Drop for ResetLogger { fn drop(&mut self) { From e7f3dc59fe304cae604add26b681bdc6741567f7 Mon Sep 17 00:00:00 2001 From: Jacob Page Date: Thu, 18 Jun 2026 13:10:49 -0700 Subject: [PATCH 03/10] perf: keep transport non-debug path allocation-free; fix docs Address Copilot re-review: - Add `TransportLogger::enabled()` (default true; `NoopTransportLogger` returns false). `log_request`/`log_response` skip capture when disabled, and `read_and_log_response` no longer clones response headers on the non-debug path. - `read_and_log_response` now returns `bytes::Bytes` (a cheap clone of the buffer reqwest already owns) instead of `Vec`, so JSON decode parses without an extra full-body copy. Added `bytes` as a direct dependency. - `retryable_status_error` only clones headers when logging is enabled. - Soften the debug_logger module docs: redaction covers sensitive headers, but URLs and bodies are printed in full and may still contain secrets. Co-Authored-By: Claude Opus 4.8 --- Cargo.lock | 1 + Cargo.toml | 1 + src/transport/client.rs | 57 +++++++++++++++++++++++++++++++++-------- 3 files changed, 48 insertions(+), 11 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index e387f77..d3a5112 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -401,6 +401,7 @@ version = "0.3.1" dependencies = [ "async-trait", "base64", + "bytes", "chrono", "clap", "jmespath", diff --git a/Cargo.toml b/Cargo.toml index 2cf5b3a..e432c2f 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -19,6 +19,7 @@ path = "src/lib.rs" [dependencies] async-trait = "0.1.89" base64 = "0.22.1" +bytes = "1.11" keyring = { version = "3.6.1", optional = true, default-features = false } open = { version = "5.3.2", optional = true } rand = { version = "0.9", optional = true } diff --git a/src/transport/client.rs b/src/transport/client.rs index f4c180a..a9290c9 100644 --- a/src/transport/client.rs +++ b/src/transport/client.rs @@ -6,6 +6,7 @@ use std::{ time::Duration, }; +use bytes::Bytes; use reqwest::{Method, StatusCode, header}; use serde::{Serialize, de::DeserializeOwned}; use serde_json::Value; @@ -202,6 +203,16 @@ pub struct TransportLogEvent { pub trait TransportLogger: Send + Sync + std::fmt::Debug { /// Records one debug event. fn debug(&self, event: &TransportLogEvent); + + /// Whether this logger records anything. + /// + /// Defaults to `true`. The transport checks this before capturing request + /// and response headers/bodies, so a logger that returns `false` (such as + /// [`NoopTransportLogger`]) keeps the common non-debug path free of those + /// clones. + fn enabled(&self) -> bool { + true + } } /// Logger that intentionally drops transport events. @@ -210,6 +221,10 @@ pub struct NoopTransportLogger; impl TransportLogger for NoopTransportLogger { fn debug(&self, _event: &TransportLogEvent) {} + + fn enabled(&self) -> bool { + false + } } /// Authenticated HTTP client for CLI command implementations. @@ -454,7 +469,7 @@ impl HttpClient { parse_error_body(status, &String::from_utf8_lossy(&bytes), "GET", path).into(), ); } - Ok(bytes) + Ok(bytes.to_vec()) } /// Sends POST and streams the raw response body into a writer. @@ -1054,7 +1069,13 @@ impl HttpClient { /// Emits an `http request` event capturing the built request's headers and /// in-memory body. Streaming bodies (e.g. multipart) report no body. + /// + /// Skips capture entirely when the logger is disabled, so the non-debug path + /// does not clone headers or copy request bodies. fn log_request(&self, request: &reqwest::Request) { + if !self.logger.enabled() { + return; + } self.logger.debug(&TransportLogEvent { message: "http request", fields: BTreeMap::from([ @@ -1081,6 +1102,9 @@ impl HttpClient { body: Option<&[u8]>, body_bytes: Option, ) { + if !self.logger.enabled() { + return; + } let mut fields = BTreeMap::from([ ("status".to_owned(), status.as_u16().to_string()), ("method".to_owned(), method.to_owned()), @@ -1100,25 +1124,32 @@ impl HttpClient { /// Reads a response body once, emits the `http response` event, and returns /// the status and buffered bytes. `include_body` controls whether the body /// is attached to the log or only its size is reported. + /// + /// Returns the body as [`Bytes`] (a cheap clone of the buffer `reqwest` + /// already owns) so callers decode without an extra copy. When the logger is + /// disabled, response headers are not cloned and no event is built. async fn read_and_log_response( &self, response: reqwest::Response, method: &str, path: &str, include_body: bool, - ) -> Result<(StatusCode, Vec)> { + ) -> Result<(StatusCode, Bytes)> { let status = response.status(); - let headers = response.headers().clone(); + let logging = self.logger.enabled(); + let headers = logging.then(|| response.headers().clone()); let body = response .bytes() .await .map_err(|err| CliCoreError::message(format!("transport: decode response: {err}")))?; - if include_body { - self.log_response(method, path, status, &headers, Some(&body), None); - } else { - self.log_response(method, path, status, &headers, None, Some(body.len())); + if let Some(headers) = headers { + if include_body { + self.log_response(method, path, status, &headers, Some(&body), None); + } else { + self.log_response(method, path, status, &headers, None, Some(body.len())); + } } - Ok((status, body.to_vec())) + Ok((status, body)) } async fn inject_auth(&self, request: &mut reqwest::Request) -> Result<()> { @@ -1176,10 +1207,12 @@ impl HttpClient { path: &str, ) -> CliCoreError { let status = response.status(); - let headers = response.headers().clone(); + let headers = self.logger.enabled().then(|| response.headers().clone()); match response.bytes().await { Ok(body) => { - self.log_response(method, path, status, &headers, Some(&body), None); + if let Some(headers) = &headers { + self.log_response(method, path, status, headers, Some(&body), None); + } CliCoreError::message(format!( "transport: {method} {path}: status {}: {}", status.as_u16(), @@ -1187,7 +1220,9 @@ impl HttpClient { )) } Err(err) => { - self.log_response(method, path, status, &headers, None, None); + if let Some(headers) = &headers { + self.log_response(method, path, status, headers, None, None); + } CliCoreError::message(format!( "transport: {method} {path}: status {} (body read failed: {err})", status.as_u16() From 3e92301112472bb76395aebed25503633afd47f4 Mon Sep 17 00:00:00 2001 From: Jacob Page Date: Thu, 18 Jun 2026 13:11:23 -0700 Subject: [PATCH 04/10] docs: don't call debug output safe to share URLs and request/response bodies are printed in full and may contain secrets even with headers redacted; warn rather than calling the output ticket-safe. Co-Authored-By: Claude Opus 4.8 --- src/transport/debug_logger.rs | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/transport/debug_logger.rs b/src/transport/debug_logger.rs index d75ba04..bac5ce5 100644 --- a/src/transport/debug_logger.rs +++ b/src/transport/debug_logger.rs @@ -2,8 +2,9 @@ //! //! [`StderrTransportLogger`] renders [`TransportLogEvent`]s as a curl-style //! request/response trace on stderr. It is the logger the CLI installs when -//! `--debug` selects the `transport` component. Sensitive headers are redacted -//! so the output is safe to paste into a ticket. +//! `--debug` selects the `transport` component. Sensitive headers are redacted, +//! but URLs and request/response bodies are printed in full and may still +//! contain secrets — treat the output as sensitive before sharing it. use std::io::Write; From c3f23bff42bd189bae386b1c9671c8ad0141fa25 Mon Sep 17 00:00:00 2001 From: Jacob Page Date: Thu, 18 Jun 2026 13:15:57 -0700 Subject: [PATCH 05/10] perf: gate reqwest-direct debug helpers on logger.enabled() MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit debug_log_reqwest_request / debug_log_reqwest_response now fetch the default logger once and return early when it is disabled, so reqwest-direct call sites clone no headers and copy no body on the non-debug path — consistent with HttpClient::log_request/log_response. Co-Authored-By: Claude Opus 4.8 --- src/transport/client.rs | 21 +++++++++++++++------ 1 file changed, 15 insertions(+), 6 deletions(-) diff --git a/src/transport/client.rs b/src/transport/client.rs index a9290c9..119d376 100644 --- a/src/transport/client.rs +++ b/src/transport/client.rs @@ -114,10 +114,14 @@ pub fn default_transport_logger() -> Arc { /// or progenitor-generated clients that cannot use [`HttpClient`] — so a single /// `--debug`-controlled trace can still cover them. Captures the request method, /// URL, headers, and in-memory body. Pairs with [`debug_log_reqwest_response`]. -/// It is a no-op unless a logger has been installed via -/// [`set_default_transport_logger`]. +/// It is a no-op (no header clone or body copy) unless an enabled logger has +/// been installed via [`set_default_transport_logger`]. pub fn debug_log_reqwest_request(request: &reqwest::Request) { - default_transport_logger().debug(&TransportLogEvent { + let logger = default_transport_logger(); + if !logger.enabled() { + return; + } + logger.debug(&TransportLogEvent { message: "http request", fields: BTreeMap::from([ ("method".to_owned(), request.method().as_str().to_owned()), @@ -135,10 +139,15 @@ pub fn debug_log_reqwest_request(request: &reqwest::Request) { /// transport logger. /// /// Companion to [`debug_log_reqwest_request`] for `reqwest`-direct call sites. -/// The caller passes the already-read response body. It is a no-op unless a -/// logger has been installed via [`set_default_transport_logger`]. +/// The caller passes the already-read response body. It is a no-op (no header +/// clone or body copy) unless an enabled logger has been installed via +/// [`set_default_transport_logger`]. pub fn debug_log_reqwest_response(status: StatusCode, headers: &header::HeaderMap, body: &[u8]) { - default_transport_logger().debug(&TransportLogEvent { + let logger = default_transport_logger(); + if !logger.enabled() { + return; + } + logger.debug(&TransportLogEvent { message: "http response", fields: BTreeMap::from([("status".to_owned(), status.as_u16().to_string())]), headers: Some(header_pairs(headers)), From e429060d46b74fc6f7bad7df4ce59110b96c783d Mon Sep 17 00:00:00 2001 From: Jacob Page Date: Thu, 18 Jun 2026 13:22:50 -0700 Subject: [PATCH 06/10] perf: skip success-body read for *_without_response when not logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Address Copilot re-review: - ensure_success_response no longer buffers the body on a non-error status when logging is disabled, restoring the pre-logging behavior where *_without_response calls never read success bodies. The body is read only when it's needed — to build an error message or to feed an enabled logger. - read_and_log_response's body-read failure now reports "read response body" instead of "decode response", which was misleading on raw/byte-download paths (get_raw/get_bytes/post_raw). JSON parse errors still say "decode". Co-Authored-By: Claude Opus 4.8 --- src/transport/client.rs | 15 +++++++++++---- 1 file changed, 11 insertions(+), 4 deletions(-) diff --git a/src/transport/client.rs b/src/transport/client.rs index 119d376..4cf95c7 100644 --- a/src/transport/client.rs +++ b/src/transport/client.rs @@ -1147,10 +1147,9 @@ impl HttpClient { let status = response.status(); let logging = self.logger.enabled(); let headers = logging.then(|| response.headers().clone()); - let body = response - .bytes() - .await - .map_err(|err| CliCoreError::message(format!("transport: decode response: {err}")))?; + let body = response.bytes().await.map_err(|err| { + CliCoreError::message(format!("transport: read response body: {err}")) + })?; if let Some(headers) = headers { if include_body { self.log_response(method, path, status, &headers, Some(&body), None); @@ -1198,6 +1197,14 @@ impl HttpClient { method: &str, path: &str, ) -> Result<()> { + // A `*_without_response` call discards the body, so the body is only + // needed to build an error message or to feed the logger. When neither + // applies (non-error status, logging disabled), skip buffering it — + // matching the pre-logging behavior of not reading success bodies. + let is_error = response.status().is_client_error() || response.status().is_server_error(); + if !is_error && !self.logger.enabled() { + return Ok(()); + } let (status, body) = self .read_and_log_response(response, method, path, true) .await?; From fa3c7f009afbe04488bbc370714cbd906fc14ed0 Mon Sep 17 00:00:00 2001 From: Jacob Page Date: Thu, 18 Jun 2026 13:28:30 -0700 Subject: [PATCH 07/10] fix: trim and drop empty redacted header names Redaction is a safety feature, so a config value with stray whitespace (or an empty entry) must not silently fail to match and leak the header. Both StderrTransportLogger::with_redacted_headers and CliConfig::with_redacted_debug_headers now trim names and drop empties. Co-Authored-By: Claude Opus 4.8 --- src/cli.rs | 8 ++++++-- src/transport/debug_logger.rs | 23 +++++++++++++++-------- 2 files changed, 21 insertions(+), 10 deletions(-) diff --git a/src/cli.rs b/src/cli.rs index a3bb55e..5bf0dd9 100644 --- a/src/cli.rs +++ b/src/cli.rs @@ -364,14 +364,18 @@ impl CliConfig { /// auth headers — for example a custom API-key header that an /// [`AuthInjector`](crate::transport::AuthInjector) sets. Matching is /// case-insensitive and additive: the built-in set is always redacted. - /// Calls accumulate. + /// Calls accumulate. Names are trimmed and empty entries are dropped, so a + /// mistyped value with stray whitespace cannot silently disable redaction. #[must_use] pub fn with_redacted_debug_headers( mut self, names: impl IntoIterator>, ) -> Self { self.redacted_debug_headers - .extend(names.into_iter().map(Into::into)); + .extend(names.into_iter().filter_map(|name| { + let name = name.into().trim().to_owned(); + (!name.is_empty()).then_some(name) + })); self } diff --git a/src/transport/debug_logger.rs b/src/transport/debug_logger.rs index bac5ce5..aa53644 100644 --- a/src/transport/debug_logger.rs +++ b/src/transport/debug_logger.rs @@ -62,17 +62,19 @@ impl StderrTransportLogger { /// auth headers — for example a custom API-key header an auth injector sets. /// Names are matched case-insensitively. Additive only: the built-in set /// (`authorization`, `proxy-authorization`, `cookie`, `set-cookie`, - /// `x-api-key`) is always redacted. + /// `x-api-key`) is always redacted. Names are trimmed and empty entries are + /// dropped, so a stray-whitespace config value cannot silently fail to + /// match (which would leak the header). #[must_use] pub fn with_redacted_headers( mut self, names: impl IntoIterator>, ) -> Self { - self.extra_redacted.extend( - names - .into_iter() - .map(|name| name.into().to_ascii_lowercase()), - ); + self.extra_redacted + .extend(names.into_iter().filter_map(|name| { + let name = name.into().trim().to_ascii_lowercase(); + (!name.is_empty()).then_some(name) + })); self } @@ -262,8 +264,13 @@ mod tests { ]), body: None, }; - // Configured with mixed case to prove matching ignores case. - let logger = StderrTransportLogger::new().with_redacted_headers(["X-LiteLLM-API-Key"]); + // Mixed case + stray whitespace + an empty entry, to prove names are + // trimmed (so they still match) and empties are dropped. + let logger = StderrTransportLogger::new().with_redacted_headers([ + " X-LiteLLM-API-Key ", + " ", + "", + ]); let rendered = logger.format_event(&event); assert!(rendered.contains(&format!("> x-litellm-api-key: {REDACTED}"))); assert!(!rendered.contains("sk-leak-me")); From e29513a80c09ed43328f8a28df90d9299f22814d Mon Sep 17 00:00:00 2001 From: Jacob Page Date: Thu, 18 Jun 2026 13:33:58 -0700 Subject: [PATCH 08/10] fix: debug_component_enabled fails closed on empty component An empty/whitespace component name is now never enabled, even by `*`, so the public helper can't return true for an invalid component query. Co-Authored-By: Claude Opus 4.8 --- src/flags.rs | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/src/flags.rs b/src/flags.rs index ff033b4..c0f6d2f 100644 --- a/src/flags.rs +++ b/src/flags.rs @@ -508,6 +508,10 @@ fn collect_flag_names(command: &Command, visit: &mut impl FnMut(&Arg, String)) { #[must_use] pub fn debug_component_enabled(pattern: &str, component: &str) -> bool { let component = component.trim().to_ascii_lowercase(); + // Fail closed: an empty component name is never enabled, not even by `*`. + if component.is_empty() { + return false; + } let mut enabled = false; for raw in pattern.split(',') { let token = raw.trim(); @@ -565,6 +569,9 @@ mod tests { assert!(debug_component_enabled("-*,transport", "transport")); // Whitespace and case are ignored. assert!(debug_component_enabled(" Transport , -auth ", "transport")); + // An empty component fails closed, even against a wildcard. + assert!(!debug_component_enabled("*", "")); + assert!(!debug_component_enabled("*", " ")); } #[test] From 3676096b22e9cf173bd5091a646dc2bc99f63b01 Mon Sep 17 00:00:00 2001 From: Jacob Page Date: Thu, 18 Jun 2026 13:39:15 -0700 Subject: [PATCH 09/10] perf: gate log_debug (retry events) on logger.enabled() The last remaining capture site: log_debug built the fields map even when the logger was disabled. Now every transport logging entry point skips allocation on the non-debug path. Co-Authored-By: Claude Opus 4.8 --- src/transport/client.rs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/transport/client.rs b/src/transport/client.rs index 4cf95c7..3ded416 100644 --- a/src/transport/client.rs +++ b/src/transport/client.rs @@ -1065,6 +1065,9 @@ impl HttpClient { message: &'static str, fields: impl IntoIterator, ) { + if !self.logger.enabled() { + return; + } self.logger.debug(&TransportLogEvent { message, fields: fields From f6aa72b3dd868067dd62b3a7ba831b6c1aa42ad1 Mon Sep 17 00:00:00 2001 From: Jacob Page Date: Thu, 18 Jun 2026 13:59:39 -0700 Subject: [PATCH 10/10] docs: document working --debug forms; harden logger test MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Copilot re-review: - The `--debug transport` space form does not work before the subcommand: `normalize_optional_global_flags_before_command` treats `--debug` as an optional-value flag at the root and rewrites it to `--debug=*`, leaving the next token positional (so `--debug transport ` fails). Verified at runtime. Docs now use the forms that work at root — bare `--debug` (all), `--debug=transport`, `--debug='*,-transport'` — and note the space form only attaches a value after the leaf command. - install_debug_transport_logger test now asserts on `TransportLogger::enabled()` instead of the logger's `Debug` string, which is brittle to formatting/field changes. Co-Authored-By: Claude Opus 4.8 --- docs/concepts.md | 4 ++-- src/cli.rs | 21 ++++++--------------- 2 files changed, 8 insertions(+), 17 deletions(-) diff --git a/docs/concepts.md b/docs/concepts.md index 319fcb8..bdcfe5b 100644 --- a/docs/concepts.md +++ b/docs/concepts.md @@ -270,7 +270,7 @@ populate middleware: | `--schema` | `schema` | `false` | Renders command schema instead of running business logic. | | `--reason` | `reason` | empty | Reason passed to authorization. | | `--timeout` | `timeout` | `0s` | Command deadline (e.g. `60s`, `5m`); default `0s` = no timeout. | -| `--debug` | `debug` | empty | Enables debug components (comma-separated patterns: `*`, `transport`, `*,-auth`). `transport` dumps HTTP requests/responses to stderr. See [HTTP debug logging](#http-debug-logging). | +| `--debug` | `debug` | empty | Enables debug components (comma-separated patterns). Bare `--debug` enables all; a specific value uses the `=` form: `--debug=transport`, `--debug='*,-auth'`. `transport` dumps HTTP requests/responses to stderr. See [HTTP debug logging](#http-debug-logging). | | `--search` | `search` | empty | Searches command and guide documentation before command execution. | Applications can add additional global flags through `CliConfig::register_flags` and copy parsed @@ -591,7 +591,7 @@ credentials, and no-op injectors. ### HTTP debug logging -The global `--debug` flag drives transport diagnostics through the `transport` component (`--debug`, `--debug transport`, or `--debug '*'`; `--debug '*,-transport'` keeps everything else but silences HTTP). `flags::debug_component_enabled` parses the comma-separated pattern. +The global `--debug` flag drives transport diagnostics through the `transport` component. Bare `--debug` enables every component; to select one, use the `=` form so the value is not mistaken for the command: `--debug=transport`, or `--debug='*,-transport'` to keep everything else but silence HTTP. (As an optional-value global flag, `--debug` only attaches a space-separated value when it appears after the leaf command; before the command, write `--debug=transport`.) `flags::debug_component_enabled` parses the comma-separated pattern. When `transport` is selected the engine publishes a process-wide `StderrTransportLogger` via `transport::set_default_transport_logger`. Every `HttpClient` built afterward inherits it as its default logger (mirroring `set_default_user_agent`), so command handlers get a curl-style request/response trace on stderr with **no per-command wiring**. A client that sets its own logger with `HttpClientBuilder::logger` still overrides the default. The logger is installed once, before the command handler runs, and shared by every client the handler builds, so all of a command's HTTP requests are logged. diff --git a/src/cli.rs b/src/cli.rs index 5bf0dd9..81e38eb 100644 --- a/src/cli.rs +++ b/src/cli.rs @@ -3063,27 +3063,18 @@ mod user_agent_tests { .unwrap_or_else(std::sync::PoisonError::into_inner); let _restore = crate::transport::client::RestoreDefaultTransportLogger; - // `transport` selected -> a real stderr logger is published. + // `transport` selected -> an active (enabled) logger is published. install_debug_transport_logger("transport", &[]); - assert!( - format!("{:?}", crate::transport::default_transport_logger()) - .starts_with("StderrTransportLogger") - ); + assert!(crate::transport::default_transport_logger().enabled()); - // Wildcard with transport excluded -> back to the noop. + // Wildcard with transport excluded -> back to a disabled (noop) logger. install_debug_transport_logger("*,-transport", &[]); - assert_eq!( - format!("{:?}", crate::transport::default_transport_logger()), - "NoopTransportLogger" - ); + assert!(!crate::transport::default_transport_logger().enabled()); - // Empty pattern -> noop. + // Empty pattern -> disabled (noop). install_debug_transport_logger("transport", &[]); install_debug_transport_logger("", &[]); - assert_eq!( - format!("{:?}", crate::transport::default_transport_logger()), - "NoopTransportLogger" - ); + assert!(!crate::transport::default_transport_logger().enabled()); } }