diff --git a/crates/api-core/src/handlers/host_reprovisioning.rs b/crates/api-core/src/handlers/host_reprovisioning.rs index 68966043d1..86b838a76f 100644 --- a/crates/api-core/src/handlers/host_reprovisioning.rs +++ b/crates/api-core/src/handlers/host_reprovisioning.rs @@ -79,6 +79,17 @@ pub(crate) async fn trigger_host_reprovisioning( &machine_id, ) .await?; + // Manual initiations pair with the same completion emit the + // update manager's automatic path gets, keeping the + // started-to-completed gap truthful for every initiator. + carbide_instrument::emit( + crate::machine_update_manager::metrics::FirmwareUpdateProgress { + target: crate::machine_update_manager::metrics::FirmwareUpdateTarget::Host, + phase: crate::machine_update_manager::metrics::FirmwareUpdatePhase::Started, + machine_id, + detail: initiator.to_string(), + }, + ); } Mode::Clear => { db::host_machine_update::clear_host_reprovisioning_request(&mut txn, &machine_id) diff --git a/crates/api-core/src/handlers/svpc.rs b/crates/api-core/src/handlers/svpc.rs index 8aa1d83768..2e3495c9d3 100644 --- a/crates/api-core/src/handlers/svpc.rs +++ b/crates/api-core/src/handlers/svpc.rs @@ -34,6 +34,9 @@ use rpc::protos::mlx_device::MlxDeviceInfo; use tonic::{Request, Response, Status}; use crate::api::{Api, log_request_data}; +use crate::machine_update_manager::metrics::{ + FirmwareUpdatePhase, FirmwareUpdateProgress, FirmwareUpdateTarget, +}; use crate::{CarbideError, CarbideResult}; // Code to handle SVPC specific information. @@ -197,12 +200,16 @@ fn build_apply_firmware_command<'a>( return None; } - tracing::info!( - %machine_id, %pci_name, %part_number, %psid, - observed_fw_version = ?device_info.fw_version_current, - expected_fw_version = %fw_profile.firmware_spec.version, - "firmware version mismatch, applying firmware" - ); + carbide_instrument::emit(FirmwareUpdateProgress { + target: FirmwareUpdateTarget::SuperNic, + phase: FirmwareUpdatePhase::Started, + machine_id, + detail: format!( + "pci_name={pci_name} part_number={part_number} psid={psid} \ + observed_fw_version={:?} expected_fw_version={}", + device_info.fw_version_current, fw_profile.firmware_spec.version + ), + }); Some(Cow::Borrowed(fw_profile)) })(); diff --git a/crates/api-core/src/machine_update_manager/dpu_nic_firmware.rs b/crates/api-core/src/machine_update_manager/dpu_nic_firmware.rs index 80a79619b1..0003e84655 100644 --- a/crates/api-core/src/machine_update_manager/dpu_nic_firmware.rs +++ b/crates/api-core/src/machine_update_manager/dpu_nic_firmware.rs @@ -29,6 +29,10 @@ use sqlx::PgConnection; use super::dpu_nic_firmware_metrics::DpuNicFirmwareUpdateMetrics; use super::machine_update_module::MachineUpdateModule; +use super::metrics::{ + FirmwareUpdateFailed, FirmwareUpdateFailureCause, FirmwareUpdatePhase, FirmwareUpdateProgress, + FirmwareUpdateTarget, +}; use crate::cfg::file::CarbideConfig; use crate::machine_update_manager::MachineUpdateManager; use crate::{CarbideResult, DatabaseError}; @@ -46,6 +50,14 @@ pub struct DpuNicFirmwareUpdate { /// DPF handle for discovering outdated DPF-managed DPUs. `None` when DPF /// is disabled in config; in that case `find_outdated_dpus_dpf` is not called. pub dpf: Option>, + /// Wrong-version outcomes already counted, keyed by DPU and the version it + /// landed on: the condition persists across manager passes (the update + /// marker stays until an operator intervenes or a new update runs), and a + /// counter must record the outcome once, not once per poll. An entry + /// clears when the DPU's markers clear, so a later attempt that lands + /// wrong again is a new outcome. In-memory: a restart re-reports at most + /// once per stuck DPU. + pub reported_wrong_versions: std::sync::Mutex>, } #[async_trait] @@ -105,11 +117,6 @@ impl MachineUpdateModule for DpuNicFirmwareUpdate { output + format!("{} ({}) ", dpu.dpu_machine_id, dpu.firmware_version).as_str() }); - tracing::info!( - "Starting DPU updates for host {}: {}", - host_machine_id, - dpu_update_string - ); // If the reprovisioning failed to update the database for a // given {dpu,host}_machine_id, log it as a warning and don't // add it to updates_started. @@ -124,11 +131,13 @@ impl MachineUpdateModule for DpuNicFirmwareUpdate { { match reprovisioning_err { DatabaseError::NotFoundError { id, .. } => { - tracing::warn!( - "failed to trigger reprovisioning for managed host : {} - no update match for id: {}", - host_machine_id, - id - ); + carbide_instrument::emit(FirmwareUpdateFailed { + target: FirmwareUpdateTarget::DpuNic, + cause: FirmwareUpdateFailureCause::NoUpdateMatch, + machine_id: host_machine_id, + unmatched_dpu_machine_id: id, + firmware_version: String::new(), + }); continue; } _ => { @@ -139,6 +148,15 @@ impl MachineUpdateModule for DpuNicFirmwareUpdate { txn.commit().await?; + // Counted only once the trigger is committed: a DPU that left + // ready between snapshot and trigger is a NoUpdateMatch failure, + // not a started update. + carbide_instrument::emit(FirmwareUpdateProgress { + target: FirmwareUpdateTarget::DpuNic, + phase: FirmwareUpdatePhase::Started, + machine_id: host_machine_id, + detail: dpu_update_string, + }); updates_started.insert(host_machine_id); } @@ -163,13 +181,26 @@ impl MachineUpdateModule for DpuNicFirmwareUpdate { machine_id = %updated_machine.dpu_machine_id, "Failed to remove machine update markers: {}", e ); + } else if let Ok(mut reported) = self.reported_wrong_versions.lock() { + reported.retain(|(dpu, _)| *dpu != updated_machine.dpu_machine_id); } - } else { - tracing::warn!( - machine_id = %updated_machine.dpu_machine_id, - firmware_version = %updated_machine.firmware_version, - "Incorrect firmware version after attempted update" - ); + } else if self + .reported_wrong_versions + .lock() + .is_ok_and(|mut reported| { + reported.insert(( + updated_machine.dpu_machine_id, + updated_machine.firmware_version.clone(), + )) + }) + { + carbide_instrument::emit(FirmwareUpdateFailed { + target: FirmwareUpdateTarget::DpuNic, + cause: FirmwareUpdateFailureCause::WrongVersionAfterUpdate, + machine_id: updated_machine.dpu_machine_id, + unmatched_dpu_machine_id: String::new(), + firmware_version: updated_machine.firmware_version, + }); } } Ok(()) @@ -243,6 +274,7 @@ impl DpuNicFirmwareUpdate { let mut metrics = DpuNicFirmwareUpdateMetrics::new(); metrics.register_callbacks(&meter); Some(DpuNicFirmwareUpdate { + reported_wrong_versions: std::sync::Mutex::new(HashSet::new()), metrics: Some(metrics), config, dpf, diff --git a/crates/api-core/src/machine_update_manager/host_firmware.rs b/crates/api-core/src/machine_update_manager/host_firmware.rs index d811ff7e5d..d0ace20657 100644 --- a/crates/api-core/src/machine_update_manager/host_firmware.rs +++ b/crates/api-core/src/machine_update_manager/host_firmware.rs @@ -32,6 +32,7 @@ use sqlx::PgConnection; use tokio::sync::Mutex; use super::machine_update_module::MachineUpdateModule; +use super::metrics::{FirmwareUpdatePhase, FirmwareUpdateProgress, FirmwareUpdateTarget}; use crate::CarbideResult; use crate::cfg::file::CarbideConfig; @@ -90,8 +91,6 @@ impl MachineUpdateModule for HostFirmwareUpdate { continue; } - tracing::info!("Moving {} to host reprovision", machine_update); - db::host_machine_update::trigger_host_reprovisioning_request( &mut txn, "Automated", @@ -99,6 +98,15 @@ impl MachineUpdateModule for HostFirmwareUpdate { ) .await?; + // Counted after the trigger succeeds; the commit below spans the + // whole batch, so a later DB error can re-count machines on the + // next pass -- the same repeat-on-retry the old log line had. + carbide_instrument::emit(FirmwareUpdateProgress { + target: FirmwareUpdateTarget::Host, + phase: FirmwareUpdatePhase::Started, + machine_id: *machine_update, + detail: String::new(), + }); updates_started.insert(*machine_update); } @@ -109,18 +117,21 @@ impl MachineUpdateModule for HostFirmwareUpdate { async fn clear_completed_updates(&self, txn: &mut PgConnection) -> CarbideResult<()> { let completed = db::host_machine_update::find_completed_updates(txn).await?; - if !completed.is_empty() { - tracing::info!("Completed host firmware updates: {completed:?}"); - for machine in completed { - db::machine::remove_health_report( - txn, - &machine, - health_report::HealthReportApplyMode::Merge, - HOST_FW_UPDATE_HEALTH_REPORT_SOURCE, - ) - .await?; - db::machine::update_update_complete(&machine, true, txn).await?; - } + for machine in completed { + db::machine::remove_health_report( + txn, + &machine, + health_report::HealthReportApplyMode::Merge, + HOST_FW_UPDATE_HEALTH_REPORT_SOURCE, + ) + .await?; + db::machine::update_update_complete(&machine, true, txn).await?; + carbide_instrument::emit(FirmwareUpdateProgress { + target: FirmwareUpdateTarget::Host, + phase: FirmwareUpdatePhase::Completed, + machine_id: machine, + detail: String::new(), + }); } Ok(()) } diff --git a/crates/api-core/src/machine_update_manager/metrics.rs b/crates/api-core/src/machine_update_manager/metrics.rs index 2775e5ff78..72b9021316 100644 --- a/crates/api-core/src/machine_update_manager/metrics.rs +++ b/crates/api-core/src/machine_update_manager/metrics.rs @@ -17,6 +17,7 @@ use std::sync::Arc; use std::sync::atomic::{AtomicU64, Ordering}; +use carbide_uuid::machine::MachineId; use opentelemetry::metrics::Meter; pub struct MachineUpdateManagerMetrics { @@ -69,3 +70,237 @@ impl MachineUpdateManagerMetrics { .build(); } } + +/// The device class a firmware update targets: the `target` label shared by +/// [`FirmwareUpdateProgress`] and [`FirmwareUpdateFailed`]. +#[derive(Debug, Clone, Copy, PartialEq, Eq, carbide_instrument::LabelValue)] +pub enum FirmwareUpdateTarget { + /// Host firmware, applied through host reprovisioning. + Host, + /// DPU NIC firmware, applied through DPU reprovisioning. + DpuNic, + /// SuperNIC firmware, applied through the DPA scout flow. + SuperNic, +} + +/// The phase a firmware update just reached, as the `phase` label on +/// [`FirmwareUpdateProgress`]. +#[derive(Debug, Clone, Copy, PartialEq, Eq, carbide_instrument::LabelValue)] +pub enum FirmwareUpdatePhase { + Started, + Completed, +} + +/// A firmware update reached a phase. For the `host` target both phases +/// fire, so the started-to-completed gap is the in-flight backlog: a started +/// series that moves while completed stays flat points at updates that never +/// finish. The `dpu_nic` and `super_nic` targets emit `started` only -- +/// completion shows in their own state flows -- and a SuperNIC re-counts one +/// `started` per scout pass while a device stays mismatched, since each pass +/// issues a real apply command. Both phases are at-least-once on transient +/// database errors: the update manager's batch transaction can roll back +/// after an emit, and the next pass re-counts -- the same repeat-on-retry +/// the log lines always had. +#[derive(carbide_instrument::Event)] +#[event( + name = "carbide_firmware_updates_total", + component = "nico-api", + log = info, + metric = counter, + message = "Firmware update progress", + describe = "Number of firmware updates started and completed, by update target and phase" +)] +pub struct FirmwareUpdateProgress { + #[label] + pub target: FirmwareUpdateTarget, + #[label] + pub phase: FirmwareUpdatePhase, + /// The host being reprovisioned (Host), the host whose DPUs update + /// (DpuNic), or the machine holding the device (SuperNic). + #[context] + pub machine_id: MachineId, + /// What the site knows beyond the machine id: the DPU list with firmware + /// versions for DpuNic, the device identity and observed/expected + /// versions for SuperNic. For Host it is empty on automatic starts and + /// names the initiator on operator-initiated ones. + #[context] + pub detail: String, +} + +/// Why a firmware update failed, as the `cause` label on +/// [`FirmwareUpdateFailed`]. +#[derive(Debug, Clone, Copy, PartialEq, Eq, carbide_instrument::LabelValue)] +pub enum FirmwareUpdateFailureCause { + /// Triggering reprovisioning found no ready machine row to update. + NoUpdateMatch, + /// The update ran but the device still reports an unexpected version. + WrongVersionAfterUpdate, +} + +/// A firmware update attempt failed. The per-target, per-cause rate is the +/// alert; the log line names the machine and version involved. +#[derive(carbide_instrument::Event)] +#[event( + name = "carbide_firmware_update_failures_total", + component = "nico-api", + log = warn, + metric = counter, + message = "Firmware update failed", + describe = "Number of firmware update failures, by update target and cause" +)] +pub struct FirmwareUpdateFailed { + #[label] + pub target: FirmwareUpdateTarget, + #[label] + pub cause: FirmwareUpdateFailureCause, + /// The host whose update could not start (NoUpdateMatch) or the DPU + /// reporting the wrong version (WrongVersionAfterUpdate). + #[context] + pub machine_id: MachineId, + /// The DPU the reprovisioning trigger could not match (NoUpdateMatch); + /// empty otherwise. + #[context] + pub unmatched_dpu_machine_id: String, + /// The firmware version observed after the attempted update + /// (WrongVersionAfterUpdate); empty otherwise. + #[context] + pub firmware_version: String, +} + +#[cfg(test)] +mod tests { + use std::str::FromStr as _; + + use carbide_instrument::testing::{CapturedLog, MetricsCapture, capture_logs}; + + use super::*; + + fn field<'a>(log: &'a CapturedLog, name: &str) -> Option<&'a str> { + log.fields + .iter() + .find(|(key, _)| key == name) + .map(|(_, value)| value.as_str()) + } + + fn machine_id() -> MachineId { + MachineId::from_str("fm100hseddco33hvlofuqvg543p6p9aj60g76q5cq491g9m9tgtf2dk0530") + .expect("valid machine id") + } + + /// One emit writes the INFO progress line (machine id plus the site's + /// detail) and moves `carbide_firmware_updates_total` under the site's + /// target and phase. + #[test] + fn firmware_update_progress_logs_info_and_counts() { + let metrics = MetricsCapture::start(); + let logs = capture_logs(|| { + carbide_instrument::emit(FirmwareUpdateProgress { + target: FirmwareUpdateTarget::SuperNic, + phase: FirmwareUpdatePhase::Started, + machine_id: machine_id(), + detail: "pci_name=0000:cc:00.0 observed_fw_version=Some(\"28.39.1000\") \ + expected_fw_version=28.39.1002" + .to_string(), + }); + }); + + assert_eq!(logs.len(), 1); + assert_eq!(logs[0].level, tracing::Level::INFO); + assert_eq!(logs[0].message, "Firmware update progress"); + assert_eq!(field(&logs[0], "target"), Some("super_nic")); + assert_eq!(field(&logs[0], "phase"), Some("started")); + let id = machine_id().to_string(); + assert_eq!(field(&logs[0], "machine_id"), Some(id.as_str())); + assert!( + field(&logs[0], "detail") + .expect("detail field") + .contains("expected_fw_version=28.39.1002") + ); + + assert_eq!( + metrics.counter_delta( + "carbide_firmware_updates_total", + &[("target", "super_nic"), ("phase", "started")], + ), + 1.0 + ); + } + + /// The phase label separates the started and completed series for the + /// same target: one update crossing both phases moves each counter once. + #[test] + fn firmware_update_progress_counts_each_phase_separately() { + let metrics = MetricsCapture::start(); + capture_logs(|| { + for phase in [FirmwareUpdatePhase::Started, FirmwareUpdatePhase::Completed] { + carbide_instrument::emit(FirmwareUpdateProgress { + target: FirmwareUpdateTarget::Host, + phase, + machine_id: machine_id(), + detail: String::new(), + }); + } + }); + + for phase in ["started", "completed"] { + assert_eq!( + metrics.counter_delta( + "carbide_firmware_updates_total", + &[("target", "host"), ("phase", phase)], + ), + 1.0, + "phase {phase}" + ); + } + } + + /// A failure emit writes the WARN line with its cause's context and moves + /// `carbide_firmware_update_failures_total`; the two causes count as + /// independent series. + #[test] + fn firmware_update_failed_logs_warn_and_counts_by_cause() { + let metrics = MetricsCapture::start(); + let logs = capture_logs(|| { + carbide_instrument::emit(FirmwareUpdateFailed { + target: FirmwareUpdateTarget::DpuNic, + cause: FirmwareUpdateFailureCause::NoUpdateMatch, + machine_id: machine_id(), + unmatched_dpu_machine_id: + "fm100ptrh18t1lrjg2pqagkh3sfigr9m65dejvkq168ako07sc0uibpp5q0".to_string(), + firmware_version: String::new(), + }); + carbide_instrument::emit(FirmwareUpdateFailed { + target: FirmwareUpdateTarget::DpuNic, + cause: FirmwareUpdateFailureCause::WrongVersionAfterUpdate, + machine_id: machine_id(), + unmatched_dpu_machine_id: String::new(), + firmware_version: "11.10.1000".to_string(), + }); + }); + + assert_eq!(logs.len(), 2); + assert!(logs.iter().all(|log| log.level == tracing::Level::WARN)); + assert!( + logs.iter() + .all(|log| log.message == "Firmware update failed") + ); + assert_eq!(field(&logs[0], "cause"), Some("no_update_match")); + assert_eq!( + field(&logs[0], "unmatched_dpu_machine_id"), + Some("fm100ptrh18t1lrjg2pqagkh3sfigr9m65dejvkq168ako07sc0uibpp5q0") + ); + assert_eq!(field(&logs[1], "cause"), Some("wrong_version_after_update")); + assert_eq!(field(&logs[1], "firmware_version"), Some("11.10.1000")); + + for cause in ["no_update_match", "wrong_version_after_update"] { + assert_eq!( + metrics.counter_delta( + "carbide_firmware_update_failures_total", + &[("target", "dpu_nic"), ("cause", cause)], + ), + 1.0, + "cause {cause}" + ); + } + } +} diff --git a/crates/api-core/src/tests/dpu_nic_firmware.rs b/crates/api-core/src/tests/dpu_nic_firmware.rs index 43eb90493d..f553fa259f 100644 --- a/crates/api-core/src/tests/dpu_nic_firmware.rs +++ b/crates/api-core/src/tests/dpu_nic_firmware.rs @@ -17,6 +17,7 @@ use std::collections::HashSet; use std::string::ToString; +use carbide_instrument::testing::MetricsCapture; use carbide_machine_controller::health_report::create_host_update_health_report_dpufw; use common::api_fixtures::{create_managed_host, create_managed_host_multi_dpu, create_test_env}; use model::machine::LoadSnapshotOptions; @@ -40,6 +41,7 @@ async fn test_start_updates(pool: sqlx::PgPool) -> Result<(), Box Result<(), Box Result<(), Box= 1.0 + ); + // Check if health override is placed let managed_host = managed_host.snapshot(&mut txn).await; @@ -89,6 +104,7 @@ async fn test_start_updates_with_multidpu( txn.commit().await?; let dpu_nic_firmware_update = DpuNicFirmwareUpdate { + reported_wrong_versions: std::sync::Mutex::new(std::collections::HashSet::new()), metrics: None, config: env.config.clone(), dpf: None, @@ -132,6 +148,7 @@ async fn test_get_updates_in_progress( managed_host.update_nic_firmware_version(&mut txn).await?; txn.commit().await?; let dpu_nic_firmware_update = DpuNicFirmwareUpdate { + reported_wrong_versions: std::sync::Mutex::new(std::collections::HashSet::new()), metrics: None, config: env.config.clone(), dpf: None, @@ -180,6 +197,7 @@ async fn test_check_for_updates(pool: sqlx::PgPool) -> Result<(), Boxcarbide_endpoint_exploration_success_countgaugeThe amount of endpoint explorations that have been successful carbide_endpoint_explorations_countgaugeThe amount of endpoint explorations that have been attempted carbide_external_call_duration_millisecondshistogramDuration of outbound calls by backend, operation, and outcome; the _count series, split by outcome, gives the request and error rates. +carbide_firmware_update_failures_totalcounterNumber of firmware update failures, by update target and cause +carbide_firmware_updates_totalcounterNumber of firmware updates started and completed, by update target and phase carbide_gpus_in_use_countgaugeThe total number of GPUs that are actively used by tenants in instances in the NICo deployment carbide_gpus_total_countgaugeThe total number of GPUs available in the NICo deployment carbide_gpus_usable_countgaugeThe remaining number of GPUs in the NICo deployment which are available for immediate instance creation