From 1e0b6fbb68fc712449c2a0b0e8e38de9a7b554e5 Mon Sep 17 00:00:00 2001 From: Brian Fjeldstad Date: Fri, 30 Oct 2026 16:57:27 +0000 Subject: [PATCH] telemetry: enrich platform and startup metrics Rebase onto agent configuration read-error handling. Apply approved telemetry review fixes at their owning layer. Original layer head: 5e78b226300e72aa68293d989bbcc112715d1bdb Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 43cb811b-f191-4d90-852f-e3373041ca11 --- Cargo.toml | 1 + crates/osutils/src/virt.rs | 70 +++++++++- crates/trident/src/diagnostics.rs | 35 +---- crates/trident/src/lib.rs | 12 +- crates/trident/src/logging/tracestream.rs | 133 ++++++++++++++++++- crates/trident/src/telemetry.rs | 3 + docs/Reference/Telemetry.md | 153 ++++++++++++++++++++++ 7 files changed, 371 insertions(+), 36 deletions(-) create mode 100644 docs/Reference/Telemetry.md diff --git a/Cargo.toml b/Cargo.toml index 0e6ad22a3f..4fd983cfbf 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -61,6 +61,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/osutils/src/virt.rs b/crates/osutils/src/virt.rs index 9f19d05ce9..8aba4a1a9c 100644 --- a/crates/osutils/src/virt.rs +++ b/crates/osutils/src/virt.rs @@ -1,4 +1,24 @@ -//! This module contains helper functions for working with virtualized environments. +//! Detects whether Trident is running inside a virtual machine, and if so, +//! which hypervisor, by reading DMI/SMBIOS sysfs files. Shared by +//! `trident::diagnostics` (the support-bundle `HostDescription::virt_type`, +//! the detected hypervisor name or `None`) and `trident::logging::tracestream` +//! (the `platform_info.vm` telemetry field, a plain boolean), so the two +//! never diverge on what counts as "virtual". Also home to the unrelated +//! `virtdeploy` best-effort detection used by boot-order workarounds. +//! +//! `detect_hypervisor` only recognizes hypervisors that override the DMI +//! vendor/product strings to a known value (QEMU/KVM, Hyper-V). It does not +//! use the CPUID hypervisor-present bit, since a hardened or nested +//! hypervisor can mask both signals; this is a best-effort heuristic, not a +//! guarantee. + +use anyhow::Context; + +/// Path to DMI file with vendor information. +const DMI_SYS_VENDOR_FILE: &str = "/sys/class/dmi/id/sys_vendor"; + +/// Path to DMI file with product name. +const DMI_PRODUCT_NAME_FILE: &str = "/sys/class/dmi/id/product_name"; /// Does a best-effort check to determine whether we are running in a virtdeploy VM. pub fn is_virtdeploy() -> bool { @@ -14,3 +34,51 @@ pub fn is_virtdeploy() -> bool { false } + +/// Returns the detected hypervisor name (e.g. `"qemu"`, `"hyperv"`), or +/// `None` if the DMI vendor/product strings were read successfully but did +/// not match a known hypervisor (including physical hardware). +/// +/// Returns `Err` whenever a required DMI file could not be read, so callers +/// that want to report collection failures (see +/// `trident::diagnostics::get_virtualization_info`) can distinguish +/// "unreadable" from "read fine, not virtualized". The error carries the +/// failing file's path via context, so it remains actionable after being +/// formatted/logged. +pub fn detect_hypervisor() -> Result, anyhow::Error> { + let vendor = std::fs::read_to_string(DMI_SYS_VENDOR_FILE) + .with_context(|| format!("Failed to read '{DMI_SYS_VENDOR_FILE}'"))? + .trim() + .to_lowercase(); + if vendor.contains("qemu") { + return Ok(Some("qemu".to_string())); + } + + let product = std::fs::read_to_string(DMI_PRODUCT_NAME_FILE) + .with_context(|| format!("Failed to read '{DMI_PRODUCT_NAME_FILE}'"))? + .trim() + .to_lowercase(); + if vendor.contains("microsoft corporation") && product.contains("virtual machine") { + return Ok(Some("hyperv".to_string())); + } + + Ok(None) +} + +/// Convenience wrapper over [`detect_hypervisor`] for callers (e.g. +/// telemetry) that only care whether this is a VM, not which hypervisor, +/// and don't need to distinguish "unreadable DMI files" from "not a VM" -- +/// both cases are reported as `false`. +pub fn is_virtual() -> bool { + detect_hypervisor().unwrap_or(None).is_some() +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn test_is_virtual_matches_detect_hypervisor() { + assert_eq!(is_virtual(), detect_hypervisor().unwrap_or(None).is_some()); + } +} diff --git a/crates/trident/src/diagnostics.rs b/crates/trident/src/diagnostics.rs index f42d459f6e..6401026be1 100644 --- a/crates/trident/src/diagnostics.rs +++ b/crates/trident/src/diagnostics.rs @@ -18,6 +18,7 @@ use osutils::{ findmnt::FindMnt, lsblk, pcrlock::{self, LogOutput}, + virt, }; use trident_api::{ config::{Check, Health}, @@ -35,12 +36,6 @@ use crate::{ /// Name of the top-level directory in the diagnostics tarball const DIAGNOSTICS_BUNDLE_PREFIX: &str = "trident-diagnostics"; -/// Path to DMI file with vendor information -const DMI_SYS_VENDOR_FILE: &str = "/sys/class/dmi/id/sys_vendor"; - -/// Path to DMI file with product name -const DMI_PRODUCT_NAME_FILE: &str = "/sys/class/dmi/id/product_name"; - /// Name of the trident systemd service const TRIDENT_SERVICE_NAME: &str = "trident.service"; @@ -330,33 +325,13 @@ fn collect_service_status( fn get_virtualization_info(failures: &mut Vec) -> Option { debug!("Collecting virtualization info"); - let content = match fs::read_to_string(DMI_SYS_VENDOR_FILE) { - Ok(c) => c, + match virt::detect_hypervisor() { + Ok(virt_type) => virt_type, Err(e) => { - record_failure(failures, "virtualization info (dmi_sys vendor)", &e); - return None; - } - }; - - let vendor = content.trim().to_lowercase(); - if vendor.contains("qemu") { - return Some("qemu".to_string()); - } - - let product = match fs::read_to_string(DMI_PRODUCT_NAME_FILE) { - Ok(p) => p, - Err(e) => { - record_failure(failures, "virtualization info (dmi_sys product)", &e); - return None; + record_failure(failures, "virtualization info", &e); + None } - }; - - let product = product.trim().to_lowercase(); - if vendor.contains("microsoft corporation") && product.contains("virtual machine") { - return Some("hyperv".to_string()); } - - None } struct FileToCollect { diff --git a/crates/trident/src/lib.rs b/crates/trident/src/lib.rs index ff54965d97..e5de97dbb4 100644 --- a/crates/trident/src/lib.rs +++ b/crates/trident/src/lib.rs @@ -295,7 +295,17 @@ impl Trident { )); } - tracing::info!(metric_name = events::TRIDENT_START); + // See `logging::tracestream::clock_boottime_uptime_secs` for the + // NaN-fallback rationale and its regression test. + let uptime_secs = logging::tracestream::clock_boottime_uptime_secs( + nix::time::clock_gettime(nix::time::ClockId::CLOCK_BOOTTIME), + ); + // `acl` and `arch` are process-lifetime, host-level facts (like + // `vm`), so they're stamped onto every telemetry event via + // `PLATFORM_INFO` (see + // `logging::tracestream::populate_platform_info`) instead of + // being scoped to just this one metric. + tracing::info!(metric_name = events::TRIDENT_START, value = uptime_secs,); Ok(Self { host_config, diff --git a/crates/trident/src/logging/tracestream.rs b/crates/trident/src/logging/tracestream.rs index 452bb924e8..a3fc475385 100644 --- a/crates/trident/src/logging/tracestream.rs +++ b/crates/trident/src/logging/tracestream.rs @@ -24,14 +24,41 @@ use tracing_subscriber::{layer::Layer, registry::LookupSpan}; use crate::command_kind::CommandKind; use trident_api::error::TridentError; +/// Reads `CLOCK_BOOTTIME` (nanosecond-resolution time since boot, +/// including any suspended time -- unlike `sysinfo::System::uptime()` or a +/// naive `/proc/uptime` parse, which only expose whole-second resolution) +/// and converts it into the `trident_start` uptime metric value. Used by +/// `Trident::new`'s startup telemetry (see the `trident_start` call site +/// in `lib.rs`), which passes it the live `nix::time::clock_gettime` +/// result. +/// +/// Best-effort: `clock_gettime` with a valid clock ID essentially never +/// fails on Linux, but falls back to `f64::NAN` -- which `json!()` +/// serializes as JSON `null`, a genuine "not available" rather than a +/// misleading literal zero (see +/// `test_clock_boottime_uptime_secs_nan_fallback_serializes_as_json_null` +/// below) -- rather than failing startup if it somehow does. +pub(crate) fn clock_boottime_uptime_secs( + clock_read: Result, +) -> f64 { + clock_read + .map(|ts| std::time::Duration::from(ts).as_secs_f64()) + .unwrap_or_else(|e| { + warn!("Failed to read CLOCK_BOOTTIME: {e}"); + f64::NAN + }) +} + use osutils::{ dmi, files, osrelease::{OsRelease, OS_RELEASE_PATH}, - uname, + uname, virt, }; +use sysdefs::arch::SystemArchitecture; use crate::{ - datastore::DataStore, logging::operation_context, TRIDENT_METRICS_FILE_PATH, TRIDENT_VERSION, + datastore::DataStore, init::acl, logging::operation_context, TRIDENT_METRICS_FILE_PATH, + TRIDENT_VERSION, }; lazy_static::lazy_static! { @@ -820,6 +847,29 @@ fn populate_platform_info() -> BTreeMap { fields::KERNEL_VERSION.to_string(), json!(kernel_release.trim()), ); + + // Whether this host is virtualized (see `osutils::virt` for the + // detection heuristic and its caveats). + platform_info.insert(fields::VM.to_string(), json!(virt::is_virtual())); + + let arch: &'static str = SystemArchitecture::current().into(); + platform_info.insert(fields::ARCH.to_string(), json!(arch)); + // Best-effort: a failure to determine whether this is an ACL (Azure + // Container Linux) host must never fail startup, it only means this + // one field is missing from every telemetry event for this + // invocation. A detection failure is reported as "unknown", not + // "false" -- conflating "known non-ACL" with "couldn't tell" would + // misclassify a host whose ACL check simply failed to run as + // definitively non-ACL. + let acl = match acl::is_acl() { + Ok(is_acl) => is_acl.to_string(), + Err(e) => { + warn!("Failed to determine if host is running ACL: {e:?}"); + "unknown".to_string() + } + }; + platform_info.insert(fields::ACL.to_string(), json!(acl)); + platform_info } @@ -955,6 +1005,63 @@ mod tests { ); } + #[test] + /// Regression test for a Copilot review finding on PR #778: claimed + /// that `clock_boottime_uptime_secs`'s `f64::NAN` fallback, passed + /// through `tracing::info!(value = ...)` to + /// `TraceEntryVisitor::record_f64`'s `json!(value)`, would make + /// `serde_json` unable to serialize the entry, panicking instead of + /// staying best-effort. Calls the exact function `lib.rs`'s + /// `trident_start` metric uses (see its call site), forcing the + /// failure branch with a synthetic `Errno`, then sends the resulting + /// value through the real tracing -> visitor -> file-write pipeline + /// (not just a standalone `serde_json` snippet): `json!(f64)` goes + /// through `Value::from(f64)`, which maps non-finite floats to + /// `Value::Null` rather than erroring, so the written line contains a + /// valid JSON `"value":null` and the file write completes normally. + fn test_clock_boottime_uptime_secs_nan_fallback_serializes_as_json_null() { + let uptime_secs = clock_boottime_uptime_secs(Err(nix::errno::Errno::EINVAL)); + assert!( + uptime_secs.is_nan(), + "a failed clock read must fall back to NaN, not a misleading literal value" + ); + + let temp_dir = tempfile::tempdir().unwrap(); + let metrics_path = temp_dir.path().join("metrics.jsonl"); + let tracestream = TraceStream::default(); + let trace_sender = tracestream + .make_trace_sender_with_metrics_path(metrics_path.to_str().unwrap()) + .with_filter(filter::LevelFilter::INFO); + + let _guard = tracing::subscriber::set_default( + tracing_subscriber::Registry::default().with(trace_sender), + ); + + tracing::info!(metric_name = "trident_start", value = uptime_secs); + + std::thread::sleep(std::time::Duration::from_millis(100)); + + let file = File::open(&metrics_path).unwrap(); + let reader = BufReader::new(file); + let lines: Vec = reader.lines().map(|l| l.unwrap()).collect(); + + let entry_line = lines + .iter() + .find(|line| line.contains(r#""metric_name":"trident_start""#)) + .expect("expected trident_start metric not found in the local metrics file"); + + // Confirm the line is valid, parseable JSON (i.e. writing a NaN + // value never broke serialization) and that the value field landed + // as JSON null rather than a literal 0 or a serialization failure. + let parsed: serde_json::Value = + serde_json::from_str(entry_line).expect("trace entry line must be valid JSON"); + assert_eq!( + parsed.get("value"), + Some(&Value::Null), + "NaN metric value should serialize as JSON null, not a literal 0 or an error" + ); + } + #[test] fn test_startup_events_omit_ids_without_operation_context() { for name in ["command_start", "trident_start"] { @@ -1416,13 +1523,31 @@ mod functional_test { "kernel_version".to_string(), json!(uname::kernel_release().unwrap().trim()), ); + expected_platform_info.insert("vm".to_string(), json!(virt::is_virtual())); // Call the function to get the actual result. let platform_info = populate_platform_info(); - // Assert that the actual result matches the expected result. + let expected_arch: &'static str = SystemArchitecture::current().into(); + assert_eq!(platform_info.get("arch").unwrap(), &json!(expected_arch)); + // Host-dependent (like the fields above): just assert the field is + // present and one of the values `acl::is_acl()` can actually + // produce, rather than a fixed expectation, since whether the VM + // running this test is an ACL host isn't controlled by the test. + let acl = platform_info.get("acl").unwrap().as_str().unwrap(); + assert!( + ["true", "false", "unknown"].contains(&acl), + "unexpected acl value: {acl}" + ); + + // Assert that the actual result matches the expected result for + // every field with a fixed expectation (arch/acl are asserted + // separately above since they are host-dependent). + let mut actual_platform_info = platform_info; + actual_platform_info.remove("arch"); + actual_platform_info.remove("acl"); assert_eq!( - platform_info, expected_platform_info, + actual_platform_info, expected_platform_info, "Platform info does not match the expected result" ); } diff --git a/crates/trident/src/telemetry.rs b/crates/trident/src/telemetry.rs index 15f8b7328c..60b01e559b 100644 --- a/crates/trident/src/telemetry.rs +++ b/crates/trident/src/telemetry.rs @@ -14,6 +14,8 @@ pub(crate) mod events { } pub(crate) mod fields { + pub const ACL: &str = "acl"; + pub const ARCH: &str = "arch"; pub const ASSET_ID: &str = "asset_id"; pub const COMMAND: &str = "command"; pub const EXECUTION_TIME: &str = "execution_time"; @@ -28,4 +30,5 @@ pub(crate) mod fields { pub const TOTAL_MEMORY_GIB: &str = "total_memory_gib"; pub const TRIDENT_VERSION: &str = "trident_version"; pub const VALUE: &str = "value"; + pub const VM: &str = "vm"; } diff --git a/docs/Reference/Telemetry.md b/docs/Reference/Telemetry.md new file mode 100644 index 0000000000..cf8a8431ea --- /dev/null +++ b/docs/Reference/Telemetry.md @@ -0,0 +1,153 @@ +--- +sidebar_position: 4 +--- + +# Telemetry + +Trident records enriched metrics and span timings in +`/var/log/trident-metrics.jsonl`, regardless of whether remote telemetry is +enabled. When journald is available, a separate tracing layer records events +and spans under the `trident-tracing` syslog identifier. + +The outputs are not equivalent. The host metadata and correlation IDs +described below are added to JSONL records; they are not automatically +added to journald entries. Retrieve the journald output with: + +``` bash +journalctl -t trident-tracing +``` + +The local metrics file is truncated when a tracing-enabled process starts, +then accumulates that process's records. A daemon can therefore retain +metrics from multiple gRPC requests in one file. `diagnose` preserves and +packages the existing file without initializing this tracing output. + +## Host Metadata + +Every recorded event also includes as much of the following host metadata +as is available at the time: + +- `asset_id`: the host's DMI product UUID (a stable hardware identifier). +- `os_release`: the `VERSION` field from `/etc/os-release`. +- `kernel_version`: the running kernel release (`uname -r`). +- `total_cpu`: the number of CPUs. +- `total_memory_gib`: total memory, in GiB. +- `vm`: whether the host appears to be a virtual machine, detected from DMI + vendor/product strings (`/sys/class/dmi/id/sys_vendor`, + `/sys/class/dmi/id/product_name`). Best-effort: reports `false` if the + DMI files are unreadable or the hypervisor is not one of the recognized + vendors, not necessarily "definitely bare metal". +- `arch`: the CPU architecture Trident is running on, as reported by + `SystemArchitecture` (e.g. `amd64`, `arm64` -- not the kernel's own + `x86_64`/`aarch64` naming). +- `acl`: whether the host is running Azure Container Linux (ACL), as a + string -- `"true"`, `"false"`, or `"unknown"` if detection itself + failed. Best-effort, like `vm` above: an `"unknown"` detection failure + is kept distinct from a known negative, rather than folded into + `"false"`. +- `trident_version`: the running Trident version. +- `installation_id`: an ID that lets separate events be correlated back to + the same host installation over time, including its multiboot + environments. +- `servicing_id`: an ID that lets events emitted across a whole servicing + operation (an install, update, or manual rollback) be correlated with + each other. +- `operation_id`: an ID that lets events emitted during the same command + invocation be correlated with each other. +- `command`: which command produced the event (e.g. `install`, `update`, + `update_stage`, `update_finalize`, `commit`, `rollback`, `rebuild_raid`). +- `source`: which of Trident's entry points produced the event -- `cli` (a + command run directly, without a daemon) or `daemon` (a command the + daemon executed for a gRPC request). A third entry point, `grpc-client` + (the CLI acting as a client, relaying a command to a running daemon), + is defined but not currently wired up to produce this enrichment -- + see `logging::operation_context`'s module doc for why that's not + considered a gap worth closing. + +`command_start` and `trident_start` always omit `installation_id` and +`servicing_id`, even when those IDs are already cached. These startup +events retain `operation_id`, `command`, `source`, and host metadata. +Later events include the persistent IDs when available. + +## Correlation ID Lifecycle + +The four correlation-style fields above have deliberately different +lifetimes -- some outlive many servicing operations, some are recreated on +every reinstall, and some exist only for a single command invocation. The +diagram below shows how each behaves across a representative sequence of +operations: `install`, `commit`, `update`, `commit`, `update-stage`, +`update-finalize`, `commit`, `rollback`, `commit`, `install`, `commit`. + +```mermaid +%%{init: {'gantt': {'displayMode': 'compact', 'leftPadding': 130}}}%% +gantt + dateFormat YYYY-MM-DD + axisFormat + title Correlation ID Lifecycles Across a Servicing Sequence + + section Operations + install :milestone, m1, 2024-01-01, 0d + commit :milestone, m2, 2024-01-02, 0d + update :milestone, m3, 2024-01-03, 0d + commit :milestone, m4, 2024-01-04, 0d + update-stage :milestone, m5, 2024-01-05, 0d + update-finalize :milestone, m6, 2024-01-06, 0d + commit :milestone, m7, 2024-01-07, 0d + rollback :milestone, m8, 2024-01-08, 0d + commit :milestone, m9, 2024-01-09, 0d + install :milestone, m10, 2024-01-10, 0d + commit :milestone, m11, 2024-01-11, 0d + + section operation_id + install :o1, 2024-01-01, 1d + commit :o2, 2024-01-02, 1d + update :o3, 2024-01-03, 1d + commit :o4, 2024-01-04, 1d + update-stage :o5, 2024-01-05, 1d + update-finalize :o6, 2024-01-06, 1d + commit :o7, 2024-01-07, 1d + rollback :o8, 2024-01-08, 1d + commit :o9, 2024-01-09, 1d + install :o10, 2024-01-10, 1d + commit :o11, 2024-01-11, 1d + + section servicing_id + servicing_id (from install) :crit, sid1, 2024-01-01, 2d + servicing_id (from update) :crit, sid2, 2024-01-03, 2d + servicing_id (from update-stage) :crit, sid3, 2024-01-05, 3d + servicing_id (from rollback) :crit, sid4, 2024-01-08, 2d + servicing_id (from install) :crit, sid5, 2024-01-10, 2d + + section installation_id + installation_id #1 (since install #1) :done, inst1, 2024-01-01, 9d + installation_id #2 (since install #2) :done, inst2, 2024-01-10, 2d + + section asset_id + asset_id (never recreated) :active, asset1, 2024-01-01, 11d +``` + +Reading the diagram by row, from most to least stable: + +- **`asset_id`**: identifies the physical machine itself, via its DMI + product UUID. The most stable of the four -- read directly from + hardware rather than the datastore, so it survives every reinstall, + including the second `install` (day 10) that recreates + `installation_id`. +- **`installation_id`**: normally created once at the first `install` + and shared by its multiboot environments. A multiboot install inherits + the running OS's installation ID, persisting it in the staging datastore + and then copying it into the target datastore during finalize. A reused + staging datastore adopts the source ID without resetting servicing state. + An independent reinstall with a new datastore creates a new ID (the + second `install`, day 10, in the diagram). The CIH update-bootstrap path + and migrating a legacy (pre-`installation_id`) datastore can also create + an ID outside of `install`. Existing multiboot partitions are not scanned + to reconcile previously divergent IDs. +- **`servicing_id`**: correlates every event in one servicing episode + (across separate stage/finalize invocations and any later `commit`) + back to whichever invocation actually staged it. Regenerated by every + invocation that stages something new (`install`, `update`, + `update-stage`, `rollback`) -- note `update-finalize` does *not* + regenerate it, since finalize-only invocations only read the value back. +- **`operation_id`**: the shortest-lived of the four, minted fresh for + every single command invocation and never reused.