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,27 @@ pub fn execute_rollback(
     requested_rollback_kind: ManualRollbackRequestKind,
     allowed_operations: &Operations,
 ) -> Result<(ExitKind, ServicingType), TridentError> {
+    // Fired once per *logical* rollback, not once per call: a
+    // finalize-only call (the second step of the CLI/gRPC two-step
+    // stage-then-finalize flow) resumes a rollback that was already
+    // staged -- and therefore already reported -- by an earlier
+    // stage-having call (stage-only or combined), so it isn't a new
+    // start. Gating on `has_stage()` fires exactly for the calls that
+    // genuinely begin a rollback (stage-only and combined); a
+    // finalize-only call fires nothing here. Whatever identifying context
+    // is known this early is included -- the specific A/B-vs-runtime
+    // `ManualRollbackKind` isn't determined until the stage/finalize
+    // logic below runs, so it isn't included here.
+    if allowed_operations.has_stage() {
+        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 +315,25 @@ 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
+        );
+
+        // Persistence happens in the caller (execute_rollback), after this
+        // function returns -- not here. This function's own outcome metric
+        // has already fired above by the time that happens, so the
+        // archived metrics file still includes it; persisting again here
+        // as well would just archive the same (or, with second-resolution
+        // filenames, a second) copy.
         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

@@ -11,7 +11,9 @@ use trident_api::{
 use crate::{
     datastore::DataStore,
     engine::{self, EngineContext, EngineContextParams},
-    health, monitor_metrics, ExitKind,
+    health,
+    logging::operation_context,
+    monitor_metrics, ExitKind,
 };
 
 use super::Subsystem;
@@ -91,10 +93,51 @@ pub(crate) fn finalize_update(
     if let Err(e) = finalize_result {
         error!("Runtime update finalize failed with message:\n{e:?}");
         // Attempt an auto-rollback
-        return rollback(subsystems, state, update_start_time).message(format!(
+        let rollback_result = rollback(subsystems, state, update_start_time).message(format!(
             "Auto-rollback was triggered by runtime update failure:\n{e:?}"
         ));
+        // Persist here (not inside finalize_or_rollback_runtime_update --
+        // see the comment on that function) now that the auto-rollback's
+        // own outcome is known, so the archived metrics file actually
+        // includes it either way -- including a *failed* auto-rollback.
+        // Explicitly fire `command_error` for that final outcome *before*
+        // persisting (rather than leaving it to `run_command`/
+        // `run_command_if`, further up the call stack, which would only
+        // see it well after this archive is already written): this is a
+        // no-op if that outer wrapper has (unusually) already reported an
+        // error for this operation, and it's the same call that wrapper
+        // would otherwise make on its own once `rollback_result`
+        // eventually reaches it as an `Err`, so this doesn't introduce a
+        // second, duplicate `command_error` event.
+        if let Err(ref outcome_error) = rollback_result {
+            operation_context::report_command_error(outcome_error);
+        }
+        engine::persist_background_log_and_metrics(
+            &state.host_status().spec.trident.datastore_path,
+            None,
+            state.host_status().servicing_state,
+        );
+        return rollback_result;
     }
+
+    // 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);
+
+    // Persist *after* the success metric above so the archived metrics
+    // file on the target OS actually includes this event, not just a
+    // snapshot taken before it was ever emitted.
+    engine::persist_background_log_and_metrics(
+        &state.host_status().spec.trident.datastore_path,
+        None,
+        state.host_status().servicing_state,
+    );
+
     finalize_result
 }
 
@@ -211,12 +254,13 @@ fn finalize_or_rollback_runtime_update(
         );
     }
 
-    // Persist the Trident background log and metrics file to the updated target OS
-    engine::persist_background_log_and_metrics(
-        &state.host_status().spec.trident.datastore_path,
-        None,
-        state.host_status().servicing_state,
-    );
+    // Persistence moved to each caller (finalize_update, and
+    // manual_rollback::finalize_rollback for the manual-rollback case),
+    // right after their own final outcome metric fires -- this function
+    // returning `Ok` here does not by itself mean any of those metrics
+    // have been emitted yet, so persisting here could snapshot the
+    // metrics file before its own caller's success/rollback event was
+    // ever appended to it.
 
     Ok(ExitKind::Done)
 }

crates/trident/src/grpc_client/mod.rs

@@ -1,20 +1,24 @@
-use std::process::ExitCode;
+use std::{cell::Cell, process::ExitCode};
 
 use anyhow::{bail, Context, Error};
 use log::error;
 use tokio::fs;
 use tokio::runtime::Builder;
+use tonic::Code;
+
+use trident_api::error::{InternalError, TridentError};
 
 use crate::{
-    cli::{ClientArgs, ClientCommands, TridentExitCodes},
-    ExitKind, TRIDENT_VERSION,
+    cli::{self, ClientArgs, ClientCommands, TridentExitCodes},
+    command_name,
+    logging::operation_context,
+    run_command_if, ExitKind, OperationSource, TRIDENT_VERSION,
 };
 
-use crate::cli;
-
 mod error;
 mod tridentclient;
 
+use error::TridentClientError;
 use tridentclient::{RebootHandling, TridentClient};
 
 pub fn client_main(args: &ClientArgs) -> ExitCode {
@@ -24,7 +28,68 @@ pub fn client_main(args: &ClientArgs) -> ExitCode {
         return TridentExitCodes::SetupFailed.into();
     };
 
-    match runtime.block_on(run_client(args)) {
+    // `setup_tracing()` (see `main.rs`) treats grpc-client the same as any
+    // other command -- it's a first-class telemetry participant, not just
+    // a transport-only escape hatch, so it fires `command_start` like
+    // every other command. `command_error` is more selective (see
+    // `is_transport_failure` below). `run_client`'s errors are plain
+    // `anyhow::Error` (not `TridentError`), so they're wrapped in a
+    // generic `InternalError::Internal` here purely to get them into
+    // `run_command_if`'s `Result<_, TridentError>` shape -- the original
+    // anyhow context chain is preserved as the error's source and still
+    // printed in full below.
+    // Install/Update get the same stage/finalize-granular naming
+    // (`install_stage`, `update_finalize`, etc.) the CLI and daemon use for
+    // servicing telemetry -- otherwise every grpc-client update/install
+    // would collapse to the generic `client_update`/`client_install`
+    // regardless of which operations were actually requested.
+    let command = match &args.command {
+        ClientCommands::Install {
+            allowed_operations, ..
+        }
+        | ClientCommands::Update {
+            allowed_operations, ..
+        } => command_name(
+            args.command.name().trim_start_matches("client-"),
+            &cli::to_operations(allowed_operations),
+        ),
+        // Every other variant's name() is also "client-"-prefixed (see
+        // `ClientCommands::name()`) -- strip it here too so e.g. `commit`/
+        // `stream_disk` match the CLI/daemon's own naming for the same
+        // logical command instead of reporting as `client_commit`/
+        // `client_stream_disk`.
+        _ => args
+            .command
+            .name()
+            .trim_start_matches("client-")
+            .replace('-', "_"),
+    };
+
+    // `run_client` (the actual RPC) runs *inside* this closure, not before
+    // it, so `command_start` (fired by `run_command_if` the moment this
+    // closure is entered) actually brackets the RPC instead of always
+    // following it -- otherwise every client-side event the RPC itself
+    // fires, and the timestamp of `command_start` itself, would be
+    // reported after the call had already finished. `is_transport_failure`
+    // is computed from the raw `anyhow::Error` chain here, inside the
+    // closure, and stashed via `transport_failure` for `run_command_if`'s
+    // `should_report` predicate below, which only ever sees the already-
+    // wrapped `TridentError` and has no way to inspect that chain itself.
+    let transport_failure = Cell::new(false);
+    let result = run_command_if(
+        &command,
+        OperationSource::GrpcClient,
+        || {
+            let client_result = runtime.block_on(run_client(args));
+            transport_failure.set(is_transport_failure(&client_result));
+            client_result.map_err(|e| {
+                TridentError::with_source(InternalError::Internal("grpc-client command failed"), e)
+            })
+        },
+        |_error| transport_failure.get() && is_servicing_client_command(&args.command),
+    );
+
+    match result {
         Err(e) => {
             error!("Client failed: {:?}", e);
             return TridentExitCodes::Failed.into();
@@ -41,6 +106,68 @@ pub fn client_main(args: &ClientArgs) -> ExitCode {
     TridentExitCodes::Success.into()
 }
 
+/// The daemon fires its own, correctly-classified `command_error` for any
+/// request it actually received and acted on -- including one it rejected
+/// outright (see e.g. `services::reject_invalid_argument`). A genuine
+/// transport-level failure -- the daemon never received or finished
+/// answering this request at all -- has no other reporter, and is what
+/// this checks for:
+/// - `ConnectionError`: the initial connection attempt itself failed
+///   (socket not found, connection refused).
+/// - `RequestError`/`ResponseError` whose wrapped `Status` is
+///   `Code::Unavailable`, *except* for the daemon's own admission-control
+///   rejections -- connection-lock or servicing-lock contention (see
+///   `try_acquire_read_lock`/`try_acquire_write_lock`/`servicing_request`/
+///   `reading_request` in `server::tridentserver`), which deliberately
+///   also return `Code::Unavailable` since a busy daemon is retryable the
+///   same way a broken connection is. Those are recognized by their fixed
+///   message text (`CONNECTION_LOCK_BUSY_MESSAGE`/`SERVICING_LOCK_BUSY_MESSAGE`)
+///   and excluded here, since the daemon DID receive and answer this
+///   request, unlike tonic's own `Code::Unavailable` for a connection that
+///   broke mid-call (e.g. the daemon process died or the socket was closed
+///   while a request/response was in flight).
+fn is_transport_failure(client_result: &Result<ExitKind, Error>) -> bool {
+    client_result.as_ref().err().is_some_and(|e| {
+        e.chain()
+            .any(|cause| match cause.downcast_ref::<TridentClientError>() {
+                Some(TridentClientError::ConnectionError(..)) => true,
+                Some(TridentClientError::RequestError(_, status))
+                | Some(TridentClientError::ResponseError(_, status)) => {
+                    status.code() == Code::Unavailable
+                        && status.message() != operation_context::CONNECTION_LOCK_BUSY_MESSAGE
+                        && status.message() != operation_context::SERVICING_LOCK_BUSY_MESSAGE
+                }
+                _ => false,
+            })
+    })
+}
+
+/// Whether `command` is a servicing operation for the purposes of the
+/// `command_error` contract documented in `docs/Reference/Telemetry.md`'s
+/// "Command Errors" section: only a servicing command's own failure gets a
+/// `command_error` event -- `command_start` still fires for every command
+/// (see the comment in `client_main` above). A read-only command like
+/// `client-version` can still hit a transport-level failure (the daemon it
+/// talked to was unreachable), but that failure isn't a "servicing command
+/// failed" in the sense the docs describe, so it's deliberately excluded
+/// here, mirroring the CLI's own read-only exclusions in `main.rs`.
+///
+/// `Rollback { check: true, .. }` is `rollback --check`, a read-only dry
+/// run (mirrors `main.rs`'s own `Commands::Rollback { check: true, .. }`
+/// special-casing) -- only a real (non-check) rollback is a servicing
+/// command here.
+fn is_servicing_client_command(command: &ClientCommands) -> bool {
+    matches!(
+        command,
+        ClientCommands::Install { .. }
+            | ClientCommands::Update { .. }
+            | ClientCommands::Commit
+            | ClientCommands::RebuildRaid { .. }
+            | ClientCommands::Rollback { check: false, .. }
+            | ClientCommands::StreamDisk { .. }
+    )
+}
+
 async fn run_client(args: &ClientArgs) -> Result<ExitKind, Error> {
     let mut client = TridentClient::connect(&args.server)
         .await

crates/trident/src/lib.rs

@@ -62,8 +62,9 @@ pub use crate::{
         logfwd::LogForwarder,
         logstream::Logstream,
         operation_context::{
-            run_with_captured_operation, run_with_operation, save_reboot_operation,
-            take_reboot_operation, OperationSource,
+            command_name, run_command, run_command_if, run_reboot_command,
+            run_with_captured_operation, save_reboot_operation, take_reboot_operation,
+            OperationSource,
         },
         tracestream::TraceStream,
     },
@@ -313,7 +314,40 @@ 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.
+        // A detection failure is reported as "unknown", not "false" --
+        // conflating "known non-ACL" with "couldn't tell" would
+        // misclassify a host whose CIH check simply failed to run as
+        // definitively non-ACL.
+        let acl = match cih::is_cih() {
+            Ok(true) => "true",
+            Ok(false) => "false",
+            Err(e) => {
+                warn!("Failed to determine if host is running CIH: {e:?}");
+                "unknown"
+            }
+        };
+        // 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,
@@ -875,7 +909,17 @@ impl Trident {
         self.host_config = Some(config);
         self.is_stream_image = true;
 
-        self.install(datastore, Operations::all(), false, Some(image))
+        // `stream_image_start` above marks the beginning of a streamed
+        // install; mirror it with a completion signal here so streaming
+        // failures/successes are distinguishable in telemetry without
+        // relying on the downstream `clean_install_*` metrics (which are
+        // specific to the clean-install engine step, not the streaming
+        // entry point as a whole).
+        let result = self.install(datastore, Operations::all(), false, Some(image));
+        if result.is_ok() {
+            tracing::info!(metric_name = "stream_image_success", value = true);
+        }
+        result
     }
 
     pub fn commit(