Compare commits

...

2 Commits

Author SHA1 Message Date
admin 0722b2cdb0 agent: a whole-box backup that cannot fit its local target is skipped with a reason before anything starts (R-685)
gates / gates (push) Successful in 13s
Free space is read from GET /nodes/<node>/storage — GET /storage carries no usage (found live, before release).

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0159rPz1ZhFKsS53msqPYxtS
2026-09-24 22:48:51 +02:00
admin 4fe2f81a32 CHANGELOG + REPORT + CONTEXT: v0.133.0 released (tag + package verified by download), not delivered
gates / gates (push) Successful in 13s
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0159rPz1ZhFKsS53msqPYxtS
2026-09-24 16:25:47 +02:00
6 changed files with 225 additions and 63 deletions
+29
View File
@@ -1,3 +1,32 @@
## v0.133.0 — a restore-test can never fill a box's disk; leftovers retried on a timer (2026-09-24, R-672, R-673)
> **RELEASED 2026-09-24** by `scripts/release-agent.sh` — tag `v0.133.0` (`9bdb4da`), sha256 `3aa303452b8c6be58573d00af01a0ab4a0d97e4f885ffecd0144a18ac24e69b6`, verified by an independent anonymous download. **NOT delivered** (needs an operator-signed `agent_update` job per box, R-530) and **NOT vouched**.
**MinAgent impact:** none required by any controller. Hub **v0.124.0** makes a thin pool CRITICAL at 90 %
(data or metadata) and keys the storage-fill alarm per pool per 6 h; an older hub still raises its generic
90/95 % storage-fill events from the same report.
- **R-672 — the space preflight** (`reconcile/restoretest_space.go`, provider `internal/restorespace`). Before
anything is journaled or created, a restore-test needs free data ≥ restored × 1.2 + 5 GiB on its target
(`backup.restore_test_space_factor` / `backup.restore_test_space_reserve_gib`) and room in a thin pool's
metadata. `restored` is the UNCOMPRESSED size — the vzdump log's "Total bytes written" (a file-backed
archive) or the PBS snapshot size; the archive FILE is never used (9201: 6.9 GB file, 22.6 GB restore). The
target moves OFF the tested guest's own pool when another storage is eligible (active, `rootdir`, and the
agent holds Datastore.AllocateSpace there) and fits. Anything unknown refuses. A refusal is reported to the
hub as the test's result (`pass=false`, `skipped=true`, "skipped: not enough space on …") — never a pass,
never dropped. The archive config is read once (it was read twice). Measured case: demo-hp 2026-09-24 —
the restore-test that filled `local-lvm` would now be refused (needs 32.1 GB, 23.2 GB free).
- **R-672 — a failed scratch teardown is retried every 10 minutes** (`Engine.RetryScratchTeardown`, the
daemon's janitor), not only by Recover at agent start; never a vmid a running test owns; after 3 failed
tries the operator is told through a failed restore-test record naming the scratch guest.
- **R-672 — a thin pool crossing 90 % requests an immediate host report** (`Observer.SetThinHighTrigger`, the
storage watchdog's read path, every few seconds; re-armed below 85 %), so the hub's alarm sees it in
seconds, not at the next 15-minute report.
- **R-673 — the stale-lock sweep runs on the same 10-minute timer** (it ran only at start: a stale
`snapshot-delete` lock blocked 9201's whole-box backups for five hours), holding the one-heavy-operation
gate so no agent backup can start between its "no vzdump running" check and its unlock.
- Red-proofs: six, each seen failing (REPORT).
## v0.132.0 — a controller that dies slowly is reported, not just restarted (2026-09-17, R-539)
> **RELEASED 2026-09-17** by `scripts/release-agent.sh` — tag `v0.132.0`, sha256 `4afe815749a41b327ebe4a98a4557ad2acffb1fa71740a3a8b8003473b835321`. **Vouched 2026-09-17** for Day-0 installs on the operator's word, together with golden **0.246.0** (the hub's R-120 gate required the newer golden first). Delivered to demo-hp and the N100 by an operator-signed `agent_update` job each (operator ruling 3 of 2026-09-16), not by a floor.
+9
View File
@@ -1,5 +1,14 @@
# CONTEXT — felhom-agent working state
> **2026-09-24 — v0.133.0 RELEASED, NOT DELIVERED (R-672, R-673).** Restore-test space preflight
> (`reconcile/restoretest_space.go`, `internal/restorespace`): uncompressed size from the vzdump log / PBS size,
> × 1.2 + 5 GiB, thin metadata, off the tested guest's pool, unknown refuses, reported as `skipped` non-pass.
> Janitor (`cmd/felhom-agent/janitor.go`) every 10 min: `Engine.RetryScratchTeardown` + stale-lock sweep under
> the heavy-op gate. Thin pool ≥ 90 % → immediate report (hub v0.124.0 alarms). **Operator rulings 2026-09-24
> (evening):** the scheduled restore-test is OFF on both demo hosts (`backup.restore_test_eval_interval_seconds:
> -1` — note: 0 means the 6 h DEFAULT, only a negative disables) until v0.133.0 is delivered there; saved configs
> `/etc/felhom-agent/agent.json.pre-r672`. demo-hp 9201 was repaired (stop, fsck, start; two Redis AOF tails cut).
> Snapshot of the current state + open threads. Authoritative history lives in `CHANGELOG.md` (top
> entry = current); the end-of-task detail lives in `REPORT.md`.
+22 -58
View File
@@ -1,65 +1,29 @@
# REPORT — agent v0.132.0: a controller that dies slowly is reported, not just restarted
# REPORT — agent v0.133.0: a restore-test can never fill a box's disk (2026-09-24, R-672, R-673)
**2026-09-17.** R-539, operator ruling 3 of 2026-09-16. Architecture: `felhom.eu/documentation/architecture/03-host-agent.md` (the supervisor and its budget).
Full record: `felhom.eu/documentation/audits/r672-2026-09-24/README.md`.
## Claims in the brief that turned out wrong — named first
## Shipped (released, not delivered)
Tag `v0.133.0` (`9bdb4da`), package sha256 `3aa30345…e69b6`, verified by anonymous download. Delivery needs the
operator's signed `agent_update` job per box.
1. **„Emit `controller_slow_crashloop` from the agent."** The agent has no event channel. It carries
timestamps in its heartbeat stanza and the **hub** mints the event when one moves. So the build was
three wire fields here **plus** a hub checker change (hub v0.117.0), not an event registration alone.
2. **„Five kills 20 min apart is too long — make the interval configurable for the test."** Not needed,
and not done: the proof restart from B.4(a) was already persisted, so four more real kills ~8 minutes
apart reached five in 24 hours inside the session, with the **production** window. 8 minutes keeps any
15-minute window at two restarts, so the fast brake never interferes.
- **Space preflight** before anything is created: free ≥ restored × 1.2 + 5 GiB, `restored` UNCOMPRESSED (vzdump
log "Total bytes written" / PBS snapshot size), thin metadata with room, off the tested guest's pool when
another eligible storage fits, unknown refuses, reported as a non-pass (`skipped`).
- **Scratch teardown retried every 10 min**; operator told once after 3 failed tries.
- **Thin pool ≥ 90 %** → immediate host report (hub v0.124.0 alarms `storage_fill_critical`, per pool per 6 h).
- **R-673:** the stale-lock sweep on the same timer, under the one-heavy-op gate.
## What shipped
## Red-proofs (each seen failing; files in `felhom.eu/documentation/audits/r672-2026-09-24/redproofs/`)
1. preflight removed → the 2026-09-24 restore issued again; 2. archive FILE size used → "the compressed file size
was used"; 3. timer pass a no-op → "the leaked scratch was not destroyed by the timer"; 4. sweep without the gate →
"the sweep ran while a backup held the gate"; 5. no 90 % edge → "0 report requests, want 1"; 6. every skip dropped →
"a space refusal never reached the host report". Full suite `go test ./...` green; `agent_gates.py` OK.
`internal/localapi/controllersupervisor.go`: beside the unchanged 3-in-15 brake, restarts the supervisor
performed in the last 24 hours. At the fifth, `slow_crashloop_since` moves (at most once per 24 h);
`slow_crashloop` and `restarts_24h` ride the stanza (`internal/hub/report.go`). Persisted per guest in
`/var/lib/felhom-agent/guests/<vmid>/controller-restarts-24h.json` (tmp + rename, 0600); unreadable or
corrupt → WARN and a clean start. Never stops restarting. Deliberate kills count. The startup line prints
the new limits.
## Red-proofs — each seen failing, then passing
| test | break | failure seen |
|---|---|---|
| `TestControllerSupervisor_SlowCrashloop` | no counter | `five restarts 20 minutes apart did not raise slow_crashloop — this is R-539` |
| same | once-per-24h guard removed | `the raise moved again on the 6th restart … mailed per restart` |
| `…SlowCounterSurvivesAgentRestart` | save removed | `the agent restart reset the slow counter … Restarts24h:1` |
Negative control: restarts 7 h apart never raise it. Wire shape extended (`restarts_24h`, `slow_crashloop`).
## Gates and release
`go build ./... && go vet ./... && go test ./...` — green, 30 packages. `agent_gates.py --fast` — all OK.
Released by `scripts/release-agent.sh`: tag `v0.132.0`, sha256
`4afe815749a41b327ebe4a98a4557ad2acffb1fa71740a3a8b8003473b835321`, verified by independent download.
**Not vouched** for Day-0 installs (the operator's act). Code `18d03bd`, release record `CHANGELOG` commit after it.
## Delivery — operator-signed, per box (ruling 1 of 2026-09-16)
| box | signed | authorised → completed | committed | startup line |
|---|---|---|---|---|
| demo-hp (`demo-hp-bb76ea`) | 08:27:36Z | 08:29:25Z | 08:30:29Z | `slow_crashloop_max=5 slow_crashloop_window=24h0m0s` |
| N100 (`demo-felhom-8363b5`) | 08:27:36Z | 08:34:48Z | 08:35:52Z | same |
Peti's box: not touched. Evidence: `felhom.eu/documentation/audits/evidence-chaos-fixes-2026-09-17/partC-agent-update.txt`.
## Live validation — PASS, production window
On demo-hp guest 9201: five controller kills (08:51:53Z from B.4(a), then 08:57, 09:05, 09:13, 09:21),
each restarted by the agent in 42–56 s, never by hand; the fast brake never armed. At #5:
`SLOW CRASH-LOOP — … restarts_24h=5 window=24h0m0s threshold=5`; persisted file holds the five times and the
raise. The hub minted `controller_slow_crashloop` at 09:29:40Z and **exactly one** operator mail arrived.
Evidence: `…/partC-live-slow-crashloop.txt`.
## Teardown
Nothing provisioned. Stated effect on the demo box: 9201's counter holds five restarts and stays raised
until 09:22Z on 2026-09-18; it cannot mail again inside that window.
## Live (demo-hp, the on-demand `--selftest=restore-test`, cadence OFF)
(a) factor 10 → refused: needs 215.5 GiB, has 22.1 GiB. (b) normal margin → refused: restoring 21.1 GiB needs 30.3 GiB,
has 22.1 GiB — correct: no full restore-test fits demo-hp under 80 % pool use. (c) a forced teardown failure could not
run live (it needs a scratch guest, which (b) shows cannot be created within the 80 % rule) — unit tests only. Pool
58.99 % before and after every run; nothing created.
## Observations
1. The persisted file writes the zero raise time as `"0001-01-01T00:00:00Z"` (Go `omitempty` does not omit a zero `time.Time`). **NOT-A-FINDING: the loader reads it back as zero (`IsZero`), which the live file and the restart test both exercised; cosmetic only.**
1. demo-hp has no second eligible storage for a restore-test: `nvme-scratch` takes `rootdir`, but the agent holds no grant there. FILED: R-672
+18 -5
View File
@@ -24,11 +24,13 @@ type fakeBackupAPI struct {
cfgErr error
content []proxmox.StorageContent
contentErr error
storages []proxmox.Storage // returned by ListStorage (the local-prune scope gate)
storageErr error
vzdumps []proxmox.VzdumpOptions
logLines []string // returned by TaskLogTail (e.g. "INFO: backup mode: stop")
waitGate chan struct{} // if non-nil, WaitTask blocks until closed (8B.2 watcher timing)
storages []proxmox.Storage // returned by ListStorage (the local-prune scope gate) — DEFINITIONS: like
// production's GET /storage, it never carries usage; ListStorage strips Avail/Used (R-685's live lesson)
nodeStorages []proxmox.Storage // returned by NodeStorage (GET /nodes/{node}/storage — WITH usage)
storageErr error
vzdumps []proxmox.VzdumpOptions
logLines []string // returned by TaskLogTail (e.g. "INFO: backup mode: stop")
waitGate chan struct{} // if non-nil, WaitTask blocks until closed (8B.2 watcher timing)
}
func (f *fakeBackupAPI) Vzdump(_ context.Context, o proxmox.VzdumpOptions) (string, error) {
@@ -48,6 +50,17 @@ func (f *fakeBackupAPI) StorageContent(_ context.Context, _ string) ([]proxmox.S
return f.content, f.contentErr
}
func (f *fakeBackupAPI) ListStorage(_ context.Context) ([]proxmox.Storage, error) {
out := make([]proxmox.Storage, len(f.storages))
for i, s := range f.storages {
s.Avail, s.Used, s.Total = 0, 0, 0 // GET /storage has no usage — a fake that had it hid R-685's defect
out[i] = s
}
return out, f.storageErr
}
func (f *fakeBackupAPI) NodeStorage(_ context.Context) ([]proxmox.Storage, error) {
if f.nodeStorages != nil {
return f.nodeStorages, f.storageErr
}
return f.storages, f.storageErr
}
func (f *fakeBackupAPI) TaskLogTail(_ context.Context, _ string, _ int) ([]string, error) {
+83
View File
@@ -0,0 +1,83 @@
package backup
import (
"context"
"strings"
"testing"
"gitea.dooplex.hu/admin/felhom-agent/internal/proxmox"
)
// R-685 (v0.134.0) — a whole-box backup that cannot fit its LOCAL target is a named skip BEFORE anything
// starts, with the numbers in the record's Error, never a vzdump that fills the disk and fails.
const gib = int64(1) << 30
func spaceAPI(avail int64, lastArchive int64, typ string) *fakeBackupAPI {
api := &fakeBackupAPI{vzdumpUPID: "UPID:vzdump:1",
storages: []proxmox.Storage{{Storage: "local", Type: typ, Content: "backup", Avail: avail}}}
if lastArchive > 0 {
api.content = []proxmox.StorageContent{{VolID: "local:backup/vzdump-lxc-9201-2026_09_24-21_59_25.tar.zst",
Content: "backup", VMID: 9201, Size: lastArchive, CTime: 1790280000}}
}
return api
}
// TestR685_BackupThatCannotFitIsSkipped — demo-hp's shape: an 8.2 GB archive, 4 GiB free. No vzdump is
// started; the record says why, with the numbers, under a stable prefix.
//
// COMPANION RED-PROOF (REPORT.md): drop the spaceFits call from backup() — this test fails at "a vzdump
// was started on a target that cannot hold it".
func TestR685_BackupThatCannotFitIsSkipped(t *testing.T) {
api := spaceAPI(4*gib, 8182759056, "dir")
r := NewBackupRunner(api, "local", proxmox.ModeSnapshot, "", "keep-last=1", quiet())
rec, err := r.Backup(context.Background(), 9201)
if len(api.vzdumps) != 0 {
t.Fatalf("a vzdump was started on a target that cannot hold it: %+v", api.vzdumps)
}
if err == nil || rec.Success || !strings.HasPrefix(rec.Error, BackupSkipNoSpacePrefix) {
t.Fatalf("want a named skip, got err=%v rec=%+v", err, rec)
}
for _, want := range []string{"4.0 GiB free", "7.6 GiB", "10.5 GiB"} {
if !strings.Contains(rec.Error, want) {
t.Errorf("the reason must carry the numbers (%q missing): %s", want, rec.Error)
}
}
}
// TestR685_BackupThatFitsRuns — the same archive with 16 GiB free (demo-hp after tonight's prune) runs.
func TestR685_BackupThatFitsRuns(t *testing.T) {
api := spaceAPI(16*gib, 8182759056, "dir")
r := NewBackupRunner(api, "local", proxmox.ModeSnapshot, "", "keep-last=1", quiet())
_, _ = r.Backup(context.Background(), 9201)
if len(api.vzdumps) != 1 {
t.Fatalf("a backup that fits must run, vzdumps=%d", len(api.vzdumps))
}
}
// TestR685_FailsOpen — never refuse on what is not KNOWN: a PBS target, a first backup (no archive to
// size from), an unknown free figure, or a storage list that cannot be read.
func TestR685_FailsOpen(t *testing.T) {
cases := map[string]*fakeBackupAPI{
"pbs target": spaceAPI(1*gib, 8*gib, "pbs"),
"first backup": spaceAPI(1*gib, 0, "dir"),
"avail unknown": spaceAPI(0, 8*gib, "dir"),
"storage list error": func() *fakeBackupAPI {
a := spaceAPI(1*gib, 8*gib, "dir")
a.storageErr = context.DeadlineExceeded
return a
}(),
}
for name, api := range cases {
target := "local"
if name == "pbs target" {
api.storages[0].Storage = "felhom-pbs"
target = "felhom-pbs"
}
r := NewBackupRunner(api, target, proxmox.ModeSnapshot, "", "", quiet())
_, _ = r.Backup(context.Background(), 9201)
if len(api.vzdumps) != 1 {
t.Errorf("%s: the preflight must fail OPEN, but no vzdump ran", name)
}
}
}
+64
View File
@@ -22,6 +22,10 @@ type BackupAPI interface {
StorageContent(ctx context.Context, store string) ([]proxmox.StorageContent, error)
// ListStorage enumerates storages (name+type) — used to scope local-only retention (never prune PBS).
ListStorage(ctx context.Context) ([]proxmox.Storage, error)
// NodeStorage is GET /nodes/{node}/storage — the storages WITH live usage (avail/used). R-685's space
// preflight reads free space HERE: ListStorage (GET /storage) is the cluster DEFINITIONS and carries no
// usage at all — measured live 2026-09-24 on demo-hp, where reading it let a backup through.
NodeStorage(ctx context.Context) ([]proxmox.Storage, error)
// TaskLogTail reads trailing task-log lines — used to read the ACTUAL vzdump mode
// (PVE may downgrade a requested snapshot to stop for a stopped guest — spike B1).
TaskLogTail(ctx context.Context, upid string, limit int) ([]string, error)
@@ -170,6 +174,16 @@ func (r *BackupRunner) backup(ctx context.Context, vmid int, onSnapshot func())
rec.UncoveredVolumes = []string{}
}
// R-685 (v0.134.0): will the new archive FIT on a local target? Asked before anything runs, so a
// target that cannot hold it is a named SKIP with the numbers, not a nightly "No space left on
// device" that only the vzdump log explains (demo-hp, every night from 2026-09-23 — R-684).
if ok, why := r.spaceFits(ctx, vmid); !ok {
rec.Error = BackupSkipNoSpacePrefix + why
rec.DurationSeconds = time.Since(start).Seconds()
r.logger.Warn("backup SKIPPED by the space preflight (R-685) — nothing was started", "vmid", vmid, "target", r.target, "reason", why)
return rec, fmt.Errorf("backup: %s", rec.Error)
}
upid, err := r.api.Vzdump(ctx, proxmox.VzdumpOptions{
VMID: vmid, Storage: r.target, Mode: r.mode, Notes: r.notes,
PruneBackups: r.localPruneSpec(ctx), // local target → keep-last=N; PBS/unknown → "" (no prune)
@@ -217,6 +231,56 @@ func (r *BackupRunner) backup(ctx context.Context, vmid int, onSnapshot func())
return rec, nil
}
// BackupSkipNoSpacePrefix starts a backup record's Error when the space preflight refused (R-685) — a
// stable prefix the controller's page and the hub can key on.
const BackupSkipNoSpacePrefix = "skipped: not enough space: "
// Space preflight margins (R-685): the new archive is predicted as the newest archive of this guest on the
// target × backupSpaceGrowth, plus backupSpaceFloorBytes of headroom for the host. MEASURED 2026-09-24:
// demo-hp 9201's archives grew 5.8 → 6.2 → 6.9 → 7.6 GB in four nights (+10 % a night at worst), so 1.25
// covers two nights' growth. PVE prunes old archives only AFTER a successful backup, so the free space
// must hold the new archive while every kept one still exists.
const (
backupSpaceGrowth = 1.25
backupSpaceFloorBytes = int64(1) << 30
)
// spaceFits answers whether a new archive of vmid fits on a LOCAL (non-PBS) target. It FAILS OPEN — a
// backup is the thing being protected, so an unreadable storage, an unknown type or a first backup (no
// previous archive to size from) proceeds and says so; only a POSITIVE "it does not fit" refuses.
func (r *BackupRunner) spaceFits(ctx context.Context, vmid int) (bool, string) {
// NodeStorage, never ListStorage: only the node view carries avail (see BackupAPI.NodeStorage).
stores, err := r.api.NodeStorage(ctx)
if err != nil {
r.logger.Warn("backup: space preflight could not read storage usage — proceeding (fail-open)", "target", r.target, "err", err)
return true, ""
}
var st *proxmox.Storage
for i := range stores {
if stores[i].Storage == r.target {
st = &stores[i]
break
}
}
if st == nil || st.Type == "pbs" || st.Avail <= 0 {
return true, "" // PBS dedups and has its own lifecycle; an unknown avail never refuses
}
_, last, err := r.latestArchive(ctx, vmid)
if err != nil || last <= 0 {
r.logger.Info("backup: space preflight has no previous archive to size from — proceeding", "vmid", vmid, "target", r.target)
return true, ""
}
need := int64(float64(last)*backupSpaceGrowth) + backupSpaceFloorBytes
if st.Avail >= need {
r.logger.Info("backup: space preflight passed", "vmid", vmid, "target", r.target, "last_archive_bytes", last, "need_bytes", need, "avail_bytes", st.Avail)
return true, ""
}
return false, fmt.Sprintf("%s has %s free; the last archive of guest %d was %s, so a new one needs about %s (old archives are removed only after a successful backup)",
r.target, humanGiB(st.Avail), vmid, humanGiB(last), humanGiB(need))
}
func humanGiB(b int64) string { return fmt.Sprintf("%.1f GiB", float64(b)/(1<<30)) }
// watchForSnapshot polls the running backup's task log until it sees the storage-snapshot marker
// (→ onSnapshot once) or the requested mode is reported as `stop` (→ downgraded; the marker will
// never come, so stop watching) or ctx is cancelled (backup finished). Best-effort: a log-read