telemetry: additional metrics (error, consistent start/success)

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"

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);
     }
 

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,

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
 }
 

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,

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<Option<(String, String)>> = 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<T, TridentError>` 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<T>(
+    command: &str,
+    f: impl FnOnce() -> Result<T, TridentError>,
+) -> Result<T, TridentError> {
+    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<i32, TridentError> = 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<std::sync::Mutex<Vec<std::collections::BTreeMap<String, String>>>>,
+    }
+
+    struct CaptureVisitor(std::collections::BTreeMap<String, String>);
+
+    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<S> tracing_subscriber::layer::Layer<S> 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")));
+    }
 }

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)

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();

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<T, K> {

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: