diff --git a/Cargo.lock b/Cargo.lock index 0ea92d55..79b3f277 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2372,7 +2372,7 @@ dependencies = [ [[package]] name = "omnect-device-service" -version = "0.44.1" +version = "0.45.0" dependencies = [ "actix-server", "actix-web", diff --git a/Cargo.toml b/Cargo.toml index 538ecb62..aec85bde 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -8,7 +8,7 @@ license = "MIT OR Apache-2.0" name = "omnect-device-service" readme = "README.md" repository = "https://github.com/omnect/omnect-device-service.git" -version = "0.44.1" +version = "0.45.0" [dependencies] actix-server = { version = "2.6", default-features = false } diff --git a/README.md b/README.md index 719a795f..d21290ad 100644 --- a/README.md +++ b/README.md @@ -923,6 +923,12 @@ curl -X POST --unix-socket /run/omnect-device-service/api.sock http://localhost/ curl -X POST --unix-socket /run/omnect-device-service/api.sock http://localhost/healthcheck/v1 ``` +Independent of this endpoint, the [healthcheck](healthcheck/) directory contains +scripts that check specific system functions and rate each one green, yellow, or +red. `omnect_health_check.sh` runs the checks configured in +`omnect_health_checks.json` and derives the script name from each entry's type, +so the configuration file lists what a device actually checks. + ### Status updates omnect-device-service is capable to publish certain properties to a list of defined endpoints. Currently the following properties are published: diff --git a/healthcheck/omnect_health__crash_loop.sh b/healthcheck/omnect_health__crash_loop.sh new file mode 100644 index 00000000..2749f996 --- /dev/null +++ b/healthcheck/omnect_health__crash_loop.sh @@ -0,0 +1,73 @@ +#!/bin/sh +# + +. healthchecklib.sh + +# prints crash-looping services to stdout; returns 1 if they cannot be determined +function find_crash_loops() { + local unit props active sub found="" units + + units=$(systemctl list-units --all --type=service --no-legend --plain | awk '{print $1}') + if [ -z "${units}" ]; then + return 1 + fi + + for unit in ${units}; do + props=$(systemctl show "${unit}" -p ActiveState,SubState 2>/dev/null) || continue + active=$(echo "${props}" | sed -n 's/^ActiveState=//p') + sub=$(echo "${props}" | sed -n 's/^SubState=//p') + + # only a live loop is rated red: NRestarts has no time window and keeps + # counting occasional restarts, and a unit that gave up restarting shows + # up as a failed unit in the system-running check + if [ "${active}" = "activating" ]; then + case "${sub}" in + # 'auto-restart-queued' is the same pending restart with the + # restart job already queued + auto-restart|auto-restart-queued) + found="${found} ${unit}(${sub})" + ;; + esac + fi + done + + echo "${found}" +} + +function do_check() { + local found rating=0 + + found=$(find_crash_loops) || rating=2 + [ -z "${found}" ] || rating=2 + print_rating ${rating} crash_loop "$ME" + do_rate ${rating} + return ${rating} +} + +function do_get_infos() { + local found rating=0 error="" + + found=$(find_crash_loops) || { rating=2; error="failed to list services"; } + [ -z "${found}" ] || rating=2 + print_info_header "${ME}" "${rating}" + [ -z "${error}" ] || echo "${error}" + [ -z "${found}" ] || echo "crash-looping services:${found}" + return ${rating} +} + +command="${1:-check}" +[ "$1" ] && shift +check_command_arg "$command" + +case "$command" in + check) + do_check "$@" + retval=$? + ;; + get-infos) + do_get_infos "$@" + retval=$? + ;; +esac + +exit $retval diff --git a/healthcheck/omnect_health__system_running.sh b/healthcheck/omnect_health__system_running.sh index d3149fb2..36ba0c05 100644 --- a/healthcheck/omnect_health__system_running.sh +++ b/healthcheck/omnect_health__system_running.sh @@ -19,9 +19,10 @@ function do_get_infos() { local ret checkit ret=$? - # TODO/FIXME: how to find and show reasons for this state? print_info_header "${ME}" "$ret" - [ $ret = 0 ] || { systemctl is-system-running; systemctl --failed; } + # a state other than "running" comes from failed units or from jobs that + # are still pending + [ $ret = 0 ] || { systemctl is-system-running; systemctl --failed; systemctl list-jobs; } return $ret } diff --git a/healthcheck/omnect_health_checks.json b/healthcheck/omnect_health_checks.json index 53880609..ab00f1cc 100644 --- a/healthcheck/omnect_health_checks.json +++ b/healthcheck/omnect_health_checks.json @@ -42,6 +42,10 @@ "name": "system_running", "type": "system_running" }, + { + "name": "crash_loop", + "type": "crash_loop" + }, { "name": "timesync", "type": "timesync" diff --git a/healthcheck/omnect_health_checks.json.template b/healthcheck/omnect_health_checks.json.template index bc107e99..4c4fafdf 100644 --- a/healthcheck/omnect_health_checks.json.template +++ b/healthcheck/omnect_health_checks.json.template @@ -75,6 +75,10 @@ "name": "system_running", "type": "system_running" }, + { + "name": "crash_loop", + "type": "crash_loop" + }, { "name": "timesync", "type": "timesync" diff --git a/src/systemd/mod.rs b/src/systemd/mod.rs index 7aaead12..730f6bf6 100644 --- a/src/systemd/mod.rs +++ b/src/systemd/mod.rs @@ -3,11 +3,33 @@ pub mod unit; pub mod watchdog; use anyhow::{Context, Result}; -use log::info; +use log::{error, info, warn}; use sd_notify::NotifyState; -use std::sync::Once; -use systemd_zbus::ManagerProxy; -use tokio_stream::StreamExt; +use serde::Deserialize; +use std::{ + future::Future, + mem::Discriminant, + sync::Once, + time::{Duration, Instant}, +}; +use zbus::{proxy::CacheProperties, zvariant::OwnedObjectPath, zvariant::Type}; + +const SYSTEM_STATE_RUNNING: &str = "running"; +const SYSTEM_STATE_DEGRADED: &str = "degraded"; +const ACTIVE_STATE_ACTIVATING: &str = "activating"; +const ACTIVE_STATE_FAILED: &str = "failed"; +const SUB_STATE_AUTO_RESTART: &str = "auto-restart"; +// the same pending restart with the restart job already queued +const SUB_STATE_AUTO_RESTART_QUEUED: &str = "auto-restart-queued"; +const SYSTEM_HEALTHY_POLL_INTERVAL: Duration = Duration::from_secs(2); +// a single poll can land in a restart window in either direction, so a healthy +// and an unhealthy verdict both need this many observations +const HEALTH_CONFIRMATION_POLLS: u32 = 3; +const CRASH_LOOP_RESTART_THRESHOLD_ENV: &str = "CRASH_LOOP_RESTART_THRESHOLD"; +const CRASH_LOOP_RESTART_THRESHOLD_DEFAULT: u32 = 3; +// the unit list ends up in extra_info, which is written to a fixed size pmsg +// record shared by several reboot reasons +const MAX_REPORTED_UNITS: usize = 10; pub fn sd_notify_ready() { static SD_NOTIFY_ONCE: Once = Once::new(); @@ -67,28 +89,1038 @@ pub async fn reboot(reason: &str, extra_info: &str) -> Result<()> { Ok(()) } -pub async fn wait_for_system_running() -> Result<()> { +// ListUnits as returned by systemd, with the states as strings: the typed +// bindings reject a state they do not know, which fails the whole reply, so a +// state a newer systemd adds would break the update validation on every device. +// All fields have to be there to match the signature, only some are read. +#[allow(dead_code)] +#[derive(Debug, Deserialize, Type)] +struct ListedUnit { + name: String, + description: String, + load_state: String, + active_state: String, + sub_state: String, + followed_unit: String, + path: OwnedObjectPath, + queued_job: u32, + job_type: String, + job_path: OwnedObjectPath, +} + +#[zbus::proxy( + interface = "org.freedesktop.systemd1.Manager", + default_service = "org.freedesktop.systemd1", + default_path = "/org/freedesktop/systemd1" +)] +trait SystemdManager { + #[zbus(property)] + fn system_state(&self) -> zbus::Result; + + fn list_units(&self) -> zbus::Result>; +} + +pub async fn wait_for_system_healthy(deadline: Duration) -> Result<()> { let connection = system_connection().await?; - // here we use manager which explicitly doesn't cache the system state - let manager = ManagerProxy::builder(&connection) + // we poll SystemState explicitly; the property cache must not hide changes + let manager = SystemdManagerProxy::builder(&connection) .uncached_properties(&["SystemState"]) .build() .await - .context("wait_for_system_running: failed to create manager")?; + .context("wait_for_system_healthy: failed to create manager")?; + + watch_system_health( + SYSTEM_HEALTHY_POLL_INTERVAL, + deadline, + crash_loop_restart_threshold(), + || poll_system_health(&connection, &manager), + ) + .await +} + +// the poll is injected so the decision can be tested without a system bus +async fn watch_system_health( + poll_interval: Duration, + deadline: Duration, + threshold: u32, + mut poll: F, +) -> Result<()> +where + F: FnMut() -> Fut, + Fut: Future)>>, +{ + let start = Instant::now(); + let mut tally = HealthTally::default(); + let mut same_class_polls = 0u32; + let mut last_class: Option> = None; + let mut last_health: Option = None; + let mut poll_errors = 0u32; + + loop { + match poll().await { + Ok((state, units)) => { + poll_errors = 0; + let health = rate_system_health(&state, &units, threshold); + + let current = std::mem::discriminant(&health); + same_class_polls = if last_class == Some(current) { + same_class_polls + 1 + } else { + 1 + }; + last_class = Some(current); + tally.observe(&health); + + if same_class_polls >= HEALTH_CONFIRMATION_POLLS { + match &health { + SystemHealth::Healthy => return Ok(()), + SystemHealth::Degraded(units) => anyhow::bail!(degraded_extra_info(units)), + SystemHealth::CrashLooping(units) => { + anyhow::bail!(crash_loop_extra_info(units)) + } + // no final verdict, so these keep polling until the deadline + SystemHealth::Restarting(_) | SystemHealth::Starting(_) => {} + } + } + + last_health = Some(health); + } + // a bus that stays broken is a failure, but a single failed poll is + // no observation and must not decide, just like a single unhealthy one + Err(e) => { + poll_errors += 1; + if poll_errors >= HEALTH_CONFIRMATION_POLLS { + // the reboot reason takes the outermost message only, so the + // cause has to be in it + anyhow::bail!("failed to poll system health repeatedly: {e:#}"); + } + warn!("system health poll failed, retrying: {e:#}"); + same_class_polls = 0; + last_class = None; + } + } + + if start.elapsed() >= deadline { + return deadline_verdict(&tally, last_health.as_ref()); + } + + tokio::time::sleep(poll_interval).await; + } +} + +// the verdict once the deadline is reached: an unhealthy tally outweighs the +// last observation, so a system that alternates is not decided by whichever +// poll happened to be last +fn deadline_verdict(tally: &HealthTally, last_health: Option<&SystemHealth>) -> Result<()> { + if let Some(info) = tally.unhealthy_verdict() { + return Err(anyhow::anyhow!("{info}")); + } + + // a healthy observation the tally did not turn into a verdict still speaks + // for the update, whatever state the last poll happened to see + if tally.healthy_polls > 0 { + return Ok(()); + } + + match last_health { + // reaching the crash loop threshold takes threshold x RestartSec, much + // longer than the confirmation polls, so a pending restart is no proof + // of a loop and must not roll back the update + Some(SystemHealth::Restarting(units)) => { + warn!( + "deadline reached while units were still restarting: {}", + report_units(units) + ); + Ok(()) + } + Some(SystemHealth::Starting(state)) => Err(anyhow::anyhow!( + "system not healthy within deadline, last state: {state}" + )), + // an unhealthy observation the tally did not confirm is no basis for a + // rollback + Some(SystemHealth::Healthy | SystemHealth::Degraded(_) | SystemHealth::CrashLooping(_)) => { + Ok(()) + } + // every poll failed + None => Err(anyhow::anyhow!( + "no system health observation within deadline" + )), + } +} - if manager.system_state().await? != "running" { - manager - .receive_system_state_changed() +async fn poll_system_health( + connection: &zbus::Connection, + manager: &SystemdManagerProxy<'_>, +) -> Result<(SystemState, Vec)> { + let state = SystemState::parse( + &manager + .system_state() .await - .filter(|p| p.name() == "running") - .next() - .await; + .context("poll_system_health: failed to get system state")?, + ); + + let units = if matches!(state, SystemState::Other(_)) { + vec![] + } else { + collect_unit_health(connection, manager).await? + }; + + Ok((state, units)) +} + +async fn collect_unit_health( + connection: &zbus::Connection, + manager: &SystemdManagerProxy<'_>, +) -> Result> { + let mut units = vec![]; + + for unit in manager + .list_units() + .await + .context("collect_unit_health: failed to list units")? + { + // a transient per-unit D-Bus error must not abort the validation, so it + // counts as 0 + let n_restarts = if unit.name.ends_with(".service") + && in_restart_cycle(&unit.active_state, &unit.sub_state) + { + service_n_restarts(connection, &unit).await.unwrap_or(0) + } else { + 0 + }; + + units.push(UnitHealth { + name: unit.name, + active_state: unit.active_state, + sub_state: unit.sub_state, + n_restarts, + }); } - Ok(()) + Ok(units) +} + +async fn service_n_restarts(connection: &zbus::Connection, unit: &ListedUnit) -> Result { + Ok(systemd_zbus::ServiceProxy::builder(connection) + .path(unit.path.clone())? + // a single read per poll: the default cache would subscribe to + // PropertiesChanged for this unit and be dropped right after + .cache_properties(CacheProperties::No) + .build() + .await? + .n_restarts() + .await?) } #[cfg(feature = "mock")] pub async fn reboot(_reason: &str, _extra_info: &str) -> Result<()> { Ok(()) } + +// overridable: how many retries are normal varies per deployment +fn crash_loop_restart_threshold() -> u32 { + let mut threshold = CRASH_LOOP_RESTART_THRESHOLD_DEFAULT; + if let Ok(value) = std::env::var(CRASH_LOOP_RESTART_THRESHOLD_ENV) { + match value.parse::() { + // 0 would rate every service in a restart cycle a crash loop + Ok(0) | Err(_) => error!( + "ignore invalid crash loop restart threshold {value} and use default {threshold}" + ), + Ok(value) => threshold = value, + }; + } + threshold +} + +#[derive(Debug, Clone, PartialEq)] +struct UnitHealth { + name: String, + active_state: String, + sub_state: String, + n_restarts: u32, +} + +// the systemd system states this check distinguishes +#[derive(Debug, PartialEq)] +enum SystemState { + Running, + Degraded, + Other(String), +} + +impl SystemState { + fn parse(state: &str) -> Self { + match state { + SYSTEM_STATE_RUNNING => Self::Running, + SYSTEM_STATE_DEGRADED => Self::Degraded, + other => Self::Other(other.to_string()), + } + } +} + +#[derive(Debug, PartialEq)] +enum SystemHealth { + Healthy, + Starting(String), + Restarting(Vec), + Degraded(Vec), + CrashLooping(Vec), +} + +#[derive(Default)] +struct CauseTally { + polls: u32, + last_info: Option, +} + +impl CauseTally { + fn observe(&mut self, info: String) { + self.polls += 1; + self.last_info = Some(info); + } +} + +// all observations of a wait; only healthy and unhealthy ones carry a verdict, +// a starting or restarting system says nothing yet +#[derive(Default)] +struct HealthTally { + healthy_polls: u32, + degraded: CauseTally, + crash_looping: CauseTally, +} + +impl HealthTally { + fn observe(&mut self, health: &SystemHealth) { + match health { + SystemHealth::Healthy => self.healthy_polls += 1, + SystemHealth::Degraded(units) => self.degraded.observe(degraded_extra_info(units)), + SystemHealth::CrashLooping(units) => { + self.crash_looping.observe(crash_loop_extra_info(units)) + } + SystemHealth::Restarting(_) | SystemHealth::Starting(_) => {} + } + } + + fn unhealthy_polls(&self) -> u32 { + self.degraded.polls + self.crash_looping.polls + } + + // an unhealthy verdict needs as many observations as a confirmed one, only + // not consecutive; without a single healthy observation there is nothing + // that speaks for the update, so one unhealthy observation is enough + fn unhealthy_verdict(&self) -> Option<&str> { + let unhealthy = self.unhealthy_polls(); + if unhealthy == 0 || (unhealthy < HEALTH_CONFIRMATION_POLLS && self.healthy_polls > 0) { + return None; + } + + // the count decides that the system is unhealthy, so the reported cause + // is the one it counted most often; an equal count reports the crash + // loop, the more specific of the two + let cause = if self.crash_looping.polls >= self.degraded.polls { + &self.crash_looping + } else { + &self.degraded + }; + cause.last_info.as_deref() + } +} + +// systemd parks a unit in the auto-restart sub state between a failed start and +// the next attempt, so only there is a restart pending; a normal start, and a +// unit that recovered or gave up, is not +fn in_restart_cycle(active_state: &str, sub_state: &str) -> bool { + active_state == ACTIVE_STATE_ACTIVATING + && matches!( + sub_state, + SUB_STATE_AUTO_RESTART | SUB_STATE_AUTO_RESTART_QUEUED + ) +} + +fn restart_cycle_units(units: &[UnitHealth], matches: impl Fn(u32) -> bool) -> Vec { + let mut names: Vec = units + .iter() + .filter(|u| in_restart_cycle(&u.active_state, &u.sub_state) && matches(u.n_restarts)) + .map(|u| u.name.clone()) + .collect(); + names.sort(); + names +} + +fn crash_looping_units(units: &[UnitHealth], threshold: u32) -> Vec { + restart_cycle_units(units, |n_restarts| n_restarts >= threshold) +} + +fn restarting_units(units: &[UnitHealth], threshold: u32) -> Vec { + restart_cycle_units(units, |n_restarts| (1..threshold).contains(&n_restarts)) +} + +fn failed_units(units: &[UnitHealth]) -> Vec { + let mut failed: Vec = units + .iter() + .filter(|u| u.active_state == ACTIVE_STATE_FAILED) + .map(|u| u.name.clone()) + .collect(); + failed.sort(); + failed +} + +fn rate_system_health(state: &SystemState, units: &[UnitHealth], threshold: u32) -> SystemHealth { + if let SystemState::Other(state) = state { + return SystemHealth::Starting(state.clone()); + } + + let looping = crash_looping_units(units, threshold); + if !looping.is_empty() { + return SystemHealth::CrashLooping(looping); + } + + if *state == SystemState::Degraded { + let failed = failed_units(units); + return if failed.is_empty() { + // the state was read before the unit list, so the failed unit may + // already be gone; without a name there is nothing to report + SystemHealth::Starting(SYSTEM_STATE_DEGRADED.to_string()) + } else { + SystemHealth::Degraded(failed) + }; + } + + let restarting = restarting_units(units, threshold); + if !restarting.is_empty() { + return SystemHealth::Restarting(restarting); + } + + SystemHealth::Healthy +} + +fn report_units(units: &[String]) -> String { + if units.len() <= MAX_REPORTED_UNITS { + return units.join(" "); + } + + format!( + "{} (+{} more)", + units[..MAX_REPORTED_UNITS].join(" "), + units.len() - MAX_REPORTED_UNITS + ) +} + +fn degraded_extra_info(units: &[String]) -> String { + format!("system degraded, failed units: {}", report_units(units)) +} + +fn crash_loop_extra_info(units: &[String]) -> String { + format!("crash-looping units: {}", report_units(units)) +} + +#[cfg(test)] +mod tests { + use super::*; + + // the sub state is only read for the restart cycle, so it follows the active + // state here; a unit in a restart cycle comes from restart_cycle_unit() + fn unit(name: &str, active_state: &str, n_restarts: u32) -> UnitHealth { + let sub_state = match active_state { + "active" => "running", + ACTIVE_STATE_ACTIVATING => "start", + other => other, + }; + UnitHealth { + name: name.to_string(), + active_state: active_state.to_string(), + sub_state: sub_state.to_string(), + n_restarts, + } + } + + fn restart_cycle_unit(name: &str, sub_state: &str, n_restarts: u32) -> UnitHealth { + UnitHealth { + name: name.to_string(), + active_state: ACTIVE_STATE_ACTIVATING.to_string(), + sub_state: sub_state.to_string(), + n_restarts, + } + } + + fn names(names: &[&str]) -> Vec { + names.iter().map(|n| n.to_string()).collect() + } + + // tests share the process, so a failing assert must not leave the variable + // behind for whatever test runs next + struct EnvVarGuard { + key: &'static str, + previous: Option, + } + + impl EnvVarGuard { + fn new(key: &'static str, value: &str) -> Self { + let guard = Self { + key, + previous: std::env::var(key).ok(), + }; + guard.set(value); + guard + } + + fn set(&self, value: &str) { + crate::common::set_env_var(self.key, value); + } + } + + impl Drop for EnvVarGuard { + fn drop(&mut self) { + match &self.previous { + Some(value) => crate::common::set_env_var(self.key, value), + None => crate::common::remove_env_var(self.key), + } + } + } + + type ScriptedPoll = Result<(SystemState, Vec)>; + + const POLL_ERROR: &str = "system bus is gone"; + + // drives the decision loop over a scripted poll sequence; an exhausted + // script is an error, so a test can prove the loop did not stop early + async fn watch(script: Vec, deadline: Duration) -> (Result<()>, usize) { + let mut script = script.into_iter(); + let mut polls = 0usize; + let result = watch_system_health( + Duration::ZERO, + deadline, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT, + || { + polls += 1; + std::future::ready( + script + .next() + .unwrap_or_else(|| Err(anyhow::anyhow!("poll script exhausted"))), + ) + }, + ) + .await; + (result, polls) + } + + fn healthy_poll() -> ScriptedPoll { + Ok((SystemState::Running, vec![unit("a.service", "active", 0)])) + } + + fn degraded_poll() -> ScriptedPoll { + Ok(( + SystemState::Degraded, + vec![unit("a.service", ACTIVE_STATE_FAILED, 0)], + )) + } + + fn crash_loop_poll() -> ScriptedPoll { + Ok(( + SystemState::Running, + vec![restart_cycle_unit( + "loop.service", + SUB_STATE_AUTO_RESTART, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT, + )], + )) + } + + fn restarting_poll() -> ScriptedPoll { + Ok(( + SystemState::Running, + vec![restart_cycle_unit( + "loop.service", + SUB_STATE_AUTO_RESTART, + 1, + )], + )) + } + + fn failed_poll() -> ScriptedPoll { + Err(anyhow::anyhow!(POLL_ERROR)) + } + + // the reply is only deserializable if the struct matches what ListUnits + // returns: a(ssssssouso) + #[test] + fn listed_unit_matches_the_list_units_signature() { + assert_eq!(ListedUnit::SIGNATURE.to_string(), "(ssssssouso)"); + } + + // a state this check does not rate must stay uninteresting instead of + // failing the poll, which is why the states are read as strings + #[test] + fn an_unrated_state_is_healthy() { + let units = vec![unit("a.service", "refreshing", 5)]; + assert_eq!( + rate_system_health( + &SystemState::Running, + &units, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::Healthy + ); + } + + #[test] + fn healthy_when_running_without_crash_loops() { + let units = vec![unit("a.service", "active", 0)]; + assert_eq!( + rate_system_health( + &SystemState::Running, + &units, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::Healthy + ); + } + + #[test] + fn non_final_states_keep_polling() { + assert_eq!( + rate_system_health( + &SystemState::parse("initializing"), + &[], + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::Starting("initializing".to_string()) + ); + } + + #[test] + fn degraded_lists_failed_units_sorted() { + let units = vec![ + unit("b.service", ACTIVE_STATE_FAILED, 0), + unit("a.service", ACTIVE_STATE_FAILED, 0), + ]; + assert_eq!( + rate_system_health( + &SystemState::Degraded, + &units, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::Degraded(names(&["a.service", "b.service"])) + ); + } + + #[test] + fn degraded_lists_failed_non_service_units() { + let units = vec![unit("data.mount", ACTIVE_STATE_FAILED, 0)]; + assert_eq!( + rate_system_health( + &SystemState::Degraded, + &units, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::Degraded(names(&["data.mount"])) + ); + } + + // the state is read before the unit list, so the failed unit can be gone by + // then and there is nothing to name in the reboot reason + #[test] + fn degraded_without_failed_units_keeps_polling() { + let units = vec![unit("a.service", "active", 0)]; + assert_eq!( + rate_system_health( + &SystemState::Degraded, + &units, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::Starting(SYSTEM_STATE_DEGRADED.to_string()) + ); + } + + // the threshold takes threshold x RestartSec to be reached, which is longer + // than the confirmation polls take, so health must not be confirmed while a + // restart is pending + #[test] + fn restart_below_threshold_is_not_yet_healthy() { + for n_restarts in 1..CRASH_LOOP_RESTART_THRESHOLD_DEFAULT { + let units = vec![restart_cycle_unit( + "loop.service", + SUB_STATE_AUTO_RESTART, + n_restarts, + )]; + assert_eq!( + rate_system_health( + &SystemState::Running, + &units, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::Restarting(names(&["loop.service"])), + "{n_restarts} restarts should keep the check polling" + ); + } + } + + #[test] + fn system_without_restarts_is_healthy() { + let units = vec![ + unit("a.service", "active", 0), + unit("b.timer", "inactive", 0), + ]; + assert_eq!( + rate_system_health( + &SystemState::Running, + &units, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::Healthy + ); + } + + #[test] + fn restart_threshold_is_a_crash_loop() { + let units = vec![restart_cycle_unit( + "loop.service", + SUB_STATE_AUTO_RESTART, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT, + )]; + assert_eq!( + rate_system_health( + &SystemState::Running, + &units, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::CrashLooping(names(&["loop.service"])) + ); + } + + // a queued restart is the same pending restart, newer systemd reports it as + // its own sub state + #[test] + fn a_queued_restart_is_a_crash_loop() { + let units = vec![restart_cycle_unit( + "loop.service", + SUB_STATE_AUTO_RESTART_QUEUED, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT, + )]; + assert_eq!( + rate_system_health( + &SystemState::Running, + &units, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::CrashLooping(names(&["loop.service"])) + ); + } + + // 'activating' is also a normal start, e.g. by a timer or a dependency; a + // restart history must not keep the check polling then + #[test] + fn a_normal_start_with_restart_history_is_healthy() { + let units = vec![unit("a.service", ACTIVE_STATE_ACTIVATING, 5)]; + assert_eq!( + rate_system_health( + &SystemState::Running, + &units, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::Healthy + ); + } + + #[test] + fn custom_threshold_is_honored() { + let units = vec![restart_cycle_unit( + "loop.service", + SUB_STATE_AUTO_RESTART, + 1, + )]; + assert_eq!( + rate_system_health(&SystemState::Running, &units, 1), + SystemHealth::CrashLooping(names(&["loop.service"])) + ); + } + + #[test] + fn zero_threshold_falls_back_to_default() { + let env = EnvVarGuard::new(CRASH_LOOP_RESTART_THRESHOLD_ENV, "0"); + assert_eq!( + crash_loop_restart_threshold(), + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ); + env.set("5"); + assert_eq!(crash_loop_restart_threshold(), 5); + } + + #[test] + fn recovered_unit_with_restart_history_is_not_a_crash_loop() { + let units = vec![unit("a.service", "active", 5)]; + assert_eq!( + rate_system_health( + &SystemState::Running, + &units, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::Healthy + ); + } + + // a unit that gave up restarting is a failed unit, which the degraded state + // already reports, so it must not be counted as a loop + #[test] + fn unit_that_gave_up_restarting_is_not_a_crash_loop() { + let units = vec![unit("loop.service", ACTIVE_STATE_FAILED, 5)]; + assert_eq!( + rate_system_health( + &SystemState::Degraded, + &units, + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT + ), + SystemHealth::Degraded(names(&["loop.service"])) + ); + } + + #[test] + fn unparseable_threshold_falls_back_to_default() { + let env = EnvVarGuard::new(CRASH_LOOP_RESTART_THRESHOLD_ENV, ""); + for value in ["", "no", "-1"] { + env.set(value); + assert_eq!( + crash_loop_restart_threshold(), + CRASH_LOOP_RESTART_THRESHOLD_DEFAULT, + "\"{value}\" should fall back to the default" + ); + } + } + + #[test] + fn reported_units_are_capped() { + let units: Vec = (0..MAX_REPORTED_UNITS + 3) + .map(|i| format!("u{i}.service")) + .collect(); + let reported = report_units(&units); + assert!(reported.ends_with("(+3 more)"), "{reported}"); + assert_eq!(reported.matches(".service").count(), MAX_REPORTED_UNITS); + } + + // exact strings are a contract with omnect-os CI + // (TEST_REBOOT_REASON_CHECK_EXTRA_INFO does an exact match) + #[test] + fn extra_info_strings_match_ci_contract() { + assert_eq!( + degraded_extra_info(&["dummy-failed.service".to_string()]), + "system degraded, failed units: dummy-failed.service" + ); + assert_eq!( + crash_loop_extra_info(&["dummy-crash-loop.service".to_string()]), + "crash-looping units: dummy-crash-loop.service" + ); + } + + #[tokio::test(flavor = "multi_thread")] + async fn health_is_confirmed_by_consecutive_polls() { + let script = (0..HEALTH_CONFIRMATION_POLLS) + .map(|_| healthy_poll()) + .collect(); + let (result, polls) = watch(script, Duration::from_secs(60)).await; + result.expect("healthy system should validate"); + assert_eq!(polls, HEALTH_CONFIRMATION_POLLS as usize); + } + + #[tokio::test(flavor = "multi_thread")] + async fn fewer_healthy_polls_do_not_confirm() { + let script = (0..HEALTH_CONFIRMATION_POLLS - 1) + .map(|_| healthy_poll()) + .collect(); + let (result, _) = watch(script, Duration::from_secs(60)).await; + assert!(result.is_err(), "health confirmed too early"); + } + + // one poll can land between a unit failing and something restarting it, so a + // single observation must not roll back the update + #[tokio::test(flavor = "multi_thread")] + async fn single_degraded_poll_does_not_roll_back() { + let mut script = vec![degraded_poll()]; + script.extend((0..HEALTH_CONFIRMATION_POLLS).map(|_| healthy_poll())); + let (result, _) = watch(script, Duration::from_secs(60)).await; + result.expect("a single degraded poll should not fail the validation"); + } + + #[tokio::test(flavor = "multi_thread")] + async fn confirmed_degraded_rolls_back_with_the_failed_units() { + let script = (0..HEALTH_CONFIRMATION_POLLS) + .map(|_| degraded_poll()) + .collect(); + let (result, _) = watch(script, Duration::from_secs(60)).await; + assert_eq!( + result.expect_err("degraded system should fail").to_string(), + degraded_extra_info(&names(&["a.service"])) + ); + } + + #[tokio::test(flavor = "multi_thread")] + async fn confirmed_crash_loop_rolls_back_with_the_looping_units() { + let script = (0..HEALTH_CONFIRMATION_POLLS) + .map(|_| crash_loop_poll()) + .collect(); + let (result, _) = watch(script, Duration::from_secs(60)).await; + assert_eq!( + result.expect_err("crash loop should fail").to_string(), + crash_loop_extra_info(&names(&["loop.service"])) + ); + } + + fn tally(observations: &[SystemHealth]) -> HealthTally { + let mut tally = HealthTally::default(); + for health in observations { + tally.observe(health); + } + tally + } + + fn degraded() -> SystemHealth { + SystemHealth::Degraded(names(&["a.service"])) + } + + #[test] + fn unconfirmed_unhealthy_polls_do_not_decide_the_deadline() { + for unhealthy in 1..HEALTH_CONFIRMATION_POLLS { + let mut observations = vec![SystemHealth::Healthy]; + observations.extend((0..unhealthy).map(|_| degraded())); + assert_eq!( + tally(&observations).unhealthy_verdict(), + None, + "{unhealthy} degraded polls should not outweigh a healthy one" + ); + } + } + + // the deadline verdict must not depend on which poll happened to be last + #[test] + fn repeated_unhealthy_polls_decide_the_deadline() { + let mut observations: Vec = (0..HEALTH_CONFIRMATION_POLLS) + .flat_map(|_| [SystemHealth::Healthy, degraded()]) + .collect(); + for last_health in [SystemHealth::Healthy, degraded()] { + assert_eq!( + deadline_verdict(&tally(&observations), Some(&last_health)) + .expect_err("an alternating system should fail") + .to_string(), + degraded_extra_info(&names(&["a.service"])) + ); + observations.push(last_health); + } + } + + // the count and the reported cause must agree: what was seen most often + #[test] + fn the_cause_seen_most_often_is_reported() { + let observations = [ + SystemHealth::Healthy, + degraded(), + SystemHealth::CrashLooping(names(&["loop.service"])), + degraded(), + ]; + assert_eq!( + tally(&observations).unhealthy_verdict(), + Some(degraded_extra_info(&names(&["a.service"])).as_str()) + ); + } + + // without a healthy observation there is nothing that speaks for the update + #[test] + fn a_single_unhealthy_poll_decides_a_deadline_without_healthy_polls() { + assert_eq!( + deadline_verdict(&tally(&[degraded()]), Some(°raded())) + .expect_err("a system that was never healthy should fail") + .to_string(), + degraded_extra_info(&names(&["a.service"])) + ); + } + + // a system that was up before must not be rolled back because the last poll + // saw a state the check does not rate, e.g. degraded without a name to report + #[test] + fn a_healthy_poll_survives_an_unrated_last_observation() { + let unrated = SystemHealth::Starting(SYSTEM_STATE_DEGRADED.to_string()); + deadline_verdict(&tally(&[SystemHealth::Healthy]), Some(&unrated)) + .expect("a healthy observation should still count at the deadline"); + } + + #[test] + fn unconfirmed_degraded_at_the_deadline_does_not_roll_back() { + let observations = [SystemHealth::Healthy, degraded()]; + deadline_verdict(&tally(&observations), Some(°raded())) + .expect("a single degraded poll is no basis for a rollback"); + } + + // alternating failures never confirm one class, so only the deadline ends the + // wait - it must not poll forever + #[tokio::test(flavor = "multi_thread")] + async fn alternating_failures_end_at_the_deadline() { + let script = vec![degraded_poll(), crash_loop_poll()]; + let (result, polls) = watch(script, Duration::ZERO).await; + assert!(result.is_err()); + assert_eq!( + polls, 1, + "the deadline should end the wait on the first poll" + ); + } + + #[tokio::test(flavor = "multi_thread")] + async fn pending_restart_at_the_deadline_is_accepted() { + let (result, _) = watch(vec![restarting_poll()], Duration::ZERO).await; + result.expect("a pending restart is no proof of a crash loop"); + } + + // a bus hiccup while the system is still booting is a single observation + // like any other and must not roll back the update + #[tokio::test(flavor = "multi_thread")] + async fn a_failed_poll_does_not_end_the_wait() { + let mut script = vec![failed_poll()]; + script.extend((0..HEALTH_CONFIRMATION_POLLS).map(|_| healthy_poll())); + let (result, _) = watch(script, Duration::from_secs(60)).await; + result.expect("a single failed poll should not fail the validation"); + } + + #[tokio::test(flavor = "multi_thread")] + async fn repeatedly_failed_polls_end_the_wait() { + let script = (0..HEALTH_CONFIRMATION_POLLS) + .map(|_| failed_poll()) + .collect(); + let (result, polls) = watch(script, Duration::from_secs(60)).await; + let error = result.expect_err("a broken bus should fail the validation"); + // the cause has to be in the message the reboot reason takes + assert_eq!( + error.to_string(), + format!("failed to poll system health repeatedly: {POLL_ERROR}") + ); + assert_eq!(polls, HEALTH_CONFIRMATION_POLLS as usize); + } + + // a failed poll is no observation, so the confirmation starts over + #[tokio::test(flavor = "multi_thread")] + async fn a_failed_poll_breaks_the_confirmation() { + let mut script = vec![healthy_poll(), healthy_poll(), failed_poll()]; + script.extend((0..HEALTH_CONFIRMATION_POLLS).map(|_| healthy_poll())); + let (result, polls) = watch(script, Duration::from_secs(60)).await; + result.expect("healthy system should validate"); + assert_eq!(polls, 3 + HEALTH_CONFIRMATION_POLLS as usize); + } + + #[test] + fn a_deadline_without_any_observation_fails() { + assert_eq!( + deadline_verdict(&HealthTally::default(), None) + .expect_err("a wait without an observation should fail") + .to_string(), + "no system health observation within deadline" + ); + } + + #[tokio::test(flavor = "multi_thread")] + async fn still_starting_at_the_deadline_fails() { + let script = vec![Ok((SystemState::parse("initializing"), vec![]))]; + let (result, _) = watch(script, Duration::ZERO).await; + assert_eq!( + result + .expect_err("a system that never starts should fail") + .to_string(), + "system not healthy within deadline, last state: initializing" + ); + } +} diff --git a/src/twin/firmware_update/update_validation.md b/src/twin/firmware_update/update_validation.md index 6bc443c7..e4c63954 100644 --- a/src/twin/firmware_update/update_validation.md +++ b/src/twin/firmware_update/update_validation.md @@ -9,7 +9,9 @@ After flashing an update to the new root partition, the device boots this partit The following checks must be passed in order to successfully validate an update: - omnect-device-service.service status is in state [running](https://www.freedesktop.org/software/systemd/man/latest/systemctl.html#status%20PATTERN%E2%80%A6%7CPID%E2%80%A6%5D) -- system is in state [running](https://www.freedesktop.org/software/systemd/man/latest/systemctl.html#is-system-running) +- system is in state [running](https://www.freedesktop.org/software/systemd/man/latest/systemctl.html#is-system-running) and no service is in a crash loop + (repeatedly restarting without staying active); a `degraded` system + state fails the validation - in case local update is **NOT** [configured](#local-validation) - adu-agent could be started successfully - omnect-device-service is connected to iothub (successfully provisioned) @@ -41,11 +43,42 @@ The following checks must be passed in order to successfully validate an update: - timeout used internally by omnect-device-service - the timeout is canceled as soon as initialization completed and (if configured) iothub connection is established +#### System health deadline + +- the system state is polled until the deadline, which is the remaining + validation time minus a safety margin; healthy and unhealthy both need several + observations, so a single poll landing in a restart window decides nothing +- a service in a restart cycle below the crash loop threshold keeps the check + polling, since it can still reach the threshold +- before the deadline a verdict needs consecutive observations of one kind +- a failed poll is no observation: the wait keeps polling and only gives up when + the same number of polls fails in a row. If the deadline comes first and no poll + ever succeeded, validation fails without a system state to report +- at the deadline all unhealthy observations of the wait count, consecutive or + not: validation fails once they reach the same number, or if no poll was + healthy at all. The reported cause is the one with the most observations +- otherwise one healthy observation is enough to succeed, whatever the last poll + saw, because a rollback needs evidence +- without any healthy observation the last one decides: a system that is still + starting fails, a restart pending below the threshold succeeds +- when the remaining validation time is at or below the safety margin the + deadline is zero. The first observation then decides by the rules above, and + since no poll was healthy yet a single unhealthy one fails the validation +- on a failed validation the reboot reason `swupdate-validation-failed` is + logged with the cause as extra info: the failed units, the crash-looping + units, the last system state, or why the polls failed + #### Global timeout - defined in [update-validation-observer.timer](../../../systemd/update-validation-observer.timer) - reboots the system if /run/omnect-device-service/omnect_validate_update isn't deleted by omnect-device-service in time +### Crash loop detection + +- configurable via environment variable `CRASH_LOOP_RESTART_THRESHOLD` (default 3, must be >= 1) +- a unit counts as crash-looping after this many restarts while it is still in a + restart cycle + ### Local validation In `/var/lib/omnect-device-service/update_validation_conf.json` it can be configured, if the update validation happens in a local environment, where no connection to the iothub is present. (if the file doesn't exist `"local": false` is assumed): diff --git a/src/twin/firmware_update/update_validation.rs b/src/twin/firmware_update/update_validation.rs index 89a4256d..af1567f7 100644 --- a/src/twin/firmware_update/update_validation.rs +++ b/src/twin/firmware_update/update_validation.rs @@ -8,7 +8,12 @@ use anyhow::{Context, Result}; use log::{debug, error, info, warn}; use serde::{Deserialize, Serialize}; use serde_json::json; -use std::{env, fs, path::Path, sync::Arc, time::SystemTime}; +use std::{ + env, fs, + path::Path, + sync::Arc, + time::{Instant, SystemTime}, +}; use tokio::{ sync::{RwLock, oneshot}, time::{Duration, timeout}, @@ -23,6 +28,14 @@ static UPDATE_VALIDATION_COMPLETE_BARRIER_FILE: &str = static UPDATE_VALIDATION_FAILED_FILE: &str = "/run/omnect-device-service/omnect_validate_update_failed"; static UPDATE_VALIDATION_TIMEOUT_IN_SECS_DEFAULT: u64 = 300; +static SYSTEM_HEALTHY_DEADLINE_MARGIN_IN_SECS: u64 = 30; + +// validation only starts after authentication, so the health check gets the +// time that is actually left: the margin keeps its descriptive error ahead of +// the generic validation timeout, which decides the reboot reason +fn health_deadline(remaining: Duration) -> Duration { + remaining.saturating_sub(Duration::from_secs(SYSTEM_HEALTHY_DEADLINE_MARGIN_IN_SECS)) +} #[derive(Clone, Debug, Default, Serialize)] enum UpdateValidationStatus { @@ -145,15 +158,13 @@ impl UpdateValidation { Ok(()) } - async fn validate(local_update: bool) -> Result<()> { + async fn validate(local_update: bool, deadline: Instant) -> Result<()> { debug!("validate update"); - systemd::wait_for_system_running().await?; + let remaining = deadline.saturating_duration_since(Instant::now()); + systemd::wait_for_system_healthy(health_deadline(remaining)).await?; - /* ToDo: if it returns with an error, we may want to handle the state - * "degraded" and possibly ignore certain failed services via configuration - */ - info!("system is running"); + info!("system is healthy"); // remove iot-hub-device-service barrier file and start service as part of validation debug!("starting {IOT_HUB_DEVICE_UPDATE_SERVICE}"); @@ -225,6 +236,9 @@ impl UpdateValidation { .deadline_timestamp .duration_since(SystemTime::now()) .context("failed to build remaining timeout secs")?; + // the timeout below is monotonic, so the health deadline must be too: + // a clock step during boot must not shorten it + let deadline = Instant::now() + remaining_time; let status = Arc::clone(&self.status); let local_update = self.local_update; self.tx_cancel_timer = Some(tx_cancel_timer); @@ -238,7 +252,7 @@ impl UpdateValidation { return Ok(()); } - Self::validate(local_update).await?; + Self::validate(local_update, deadline).await?; Self::finalize(status).await }; @@ -301,6 +315,37 @@ mod tests { use crate::bootloader_env::TEST_LOCK as BOOTARGS_TEST_LOCK; + #[test] + fn health_deadline_keeps_margin_to_validation_timeout() { + let remaining = Duration::from_secs(UPDATE_VALIDATION_TIMEOUT_IN_SECS_DEFAULT); + assert_eq!( + health_deadline(remaining), + remaining - Duration::from_secs(SYSTEM_HEALTHY_DEADLINE_MARGIN_IN_SECS) + ); + } + + #[test] + fn health_deadline_without_slack_is_zero() { + assert_eq!( + health_deadline(Duration::from_secs(SYSTEM_HEALTHY_DEADLINE_MARGIN_IN_SECS)), + Duration::ZERO + ); + assert_eq!(health_deadline(Duration::ZERO), Duration::ZERO); + } + + // a low configured timeout must not produce a deadline beyond it, else the + // generic timeout wins the race and the reboot reason loses the cause + #[test] + fn health_deadline_never_exceeds_remaining_time() { + for secs in [1, 10, SYSTEM_HEALTHY_DEADLINE_MARGIN_IN_SECS, 90, 1200] { + let remaining = Duration::from_secs(secs); + assert!( + health_deadline(remaining) < remaining || remaining.is_zero(), + "deadline for {secs}s remaining is not shorter than the remaining time" + ); + } + } + #[test] fn finalize_bootargs_noargs_sentinel_unsets_both_keys() { let _lock = BOOTARGS_TEST_LOCK.lock().unwrap();