diff --git a/Cargo.toml b/Cargo.toml index d83f88e0c..13fedc140 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -54,6 +54,7 @@ nix = { version = "0.30.1", features = [ "user", "socket", "signal", + "time", ], default-features = false } oci-client = "0.15.0" once_cell = "1.19" diff --git a/crates/trident/src/engine/manual_rollback/mod.rs b/crates/trident/src/engine/manual_rollback/mod.rs index 092267621..f20e5fb2b 100644 --- a/crates/trident/src/engine/manual_rollback/mod.rs +++ b/crates/trident/src/engine/manual_rollback/mod.rs @@ -96,6 +96,21 @@ pub fn execute_rollback( requested_rollback_kind: ManualRollbackRequestKind, allowed_operations: &Operations, ) -> Result<(ExitKind, ServicingType), TridentError> { + // Mirrors `engine::update::update()`'s `update_start` metric: fired + // unconditionally on every invocation (stage-only, finalize-only, or + // combined -- matching how the CLI/gRPC two-step rollback flow can call + // this more than once for the same logical rollback), with whatever + // identifying context is known this early (the specific A/B-vs-runtime + // `ManualRollbackKind` isn't determined until the stage/finalize logic + // below runs, so it isn't included here). + tracing::info!( + metric_name = "manual_rollback_start", + requested_rollback_kind = format!("{:?}", requested_rollback_kind), + servicing_state = format!("{:?}", datastore.host_status().servicing_state), + stage = allowed_operations.has_stage(), + finalize = allowed_operations.has_finalize(), + ); + // Tracks the rollback kind actually staged this call, so the trailing // "stage completed, finalize not requested this call" return below can // report it instead of a generic NoActiveServicing. Stays None when @@ -294,6 +309,19 @@ fn finalize_rollback( host_status.spec_old = Default::default(); host_status.servicing_state = ServicingState::Provisioned; })?; + + // Unlike the A/B rollback case below, a runtime rollback requires no + // reboot, so this never reaches `engine::rollback`'s post-reboot + // boot-validation flow -- the only place `manual_rollback_success` + // is otherwise fired (and only for the `ManualRollbackAbFinalized` + // state). Without this, a runtime rollback would emit + // `manual_rollback_start` but no matching success signal at all. + info!("Manual rollback of runtime update succeeded"); + tracing::info!( + metric_name = "manual_rollback_runtime_success", + value = true + ); + return Ok(rollback_exit_kind); } diff --git a/crates/trident/src/engine/manual_rollback/utils.rs b/crates/trident/src/engine/manual_rollback/utils.rs index 04df1db6b..a22a3d2af 100644 --- a/crates/trident/src/engine/manual_rollback/utils.rs +++ b/crates/trident/src/engine/manual_rollback/utils.rs @@ -23,6 +23,7 @@ lazy_static! { } /// ManualRollbackRequestKind represents the kind of manual rollback request. +#[derive(Debug, Clone, Copy)] pub enum ManualRollbackRequestKind { RollbackOnlyIfNextIsRuntimeUpdate, RollbackAvailableAbUpdate, diff --git a/crates/trident/src/engine/runtime_update.rs b/crates/trident/src/engine/runtime_update.rs index 95cc4da4e..523bfd458 100644 --- a/crates/trident/src/engine/runtime_update.rs +++ b/crates/trident/src/engine/runtime_update.rs @@ -95,6 +95,15 @@ pub(crate) fn finalize_update( "Auto-rollback was triggered by runtime update failure:\n{e:?}" )); } + + // Unlike A/B update and clean install, a runtime update requires no + // reboot, so success can be confirmed synchronously right here instead + // of via the post-reboot boot-validation flow in `engine::rollback` + // (which only ever sees `CleanInstallFinalized`/`AbUpdateFinalized`/ + // `ManualRollbackAbFinalized` -- runtime update/rollback finalize and + // return to `Provisioned` without ever going through that flow). + info!("Runtime update succeeded"); + tracing::info!(metric_name = "runtime_update_success", value = true); finalize_result } diff --git a/crates/trident/src/lib.rs b/crates/trident/src/lib.rs index 448964bc7..ff3b2edb7 100644 --- a/crates/trident/src/lib.rs +++ b/crates/trident/src/lib.rs @@ -61,7 +61,7 @@ pub use crate::{ background_uploader::{BackgroundUploadHandle, BackgroundUploader}, logfwd::LogForwarder, logstream::Logstream, - operation_context::run_with_operation, + operation_context::{run_command, run_with_operation}, tracestream::TraceStream, }, orchestrate::OrchestratorConnection, @@ -258,7 +258,35 @@ impl Trident { )); } - tracing::info!(metric_name = "trident_start"); + // Best-effort: a failure to determine whether this is a CIH (Azure + // Container Linux) host must never fail startup, it only means + // this one field is missing from the trident_start telemetry. + let acl = match cih::is_cih() { + Ok(is_cih) => is_cih, + Err(e) => { + warn!("Failed to determine if host is running CIH: {e:?}"); + false + } + }; + // CLOCK_BOOTTIME gives nanosecond-resolution time since boot + // (including any suspended time), unlike sysinfo::System::uptime() + // (or a naive /proc/uptime parse), which only exposes whole-second + // resolution. Best-effort: clock_gettime with a valid clock ID + // essentially never fails on Linux, but fall back to NaN (which + // serde_json serializes as JSON `null`, a genuine "not available" + // rather than a misleading literal zero) rather than failing + // startup if it somehow does. + let uptime_secs = nix::time::clock_gettime(nix::time::ClockId::CLOCK_BOOTTIME) + .map(|ts| Duration::from(ts).as_secs_f64()) + .unwrap_or_else(|e| { + warn!("Failed to read CLOCK_BOOTTIME: {e}"); + f64::NAN + }); + tracing::info!( + metric_name = "trident_start", + acl = acl, + uptime_secs = uptime_secs, + ); Ok(Self { host_config, diff --git a/crates/trident/src/logging/operation_context.rs b/crates/trident/src/logging/operation_context.rs index 46eabb345..aa4d5d902 100644 --- a/crates/trident/src/logging/operation_context.rs +++ b/crates/trident/src/logging/operation_context.rs @@ -23,6 +23,8 @@ use std::cell::RefCell; use uuid::Uuid; +use trident_api::error::TridentError; + thread_local! { static CURRENT_OPERATION: RefCell> = const { RefCell::new(None) }; } @@ -63,6 +65,38 @@ pub(crate) fn current() -> Option<(String, String)> { CURRENT_OPERATION.with(|cell| cell.borrow().clone()) } +/// Like [`run_with_operation`], but specifically for the +/// `Result` shape both places that run a command +/// actually use (CLI dispatch, gRPC's `servicing_request`): additionally +/// fires a `command_error` metric -- breaking the error down into `kind`, +/// `subkind`, and `location` -- if `f` returns `Err`, while the +/// operation_id/command context is still active (so it's correlated the +/// same way `command_start` is). +pub fn run_command( + command: &str, + f: impl FnOnce() -> Result, +) -> Result { + run_with_operation(command, || { + let result = f(); + if let Err(ref error) = result { + report_command_error(error); + } + result + }) +} + +/// Fires the `command_error` metric for a failed command. Split out from +/// `run_command` so it's independently testable against a constructed +/// `TridentError` without needing a real failing command. +fn report_command_error(error: &TridentError) { + tracing::info!( + metric_name = "command_error", + kind = error.kind().as_str(), + subkind = error.subkind().unwrap_or("none"), + location = error.location().as_str(), + ); +} + #[cfg(test)] mod tests { use super::*; @@ -113,4 +147,103 @@ mod tests { "each command invocation gets a fresh operation_id" ); } + + #[test] + fn test_run_command_passes_through_ok() { + let result: Result = run_command("cmd", || Ok(42)); + assert_eq!(result.unwrap(), 42); + } + + #[test] + fn test_run_command_passes_through_err_unchanged() { + let result: Result<(), TridentError> = + run_command("cmd", || Err(TridentError::internal("boom"))); + assert!(result.is_err()); + } + + #[test] + fn test_run_command_clears_context_after_error() { + let _: Result<(), TridentError> = + run_command("cmd", || Err(TridentError::internal("boom"))); + assert!( + current().is_none(), + "context must be cleared even when f returns Err" + ); + } + + /// A minimal `tracing_subscriber::Layer` that records every event's + /// fields as strings, so `report_command_error`'s output can be + /// asserted on directly instead of only checking that `run_command` + /// doesn't panic. + #[derive(Default, Clone)] + struct CapturingLayer { + events: std::sync::Arc>>>, + } + + struct CaptureVisitor(std::collections::BTreeMap); + + impl tracing::field::Visit for CaptureVisitor { + fn record_str(&mut self, field: &tracing::field::Field, value: &str) { + self.0.insert(field.name().to_string(), value.to_string()); + } + + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + self.0 + .insert(field.name().to_string(), format!("{value:?}")); + } + } + + impl tracing_subscriber::layer::Layer for CapturingLayer + where + S: tracing::Subscriber, + { + fn on_event( + &self, + event: &tracing::Event<'_>, + _ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + let mut visitor = CaptureVisitor(std::collections::BTreeMap::new()); + event.record(&mut visitor); + self.events.lock().unwrap().push(visitor.0); + } + } + + #[test] + fn test_run_command_fires_command_error_with_kind_subkind_location() { + use tracing_subscriber::layer::SubscriberExt; + + let layer = CapturingLayer::default(); + let events = layer.events.clone(); + let _guard = + tracing::subscriber::set_default(tracing_subscriber::Registry::default().with(layer)); + + let _: Result<(), TridentError> = + run_command("test_command", || Err(TridentError::internal("boom"))); + + let events = events.lock().unwrap(); + let command_error = events + .iter() + .find(|e| e.get("metric_name").map(String::as_str) == Some("command_error")) + .expect("command_error event should have been fired"); + + assert_eq!( + command_error.get("kind").map(String::as_str), + Some("internal") + ); + assert!( + command_error.get("subkind").is_some(), + "subkind should be present: {command_error:?}" + ); + assert!( + command_error + .get("location") + .is_some_and(|l| l.contains("operation_context.rs")), + "location should point at the TridentError::internal call site: {command_error:?}" + ); + // command_start (from run_with_operation) should also have fired, + // ahead of command_error. + assert!(events + .iter() + .any(|e| e.get("metric_name").map(String::as_str) == Some("command_start"))); + } } diff --git a/crates/trident/src/main.rs b/crates/trident/src/main.rs index daa32c871..fa0aa7a5f 100644 --- a/crates/trident/src/main.rs +++ b/crates/trident/src/main.rs @@ -10,9 +10,8 @@ use trident::{ cli::{self, Cli, Commands, GetKind, TridentExitCodes}, init::offline, manual_rollback::{self, utils::ManualRollbackRequestKind}, - run_with_operation, validation, AppInsightsSender, BackgroundLog, BackgroundUploader, - DataStore, ExitKind, LogForwarder, Logstream, TraceStream, Trident, - TRIDENT_BACKGROUND_LOG_PATH, + run_command, validation, AppInsightsSender, BackgroundLog, BackgroundUploader, DataStore, + ExitKind, LogForwarder, Logstream, TraceStream, Trident, TRIDENT_BACKGROUND_LOG_PATH, }; use trident_api::{ config::{HostConfigurationSource, Operations}, @@ -195,7 +194,7 @@ fn run_trident( .. } => { let ops = cli::to_operations(allowed_operations); - run_with_operation(&command_name("install", &ops), || { + run_command(&command_name("install", &ops), || { trident .install(&mut datastore, ops, multiboot, None) .map(|(exit_kind, _image_hash, _servicing_type)| exit_kind) @@ -206,13 +205,13 @@ fn run_trident( .. } => { let ops = cli::to_operations(allowed_operations); - run_with_operation(&command_name("update", &ops), || { + run_command(&command_name("update", &ops), || { trident .update(&mut datastore, ops) .map(|(exit_kind, _image_hash, _servicing_type)| exit_kind) }) } - Commands::Commit { .. } => run_with_operation("commit", || { + Commands::Commit { .. } => run_command("commit", || { trident .commit(&mut datastore) .map(|(exit_kind, _servicing_type)| exit_kind) @@ -224,13 +223,13 @@ fn run_trident( .. } => { let ops = cli::to_operations(allowed_operations); - run_with_operation(&command_name("rollback", &ops), || { + run_command(&command_name("rollback", &ops), || { trident .rollback(&mut datastore, runtime, ab, ops) .map(|(exit_kind, _servicing_type)| exit_kind) }) } - Commands::RebuildRaid { .. } => run_with_operation("rebuild_raid", || { + Commands::RebuildRaid { .. } => run_command("rebuild_raid", || { trident .rebuild_raid(&mut datastore) .map(|()| ExitKind::Done) diff --git a/crates/trident/src/server/tridentserver/mod.rs b/crates/trident/src/server/tridentserver/mod.rs index 5a497c59d..905e83057 100644 --- a/crates/trident/src/server/tridentserver/mod.rs +++ b/crates/trident/src/server/tridentserver/mod.rs @@ -212,7 +212,7 @@ impl TridentServer { // same way the CLI path does for its own dispatch. `name` already // matches the CLI's own command-naming convention (see // `command_name` in `main.rs`) for stage/finalize granularity. - let f = move || operation_context::run_with_operation(name, f); + let f = move || operation_context::run_command(name, f); // Create the gRPC response channel let (tx, rx) = mpsc::unbounded_channel(); diff --git a/crates/trident_api/src/error.rs b/crates/trident_api/src/error.rs index 1a8e4b9f3..c4bbcf5ef 100644 --- a/crates/trident_api/src/error.rs +++ b/crates/trident_api/src/error.rs @@ -918,6 +918,16 @@ impl TridentError { } .ok() } + + /// Returns the `file:line` location where this error was originally + /// constructed (via `TridentError::new`/`with_source`/`internal`, or + /// `ReportError::structured`), same format as the `location` field + /// already included in this type's `Serialize` impl. Useful for + /// telemetry/logging call sites that want the error's origin without + /// needing the full `Debug` context chain. + pub fn location(&self) -> String { + format!("{}:{}", self.0.location.file(), self.0.location.line()) + } } pub trait ReportError { diff --git a/docs/Reference/Agent-Configuration.md b/docs/Reference/Agent-Configuration.md index 982ed24fe..9ff02e4b3 100644 --- a/docs/Reference/Agent-Configuration.md +++ b/docs/Reference/Agent-Configuration.md @@ -52,6 +52,16 @@ themselves: The `_stage`/`_finalize` suffixes distinguish a two-step (stage-only or finalize-only) invocation from a single combined one. +If a command fails, a `command_error` event is also sent (tagged with the +same `operation_id`/`command` as above), breaking the failure down into: + +- `kind`: the top-level error category (e.g. `internal`, `invalid-input`, + `servicing`, `initialization`). +- `subkind`: the specific error within that category (e.g. + `check-root-privileges`), when one applies. +- `location`: the `file:line` in Trident's source where the error was + originally raised. + Telemetry defaults to **disabled** (`OptOut`). To enable it, add a line to the Agent Configuration file: