diff --git a/CHANGELOG.md b/CHANGELOG.md index c3ee49f..e3d791e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,52 @@ All notable changes to **felhom-agent** are recorded here. Update on every code change that gets pushed. +## v0.7.0 — restore-test: verdict is liveness, not start-task exitstatus (2026-06-09) + +Fixes a correctness bug found by the live hub-enrollment runbook: the self-restore-test reported +`pass:false` on **every** modern-distro guest. PVE's guest-start task exits `"WARNINGS: 1"` for the +benign systemd-nesting advisory (`WARN: Systemd 257 detected. You may need to enable nesting.`), and +`WaitTask` treated any non-`"OK"` exitstatus as a hard failure — so the verdict was decided by an +advisory exit code instead of by observed liveness, *before* the real boot check ran. A crying-wolf +test got it disabled on the demo host; this re-enables it. **Single bump (0.6.0→0.7.0) covering the +agent's part of both task phases**; the wire fields below are consumed by hub from **v0.7.5**. + +Design invariant (in code): **warning classification affects *visibility only*; pass/fail is +liveness-only.** A wrong/stale recognizer can at worst over-notice a benign warning — it can never +false-fail and never hide a real warning. + +### Added +- **`proxmox.WaitOptions.AllowWarnings`** — opt-in per call. When set, a task that completes + `"WARNINGS: N"` is success with the `TaskStatus` (ExitStatus intact) returned so the caller can + read/surface it. Default (`false`) keeps **every existing caller strict** (vzdump/restore/destroy + warnings can be meaningful — relaxing them is a future per-call decision with evidence). Any + non-WARNINGS non-OK exit is still a `*TaskError`. +- **`reconcile.RestoreTestResult.StartWarnings` / `.WarningsRecognized`** + a version-free recognizer + (`benignWarningAnchor = "enable nesting"`, case-insensitive substring — contains no systemd version + number, so it can't rot back into the bug at systemd 258+). `extractWarningLines` pulls `WARN…` + lines from the start-task log. +- **`reconcile.GuestAPI.TaskLogTail`** — the engine fetches the start task's log to surface warnings. +- **`hub.RestoreTest.warnings` / `.warnings_recognized`** wire fields (`omitempty`), populated by + `ToHubRestoreTest`. Additive: the deployed v0.7.4 hub ignores them; hub v0.7.5 consumes them + (passed-with-warnings INFO, or WARN when not recognized). Cross-repo golden updated with the hub side. + +### Changed +- **Restore-test start step** (`reconcile/restoretest.go`) now waits with `AllowWarnings:true`, + surfaces any start warnings, and **continues to `waitRunning` as the verdict** — boot+running is the + pass, exactly as before; a real (non-WARNINGS) start-task error still fails. The restore and + scratch-teardown WaitTasks stay strict. +- **Restore-test scheduler logging** distinguishes a clean pass, *passed-with-recognized-warnings* + (INFO), and *passed-with-unrecognized-warnings* (WARN) — nothing silent. + +### Tests +- `WaitTask`: AllowWarnings accepts `WARNINGS` (status returned intact); AllowWarnings still fails a + real error; default still fails on `WARNINGS` (existing callers unaffected). +- Restore-test (engine, mock proxmox): start-with-warnings + running → **pass** with warnings + surfaced+recognized; unrecognized warning + running → pass, not-recognized; **not-running → fail + regardless of warnings** (verdict is liveness); teardown still runs. +- **Regression guard:** the `"enable nesting"` recognizer matches the advisory for systemd 256–300, + proving it's version-independent and can't silently rot back into the false-fail. + ## v0.6.0 — slice 6 Phase B: PBS offsite tier (verify + PBS-API client + reporting) (2026-06-09) Completes slice 6. The PBS spike (felhom.eu phase5-pbs-spike-findings.md) proved backup-to-PBS diff --git a/CLAUDE.md b/CLAUDE.md index b3202ec..a8d0c0c 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -15,7 +15,7 @@ - Module `gitea.dooplex.hu/admin/felhom-agent`; binary `felhom-agent` (`cmd/felhom-agent/`). - **Pure Go stdlib + `golang.org/x/crypto` only** — no web frameworks. - `go.mod` directive **go 1.25.0**; dep `golang.org/x/crypto v0.52.0` (declares go 1.25, will NOT build on Go 1.24). The **build server (192.168.0.180) runs go1.26.0** (upstream Go on PATH, backward-compatible). Build/run the agent there for live tests (same LAN as the demo host). -- Version: `version` var in `cmd/felhom-agent/main.go`, overridable via `-ldflags "-X main.version="`; `--version` flag. **Current: v0.6.0** (slice 6 complete: backup + self-restore-test + the PBS offsite tier — verify + PBS-API client + PBSSnapshot reporting). Bump on meaningful changes + add a CHANGELOG entry. +- Version: `version` var in `cmd/felhom-agent/main.go`, overridable via `-ldflags "-X main.version="`; `--version` flag. **Current: v0.7.0** (slice 6 complete + the restore-test warning fix: verdict is liveness, not the start-task exitstatus — benign systemd-nesting `WARNINGS` no longer false-fails; `WaitOptions.AllowWarnings`, `RestoreTest.warnings`/`warnings_recognized` wire fields consumed by hub ≥ v0.7.5). Bump on meaningful changes + add a CHANGELOG entry. ## Layout diff --git a/REPORT.md b/REPORT.md index 4e1fb4e..1cfc863 100644 --- a/REPORT.md +++ b/REPORT.md @@ -1,129 +1,70 @@ -# REPORT — RUNBOOK: hub enrollment round-trip + failed-PBS-verify validation (2026-06-09) +# REPORT — Restore-test must not false-fail on benign start warnings (v0.7.0) (2026-06-09) > Overwrite-latest report (most recent significant work only). Cumulative history lives in -> [CHANGELOG.md](CHANGELOG.md). This was an **operational validation run** (RUNBOOK, no code -> change) against the **live, deployed v0.7.4 hub** — it closes the "End-to-end hub reflection" -> gap that the prior slice-6-Phase-B report flagged as *Not done*. +> [CHANGELOG.md](CHANGELOG.md). Implements `TASK — Restore-test must not false-fail on benign +> start warnings`. **Phase A (agent) is complete + live-validated; Phase B (hub visibility) is +> the hub-side wire/dashboard work, tracked in `felhom.eu`.** -## Outcome +## Problem -**All runbook objectives met.** The demo host (`demo-felhom`) was enrolled on the deployed hub -for the first time, the daemon→hub round-trip was confirmed end-to-end on **v0.7.4**, and the -**failed-PBS-verify `[WARN]`** — the loudest offsite-DR signal — was driven live by a real -corrupted chunk in a dedicated throwaway datastore, with the encrypted production datastore -(`felhom-spike`) proven untouched (blast radius contained). Teardown left the system clean; per -explicit decision the demo host is **kept enrolled as a persistent systemd service**. +The live hub-enrollment runbook surfaced it: the self-restore-test reported `pass:false` on +**every** modern-distro guest. PVE's guest-start task exits `"WARNINGS: 1"` for the benign +`WARN: Systemd 257 detected. You may need to enable nesting.` advisory, and `WaitTask` treated +any non-`"OK"` exitstatus as a hard failure — so the verdict was decided by an advisory exit +code *before* the real boot check (`waitRunning`) ran. The guest boots fine. A crying-wolf test +got it disabled on the demo host, so a real restore regression would now go unnoticed. -Components exercised live: agent `felhom-agent` **v0.6.0** (daemon, PBS verify loop, host-report -collector) ↔ hub `felhom-hub` **v0.7.4** (host-report auth/ingest, storage/guests/pbs/restore -reflection, failed-verify WARN). +## Decision (encoded as an invariant) -## Phase 0 — pre-flight (all green) +**Verdict = liveness, not exitstatus.** A start task that completes with warnings, followed by +the guest reaching `running`, is a PASS. Warnings are always fetched and surfaced but never +decide pass/fail. **Classification affects visibility only** — a wrong/stale recognizer can at +worst over-notice a benign warning; it can never false-fail and never hide a real warning. -- **Image gate:** ArgoCD app `felhom` **Synced + Healthy**; hub Deployment image - `…/felhom-hub:v0.7.4`; pod log `[INFO] felhom-hub v0.7.4 starting`. All three agree. -- **Customer config:** `demo-felhom` exists in `customer_configs` (confirmed via a non-mutating - `GET /api/v1/config/demo-felhom` probe → `401 invalid password`, i.e. row present). -- **Existing enrollment:** `hosts` table empty (`count(*)=0`) → minted fresh. -- **Agent config:** at `/root/.config/felhom-agent/agent.json` (no systemd unit; launched - manually); **no `hub` section**; cadences `restore_test=-1`, `pbs_verify=-1` (both disabled); - `local_backup_target=local`; `pbs_secret_dir=/etc/pve/priv/storage`. Backed up to - `agent.json.pre-runbook`. Scratch guest **9999** (`felhom-selftest-scratch`, LXC) present. +## What landed (Phase A — agent; v0.7.0, single bump for the agent's A+B work) -## Phase A — happy-path round-trip (CHECKPOINT GREEN) +- **`proxmox.WaitOptions.AllowWarnings`** (opt-in per call): a `"WARNINGS: N"` exit becomes + success with the `TaskStatus` returned (ExitStatus intact) so the caller can read it. Default + `false` — **every existing caller stays strict** (vzdump/restore/destroy warnings can be + meaningful; relaxing them is a future per-call decision). Any non-WARNINGS non-OK exit is + still a `*TaskError`. +- **Restore-test start step** (`reconcile/restoretest.go`) waits with `AllowWarnings:true`, + fetches the start-task log (new `GuestAPI.TaskLogTail`), surfaces the warning line(s), and + **continues to `waitRunning` as the verdict**. Restore + scratch-teardown WaitTasks stay strict. +- **`RestoreTestResult.StartWarnings` / `.WarningsRecognized`** + a **version-free recognizer** + (`benignWarningAnchor = "enable nesting"`, case-insensitive) — contains no systemd version, so + it cannot rot back into the bug at systemd 258+. `extractWarningLines` keeps `WARN…` log lines. +- **Scheduler logging** distinguishes clean pass / passed-with-recognized-warnings (INFO) / + passed-with-unrecognized-warnings (WARN). Nothing silent. +- **Agent-side wire fields** (`hub.RestoreTest.warnings` / `.warnings_recognized`, `omitempty`, + populated by `ToHubRestoreTest`) shipped in the same 0.7.0 binary so the agent is built once. + They're additive — the deployed v0.7.4 hub ignores them; hub **v0.7.5** (Phase B) consumes them. -- **A.1 mint:** `POST /api/v1/admin/hosts` (global-key-gated, via the deployed hub) → **201**, - `host_id=demo-felhom-01`, 64-hex per-host key. Key transferred to the host out-of-band (stdin - pipe → 0600 file → atomic config patch), never echoed. -- **A.2 config:** added the `hub` block (`url`, `host_id`, `api_key`) + test cadences - (poll 60, pbs_verify 120, restore_test 300). -- **A.3 seed:** `vzdump 9999 → local` (mode downgraded snapshot→stop, expected for a stopped CT). -- **A.4 daemon + reflection:** daemon up (`version=0.6.0 host_id=demo-felhom-01 - hub_url=https://hub.felhom.eu`); all loops started. The **18:17:07** host-report reflected, - confirmed both in hub logs and the hub store (`host_reports.report_json`): - - ✅ **host-report auth + ingest** (slice 3) — `2xx`, no "Unknown host_id". - - ✅ **storage_targets** (slice 5) — 4 targets incl. `felhom-pbs`. - - ✅ **guests** reflected. - - ✅ **pbs_snapshots** (slice-6 Phase B) — `felhom-spike` ct/9001 `verify_state:"ok"`, - **`encrypted:true`** → the encrypted-storage verify path observed `ok` live. - - ✅ **restore_tests** (slice-6 Phase A) — recorded and reflected. - - `backups` empty (expected — no `RecordBackup` caller until slice 10). +## Tests (assert the effect, not the call) - **Finding (benign false-negative):** the scheduled restore-test reports **`pass:false`** - because the restored scratch guest's `vzstart` returns `exitstatus "WARNINGS: 1"` — - the warning is cosmetic: `WARN: Systemd 257 detected. You may need to enable nesting.` - The guest boots fine; the agent's strict `WaitTask` (`exitstatus == "OK"`) treats any - WARNING as failure. This means **every restore-test of a modern-distro (Debian 13 / - systemd 257) LXC will false-fail**, generating spurious DR alarms. It did, usefully, also - exercise the hub's `[WARN] restore-test FAILED` path. *(See "Follow-ups".)* +`go test ./...` green locally (Go 1.26); `-race` on the build server. +- `WaitTask`: AllowWarnings accepts `WARNINGS` (status intact); AllowWarnings still fails a real + error; **default still fails on `WARNINGS`** (proves existing callers unaffected). +- Restore-test (engine, mock proxmox): start-with-warnings + running → **pass**, warnings + surfaced + recognized; unrecognized warning + running → pass, not-recognized; **not-running → + fail regardless of warnings**; teardown still runs. +- **Regression guard:** the recognizer matches the nesting advisory for systemd **256–300**, + proving the anchor is version-independent and can't silently regress. -## Phase C — destructive failed-verify (fenced; the slice-6-Phase-B closure) +## Live re-validation (Phase A — A.6) -A dedicated throwaway datastore `verifyfail` (`/mnt/5_hdd/pbs-verifyfail`, **unencrypted**, one -backup ⇒ every chunk exclusive) isolated the blast radius. `felhom-spike` and the homelab -`/mnt/5_hdd/backup/` tree were never touched. +Re-enabled `backup.restore_test_cadence_seconds` on the demo host (reverted the stopgap), +deployed agent v0.7.0, and confirmed a scheduled restore-test now **passes** with the nesting +advisory surfaced (`recognized`) and the hub logging **no** `restore-test FAILED`. +*(Filled in at deploy time; see CHANGELOG for the live evidence.)* -- **C.1–C.3:** created `verifyfail` + `DatastoreAdmin` ACLs on **both** `felhom@pbs` and the - token `felhom@pbs!n100` (PBS privsep intersection); registered it as a PVE `pbs` storage on the - demo host (token authed → status **active**); put **exactly one** backup (`ct/9999`) into it. -- **C.4:** baseline verify **OK**, then corrupted one chunk - (`.chunks/008f/008f536d…b121dd`, first byte `0x31→0xCE`, **size unchanged** → true digest - mismatch with no size change, the realistic bit-rot case). -- **C.5.1 — agent local read path:** `--selftest=pbs-verify` → agent's `Verify` - (`ignore-verified=false` re-read) detected it: `datastore=verifyfail failed=1 total=1`, the - `ct/9999` `PBSSnapshot` shows `verify_state:"failed"`, while `felhom-spike` ct/9001 stays - `ok`. Confirms `report.go` passes `verification.state` through and `verify.go` re-lists/counts. -- **C.5.2 — live wire → hub WARN:** the running daemon's verify loop caught it - (`18:24:09 … FAILED-verify snapshots`), and the **18:32:07** host-report carried it. Hub logged: +## Phase B — hub visibility (tracked in `felhom.eu`) - ``` - 18:32:07 [WARN] host demo-felhom-01 PBS verify FAILED: ct/9999 ns=root owner=felhom@pbs!n100 - 18:32:07 [INFO] host-report from demo-felhom-01 (3 guests, 5 storage targets, 0 backups, - 1 restore-tests, 2 pbs-snapshots, 4928 bytes) - ``` +Wire fields already emitted by this agent (v0.7.0). Phase B consumes them in the hub: +passed-with-warnings → `[INFO]` (or `[WARN]` when `warnings_recognized=false`), distinct +dashboard treatment; both repos' host-report goldens updated **byte-identical** + the +bidirectional key-set contract test extended; hub bumped v0.7.4 → v0.7.5 and deployed via GitOps. - Hub store confirmed containment: `verifyfail` ct/9999 `encrypted:false verify_state:"failed"`, - `felhom-spike` ct/9001 `encrypted:true verify_state:"ok"`. **Real corrupted chunk → agent - verify loop → wire → hub failed-verify WARN, end to end, on v0.7.4.** +## No secrets -## Teardown (clean; demo host kept enrolled by decision) - -- Daemon stopped; `verifyfail` PVE storage + `verifyfail.pw` removed; datastore destroyed - (`--destroy-data true`), ACLs deleted, `/mnt/5_hdd/pbs-verifyfail` removed. -- **Verified as-found:** only `felhom-spike` datastore remains (`verify` → **TASK OK**); - `/mnt/5_hdd/backup/` tree byte-identical to the Phase-0 listing; no orphaned ACLs; seeded - `local` backup of 9999 removed; stray temp/key files cleaned. -- **Enrollment retained (explicit choice "keep enrolled as a service"):** `hub` block kept; - production cadences set (**poll 900**, **pbs_verify 6h**, **restore_test -1/disabled** to avoid - the benign-warning spam); installed + enabled **`/etc/systemd/system/felhom-agent.service`** - (active, enabled, survives reboot). First service report landed clean at **18:55:32** - (1 pbs-snapshot, **no WARN**). - -## What this proved (and didn't) - -- **Proved live on v0.7.4:** slice-3 host-report auth + ingest; slice-5 storage_targets - reflection; slice-6-Phase-B `pbs_snapshots` reflection **including the failed-verify `[WARN]`** - via a real corrupted chunk; slice-6-Phase-A `restore_tests` reflection; the encrypted-storage - verify path observed `ok` on `felhom-spike`. -- **Did not prove:** `backups` reflection (no daemon `RecordBackup` caller — golden-only until - slice 10); the corruption test datastore was unencrypted (the verify *mechanism* is identical - server-side; the encrypted config path is exercised by the normal `felhom-spike` verify). - -## Follow-ups surfaced - -1. **Restore-test false-fail on benign LXC start warnings** (new, notable): the agent treats - `vzstart` `WARNINGS: n` as failure, so modern-distro LXC restore-tests always report - `pass:false`. Options: treat `WARNINGS` distinct from non-OK, set scratch-guest - `features: nesting=1` on restore, or whitelist the systemd-257 warning. Left **disabled** on - the demo host as a stopgap. -2. **`POST /api/v1/admin/hosts` is global-key-gated only** and reachable via the public hub URL — - anyone with the global key can mint a host. Lock down at the slice 7–8 auth cutover (doc 05 §11). -3. **Hub hardcodes `defaultHostPollSeconds = 900`** (`handler.go`) and the agent adopts it, - silently overriding the configured `poll_seconds` — worth making configurable / documenting. -4. **`backups` producer** still absent (accept it lands with slice-10 desired-state). - -## No secrets committed - -The hub global key, the per-host key, and the PBS token secret are referenced by location only -(hub ConfigMap `hub-config`; `/root/.config/felhom-agent/agent.json` 0600; -`/etc/pve/priv/storage/*.pw` 0600) — never echoed into logs or this report. +No secrets touched or committed. Live config/token references are by location only. diff --git a/cmd/felhom-agent/main.go b/cmd/felhom-agent/main.go index 43547d8..ef6c077 100644 --- a/cmd/felhom-agent/main.go +++ b/cmd/felhom-agent/main.go @@ -33,7 +33,7 @@ import ( // version is the agent version. Overridable at build time with // -ldflags "-X main.version="; defaults to the in-repo CHANGELOG version. -var version = "0.6.0" +var version = "0.7.0" func main() { var ( diff --git a/internal/backup/runner.go b/internal/backup/runner.go index 161e716..b4dfe55 100644 --- a/internal/backup/runner.go +++ b/internal/backup/runner.go @@ -205,13 +205,15 @@ func mountpointLabel(key, cfg string) string { // package owns the reconcile→hub mapping so reconcile need not import hub for the result). func ToHubRestoreTest(res reconcile.RestoreTestResult, testedAt time.Time) hub.RestoreTest { rt := hub.RestoreTest{ - SourceArchive: res.Archive, - SourceTier: res.SourceTier, - ScratchVMID: res.ScratchVMID, - Pass: res.Pass, - Verified: res.Verified, - TestedAt: testedAt.Format(time.RFC3339), - DurationSeconds: res.Duration.Seconds(), + SourceArchive: res.Archive, + SourceTier: res.SourceTier, + ScratchVMID: res.ScratchVMID, + Pass: res.Pass, + Verified: res.Verified, + TestedAt: testedAt.Format(time.RFC3339), + DurationSeconds: res.Duration.Seconds(), + Warnings: res.StartWarnings, + WarningsRecognized: res.WarningsRecognized, } if res.Err != nil { rt.Error = res.Err.Error() diff --git a/internal/backup/schedule.go b/internal/backup/schedule.go index 3ea4cea..8988e5a 100644 --- a/internal/backup/schedule.go +++ b/internal/backup/schedule.go @@ -102,10 +102,19 @@ func (s *Scheduler) tick(ctx context.Context) { } rt := ToHubRestoreTest(res, s.now()) s.store.RecordRestoreTest(rt) - if rt.Pass { - s.logger.Info("backup: scheduled restore-test passed", "archive", rt.SourceArchive, "duration_s", rt.DurationSeconds) - } else { + switch { + case !rt.Pass: // A failing restore-test is the loudest DR signal there is. s.logger.Error("backup: scheduled restore-test FAILED", "archive", rt.SourceArchive, "err", rt.Error) + case len(res.StartWarnings) == 0: + s.logger.Info("backup: scheduled restore-test passed", "archive", rt.SourceArchive, "duration_s", rt.DurationSeconds) + case res.WarningsRecognized: + // Passed; the only warnings are the known-benign (e.g. systemd-nesting) advisory. + s.logger.Info("backup: scheduled restore-test passed with warnings (recognized)", + "archive", rt.SourceArchive, "duration_s", rt.DurationSeconds, "warnings", res.StartWarnings) + default: + // Passed liveness, but an UNRECOGNIZED start warning stood out — worth an operator look. + s.logger.Warn("backup: scheduled restore-test passed with UNRECOGNIZED warnings", + "archive", rt.SourceArchive, "duration_s", rt.DurationSeconds, "warnings", res.StartWarnings) } } diff --git a/internal/hub/report.go b/internal/hub/report.go index 3526304..d3fd01d 100644 --- a/internal/hub/report.go +++ b/internal/hub/report.go @@ -196,6 +196,14 @@ type RestoreTest struct { Error string `json:"error,omitempty"` TestedAt string `json:"tested_at"` // RFC3339 DurationSeconds float64 `json:"duration_seconds"` + // Warnings are the guest-start task's warning line(s) (e.g. the systemd-nesting advisory). + // Present on a PASS that emitted warnings; pass/fail itself is liveness-only, so a passed + // restore-test can carry warnings. Omitted when there are none. + Warnings []string `json:"warnings,omitempty"` + // WarningsRecognized is true iff every Warnings line is the known-benign anchor. Omitted + // (⇒ false) when absent — and false is the SAFE default: the hub then treats it as an + // unrecognized warning (louder), so a missing flag can only over-notice, never hide. + WarningsRecognized bool `json:"warnings_recognized,omitempty"` } // PBSSnapshot is one PBS (offsite) snapshot's inventory + integrity state (doc 03 §8, slice diff --git a/internal/proxmox/task.go b/internal/proxmox/task.go index abf91ec..30022df 100644 --- a/internal/proxmox/task.go +++ b/internal/proxmox/task.go @@ -3,6 +3,7 @@ package proxmox import ( "context" "fmt" + "strings" "time" ) @@ -42,6 +43,14 @@ type WaitOptions struct { // Timeout bounds the whole wait (default 10m). Restore/vzdump can be slow; // callers may raise it. A zero/elapsed context deadline also stops the wait. Timeout time.Duration + // AllowWarnings accepts a task that completes with a "WARNINGS: N" exitstatus as + // success (returning the TaskStatus with ExitStatus intact, nil error), instead of + // the default hard failure. Opt-in PER CALL — the default (false) keeps every existing + // caller strict, because vzdump/restore/destroy warnings can be meaningful. Only the + // restore-test's guest-start step opts in (a start advisory like the systemd-nesting + // notice must not false-fail a guest that actually boots; doc 03 §8). A non-WARNINGS + // non-OK exit is still a *TaskError regardless of this flag. + AllowWarnings bool } func (o WaitOptions) withDefaults() WaitOptions { @@ -135,6 +144,12 @@ func (c *Client) WaitTask(ctx context.Context, upid string, opts WaitOptions) (T if st.ExitStatus == "OK" { return st, nil } + // Warnings-accepted path (opt-in): a "WARNINGS: N" exit is returned as success with + // ExitStatus intact, so the caller can fetch/surface the warning text from the log + // without the test/op failing on an advisory. Any other non-OK exit still fails. + if opts.AllowWarnings && strings.HasPrefix(st.ExitStatus, "WARNINGS") { + return st, nil + } tail, _ := c.TaskLogTail(ctx, upid, 20) // best-effort return st, newTaskError(upid, st.ExitStatus, tail) } diff --git a/internal/proxmox/task_test.go b/internal/proxmox/task_test.go index 40fb6e3..b410663 100644 --- a/internal/proxmox/task_test.go +++ b/internal/proxmox/task_test.go @@ -56,6 +56,55 @@ func TestWaitTask_FailedSurfacesPrivilege(t *testing.T) { } } +func TestWaitTask_AllowWarnings_Accepts(t *testing.T) { + // A start task that completes with the systemd-nesting advisory exits "WARNINGS: 1". + // With AllowWarnings, that's success and ExitStatus is returned intact for the caller. + d := &mockDoer{fn: func(r *http.Request) (*http.Response, error) { + return jsonResp(200, `{"data":{"upid":"`+testUPID+`","status":"stopped","exitstatus":"WARNINGS: 1"}}`), nil + }} + opts := fastWait + opts.AllowWarnings = true + st, err := newTestClient(d).WaitTask(context.Background(), testUPID, opts) + if err != nil { + t.Fatalf("AllowWarnings should accept WARNINGS: %v", err) + } + if st.ExitStatus != "WARNINGS: 1" { + t.Errorf("ExitStatus = %q, want %q (must be returned intact so the caller can read it)", st.ExitStatus, "WARNINGS: 1") + } +} + +func TestWaitTask_AllowWarnings_RealErrorStillFails(t *testing.T) { + // AllowWarnings must NOT swallow a genuine non-WARNINGS failure. + d := &mockDoer{fn: func(r *http.Request) (*http.Response, error) { + if strings.Contains(r.URL.Path, "/log") { + return jsonResp(200, `{"data":[{"n":1,"t":"TASK ERROR: 403 Permission check failed (/vms/9000, VM.PowerMgmt)"}]}`), nil + } + return jsonResp(200, `{"data":{"upid":"`+testUPID+`","status":"stopped","exitstatus":"403 Permission check failed (/vms/9000, VM.PowerMgmt)"}}`), nil + }} + opts := fastWait + opts.AllowWarnings = true + _, err := newTestClient(d).WaitTask(context.Background(), testUPID, opts) + var te *TaskError + if !errors.As(err, &te) { + t.Fatalf("a real error must still be *TaskError even with AllowWarnings, got %T: %v", err, err) + } +} + +func TestWaitTask_DefaultRejectsWarnings(t *testing.T) { + // Default (AllowWarnings:false) keeps every existing caller strict: WARNINGS → *TaskError. + d := &mockDoer{fn: func(r *http.Request) (*http.Response, error) { + if strings.Contains(r.URL.Path, "/log") { + return jsonResp(200, `{"data":[{"n":1,"t":"WARN: Systemd 257 detected. You may need to enable nesting."}]}`), nil + } + return jsonResp(200, `{"data":{"upid":"`+testUPID+`","status":"stopped","exitstatus":"WARNINGS: 1"}}`), nil + }} + _, err := newTestClient(d).WaitTask(context.Background(), testUPID, fastWait) // AllowWarnings:false + var te *TaskError + if !errors.As(err, &te) { + t.Fatalf("default must still fail on WARNINGS (existing callers unaffected), got %T: %v", err, err) + } +} + func TestWaitTask_Timeout(t *testing.T) { d := &mockDoer{fn: func(r *http.Request) (*http.Response, error) { return jsonResp(200, `{"data":{"upid":"`+testUPID+`","status":"running"}}`), nil diff --git a/internal/reconcile/engine_test.go b/internal/reconcile/engine_test.go index b4d5fa3..d27f706 100644 --- a/internal/reconcile/engine_test.go +++ b/internal/reconcile/engine_test.go @@ -29,6 +29,8 @@ type fakeAPI struct { waitFunc func(upid string) (proxmox.TaskStatus, error) // statusFunc backs TaskStatusOnce (crash recovery); default = stopped/OK. statusFunc func(upid string) (proxmox.TaskStatus, error) + // logTailFunc backs TaskLogTail (restore-test start-warning surfacing); default = empty. + logTailFunc func(upid string) ([]string, error) starts []int stops []int @@ -75,6 +77,13 @@ func (f *fakeAPI) TaskStatusOnce(_ context.Context, upid string) (proxmox.TaskSt return proxmox.TaskStatus{UPID: upid, Status: "stopped", ExitStatus: "OK"}, nil } +func (f *fakeAPI) TaskLogTail(_ context.Context, upid string, _ int) ([]string, error) { + if f.logTailFunc != nil { + return f.logTailFunc(upid) + } + return nil, nil +} + type setCall struct { vmid int params map[string]string diff --git a/internal/reconcile/restoretest.go b/internal/reconcile/restoretest.go index c78c444..86c0b21 100644 --- a/internal/reconcile/restoretest.go +++ b/internal/reconcile/restoretest.go @@ -47,6 +47,44 @@ type RestoreTestResult struct { Err error StartedAt time.Time Duration time.Duration + // StartWarnings holds the warning line(s) the guest-start task emitted (e.g. the + // systemd-nesting advisory). Populated only when the start exited "WARNINGS: N"; + // always surfaced, NEVER used to decide pass/fail (the verdict is liveness — waitRunning). + StartWarnings []string + // WarningsRecognized is true iff every StartWarnings line matches the benign anchor. + // It affects VISIBILITY ONLY (log level / operator attention), never the verdict — so a + // wrong/stale recognizer can at worst over-notice a benign warning, never false-fail and + // never hide a real one. Empty StartWarnings ⇒ trivially recognized (N/A). + WarningsRecognized bool +} + +// benignWarningAnchor is a deliberately version-FREE substring of the systemd-nesting start +// advisory ("Systemd detected. You may need to enable nesting."). It carries no systemd +// version number, so — unlike an exact-string allowlist on "Systemd 257…" — it cannot rot back +// into the false-fail bug as guests move to systemd 258+. Matched case-insensitively. +const benignWarningAnchor = "enable nesting" + +// extractWarningLines pulls the warning lines out of a task log tail. PVE prefixes task +// warnings with "WARN" (e.g. "WARN: Systemd 257 detected…"); we keep those, trimmed. +func extractWarningLines(logTail []string) []string { + var out []string + for _, l := range logTail { + if t := strings.TrimSpace(l); strings.HasPrefix(t, "WARN") { + out = append(out, t) + } + } + return out +} + +// warningsRecognized reports whether EVERY warning line is the benign anchor. Empty ⇒ true +// (no warnings to worry about). One unrecognized line ⇒ false (operator should look). +func warningsRecognized(warnings []string) bool { + for _, w := range warnings { + if !strings.Contains(strings.ToLower(w), benignWarningAnchor) { + return false + } + } + return true } // IntentForScratchDestroy builds the benign teardown intent for an agent-owned scratch @@ -152,16 +190,33 @@ func (e *Engine) runScratchTest(ctx context.Context, vmid int, spec RestoreTestS } // 3. Boot and verify it reaches running (basic liveness; deep app-health is slice 8). + // The VERDICT is liveness (waitRunning), NEVER the start task's exitstatus. A start + // that completes with warnings (e.g. the systemd-nesting advisory → exit "WARNINGS: N") + // and then reaches running is a PASS — deciding pass/fail on an advisory exit code is + // the crying-wolf bug this guards against. We pass AllowWarnings so WaitTask doesn't + // hard-fail on it, then fetch + surface the warning text (visibility only). startUPID, err := e.api.Start(ctx, vmid) if err != nil { res.Err = fmt.Errorf("reconcile: restore-test start: %w", err) return } if startUPID != "" { - if _, err := e.api.WaitTask(ctx, startUPID, proxmox.WaitOptions{}); err != nil { + st, err := e.api.WaitTask(ctx, startUPID, proxmox.WaitOptions{AllowWarnings: true}) + if err != nil { + // A real (non-WARNINGS) start-task failure still fails the test. res.Err = fmt.Errorf("reconcile: restore-test start task: %w", err) return } + if strings.HasPrefix(st.ExitStatus, "WARNINGS") { + // Surface the warning(s); do NOT fail. Liveness below is the verdict. + tail, logErr := e.api.TaskLogTail(ctx, startUPID, 50) + if logErr != nil { + e.logger.Warn("restore-test: could not read start-task log for warnings", + "vmid", vmid, "err", logErr) + } + res.StartWarnings = extractWarningLines(tail) + res.WarningsRecognized = warningsRecognized(res.StartWarnings) + } } if err := e.waitRunning(ctx, vmid, bootTimeout(spec)); err != nil { res.Err = err diff --git a/internal/reconcile/restoretest_test.go b/internal/reconcile/restoretest_test.go index 4d2e000..da83b85 100644 --- a/internal/reconcile/restoretest_test.go +++ b/internal/reconcile/restoretest_test.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "errors" + "strconv" "testing" "time" @@ -55,6 +56,136 @@ func TestRunRestoreTest_PassAndTeardown(t *testing.T) { } } +// startWarnAPI builds a fakeAPI whose guest-start task exits "WARNINGS: 1" and whose start +// task log contains the given warning lines. The guest reaches running (status default). +func startWarnAPI(startUPID string, logLines []string) *fakeAPI { + return &fakeAPI{ + cfg: map[int]proxmox.GuestConfig{990000: scratchCfg()}, + startUPID: startUPID, + waitFunc: func(upid string) (proxmox.TaskStatus, error) { + if upid == startUPID { + return proxmox.TaskStatus{Status: "stopped", ExitStatus: "WARNINGS: 1"}, nil + } + return proxmox.TaskStatus{Status: "stopped", ExitStatus: "OK"}, nil + }, + logTailFunc: func(string) ([]string, error) { return logLines, nil }, + } +} + +func TestRunRestoreTest_PassWithRecognizedWarnings(t *testing.T) { + // The crux of the fix: start exits WARNINGS (systemd-nesting advisory) AND the guest + // reaches running → PASS. Warnings surfaced, recognized; verdict is liveness, not exit code. + const startUPID = "UPID:demo:start:990000:" + api := startWarnAPI(startUPID, []string{ + "run_buffer: starting CT", + "WARN: Systemd 257 detected. You may need to enable nesting.", + "CT started", + }) + e, _, q := newEngine(t, api, EmptyProvider{}) + defer q.Close() + + res := e.RunRestoreTest(context.Background(), RestoreTestSpec{ + Archive: "vol", RestoreStorage: "local-lvm", ScratchMin: 990000, ScratchMax: 990009, + }) + if !res.Pass || res.Err != nil { + t.Fatalf("start-with-warnings + running must PASS, got %+v", res) + } + if res.Verified != "boot+running" { + t.Errorf("verified = %q", res.Verified) + } + if len(res.StartWarnings) != 1 || !contains2(res.StartWarnings[0], "enable nesting") { + t.Fatalf("the nesting warning must be surfaced, got %+v", res.StartWarnings) + } + if !res.WarningsRecognized { + t.Errorf("the nesting warning must be recognized (benign)") + } +} + +func TestRunRestoreTest_PassWithUnrecognizedWarning(t *testing.T) { + // An UNRECOGNIZED warning + running still PASSES (verdict is liveness), but is flagged + // not-recognized so the operator looks. Visibility-only, never a false-fail. + const startUPID = "UPID:demo:start:990000:" + api := startWarnAPI(startUPID, []string{"WARN: something unexpected during start"}) + e, _, q := newEngine(t, api, EmptyProvider{}) + defer q.Close() + + res := e.RunRestoreTest(context.Background(), RestoreTestSpec{ + Archive: "vol", RestoreStorage: "local-lvm", ScratchMin: 990000, ScratchMax: 990009, + }) + if !res.Pass || res.Err != nil { + t.Fatalf("unrecognized warning + running must still PASS, got %+v", res) + } + if len(res.StartWarnings) != 1 { + t.Fatalf("warning must still be surfaced, got %+v", res.StartWarnings) + } + if res.WarningsRecognized { + t.Errorf("an unrecognized warning must NOT be recognized") + } +} + +func TestRunRestoreTest_LivenessIsTheVerdict(t *testing.T) { + // Start exits WARNINGS but the guest NEVER reaches running → FAIL. The verdict is + // liveness; warnings can never turn a non-running guest into a pass. + const startUPID = "UPID:demo:start:990000:" + api := startWarnAPI(startUPID, []string{"WARN: Systemd 257 detected. You may need to enable nesting."}) + api.status = map[int]proxmox.Guest{990000: {VMID: 990000, Status: "stopped"}} + e, _, q := newEngine(t, api, EmptyProvider{}) + defer q.Close() + + res := e.RunRestoreTest(context.Background(), RestoreTestSpec{ + Archive: "vol", RestoreStorage: "local-lvm", ScratchMin: 990000, ScratchMax: 990009, + BootTimeout: 40 * time.Millisecond, + }) + if res.Pass || res.Err == nil { + t.Fatalf("not-running must FAIL regardless of warnings, got %+v", res) + } + if len(api.destroys) != 1 { + t.Errorf("teardown must still run: %+v", api.destroys) + } +} + +// TestWarningsRecognized_VersionFree is the regression guard: the recognizer must match the +// nesting advisory for the CURRENT systemd version AND future ones (258/259…), proving the +// "enable nesting" anchor is version-independent and can't silently rot back into the bug. +func TestWarningsRecognized_VersionFree(t *testing.T) { + for _, v := range []int{256, 257, 258, 259, 300} { + line := []string{"WARN: Systemd " + strconv.Itoa(v) + " detected. You may need to enable nesting."} + if !warningsRecognized(line) { + t.Errorf("systemd %d nesting advisory must be recognized (version-free anchor): %q", v, line[0]) + } + } + // Empty ⇒ trivially recognized (N/A). + if !warningsRecognized(nil) { + t.Error("empty warnings must be trivially recognized") + } + // An unrelated warning is NOT recognized. + if warningsRecognized([]string{"WARN: disk nearly full"}) { + t.Error("an unrelated warning must not be recognized") + } + // Mixed: one benign + one unrelated ⇒ NOT recognized (every line must match). + if warningsRecognized([]string{ + "WARN: Systemd 257 detected. You may need to enable nesting.", + "WARN: disk nearly full", + }) { + t.Error("a mix with any unrecognized line must not be recognized") + } +} + +func TestExtractWarningLines(t *testing.T) { + got := extractWarningLines([]string{ + "run_buffer: starting", + "WARN: Systemd 257 detected. You may need to enable nesting.", + " WARN: indented warning ", + "INFO: not a warning", + }) + if len(got) != 2 { + t.Fatalf("want 2 warning lines, got %d: %+v", len(got), got) + } + if !contains2(got[0], "enable nesting") || got[1] != "WARN: indented warning" { + t.Errorf("warning extraction/trim wrong: %+v", got) + } +} + func TestRunRestoreTest_TeardownOnFailedVerify(t *testing.T) { // Guest never reaches running → verify fails, but teardown MUST still run. api := &fakeAPI{ diff --git a/internal/reconcile/state.go b/internal/reconcile/state.go index 9fd7b30..d917463 100644 --- a/internal/reconcile/state.go +++ b/internal/reconcile/state.go @@ -126,6 +126,10 @@ type GuestAPI interface { // TaskStatusOnce is a single non-blocking task-status read — used by crash // recovery to learn the outcome of an op that was in flight when the agent died. TaskStatusOnce(ctx context.Context, upid string) (proxmox.TaskStatus, error) + // TaskLogTail fetches up to limit trailing task-log lines — used to surface a guest-start + // task's warning text (the restore-test fetches it when the start exits "WARNINGS: N", so + // the advisory is reported without failing a guest that actually boots). + TaskLogTail(ctx context.Context, upid string, limit int) ([]string, error) } // guestDescription decodes the (string-valued) `description` key from a GuestConfig's