Add debug logging for all Oxide API requests

Cargo.toml

@@ -23,15 +23,13 @@ crossterm = { version = "0.27.0", features = [ "event-stream" ] }
 dialoguer = "0.10.4"
 dirs = "4.0.0"
 dropshot = "0.13.0"
-env_logger = "0.10.2"
 expectorate = { version = "1.1.0", features = ["predicates"] }
 flume = "0.11.1"
 futures = "0.3.31"
 httpmock = "0.7.0"
 humantime = "2"
 indicatif = "0.17"
 libc = "0.2.170"
-log = "0.4.26"
 md5 = "0.7.0"
 newline-converter = "0.3.0"
 oauth2 = "5.0.0"
@@ -43,6 +41,7 @@ predicates = "3.1.3"
 pretty_assertions = "1.4.1"
 progenitor = { git = "https://github.com/oxidecomputer/progenitor", default-features = false }
 progenitor-client = "0.9.1"
+quote = "1.0.40"
 rand = "0.8.5"
 ratatui = "0.26.3"
 rcgen = "0.10.0"
@@ -62,6 +61,8 @@ thouart = { git = "https://github.com/oxidecomputer/thouart" }
 tokio = { version = "1.44.0", features = ["full"] }
 toml = "0.8.20"
 toml_edit = "0.22.24"
+tracing = "0.1.41"
+tracing-subscriber = { version = "0.3.19", features = ["env-filter","json"] }
 url = "2.5.4"
 uuid = { version = "1.15.1", features = ["serde", "v4"] }
 

cli/Cargo.toml

@@ -28,11 +28,9 @@ colored = { workspace = true }
 crossterm = { workspace = true }
 dialoguer = { workspace = true }
 dirs = { workspace = true }
-env_logger = { workspace = true }
 futures = { workspace = true }
 humantime = { workspace = true }
 indicatif = { workspace = true }
-log = { workspace = true }
 md5 = { workspace = true }
 oauth2 = { workspace = true }
 open = { workspace = true }
@@ -49,6 +47,8 @@ thouart = { workspace = true }
 toml = { workspace = true }
 toml_edit = { workspace = true }
 tokio = { workspace = true }
+tracing = { workspace = true }
+tracing-subscriber = { workspace = true }
 url = { workspace = true }
 uuid = { workspace = true }
 

cli/src/cli_builder.rs

@@ -2,14 +2,14 @@
 // License, v. 2.0. If a copy of the MPL was not distributed with this
 // file, You can obtain one at https://mozilla.org/MPL/2.0/.
 
-// Copyright 2024 Oxide Computer Company
+// Copyright 2025 Oxide Computer Company
 
 use std::{any::TypeId, collections::BTreeMap, marker::PhantomData, net::IpAddr, path::PathBuf};
 
 use anyhow::{bail, Result};
 use async_trait::async_trait;
 use clap::{Arg, ArgMatches, Command, CommandFactory, FromArgMatches};
-use log::LevelFilter;
+use tracing_subscriber::EnvFilter;
 
 use crate::{
     context::Context,
@@ -229,11 +229,20 @@ impl<'a> NewCli<'a> {
             timeout,
         } = OxideCli::from_arg_matches(&matches).expect("failed to parse OxideCli from args");
 
-        let mut log_builder = env_logger::builder();
-        if debug {
-            log_builder.filter_level(LevelFilter::Debug);
-        }
-        log_builder.init();
+        let env_filter = if debug {
+            EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"))
+        } else {
+            EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"))
+        };
+
+        tracing_subscriber::fmt()
+            .with_env_filter(env_filter)
+            .with_writer(std::io::stderr)
+            .json()
+            .flatten_event(true)
+            .with_current_span(false)
+            .with_span_list(false)
+            .init();
 
         let mut client_config = ClientConfig::default();
 

cli/src/cmd_auth.rs

@@ -2,7 +2,7 @@
 // License, v. 2.0. If a copy of the MPL was not distributed with this
 // file, You can obtain one at https://mozilla.org/MPL/2.0/.
 
-// Copyright 2024 Oxide Computer Company
+// Copyright 2025 Oxide Computer Company
 
 use std::error::Error;
 use std::fs::{File, OpenOptions};
@@ -465,11 +465,11 @@ impl CmdAuthStatus {
 
             match result {
                 Ok(user) => {
-                    log::debug!("success response for {} (env): {:?}", host_env, user);
+                    tracing::debug!("success response for {} (env): {:?}", host_env, user);
                     println_nopipe!("Logged in to {} as {}", host_env, user.id)
                 }
                 Err(e) => {
-                    log::debug!("error response for {} (env): {:#}", host_env, e);
+                    tracing::debug!("error response for {} (env): {:#}", host_env, e);
                     println_nopipe!("{}: {}", host_env, Self::error_msg(&e))
                 }
             };
@@ -490,11 +490,11 @@ impl CmdAuthStatus {
 
                 let status = match result {
                     Ok(v) => {
-                        log::debug!("success response for {}: {:?}", profile_info.host, v);
+                        tracing::debug!("success response for {}: {:?}", profile_info.host, v);
                         "Authenticated".to_string()
                     }
                     Err(e) => {
-                        log::debug!("error response for {}: {:#}", profile_info.host, e);
+                        tracing::debug!("error response for {}: {:#}", profile_info.host, e);
                         Self::error_msg(&e)
                     }
                 };

cli/src/cmd_version.rs

@@ -2,12 +2,12 @@
 // License, v. 2.0. If a copy of the MPL was not distributed with this
 // file, You can obtain one at https://mozilla.org/MPL/2.0/.
 
-// Copyright 2024 Oxide Computer Company
+// Copyright 2025 Oxide Computer Company
 
 use anyhow::Result;
 use async_trait::async_trait;
 use clap::Parser;
-use oxide::Client;
+use oxide::{Client, LogCtx};
 
 use crate::println_nopipe;
 use crate::{context::Context, RunnableCmd};
@@ -26,7 +26,7 @@ pub struct CmdVersion;
 impl RunnableCmd for CmdVersion {
     async fn run(&self, _ctx: &Context) -> Result<()> {
         let cli_version = built_info::PKG_VERSION;
-        let api_version = Client::new("").api_version();
+        let api_version = Client::new("", LogCtx::new()).api_version();
 
         println_nopipe!("Oxide CLI {}", cli_version);
 
@@ -52,7 +52,7 @@ fn version_success() {
 
     let mut cmd = Command::cargo_bin("oxide").unwrap();
     let cli_version = built_info::PKG_VERSION;
-    let api_version = Client::new("").api_version();
+    let api_version = Client::new("", oxide::LogCtx::new()).api_version();
 
     cmd.arg("version");
     cmd.assert().success().stdout(format!(

cli/src/main.rs

@@ -100,16 +100,21 @@ pub fn make_cli() -> NewCli<'static> {
 async fn main() {
     let new_cli = make_cli();
 
-    if let Err(e) = new_cli.run().await {
-        if let Some(io_err) = e.downcast_ref::<io::Error>() {
-            if io_err.kind() == io::ErrorKind::BrokenPipe {
-                return;
-            }
+    // Spawn a task to ensure we have a task ID, which is needed capture complete debug logs.
+    let e = match tokio::spawn(async move { new_cli.run().await }).await {
+        Err(e) => e.into(),
+        Ok(Err(e)) => e,
+        Ok(Ok(())) => return,
+    };
+
+    if let Some(io_err) = e.downcast_ref::<io::Error>() {
+        if io_err.kind() == io::ErrorKind::BrokenPipe {
+            return;
         }
-
-        eprintln_nopipe!("{e:#}");
-        std::process::exit(1)
     }
+
+    eprintln_nopipe!("{e:#}");
+    std::process::exit(1)
 }
 
 #[derive(Default)]

cli/tests/test_auth.rs

@@ -2,7 +2,7 @@
 // License, v. 2.0. If a copy of the MPL was not distributed with this
 // file, You can obtain one at https://mozilla.org/MPL/2.0/.
 
-// Copyright 2024 Oxide Computer Company
+// Copyright 2025 Oxide Computer Company
 
 use std::{
     fs::{read_to_string, write, File},
@@ -14,6 +14,7 @@ use expectorate::assert_contents;
 use httpmock::{Method::POST, Mock, MockServer};
 use oxide::types::CurrentUser;
 use oxide_httpmock::MockServerExt;
+use predicates::prelude::*;
 use predicates::str;
 use serde_json::json;
 
@@ -572,17 +573,58 @@ fn test_cmd_auth_status_env() {
 
 #[test]
 fn test_cmd_auth_debug_logging() {
-    let bad_url = "sys.oxide.invalid";
+    let server = MockServer::start();
 
-    // Validate debug logs are printed
-    Command::cargo_bin("oxide")
+    let oxide_mock = server.current_user_view(|when, then| {
+        when.into_inner()
+            .header("authorization", "Bearer oxide-token-good");
+
+        then.ok(&oxide::types::CurrentUser {
+            display_name: "privileged".to_string(),
+            id: "001de000-05e4-4000-8000-000000004007".parse().unwrap(),
+            silo_id: "d1bb398f-872c-438c-a4c6-2211e2042526".parse().unwrap(),
+            silo_name: "funky-town".parse().unwrap(),
+        });
+    });
+
+    let cmd = Command::cargo_bin("oxide")
         .unwrap()
-        .arg("--debug")
         .arg("auth")
-        .arg("login")
-        .arg("--host")
-        .arg(bad_url)
+        .arg("status")
+        .env("RUST_LOG", "oxide=debug")
+        .env("OXIDE_HOST", server.url(""))
+        .env("OXIDE_TOKEN", "oxide-token-good")
         .assert()
-        .failure()
-        .stderr(str::contains("DEBUG"));
+        .success();
+
+    let stderr_str = std::str::from_utf8(&cmd.get_output().stderr).unwrap();
+    assert!(str::is_match(r#""level":"DEBUG""#)
+        .unwrap()
+        .eval(stderr_str));
+    assert!(str::is_match(r#""message":"request succeeded""#)
+        .unwrap()
+        .eval(stderr_str));
+    assert!(str::is_match(r#""url":"http://127.0.0.1:\d+/v1/me""#)
+        .unwrap()
+        .eval(stderr_str));
+    assert!(str::is_match(r#""path":"/v1/me""#)
+        .unwrap()
+        .eval(stderr_str));
+    assert!(str::is_match(r#""remote_addr":"127.0.0.1:\d+""#)
+        .unwrap()
+        .eval(stderr_str));
+    assert!(str::is_match(r#""http.request.method":"GET""#)
+        .unwrap()
+        .eval(stderr_str));
+    assert!(str::is_match(r#""http.response.content_length":\d+"#)
+        .unwrap()
+        .eval(stderr_str));
+    assert!(str::is_match(r#""http.response.status_code":200"#)
+        .unwrap()
+        .eval(stderr_str));
+    assert!(str::is_match(r#""duration_ms":\d+"#)
+        .unwrap()
+        .eval(stderr_str));
+
+    oxide_mock.assert();
 }

cli/tests/test_net.rs

@@ -2,7 +2,7 @@
 // License, v. 2.0. If a copy of the MPL was not distributed with this
 // file, You can obtain one at https://mozilla.org/MPL/2.0/.
 
-// Copyright 2024 Oxide Computer Company
+// Copyright 2025 Oxide Computer Company
 
 use assert_cmd::Command;
 use chrono::prelude::*;
@@ -295,7 +295,7 @@ fn test_port_config() {
             then.ok(&switch1_qsfp0_view);
         });
 
-    env_logger::init();
+    tracing_subscriber::fmt().init();
 
     Command::cargo_bin("oxide")
         .unwrap()

sdk/Cargo.toml

@@ -25,6 +25,7 @@ thiserror =  { workspace = true }
 tokio = { workspace = true }
 toml = { workspace = true }
 toml_edit = { workspace = true }
+tracing = { workspace = true }
 uuid = { workspace = true }
 
 [dev-dependencies]

sdk/src/auth.rs

@@ -2,15 +2,15 @@
 // License, v. 2.0. If a copy of the MPL was not distributed with this
 // file, You can obtain one at https://mozilla.org/MPL/2.0/.
 
-// Copyright 2024 Oxide Computer Company
+// Copyright 2025 Oxide Computer Company
 
 use std::{
     collections::BTreeMap,
     net::{IpAddr, SocketAddr},
     path::{Path, PathBuf},
 };
 
-use crate::{Client, OxideAuthError};
+use crate::{Client, LogCtx, OxideAuthError};
 use reqwest::ClientBuilder;
 use serde::Deserialize;
 
@@ -178,6 +178,7 @@ impl Client {
             client_builder
                 .build()
                 .expect("failure to construct underlying client object"),
+            LogCtx::new(),
         ))
     }
 }

sdk/src/lib.rs

@@ -2,7 +2,7 @@
 // License, v. 2.0. If a copy of the MPL was not distributed with this
 // file, You can obtain one at https://mozilla.org/MPL/2.0/.
 
-// Copyright 2024 Oxide Computer Company
+// Copyright 2025 Oxide Computer Company
 
 #![forbid(unsafe_code)]
 #![doc = include_str!("../README.md")]
@@ -16,9 +16,11 @@ mod auth;
 mod clap_feature;
 pub mod extras;
 mod generated_sdk;
+pub mod tracing;
 
 pub use auth::*;
 pub use generated_sdk::*;
+pub use tracing::LogCtx;
 
 /// Errors for interfaces related to authentication
 #[derive(Error, Debug)]

sdk/src/tracing.rs

@@ -0,0 +1,200 @@
+// This Source Code Form is subject to the terms of the Mozilla Public
+// License, v. 2.0. If a copy of the MPL was not distributed with this
+// file, You can obtain one at https://mozilla.org/MPL/2.0/.
+
+// Copyright 2025 Oxide Computer Company
+
+use chrono::{DateTime, Utc};
+use reqwest::{Method, Request, Response, Url};
+use tokio::task::Id;
+use tracing::{Level, Span};
+
+use std::collections::HashMap;
+use std::error::Error;
+use std::sync::{Arc, Mutex};
+use std::time::{Duration, SystemTime};
+
+#[derive(Clone, Debug)]
+struct StartDetails {
+    url: Url,
+    method: Method,
+    start_time: SystemTime,
+    body: Option<String>,
+    span: Span,
+}
+
+/// Store Oxide API request metadata during execution so a unified log entry can
+/// be generated.
+#[derive(Clone, Debug)]
+pub struct LogCtx(Arc<Mutex<HashMap<Id, StartDetails>>>);
+
+impl LogCtx {
+    pub fn new() -> Self {
+        Self(Arc::new(Mutex::new(HashMap::new())))
+    }
+}
+
+impl Default for LogCtx {
+    fn default() -> Self {
+        Self::new()
+    }
+}
+
+pub fn on_request_start(ctx: &LogCtx, request: &Request) {
+    let url = request.url();
+    let span = tracing::debug_span!("oxide", request = format!("{} {}", request.method(), url));
+
+    let mut details = StartDetails {
+        url: url.clone(),
+        method: request.method().clone(),
+        body: None,
+        start_time: SystemTime::now(),
+        span,
+    };
+
+    // Log up to the first KiB of the request body. Avoid performing this relatively
+    // expensive operation unless the log level is DEBUG or above.
+    if tracing::enabled!(target: "oxide", Level::DEBUG) {
+        let body_bytes = request.body().and_then(|b| b.as_bytes());
+        let body = body_bytes.map(|b| {
+            let len = b.len().min(1024);
+            let mut out = String::from_utf8_lossy(&b[..len]).into_owned();
+            if b.len() > 1024 {
+                out.push_str("...");
+            }
+            out
+        });
+
+        if let Some(b) = body {
+            details.body = Some(b);
+        }
+    }
+
+    // Try to store the request details for retrieval when the requests finishes.
+    // If we're not in a tokio Task this is not possible, instead log separate
+    // events for start and finish.
+    let Some(task_id) = tokio::task::try_id() else {
+        tracing::debug!(
+            url = %url,
+            path = url.path(),
+            http.request.method = %request.method(),
+            http.request.body = details.body,
+        );
+        return;
+    };
+
+    let Ok(mut ctx_map) = ctx.0.lock() else {
+        tracing::warn!(task_id = ?task_id, "failed to take LogCtx lock");
+        return;
+    };
+
+    ctx_map.insert(task_id, details);
+}
+
+pub fn on_request_end(ctx: &LogCtx, outcome: &Result<Response, reqwest::Error>) {
+    let Some(task_id) = tokio::task::try_id() else {
+        log_uncorrelated_response(outcome);
+        return;
+    };
+
+    let Ok(mut ctx_map) = ctx.0.lock() else {
+        tracing::warn!(task_id = ?task_id, "failed to take LogCtx lock");
+        return;
+    };
+
+    let Some(details) = ctx_map.remove(&task_id) else {
+        tracing::warn!(task_id = ?task_id, response = ?outcome, "no LogCtx entry found for task");
+        log_uncorrelated_response(outcome);
+        return;
+    };
+
+    // Don't hold the lock any longer than necessary.
+    drop(ctx_map);
+
+    // Convert to a u64 so this can be logged as a JSON number.
+    let duration_ms: u64 = SystemTime::now()
+        .duration_since(details.start_time)
+        .unwrap_or_else(|_| Duration::from_secs(0))
+        .as_millis()
+        .try_into()
+        .unwrap_or(u64::MAX);
+
+    let _enter = details.span.enter();
+    match outcome {
+        Ok(resp) => {
+            tracing::debug!(
+                url = %details.url,
+                path = details.url.path(),
+                remote_addr = resp.remote_addr().map(|a| a.to_string()),
+                http.request.method = %details.method,
+                http.request.body = details.body,
+                http.response.content_length = resp.content_length(),
+                http.response.status_code = resp.status().as_u16(),
+                start_time = format_time(details.start_time),
+                duration_ms,
+                oxide.request_id = get_request_id(resp),
+                "request succeeded",
+            );
+        }
+        Err(e) => {
+            tracing::debug!(
+                url = %details.url,
+                path = details.url.path(),
+                http.request.method = %details.method,
+                http.request.body = details.body,
+                http.response.status_code = ?e.status(),
+                start_time = format_time(details.start_time),
+                duration_ms,
+                error.message = e.to_string(),
+                error.cause = ?e.source(),
+                "request failed",
+            );
+        }
+    }
+}
+
+fn log_uncorrelated_response(outcome: &Result<Response, reqwest::Error>) {
+    match outcome {
+        Ok(resp) => {
+            let url = resp.url();
+            tracing::debug!(
+                url = %url,
+                path = url.path(),
+                remote_addr = resp.remote_addr().map(|a| a.to_string()),
+                http.response.content_length = resp.content_length(),
+                http.response.status_code = resp.status().as_u16(),
+                oxide.request_id = get_request_id(resp),
+                "request succeeded",
+            );
+        }
+        Err(e) => {
+            tracing::debug!(
+                url = ?e.url(),
+                path = ?e.url().map(|u| u.path()),
+                http.response.status_code = ?e.status().map(|s| s.as_u16()),
+                error.message = e.to_string(),
+                error.cause = ?e.source(),
+                "request failed",
+            );
+        }
+    }
+}
+
+fn get_request_id(response: &Response) -> Option<&str> {
+    response
+        .headers()
+        .get("x-request-id")
+        .and_then(|id| id.to_str().ok())
+        .map(|id| id.trim_matches('"'))
+}
+
+fn format_time(time: SystemTime) -> String {
+    let datetime = time
+        .duration_since(SystemTime::UNIX_EPOCH)
+        .map(|d| DateTime::from_timestamp(d.as_secs() as i64, d.subsec_nanos()))
+        .ok()
+        .flatten()
+        .unwrap_or_else(Utc::now);
+
+    datetime.format("%Y-%m-%dT%H:%M:%S.%6fZ").to_string()
+}

xtask/Cargo.toml

@@ -8,6 +8,7 @@ publish = false
 clap = { workspace = true }
 newline-converter = { workspace = true }
 progenitor = { workspace = true, default-features = false }
+quote = { workspace = true }
 regex = { workspace = true }
 rustfmt-wrapper = { workspace = true }
 serde_json = { workspace = true }

xtask/src/main.rs

@@ -2,7 +2,7 @@
 // License, v. 2.0. If a copy of the MPL was not distributed with this
 // file, You can obtain one at https://mozilla.org/MPL/2.0/.
 
-// Copyright 2023 Oxide Computer Company
+// Copyright 2025 Oxide Computer Company
 
 #![forbid(unsafe_code)]
 
@@ -11,6 +11,7 @@ use std::{fs::File, io::Write, path::PathBuf, time::Instant};
 use clap::Parser;
 use newline_converter::dos2unix;
 use progenitor::{GenerationSettings, Generator, TagStyle};
+use quote::quote;
 use similar::{Algorithm, ChangeTag, TextDiff};
 
 #[derive(Parser)]
@@ -72,7 +73,14 @@ fn generate(
         GenerationSettings::default()
             .with_interface(progenitor::InterfaceStyle::Builder)
             .with_tag(TagStyle::Separate)
-            .with_derive("schemars::JsonSchema"),
+            .with_derive("schemars::JsonSchema")
+            .with_inner_type(quote! { crate::LogCtx })
+            .with_pre_hook(quote! {
+                crate::tracing::on_request_start
+            })
+            .with_post_hook(quote! {
+                crate::tracing::on_request_end
+            }),
     );
 
     let mut error = false;