crates/monetize-server/src/estate_order/install_why.rs
//! **Why an install makes no progress** (test3-holger-rs 2026-10-22: the site said "installing
//! (installing)" for 40+ minutes with no reason, while its main sat at `TICK stage=pairing`
//! waiting for a console login the shop no longer fed).
//!
//! While a run is `installing`, each laid box's pair status (`pairing/status.toml`, the
//! installer's last word per box) is watched for PROGRESS: a change of its tunnel, join, role,
//! step or PAIRED — a retry of the same step is no progress. Kept per run in
//! `<run>/`[`PROGRESS_FILE`] (the step each box stands at, and since when), so a restart of the
//! ONE box does not reset the clock.
//!
//! * After [`WHY_AFTER_MS`] (10 min) at one step, the operator's status says why, by name: the
//! stage, the box, since when, and the box's last wait line (holger-live `waits`: `WAITING …
//! since …`) out of its install log — or that its log says nothing readable.
//! * After [`ALERT_AFTER_MS`] (20 min), a CODE RED (`install-stall:<company>`), said as `ALERT
//! code-red` (the alert mail), on every console page; cleared when the install moves on.
//!
//! Generic: nothing here names a product.
use std::collections::BTreeMap;
use std::path::Path;
use super::{phase, EstateRun, PAIRING_DIR, PAIR_STATUS_FILE};
use crate::estate_order::setup_log::PAIRING_LOGS;
use crate::state::AppState;
/// An install at one step this long gets a Why.
pub const WHY_AFTER_MS: u64 = 10 * 60_000;
/// An install at one step this long raises a CODE RED.
pub const ALERT_AFTER_MS: u64 = 20 * 60_000;
/// Each box's step and since when, beside the run.
pub const PROGRESS_FILE: &str = "install-progress.json";
/// The CODE RED key's head.
pub const RED_PREFIX: &str = "install-stall:";
/// How much of a box's install log is read for its last wait line.
const LOG_TAIL_BYTES: u64 = 256 * 1024;
/// Where one box stood, and since when (`now` of the first look that saw it there).
#[derive(Clone, Debug, Default, PartialEq, Eq, serde::Serialize, serde::Deserialize)]
pub struct Seen {
pub at: String,
pub since_ms: u64,
}
/// One laid box as the installer last saw it.
#[derive(Clone, Debug, Default, PartialEq, Eq)]
pub struct BoxNow {
pub role: String,
/// Its last pair status line (empty: none yet).
pub signal: String,
/// What its pair status says it does, in the installer's words (`step serve (try 81: …)`).
pub step: String,
/// Its last wait line, or what its log says instead.
pub wait: Option<String>,
}
/// A box that has made no progress.
#[derive(Clone, Debug, PartialEq, Eq)]
pub struct Stall {
pub role: String,
pub since_ms: u64,
pub step: String,
pub wait: Option<String>,
}
/// Pure: **where a pair status line stands** — its parts with a step's retry text cut
/// (`step serve (try 81: …)` → `step serve`): a retry is no progress.
pub fn standing(signal: &str) -> String {
signal.split(" · ").map(|p| if p.starts_with("step ") { p.split(" (try").next().unwrap_or(p) } else { p }).map(str::trim).collect::<Vec<_>>().join(" · ")
}
fn paired(signal: &str) -> bool {
signal.trim_end().ends_with("PAIRED")
}
/// Pure: **the boxes as `status.toml` says them**, each with its last wait line from `wait_of`.
pub fn boxes_of(status_toml: &str, roles: &[&str], wait_of: &dyn Fn(&str) -> Option<String>) -> Vec<BoxNow> {
let table: toml::Table = toml::from_str(status_toml).unwrap_or_default();
roles
.iter()
.map(|role| {
let signal = table.get(*role).and_then(|v| v.get("signal")).and_then(toml::Value::as_str).map(str::trim).unwrap_or_default().to_string();
let step = super::unpaired_words(status_toml, &[role]).map(|w| w.strip_prefix(&format!("{role}: ")).map(str::to_string).unwrap_or(w)).unwrap_or_default();
BoxNow { role: role.to_string(), signal, step, wait: wait_of(role) }
})
.collect()
}
/// Pure: **`seen` brought up to `now_ms`**: a box whose standing moved is seen there from now.
/// `true` when anything changed (the file is written then).
pub fn observe(seen: &mut BTreeMap<String, Seen>, boxes: &[BoxNow], now_ms: u64) -> bool {
let mut changed = false;
for b in boxes {
let at = standing(&b.signal);
match seen.get(&b.role) {
Some(s) if s.at == at => {}
_ => {
seen.insert(b.role.clone(), Seen { at, since_ms: now_ms });
changed = true;
}
}
}
changed
}
/// Pure: **the boxes stalled at `now_ms`** — not PAIRED, at one standing for [`WHY_AFTER_MS`] or
/// more (never counted from before the install began, `installing_since_ms`).
pub fn stalls(installing_since_ms: u64, boxes: &[BoxNow], seen: &BTreeMap<String, Seen>, now_ms: u64) -> Vec<Stall> {
boxes
.iter()
.filter(|b| !paired(&b.signal))
.filter_map(|b| {
let since = seen.get(&b.role).map(|s| s.since_ms).unwrap_or(now_ms).max(installing_since_ms);
(now_ms.saturating_sub(since) >= WHY_AFTER_MS).then(|| Stall {
role: b.role.clone(),
since_ms: since,
step: if b.step.is_empty() { "no pair status reported yet".to_string() } else { b.step.clone() },
wait: b.wait.clone(),
})
})
.collect()
}
/// Pure: `ms` as `HH:MMZ` (UTC).
pub fn hm_utc(ms: u64) -> String {
let s = ms / 1_000 % 86_400;
format!("{:02}:{:02}Z", s / 3_600, s % 3_600 / 60)
}
/// Pure: a wait line with its running count cut (`… since 18:12:05Z (12 min so far)` →
/// `… since 18:12:05Z`): what an ALERT says must not change every minute.
pub fn steady(wait: &str) -> &str {
match (wait.trim_end().ends_with("so far)"), wait.rfind(" (")) {
(true, Some(i)) => &wait[..i],
_ => wait,
}
}
/// Pure: **the Why** of `stalls` at `now_ms`: per box its stage, since when, and its last wait.
/// `counts`: with the minutes (the status); without them (the ALERT's steady words).
pub fn why_words(stalls: &[Stall], now_ms: u64, counts: bool) -> String {
stalls
.iter()
.map(|s| {
let mins = now_ms.saturating_sub(s.since_ms) / 60_000;
let head = if counts { format!("{} has made no progress for {mins} min (since {})", s.role, hm_utc(s.since_ms)) } else { format!("{} has made no progress since {}", s.role, hm_utc(s.since_ms)) };
let wait = match &s.wait {
Some(w) if counts => format!("; its last wait: {w}"),
Some(w) => format!("; its last wait: {}", steady(w)),
None => "; its log names no wait".to_string(),
};
format!("{head}, at {}{wait}", s.step)
})
.collect::<Vec<_>>()
.join(". ")
}
/// Pure: **a box's last wait line** out of its install log's text: the last `WAITING …` /
/// `waiting for` / `waits for` line that is no TICK; else, when its last line that is no TICK is
/// a withheld marker, that its log says nothing readable (a release whose redaction withholds
/// every line naming a token — before nordisk-pairing 0.5.26). `None`: nothing to say.
pub fn last_wait(log: &str) -> Option<String> {
let lines: Vec<&str> = log.lines().map(str::trim).filter(|l| !l.is_empty() && !l.starts_with("TICK ")).collect();
let waits = |l: &&&str| {
let lower = l.to_ascii_lowercase();
l.contains("WAITING ") || lower.contains("waiting for") || lower.contains("waits for")
};
if let Some(l) = lines.iter().rev().find(waits) {
return Some(l.to_string());
}
let last = lines.last()?;
last.starts_with("<<WITHHELD").then(|| format!("none readable — its log withholds every line it says now ({last}): its release redacts whole lines that name a token"))
}
fn read_tail(path: &Path) -> Option<String> {
use std::io::{Read as _, Seek as _};
let mut f = std::fs::File::open(path).ok()?;
let len = f.metadata().ok()?.len();
f.seek(std::io::SeekFrom::Start(len.saturating_sub(LOG_TAIL_BYTES))).ok()?;
let mut b = Vec::new();
f.read_to_end(&mut b).ok()?;
Some(String::from_utf8_lossy(&b).into_owned())
}
/// **The stalled boxes of `run` now**, its progress file brought up to date. Empty for a run
/// that is not `installing`.
pub fn look_run(state: &AppState, run: &EstateRun) -> Vec<Stall> {
if run.phase != phase::INSTALLING {
return Vec::new();
}
let Some(dir) = state.estates.run_dir(&run.company) else { return Vec::new() };
let now = state.now();
let since = run.history.iter().rev().find(|t| t.phase == phase::INSTALLING).map(|t| t.at_ms).unwrap_or(now);
let roles: Vec<&str> = run.laid.as_ref().map(|l| l.machines.iter().map(|m| m.role.as_str()).collect()).unwrap_or_default();
let status = std::fs::read_to_string(dir.join(PAIRING_DIR).join(PAIR_STATUS_FILE)).unwrap_or_default();
let logs = dir.join(PAIRING_LOGS);
let boxes = boxes_of(&status, &roles, &|role| read_tail(&logs.join(format!("{role}.log"))).and_then(|t| last_wait(&t)));
let path = dir.join(PROGRESS_FILE);
let mut seen: BTreeMap<String, Seen> = std::fs::read(&path).ok().and_then(|b| serde_json::from_slice(&b).ok()).unwrap_or_default();
if observe(&mut seen, &boxes, now) {
if let Ok(b) = serde_json::to_vec_pretty(&seen) {
let tmp = path.with_extension("json.tmp");
if std::fs::write(&tmp, b).and_then(|_| std::fs::rename(&tmp, &path)).is_err() {
eprintln!("monetize-server: the install progress of {} could not be written to {}", run.reference, path.display());
}
}
}
stalls(since, &boxes, &seen, now)
}
/// **The operator's status words with the Why** of a stalled install appended.
pub fn with_why(state: &AppState, run: &EstateRun, words: String) -> String {
let stalled = look_run(state, run);
if stalled.is_empty() {
return words;
}
format!("{words} Why: {}.", why_words(&stalled, state.now(), true))
}
/// **The tick's look** (every tick): a CODE RED for every install at one step for
/// [`ALERT_AFTER_MS`], cleared once it moves on or ends.
pub fn look(state: &AppState) {
let now = state.now();
let red: Vec<String> = super::code_red::list(state).into_iter().map(|c| c.key).filter(|k| k.starts_with(RED_PREFIX)).collect();
for run in state.estates.all() {
let key = format!("{RED_PREFIX}{}", run.company);
let late: Vec<Stall> = look_run(state, &run).into_iter().filter(|s| now.saturating_sub(s.since_ms) >= ALERT_AFTER_MS).collect();
if late.is_empty() {
if red.contains(&key) {
super::code_red::clear(state, &key);
}
continue;
}
let label = if run.estate.is_empty() { run.company.clone() } else { run.estate.clone() };
let roles: Vec<&str> = late.iter().map(|s| s.role.as_str()).collect();
super::code_red::raise(
state,
&key,
&label,
&roles.join(", "),
&format!("the install has made no progress for {} min or more", ALERT_AFTER_MS / 60_000),
&why_words(&late, now, false),
&format!("read `monetize site installer-log {label} {}`; fix what the box waits for, or abandon the install", roles[0]),
);
}
}
#[cfg(test)]
mod tests {
use super::*;
const T0: u64 = 1_792_692_000_000; // 2026-10-22T18:00:00Z
const MIN: u64 = 60_000;
/// test3-holger-rs on 2026-10-22, as the ONE box held it: the front PAIRED at step certify
/// failing, the main at `step serve` for 40+ minutes waiting for the shared console bearer,
/// its install log nothing but withheld markers.
fn test3_status() -> String {
[
"[front]\nsignal = \" pair front: tunnel wireguard up · joined · role front · step certify (try 80: the reader at 10.44.0.3:50051 gave no signing request: transport error) · not paired\"\nlast_line = \"x\"\n",
"[main]\nsignal = \" pair main: tunnel wireguard up · joined · role primary · step serve (try 81: waiting for the server: the boot waits for the installer to feed `holger_console_token` (/data/holger-console-token is declared and not written yet)) · not paired\"\nlast_line = \"<<WITHHELD: 2 token-class lines in a row, 618 bytes, were not recorded>>\"\n",
"[twin]\nsignal = \" pair twin: tunnel wireguard up · joined · role twin · PAIRED\"\nlast_line = \"y\"\n",
]
.concat()
}
/// **An install at one step for 10 minutes says why, by name; at 20 minutes it is an ALERT
/// whose words do not change every minute** (test3-holger-rs 2026-10-22).
#[test]
fn an_install_that_makes_no_progress_says_why_by_name_and_alerts_at_twenty_minutes() {
let status = test3_status();
let main_log = "TICK stage=pairing up=60s\n<<WITHHELD: 2 token-class lines in a row, 618 bytes, were not recorded>>\nTICK stage=pairing up=120s\n";
let wait_of = |role: &str| if role == "main" { last_wait(main_log) } else { None };
let boxes = boxes_of(&status, &["front", "main", "twin"], &wait_of);
let mut seen = BTreeMap::new();
assert!(observe(&mut seen, &boxes, T0 + 12 * MIN));
// Retries are no progress: the same step with a new try count.
let later = status.replace("try 81", "try 140").replace("try 80", "try 139");
assert!(!observe(&mut seen, &boxes_of(&later, &["front", "main", "twin"], &wait_of), T0 + 30 * MIN), "{seen:?}");
assert!(stalls(T0, &boxes, &seen, T0 + 21 * MIN).is_empty(), "under 10 min at one step: no Why");
let s = stalls(T0, &boxes, &seen, T0 + 52 * MIN);
assert_eq!(s.iter().map(|s| s.role.as_str()).collect::<Vec<_>>(), vec!["front", "main"], "the PAIRED twin is not stalled");
let why = why_words(&s, T0 + 52 * MIN, true);
assert!(why.contains("main has made no progress for 40 min (since 18:12Z), at step serve (try 81: waiting for the server: the boot waits for the installer to feed `holger_console_token`"), "{why}");
assert!(why.contains("its last wait: none readable — its log withholds every line it says now (<<WITHHELD: 2 token-class lines in a row, 618 bytes, were not recorded>>)"), "{why}");
assert!(why.contains("front has made no progress for 40 min (since 18:12Z), at step certify (try 80: the reader at 10.44.0.3:50051 gave no signing request: transport error)"), "{why}");
// The ALERT's words are steady: no minute count, no running wait count.
let a = why_words(&s, T0 + 52 * MIN, false);
assert_eq!(a, why_words(&s, T0 + 53 * MIN, false));
assert!(a.contains("main has made no progress since 18:12Z"), "{a}");
}
/// A new release's box says its wait by name (holger-live `waits`): the Why names it.
#[test]
fn the_last_wait_line_is_the_boxs_own_named_wait() {
let log = "STAGE exec +3ms\nWAITING this box (primary) waits for the front's offered console key, to derive the console login from (the installer relays it from the front) since 2026-10-22T18:12:05Z (11 min so far)\nTICK stage=pairing up=720s\n";
let w = last_wait(log).unwrap();
assert!(w.starts_with("WAITING this box (primary) waits for the front's offered console key"), "{w}");
assert_eq!(steady(&w), w.trim_end_matches(" (11 min so far)"));
assert_eq!(last_wait("TICK stage=pairing up=1s\nall well\n"), None);
assert_eq!(hm_utc(T0 + 12 * MIN), "18:12Z");
assert_eq!(standing(" pair main: tunnel wireguard up · joined · step serve (try 3: x) · not paired"), "pair main: tunnel wireguard up · joined · step serve · not paired");
}
}