Add event logging (#1092)

* Currently only the `auth` CLI subcommand will log any request details
when debug logging is enabled. Adding debug logging for all requests
will enable users to troubleshoot issues on any API endpoint.

To do this, we use the newly added exec hook feature in Progenitor to
capture the details of the API call.

In addition to the log event, we also create a `Span`. This is ignored
by the CLI, but may be useful for other consumers of the SDK that want
to integrate it with their monitoring infrastructure.

An example event:

  {
    "timestamp": "2025-05-07T19:51:02.464942Z",
    "level": "DEBUG",
    "message": "request succeeded",
    "url": "https://oxide.sys.r3.oxide-preview.com/v1/instances?project=will",
    "path": "/v1/instances",
    "operation_id": "instance_list",
    "remote_addr": "45.154.216.35:443",
    "http.request.method": "GET",
    "http.response.content_length": 2377,
    "http.response.status_code": 200,
    "start_time": "2025-05-07T19:51:02.079228Z",
    "duration_ms": 385,
    "oxide.request_id": "1ff7d872-3a14-4604-8392-1e9d6e2ba8fd",
    "target": "oxide"
  }

Closes #1014

Author: wfchandler

Cargo.lock

@@ -63,6 +63,8 @@ thouart = { git = "https://github.com/oxidecomputer/thouart" }
 tokio = { version = "1.44.2", features = ["full"] }
 toml = "0.8.22"
 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.16.0", features = ["serde", "v4"] }
 

Cargo.toml

@@ -49,6 +49,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/Cargo.toml

@@ -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("oxide=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/cli_builder.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("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();
 }