restore-test: verdict is liveness, not start-task exitstatus (v0.7.0)

Fixes the crying-wolf false-fail surfaced by the live hub-enrollment runbook:
PVE's guest-start task exits "WARNINGS: 1" for the benign systemd-nesting
advisory, and WaitTask treated any non-OK exitstatus as failure, so the verdict
was decided by an advisory exit code before the real boot check ran. Every
modern-distro restore-test reported pass:false.

- proxmox.WaitOptions.AllowWarnings (opt-in; default keeps all callers strict)
- restore-test start step accepts warnings, surfaces them, verdict stays waitRunning
- RestoreTestResult.StartWarnings/.WarningsRecognized + version-free "enable
  nesting" recognizer (can't rot back at systemd 258+); GuestAPI.TaskLogTail
- hub.RestoreTest.warnings/.warnings_recognized wire fields (consumed by hub v0.7.5)
- scheduler logs clean / passed-with-recognized / passed-with-unrecognized warnings
- tests: WaitTask warnings matrix; restore-test pass/fail-on-liveness; version-free
  regression guard (systemd 256-300)

Single agent bump 0.6.0 -> 0.7.0 covering the agent half of both task phases.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
2026-06-09 19:30:03 +02:00
parent 7eea638b92
commit 6e86483185
13 changed files with 395 additions and 126 deletions
+46
View File
@@ -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 256300,
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
+1 -1
View File
@@ -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=<v>"`; `--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=<v>"`; `--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
+54 -113
View File
@@ -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 **256300**,
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.1C.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 78 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.
+1 -1
View File
@@ -33,7 +33,7 @@ import (
// version is the agent version. Overridable at build time with
// -ldflags "-X main.version=<v>"; defaults to the in-repo CHANGELOG version.
var version = "0.6.0"
var version = "0.7.0"
func main() {
var (
+9 -7
View File
@@ -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()
+12 -3
View File
@@ -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)
}
}
+8
View File
@@ -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
+15
View File
@@ -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)
}
+49
View File
@@ -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
+9
View File
@@ -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
+56 -1
View File
@@ -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 <N> 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
+131
View File
@@ -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{
+4
View File
@@ -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