diff --git a/CHANGELOG.md b/CHANGELOG.md index 8ee6fa1..016d265 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,32 @@ +## v0.294.0 — the off-site clean-up deletes honest old copies; a first install survives the image clean-up; failed compose logs its reason; the move-aside line names its destination (R-867, R-863, R-864, R-869) (2026-10-05) + +**MinAgent: 0.131.0** (unchanged). No new household string. + +- **R-867.** The fake-snapshot guard's "young" line is now built from the SAME constants as the retention policy + (`keepDaily` 7 / `keepWeekly` 4 / `keepMonthly` 6 → `retentionPolicy`): a removal is refused only when its CALENDAR + day is fewer than `keepDaily` days before today (in the snapshot's own zone, as restic buckets it) and no newer + same-day snapshot of its group supersedes it. v0.289–0.293 used a fixed 8-day age, which sat inside the keep window: + the snapshot a keep-7-dailies policy drops each night is 7 days + seconds old, so every window on a box with more than + 7 nightly snapshots refused, deleted nothing and mailed `offsite_prune_guard_refused` (measured demo-felhom + 2026-10-05 02:15 UTC). Every other refusal is unchanged: future-dated, newer than the hub allows, a plan above the + week's cap (R-833's grant still raises it), the lab's 13-fake shape. Tests run restic 0.14.0's policy itself + (`restic0140Plan`, proven identical to the 0.14.0 binary over 92 snapshots): the measured shape, 60 nights × 3 apps + with two same-day manual runs across a month boundary, weekly windows, and a skew-window fake that the line still + refuses. Recorded limit: past-dated gap-fills that steer OLDER keeps stay R-822's residual (bounded by the cap and + the hub's count check), as before. +- **R-863.** The image clean-up no longer runs while ANY compose command that can pull is running (`up`, `pull`, + `create`, `run` — install, update, restore, undo, the FileBrowser sync). New `dockerexec.BeginImageWork` / + `TryImageCleanup`: pulling commands hold a shared lock for their whole run; a clean-up pass takes it exclusively + without waiting and, when it cannot, does not run. The one-time clean-up writes its marker ONLY after a pass that ran + and is retried every 2 minutes (at most 30 times) instead of being skipped until the next start. Measured cause: on + the fresh Tester 1 box the one-time pass deleted `mariadb@sha256:…` (untagged, named by no container yet) one second + before `compose up` created BookStack's database container. +- **R-864.** A failed compose command logs and returns the TAIL of stderr (new `tailStr`, rune-safe) — compose prints + pull progress first and the reason last; the head kept only "Image … Pulling". +- **R-869.** The decision-78 move-aside log line now prints the destination the hub returned. +- Tests: `TestOffsiteGuard_RealPolicy*`, `TestRetentionPolicy_BuiltFromTheGuardConstants`, `TestR863_*`, `TestR864_*`, + `TestR869_*`. Red-proofs (9): `felhom.eu/documentation/audits/night-fixes-2026-10-05/part{A,B,D}/`. + ## v0.293.0 — the controller heals itself after the guest's Docker socket is re-created (R-860, generalises R-858) (2026-10-04) **MinAgent: 0.131.0** (unchanged). No new household string. diff --git a/REUSE.md b/REUSE.md index 807b7f5..592a512 100644 --- a/REUSE.md +++ b/REUSE.md @@ -30,7 +30,8 @@ | `stacks.OpenSignupWindow` / `SignupBlocked` / `SetupGateProbe` · `web.ServeSignupClosed` (v0.281.0, decision 47) | controller/internal/stacks/signup_block.go · controller/internal/web/setup_gate.go | `(name)` | Sign-up closed at the app's own address once the gate opens; the household's 15-minute window; the press asks the probe | **The block goes up BEFORE the gate comes down** (a failed write keeps the gate closed). Never on an app this box did not gate | | `family.Store` · `stacks.FamilyGateHost` / `familyGateTick` / `FamilyExceptRegexp` · `web.ServeFamilyGateAuth` / `ServeFamilyStart` / `ServeFamilyLogin` / `ServeFamilyLogout` (v0.287.0, decisions 63/64) | controller/internal/family/family.go · controller/internal/stacks/family_gate.go · controller/internal/web/family_gate.go | store `Add/Reset/Remove/Verify/NewSession/Valid/EndSession` · `(host)` / `()` / `(prefix)` · handlers | The PERMANENT family gate: family members with their own logins in front of a `family_gate: true` app | **A family cookie never opens the dashboard** (RequireAuth reads only `felhom_session`); the app cookie names a STORE session, so the store is asked on every request (reset/remove/logout end access at once); **every exception goes through `FamilyExceptRegexp`** (anchored — never a hand-written PathPrefix); door written before the first start, like the setup gate. `familyStoreOverride` is the test seam. Fifth atomic-write helper (family.json, fsync) — see §6 | | `stacks.OpenInstallHold` / `installHoldTick` (v0.284.0, R-741) | controller/internal/stacks/install_hold.go | `(name, by)` / `()` | An `after_install` app held behind the setup gate's door until its known login is replaced | **Written before the first start**, like the gate; opens on `after_install` success or the household's "I changed it"; the door (`SetupGateHost`) reads holds first | -| `stacks.RetainImagesAfterUpdate` / `RetainImagesAfterRemove` / `RunImageRetentionOnce` · seam `imageDocker` (v0.284.0, decision 53) | controller/internal/stacks/image_retention.go | `(name, previous)` / `(name, repos)` / `()` | Deletes an app's images older than its running + previous one | **The keep set is box-wide and read at delete time** (containers, installed composes, installed/previous records); exact id, never forced or pruned; skipped while any update runs; tests use the `imageDocker` seam, never Docker | +| `stacks.RetainImagesAfterUpdate` / `RetainImagesAfterRemove` / `RunImageRetentionOnce` (→ `(deleted, done)` since v0.294.0) / `RunImageRetentionOnceUntilDone` · seam `imageDocker` (v0.284.0, decision 53) | controller/internal/stacks/image_retention.go | `(name, previous)` / `(name, repos)` / `()` | Deletes an app's images older than its running + previous one | **The keep set is box-wide and read at delete time** (containers, installed composes, installed/previous records); exact id, never forced or pruned; skipped while any update runs AND while any image-pulling compose command runs (R-863, `dockerexec.TryImageCleanup`); the one-time pass writes its marker only after a pass that RAN; tests use the `imageDocker` seam, never Docker | +| `dockerexec.BeginImageWork(args)` / `TryImageCleanup()` / `ImagePulling(args)` (v0.294.0, R-863) | controller/internal/dockerexec/imagework.go | `defer dockerexec.BeginImageWork(args)()` | **Every NEW place that runs `compose up/pull/create/run` must hold it** (the stacks compose helpers, appexport's restore and the FileBrowser sync already do) | An image pulled by compose is named by no container until compose creates one; a clean-up pass in that window deleted it (measured, R-863). The pass takes the lock exclusively without waiting; pulling commands wait for a running pass (seconds) | | `stacks.RetainControllerImages(ControllerImageRecord)` · `selfupdate.UpdateState.RecordedPrevious` (v0.285.0, decision 56) | controller/internal/stacks/controller_image_retention.go | `({Repo, Running, Previous})` | Deletes controller images older than the running + previous one | The previous comes from the SWAP RECORD (success onto the running version), version order only as the fallback; versions above the running one and non-version tags are kept; skipped while the controller swaps itself; same `imageDocker` seam | | `stacks.CloseSignupNow` / `CloseSignupOffered` / `applyNativeLock` (v0.282.0, decisions 47/49) | controller/internal/stacks/after_setup.go | `(name)` | The app's own sign-up switch after the setup; "close sign-up now" for an app installed before the rule | **Check the installed compose reads the variable** (an old install carries the old compose until its next update) — never record a lock that is not there. One run per app at a time (`nativeLockBusy`) | | `backup.judgeCopy` / `HollowCopies` / `SetHollowCopyNotify` (Part D, v0.279.0) | controller/internal/backup/hollow_watch.go | `(app, tier, unitDir)` | A RUNNING app whose newest copy holds no data → operator digest once/day + page sentence | Uses `unitCarriesData` (the manifest, never size); a stopped held app is never flagged | @@ -246,7 +247,7 @@ | `metrics.FetchContainerLogTail` | controller/internal/metrics/logscanner.go | `(name, tailLines) (string, error)` | Raw per-container `docker logs --tail=N` | 15s timeout; caller caps/redacts (capTailLines) | | `ConfigRefresher.Reconcile` | controller/internal/report/config_refresh.go | `(ackVersion int)` | Pull-based config refresh | Re-pulls controller.yaml (re-merging local_api), then graceful self-restart; first-run = baseline, no restart | | `offsiteapply.HubRegistrar` / `HubWindowClient` / `PinnedProber` (v0.289.0, decisions 68–69) | controller/internal/offsiteapply/seams.go | `Register(ctx,pub)(fp,err)` · `Confirm` · `MoveAside` · `Open/Close` window · `Probe(ctx,host,user,port,kh,privPEM) bool` | EVERY off-site key install, the hub move-aside, the clean-up window | **The box never handles the sub-account password** — there is no consume path any more. `PinnedProber` is a POSITIVE observable (exit 0 + rclone output); "authenticates" is NOT enough — an unpinned key authenticates and can delete. | -| `Manager.offsiteWindowRetention` + `offsiteGuard` (v0.289.0, R-822) | controller/internal/backup/offbox_window.go | `(ctx, base, env, why)` · pure `(all, plan, now, newestAllowed, max) (ids, refuse)` | THE retention step for both callers (after a run, over quota) | Pinned tier: no window → nothing deleted; the guard runs BEFORE any forget; a young snapshot superseded the same day is EXCLUDED, any other young removal / future date / plan above `max_remove` REFUSES; forget is by explicit ids, oldest first. A due abandonment goes to `OffsiteAbandonClient` (hub, 7-day wait). NAS tier: the old SP-2 policy, unchanged. | +| `Manager.offsiteWindowRetention` + `offsiteGuard` (v0.289.0, R-822) | controller/internal/backup/offbox_window.go | `(ctx, base, env, why)` · pure `(all, plan, now, newestAllowed, max) (ids, refuse)` | THE retention step for both callers (after a run, over quota) | Pinned tier: no window → nothing deleted; the guard runs BEFORE any forget; "young" = fewer than `keepDaily` CALENDAR days old (v0.294.0, R-867 — the line is built from the same constants as `retentionPolicy`; never an hour count); a young snapshot superseded the same day is EXCLUDED, any other young removal / future date / plan above `max_remove` REFUSES; tests run restic 0.14.0's policy itself (`restic0140Plan`, proven identical to the binary); forget is by explicit ids, oldest first. A due abandonment goes to `OffsiteAbandonClient` (hub, 7-day wait). NAS tier: the old SP-2 policy, unchanged. | | `offsiteapply.SettleProvider` / `SettleFunc` / `Bridge.AwaitSettle` / `ReconcileWhenSettled` (R-71a, v0.162.0) | controller/internal/offsiteapply/offsiteapply.go + seams.go | `SettleState() (version, floor string, updateRunning, floorKnown bool)` | THE settle-gate: defers the offsite one-time-password consume past a managed day-0 floor-update (the F10 race). Wire the `SettleFunc` adapter over `updater.GetFloor()`/`IsUpdateRunning()` — **the updater's knowledge is the ONE floor source; never fetch the floor a second way**. Gate ONLY the bridge goroutine, and only when an updater exists (nil `Settle` = reconcile immediately). Bounds `settlePoll`/`settleFloorSubBound`/`settleOverallBound`; the floor is in-memory (report-ACK-derived, ~5–10 s), NOT persisted → unknown until the first ACK on any restart. Inject `Now`/`Sleep` in tests (no real sleeps). B′: at/above-floor GOes on the first poll, zero wait. Do NOT touch the consume/persist order or the 404 contract — ordering only | | `bootstrap.MaybeIngest` / `RefreshConfig` | controller/internal/bootstrap/bootstrap.go | bootstrap.json → controller.yaml | Day-0 + refresh | Overwrites controller.yaml, NEVER settings.json | | `api.GracefulSelfRestart` | controller/internal/api/selfrestart.go | `(logger)` | Controller self-restart | Detached exit; bootstrap unit re-runs the image | @@ -396,7 +397,7 @@ Cross-repo edges: | Duplication | Locations | |---|---| | Atomic write ×4 (+inline in settings.save) | controller/internal/backup/recovery_unit.go `atomicWrite`; controller/internal/bootstrap/bootstrap.go `writeFileAtomic`; controller/internal/setup/handlers.go `atomicWriteFile`; controller/internal/api/router.go `writeConfig0600` | -| String truncation ×3 | controller/internal/util/strings.go `TruncateStr` (rune-safe, 1 caller); controller/internal/stacks/manager.go `truncateStr` (byte-based, widely used); controller/internal/backup/offbox.go `truncate` | +| String truncation ×4 | controller/internal/util/strings.go `TruncateStr` (rune-safe, 1 caller); controller/internal/stacks/manager.go `truncateStr` (byte-based HEAD, widely used) and `tailStr` (rune-safe TAIL, v0.294.0 R-864 — use it for a command's stderr: the error is printed last); controller/internal/backup/offbox.go `truncate` | | humanizeBytes ×3 | controller/internal/appbackup/appdata.go `HumanizeBytes` (canonical) + private twin; controller/internal/appexport/estimate.go `humanizeBytes`; controller/internal/backup/appbackup_bridge.go wrapper (deliberate bridge) | | copyFile ×2 | controller/internal/stacks/migrate.go (returns bytes) vs controller/internal/appexport/export.go | | dir-size ×6 | controller/internal/stacks/delete.go `getDirSizeBytes`/`getDirSizeHuman`; controller/internal/backup/tier2.go `dirSizeBytes` (du -sb); controller/internal/appexport/estimate.go `dirSize`+`duBytes`; controller/internal/appexport/export.go `calcDirSize`; controller/internal/web/handlers.go `dirSizeHuman` | diff --git a/controller/cmd/controller/main.go b/controller/cmd/controller/main.go index 67ed5cf..280468c 100644 --- a/controller/cmd/controller/main.go +++ b/controller/cmd/controller/main.go @@ -1731,7 +1731,9 @@ func main() { return case <-time.After(3 * time.Minute): } - stackMgr.RunImageRetentionOnce() + // R-863: retried every 2 minutes while an install/update/restore is pulling (a new household's first + // installs land exactly here), instead of deleting an image compose has pulled but not yet used. + go stackMgr.RunImageRetentionOnceUntilDone(ctx, 2*time.Minute, 30) // decision 56 (R-745): the controller's own images — keep the running one and the one before it. At every // start, 3 minutes in: a swap has ended by then (the agent's verify window is 90 s), so the image the agent // would roll back to is the running one, and the one before it is in the swap record read here. diff --git a/controller/internal/appexport/restore.go b/controller/internal/appexport/restore.go index 2047d42..80fd964 100644 --- a/controller/internal/appexport/restore.go +++ b/controller/internal/appexport/restore.go @@ -938,6 +938,7 @@ func classifyDBImage(service, image, container string) *dbServiceInfo { // composeExecEnv runs docker compose in the given stack directory with env vars. func composeExecEnv(stackDir string, env map[string]string, args ...string) ([]byte, error) { + defer dockerexec.BeginImageWork(args)() // R-863: no image clean-up while a restore may pull cmdArgs := append([]string{"compose"}, args...) ctx, cancel := context.WithTimeout(context.Background(), 5*time.Minute) defer cancel() diff --git a/controller/internal/backup/offbox.go b/controller/internal/backup/offbox.go index 14feb4e..46bef1e 100644 --- a/controller/internal/backup/offbox.go +++ b/controller/internal/backup/offbox.go @@ -331,8 +331,8 @@ func (m *Manager) resetOrphanedRepo(ctx context.Context, base, env []string, rea if err != nil { return fmt.Errorf("offbox move-aside failed: %w", err) } + newPath = np // R-869 (v0.294.0): assigned BEFORE the log line — v0.293.0 logged an empty destination m.logger.Printf("[INFO] [offbox] the hub set the orphaned repo aside: %s -> %s (nothing deleted)", t.RepoPath, newPath) - newPath = np } else { port := t.Port if port == 0 { diff --git a/controller/internal/backup/offbox_window.go b/controller/internal/backup/offbox_window.go index 4a8be9e..3fdcbb6 100644 --- a/controller/internal/backup/offbox_window.go +++ b/controller/internal/backup/offbox_window.go @@ -5,6 +5,7 @@ import ( "encoding/json" "fmt" "sort" + "strconv" "strings" "time" ) @@ -22,9 +23,14 @@ import ( // snapshot for removal. So, refuse when: // - any snapshot is dated in the future (beyond offsiteGuardSkew), or after the hub's newest-allowed // bound (the moment the window opened, plus the same skew); -// - the plan would remove a snapshot younger than offsiteGuardMinAge — the honest policy -// (--keep-daily 7) never removes the newest snapshot of any of the last 7 days, while a poisoning -// shape does exactly that. +// - the plan would remove a snapshot whose calendar day is fewer than keepDaily days before today and +// that is not superseded the same day — the honest policy (--keep-daily keepDaily) never does that, +// while a poisoning shape does exactly that. v0.294.0 (R-867): the line is DERIVED from keepDaily, the +// same constant the policy is built from. v0.289–0.293 used a fixed 8-day AGE, which sat inside the +// keep window: the snapshot a keep-7-dailies policy drops each night is 7 days + seconds old, so every +// window on a box with more than 7 nightly snapshots refused and mailed an error (measured +// demo-felhom 2026-10-05). Pinned by TestOffsiteGuard_RealPolicy* (the policy itself, simulated as +// restic 0.14.0 applies it, over 15+ nightly snapshots and a month boundary). // And a plan larger than MaxRemove (the hub's number for one week) REFUSES (v0.290.0, per the 2026-10-04 // brief, replacing v0.289's cap). The cost, recorded (R-96 rule 4): after a long gap without windows the // honest backlog exceeds a week and the guard refuses until the operator grants a window by hand — R-833. @@ -33,9 +39,14 @@ import ( // // Pinned by TestOffsiteGuard_* (offbox_window_test.go), including the lab's 13-fake shape. +const offsiteGuardSkew = time.Hour + +// The ruled retention policy (SP-2), as constants: BOTH the policy's arguments and the guard's day line +// are built from these, so the guard can never sit inside the keep window (R-867). const ( - offsiteGuardSkew = time.Hour - offsiteGuardMinAge = 8 * 24 * time.Hour + keepDaily = 7 + keepWeekly = 4 + keepMonthly = 6 ) // OffsiteWindow is the hub's answer to "may I prune now?". @@ -67,7 +78,20 @@ type OffsiteWindowClient interface { func (m *Manager) SetOffsiteWindowClient(c OffsiteWindowClient) { m.offsiteWindow = c } // retentionPolicy is the ruled policy, unchanged since SP-2 (`--group-by host,tags`). -var retentionPolicy = []string{"--group-by", "host,tags", "--keep-daily", "7", "--keep-weekly", "4", "--keep-monthly", "6"} +var retentionPolicy = []string{"--group-by", "host,tags", + "--keep-daily", strconv.Itoa(keepDaily), "--keep-weekly", strconv.Itoa(keepWeekly), "--keep-monthly", strconv.Itoa(keepMonthly)} + +// calendarDaysBefore: how many calendar days s lies before now, both read in s's own zone — the zone +// restic 0.14.0 buckets a snapshot's day in (the offset stored with the snapshot). Edge, recorded: in the +// hour after local midnight on a DST change, a box whose snapshots carry two different offsets can read one +// day short; the guard then REFUSES (the safe direction) and the next week's window passes. +func calendarDaysBefore(s, now time.Time) int { + loc := s.Location() + a, b := s.In(loc), now.In(loc) + da := time.Date(a.Year(), a.Month(), a.Day(), 0, 0, 0, 0, time.UTC) + db := time.Date(b.Year(), b.Month(), b.Day(), 0, 0, 0, 0, time.UTC) + return int(db.Sub(da).Hours() / 24) +} type guardSnap struct { ID string `json:"id"` @@ -98,7 +122,8 @@ func supersededSameDay(s guardSnap, all []guardSnap) bool { } // offsiteGuard is the PURE decision: from all snapshots and the policy's remove-plan, either the ids to -// remove (oldest first) or a refusal reason. v0.290.0 (R-824): a YOUNG snapshot that a newer same-day +// remove (oldest first) or a refusal reason. v0.294.0 (R-867): "young" means fewer than keepDaily calendar +// days before today, not an age in hours. v0.290.0 (R-824): a YOUNG snapshot that a newer same-day // snapshot of its group supersedes is EXCLUDED (kept for a later window, when it is old) instead of // refusing the run — v0.289.x refused every window after any manual run. A young removal WITHOUT that // explanation still refuses: it is the poisoning signature. Future-dated snapshots, snapshots newer than @@ -114,12 +139,12 @@ func offsiteGuard(all, plan []guardSnap, now, newestAllowed time.Time, maxRemove } var keep []guardSnap for _, s := range plan { - if now.Sub(s.Time) < offsiteGuardMinAge { + if calendarDaysBefore(s.Time, now) < keepDaily { if supersededSameDay(s, all) { - continue // excluded: removed in a later window, once older than offsiteGuardMinAge + continue // excluded: removed in a later window, once keepDaily days old } - return nil, fmt.Sprintf("the policy would remove snapshot %s from %s — younger than %d days and not superseded the same day, which honest retention never does", - s.ShortID, s.Time.UTC().Format(time.RFC3339), int(offsiteGuardMinAge.Hours()/24)) + return nil, fmt.Sprintf("the policy would remove snapshot %s from %s — within the last %d days kept daily and not superseded the same day, which honest retention never does", + s.ShortID, s.Time.UTC().Format(time.RFC3339), keepDaily) } keep = append(keep, s) } diff --git a/controller/internal/backup/offbox_window_test.go b/controller/internal/backup/offbox_window_test.go index b880577..d22881a 100644 --- a/controller/internal/backup/offbox_window_test.go +++ b/controller/internal/backup/offbox_window_test.go @@ -1,9 +1,12 @@ package backup import ( + "bytes" "context" "encoding/json" "fmt" + "log" + "sort" "strings" "testing" "time" @@ -160,7 +163,7 @@ func TestOffsiteGuard_RecentRemovalRefused(t *testing.T) { now := time.Now() all := []guardSnap{snap("old", now.Add(-60*24*time.Hour)), snap("recent", now.Add(-3*24*time.Hour))} _, why := offsiteGuard(all, []guardSnap{snap("recent", now.Add(-3*24*time.Hour))}, now, now, 50) - if !strings.Contains(why, "younger than 8 days") { + if !strings.Contains(why, "within the last 7 days kept daily") { t.Fatalf("why = %q", why) } _, why = offsiteGuard(all, nil, now, now.Add(-10*24*time.Hour), 50) @@ -251,6 +254,24 @@ func TestResetOrphaned_PinnedAsksTheHub(t *testing.T) { } } +// R-869 (v0.294.0): the move-aside line names the destination. MEASURED 2026-10-05 03:08 UTC, Tester 1 box +// (v0.293.0): `the hub set the orphaned repo aside: /home/felhom-repo -> (nothing deleted)`. +// COMPANION RED-PROOF: move `newPath = np` below the log line → "the line names no destination". +func TestR869_MoveAsideLineNamesTheDestination(t *testing.T) { + m, sett := newOffboxManager(t) + var buf bytes.Buffer + m.logger = log.New(&buf, "", 0) + pinTarget(t, sett) + m.SetOffsiteMoveAside(func(context.Context) (string, error) { return "/home/felhom-repo.orphaned-20261005", nil }) + m.SetOffboxRunner(func(context.Context, []string, ...string) ([]byte, error) { return nil, nil }) + if err := m.resetOrphanedRepo(context.Background(), nil, nil, "test"); err != nil { + t.Fatal(err) + } + if !strings.Contains(buf.String(), "aside: /home/felhom-repo -> /home/felhom-repo.orphaned-20261005 (nothing deleted)") { + t.Fatalf("the line names no destination:\n%s", buf.String()) + } +} + // The provider's rclone notice must not reach a JSON parser — measured live on demo-felhom (v0.289.0). func TestStripRcloneNotice(t *testing.T) { in := "rclone: 2026/10/03 15:05:42 NOTICE: Config file \"/home/.config/rclone/rclone.conf\" not found - using defaults\n[{\"id\":\"s1\"}]\n" @@ -343,3 +364,200 @@ func TestAbandon_PinnedHandsToHubAndFollows(t *testing.T) { t.Fatalf("del=%v err=%v status=%+v evs=%v", del, err, m.AbandonStatus(), evs) } } + +// ── R-867 (v0.294.0): the guard against the REAL policy ───────────────────────────────────────────────── + +// restic0140Plan is restic 0.14.0's `forget --group-by host,tags --keep-daily D --keep-weekly W +// --keep-monthly M` (internal/restic/snapshot_policy.go ApplyPolicy): per group, newest first, a snapshot +// is kept when it opens a new day / ISO week / month bucket while that rule still has count left; every +// other snapshot is removed. Equivalence with the real binary over the same snapshot set is recorded in +// felhom.eu/documentation/audits/night-fixes-2026-10-05/partA/ (the lab run). +func restic0140Plan(all []guardSnap, daily, weekly, monthly int) (remove []guardSnap) { + groups := map[string][]guardSnap{} + var order []string + for _, s := range all { + if _, ok := groups[s.group()]; !ok { + order = append(order, s.group()) + } + groups[s.group()] = append(groups[s.group()], s) + } + for _, g := range order { + list := append([]guardSnap{}, groups[g]...) + sort.SliceStable(list, func(i, j int) bool { return list[i].Time.After(list[j].Time) }) + type bucket struct { + count int + f func(time.Time) int + last int + } + b := []bucket{ + {daily, func(d time.Time) int { return d.Year()*10000 + int(d.Month())*100 + d.Day() }, -1}, + {weekly, func(d time.Time) int { y, w := d.ISOWeek(); return y*100 + w }, -1}, + {monthly, func(d time.Time) int { return d.Year()*100 + int(d.Month()) }, -1}, + } + for _, cur := range list { + keep := false + for i := range b { + if b[i].count > 0 { + if v := b[i].f(cur.Time); v != b[i].last { + keep = true + b[i].last = v + b[i].count-- + } + } + } + if !keep { + remove = append(remove, cur) + } + } + } + return remove +} + +func without(all []guardSnap, ids []string) []guardSnap { + gone := map[string]bool{} + for _, id := range ids { + gone[id] = true + } + var out []guardSnap + for _, s := range all { + if !gone[s.ID] { + out = append(out, s) + } + } + return out +} + +// THE MEASURED SHAPE (demo-felhom window 3, 2026-10-05 02:15 UTC): the night's snapshot is taken, then the +// window runs; the policy drops the snapshot of 7 days + 5 s ago. v0.293.0's 8-day line refused it. +func TestOffsiteGuard_RealPolicyMeasuredShapeAllowed(t *testing.T) { + var all []guardSnap + for d := 0; d < 8; d++ { + at := time.Date(2026, 9, 28+d, 2, 15, 5, 0, time.UTC) + all = append(all, guardSnap{ID: fmt.Sprintf("n%d-full", d), ShortID: fmt.Sprintf("n%d", d), Time: at, Hostname: "demo-felhom", Tags: []string{"opengist"}}) + } + now := time.Date(2026, 10, 5, 2, 15, 10, 0, time.UTC) + plan := restic0140Plan(all, keepDaily, keepWeekly, keepMonthly) + if len(plan) != 1 || plan[0].ShortID != "n0" { + t.Fatalf("the policy's plan = %v, want the 2026-09-28 snapshot only", plan) + } + ids, why := offsiteGuard(all, plan, now, now, 5) + if why != "" || len(ids) != 1 || ids[0] != "n0-full" { + t.Fatalf("the honest drop of a 7 d + 5 s snapshot must pass: ids=%v why=%q", ids, why) + } +} + +// Sixty nights of a household with three apps, a window after every night's run (the worst case: the hub +// opens weekly), a same-day manual run on two days, and a month boundary: the real policy's plan is never +// refused, deletes happen, and the store settles at the policy's size. Weekly and monthly keeps survive. +func TestOffsiteGuard_RealPolicySixtyNightsNeverRefuses(t *testing.T) { + apps := []string{"opengist", "bookstack", "immich"} + var all []guardSnap + removedTotal, windowsWithRemoval := 0, 0 + start := time.Date(2026, 8, 20, 2, 15, 0, 0, time.UTC) + for night := 0; night < 60; night++ { + at := start.AddDate(0, 0, night) + for i, a := range apps { + all = append(all, guardSnap{ID: fmt.Sprintf("%s-%d-full", a, night), ShortID: fmt.Sprintf("%s%d", a, night), + Time: at.Add(time.Duration(i) * time.Second), Hostname: "box", Tags: []string{a}}) + } + if night == 20 || night == 41 { // the household pressed "back up now" in the afternoon + for _, a := range apps { + all = append(all, guardSnap{ID: fmt.Sprintf("%s-%d-manual-full", a, night), ShortID: fmt.Sprintf("%s%dm", a, night), + Time: at.Add(13 * time.Hour), Hostname: "box", Tags: []string{a}}) + } + } + now := at.Add(2 * time.Minute) + if night == 20 || night == 41 { + now = at.Add(13*time.Hour + 2*time.Minute) + } + plan := restic0140Plan(all, keepDaily, keepWeekly, keepMonthly) + ids, why := offsiteGuard(all, plan, now, now, 500) + if why != "" { + t.Fatalf("night %d (%s): the guard refused the honest policy: %s", night, now.Format(time.RFC3339), why) + } + if len(ids) > 0 { + windowsWithRemoval++ + removedTotal += len(ids) + } + all = without(all, ids) + } + if windowsWithRemoval < 15 || removedTotal < 45 { + t.Fatalf("too little was ever removed (%d windows, %d snapshots): the test does not exercise deletion", windowsWithRemoval, removedTotal) + } + // The store holds the policy's shape per app, never only the last 7 days: the end-of-month keeps remain. + per := map[string]int{} + monthEnds := 0 + for _, s := range all { + per[s.Tags[0]]++ + if s.Tags[0] == "opengist" && (s.Time.Format("01-02") == "08-31" || s.Time.Format("01-02") == "09-30") { + monthEnds++ + } + } + for _, a := range apps { + if per[a] < keepDaily || per[a] > keepDaily+keepWeekly+keepMonthly { + t.Fatalf("%s holds %d snapshots after 60 nights; policy bounds %d..%d", a, per[a], keepDaily, keepDaily+keepWeekly+keepMonthly) + } + } + if monthEnds != 2 { + t.Fatalf("the monthly keeps of 31 Aug and 30 Sep must survive; found %d", monthEnds) + } +} + +// A weekly window (the hub's real cadence) over the same nights: the backlog of one week is removed in one +// go and is never refused by the day line. +func TestOffsiteGuard_RealPolicyWeeklyWindows(t *testing.T) { + var all []guardSnap + start := time.Date(2026, 9, 1, 2, 15, 0, 0, time.UTC) + removed := 0 + for night := 0; night < 35; night++ { + at := start.AddDate(0, 0, night) + all = append(all, guardSnap{ID: fmt.Sprintf("s%d-full", night), ShortID: fmt.Sprintf("s%d", night), Time: at, Hostname: "box", Tags: []string{"app"}}) + if night%7 != 6 { + continue + } + now := at.Add(time.Minute) + plan := restic0140Plan(all, keepDaily, keepWeekly, keepMonthly) + ids, why := offsiteGuard(all, plan, now, now, 7) + if why != "" { + t.Fatalf("weekly window on %s refused: %s", now.Format("2006-01-02"), why) + } + removed += len(ids) + all = without(all, ids) + } + if removed == 0 { + t.Fatal("five weekly windows removed nothing") + } +} + +// Poisoning that the day line still catches with the REAL policy: just before midnight an add-only +// attacker plants a snapshot 50 minutes ahead — inside the future-date skew, so not refused as future — +// dated TOMORROW. The policy then counts tomorrow as a day and drops the real snapshot of six days ago. +// (Past-dated fakes cannot make the policy drop a snapshot inside the last keepDaily calendar days: those +// days are at most keepDaily distinct days and keep-daily keeps them all. Past-dated gap-fills that steer +// OLDER keeps are R-822's residual, bounded by MaxRemove and the hub's count check, not by this line.) +func TestOffsiteGuard_RealPolicySkewWindowFakeRefused(t *testing.T) { + now := time.Date(2026, 10, 12, 23, 30, 0, 0, time.UTC) + var all []guardSnap + for d := 0; d < 7; d++ { + all = append(all, guardSnap{ID: fmt.Sprintf("real%d-full", d), ShortID: fmt.Sprintf("real%d", d), + Time: time.Date(2026, 10, 12-d, 2, 15, 0, 0, time.UTC), Hostname: "box", Tags: []string{"app"}}) + } + all = append(all, guardSnap{ID: "fake-full", ShortID: "fake", Time: now.Add(50 * time.Minute), Hostname: "box", Tags: []string{"app"}}) + plan := restic0140Plan(all, keepDaily, keepWeekly, keepMonthly) + if len(plan) != 1 || plan[0].ShortID != "real6" { + t.Fatalf("plan = %v (want the real snapshot of 6 days ago)", plan) + } + _, why := offsiteGuard(all, plan, now, now, 50) + if !strings.Contains(why, "within the last 7 days kept daily") { + t.Fatalf("why = %q — a real snapshot inside the daily window must not be removed", why) + } +} + +// The policy's arguments and the guard's line come from the same constants (R-867). +func TestRetentionPolicy_BuiltFromTheGuardConstants(t *testing.T) { + got := strings.Join(retentionPolicy, " ") + want := fmt.Sprintf("--group-by host,tags --keep-daily %d --keep-weekly %d --keep-monthly %d", keepDaily, keepWeekly, keepMonthly) + if got != want || keepDaily != 7 || keepWeekly != 4 || keepMonthly != 6 { + t.Fatalf("policy = %q (want %q, the ruled 7/4/6)", got, want) + } +} diff --git a/controller/internal/dockerexec/imagework.go b/controller/internal/dockerexec/imagework.go new file mode 100644 index 0000000..dbdf4e9 --- /dev/null +++ b/controller/internal/dockerexec/imagework.go @@ -0,0 +1,62 @@ +package dockerexec + +import "sync" + +// ── R-863 (v0.294.0): no image clean-up while an image is being pulled ─────────────────────────────── +// +// MEASURED 2026-10-04 night drill, a fresh box: the controller's one-time image clean-up ran while the +// household's first BookStack install was inside `docker compose up -d`. compose had pulled +// `mariadb@sha256:…` (stored untagged) and not yet created the container, so no container, installed app +// or undo named it; the clean-up deleted it one second before compose created the container, and the +// install failed. An app being installed is not "installed" yet, and a restore or undo pulls the same way. +// +// THE RULE: every compose command that can pull an image and then create a container from it (up, pull, +// create, run) holds the image-work lock SHARED for its whole run; an image clean-up pass takes it +// EXCLUSIVELY, without waiting (TryLock). So a pass never runs while any such command runs, and a command +// that starts during a pass waits the few seconds the pass takes. A pass that cannot take the lock does +// not run; its caller tries again later. Pinned by TestR863_* (internal/stacks/image_retention_r863_test.go). + +var imageWorkMu sync.RWMutex + +// ImagePulling reports whether compose args are an image-pulling verb (up, pull, create, run). Flags +// before the verb (`-p name`, `--profile x`) are skipped. +func ImagePulling(args []string) bool { + for i := 0; i < len(args); i++ { + a := args[i] + if a == "compose" { + continue + } + if len(a) > 0 && a[0] == '-' { + switch a { + case "-p", "--project-name", "-f", "--file", "--profile", "--env-file", "--project-directory": + i++ // the flag's value + } + continue + } + switch a { + case "up", "pull", "create", "run": + return true + } + return false + } + return false +} + +// BeginImageWork holds the image-work lock shared while compose args pull images; the returned func +// releases it. For any other verb it returns a no-op. +func BeginImageWork(args []string) (end func()) { + if !ImagePulling(args) { + return func() {} + } + imageWorkMu.RLock() + return imageWorkMu.RUnlock +} + +// TryImageCleanup takes the image-work lock exclusively if no image work runs now. ok=false: something is +// pulling — do not clean up now. +func TryImageCleanup() (end func(), ok bool) { + if !imageWorkMu.TryLock() { + return nil, false + } + return imageWorkMu.Unlock, true +} diff --git a/controller/internal/stacks/deploy.go b/controller/internal/stacks/deploy.go index bcc97b4..a5ca9c5 100644 --- a/controller/internal/stacks/deploy.go +++ b/controller/internal/stacks/deploy.go @@ -15,6 +15,7 @@ import ( "gitea.dooplex.hu/admin/felhom-controller/internal/appbackup" "gitea.dooplex.hu/admin/felhom-controller/internal/crypto" + "gitea.dooplex.hu/admin/felhom-controller/internal/dockerexec" "gitea.dooplex.hu/admin/felhom-controller/internal/system" "gitea.dooplex.hu/admin/felhom-controller/internal/util" "gopkg.in/yaml.v3" @@ -837,7 +838,8 @@ func (m *Manager) PersistUnitRedeployConfig(name string, env map[string]string) // so USERDATA_PATH must be injected here too (mirrors stackEnv), else the FIRST deploy resolves // ${USERDATA_PATH} to "" and binds a bogus root-owned dir at the container root. func (m *Manager) composeExecWithEnv(dir string, env map[string]string, args ...string) (string, error) { - if m.composeExecFn != nil { // test seam (v0.280.0): a deploy test never reaches Docker + defer dockerexec.BeginImageWork(args)() // R-863 (held around the seam too, so a test sees the real rule) + if m.composeExecFn != nil { // test seam (v0.280.0): a deploy test never reaches Docker return m.composeExecFn(dir, env, args...) } cmdEnv := os.Environ() diff --git a/controller/internal/stacks/image_retention.go b/controller/internal/stacks/image_retention.go index b38f866..0b06a33 100644 --- a/controller/internal/stacks/image_retention.go +++ b/controller/internal/stacks/image_retention.go @@ -1,12 +1,15 @@ package stacks import ( + "context" + "errors" "fmt" "os" "path/filepath" "sort" "strings" "sync" + "time" "gitea.dooplex.hu/admin/felhom-controller/internal/dockerexec" ) @@ -35,6 +38,10 @@ var imageDocker = func(args ...string) (string, error) { var imageRetentionMu sync.Mutex +// errImageRetentionBusy: a pass did not run because an image may be in use by work in flight (an update, or +// any compose command that pulls — R-863). The caller tries again later; nothing was judged. +var errImageRetentionBusy = errors.New("image work in flight") + type localImage struct { ID, Repo, Tag, Digest, Size string } @@ -194,8 +201,17 @@ func (m *Manager) deleteUnkeptImages(why string, repos map[string]bool, except s m.mu.RUnlock() if busy != "" { m.logger.Printf("[INFO] [stacks] image retention (%s): skipped — %s is updating (its undo may need an image nothing else names)", why, busy) - return nil, nil + return nil, errImageRetentionBusy } + // R-863: an install, a restore or an undo inside `compose up` may have pulled an image (by digest, so + // untagged) that no container names YET. No pass while any image-pulling compose command runs; one that + // starts now waits for this pass (seconds). + endCleanup, ok := dockerexec.TryImageCleanup() + if !ok { + m.logger.Printf("[INFO] [stacks] image retention (%s): skipped — an app install, update, restore or undo is pulling images now (R-863); tried again later", why) + return nil, errImageRetentionBusy + } + defer endCleanup() imgs, err := listLocalImages() if err != nil { return nil, err @@ -293,7 +309,7 @@ func (m *Manager) RetainImagesAfterUpdate(name string, previous map[string]Insta m.logger.Printf("[INFO] [stacks] image retention after the update of %s: the app is gone — nothing to do here", name) return } - if _, err := m.deleteUnkeptImages("update of "+name, appImageRepos(dir, st.AppConfig), ""); err != nil { + if _, err := m.deleteUnkeptImages("update of "+name, appImageRepos(dir, st.AppConfig), ""); err != nil && !errors.Is(err, errImageRetentionBusy) { m.logger.Printf("[WARN] [stacks] image retention after the update of %s: %v", name, err) } } @@ -317,7 +333,7 @@ func (m *Manager) RetainImagesAfterRemove(name string, repos map[string]bool) { if len(repos) == 0 { return } - if _, err := m.deleteUnkeptImages("remove of "+name, repos, name); err != nil { + if _, err := m.deleteUnkeptImages("remove of "+name, repos, name); err != nil && !errors.Is(err, errImageRetentionBusy) { m.logger.Printf("[WARN] [stacks] image retention after the remove of %s: %v", name, err) } } @@ -349,28 +365,49 @@ func (m *Manager) imageRetentionMarker() string { // RunImageRetentionOnce is the one-time clean-up at the first start of this release: the same rule, applied to every // app image the catalog names (so the images of apps removed before this release go too). Logged; a marker file -// keeps it to once. Returns what it deleted. -func (m *Manager) RunImageRetentionOnce() []string { +// keeps it to once. Returns what it deleted, and done=false when it must be tried again (no catalog yet, or image +// work in flight — R-863: the marker is written ONLY after a pass that ran). +func (m *Manager) RunImageRetentionOnce() (deleted []string, done bool) { if _, err := os.Stat(m.imageRetentionMarker()); err == nil { - return nil + return nil, true } repos := m.catalogImageRepos() if len(repos) == 0 { - m.logger.Printf("[WARN] [stacks] image retention (one-time): no catalog read — skipped, tried again at the next start") - return nil + m.logger.Printf("[WARN] [stacks] image retention (one-time): no catalog read — skipped, tried again later") + return nil, false } before, _ := imageDocker("system", "df", "--format", "{{.Type}} {{.Size}} {{.Reclaimable}}") deleted, err := m.deleteUnkeptImages("one-time clean-up", repos, "") + if errors.Is(err, errImageRetentionBusy) { + return nil, false // logged by the pass; tried again later + } if err != nil { - m.logger.Printf("[WARN] [stacks] image retention (one-time): %v — tried again at the next start", err) - return nil + m.logger.Printf("[WARN] [stacks] image retention (one-time): %v — tried again later", err) + return nil, false } after, _ := imageDocker("system", "df", "--format", "{{.Type}} {{.Size}} {{.Reclaimable}}") m.logger.Printf("[INFO] [stacks] image retention (one-time): deleted %d image(s). docker disk before: %s | after: %s", len(deleted), strings.Join(strings.Fields(firstLine(before)), " "), strings.Join(strings.Fields(firstLine(after)), " ")) _ = os.MkdirAll(filepath.Dir(m.imageRetentionMarker()), 0o755) _ = os.WriteFile(m.imageRetentionMarker(), []byte(fmt.Sprintf("deleted %d\n%s\n", len(deleted), strings.Join(deleted, "\n"))), 0o644) - return deleted + return deleted, true +} + +// RunImageRetentionOnceUntilDone runs the one-time clean-up, and again every `every` until it has run (R-863: +// a pass that met image work in flight, or found no catalog yet, is retried — no longer only at the next start), +// at most `tries` times. +func (m *Manager) RunImageRetentionOnceUntilDone(ctx context.Context, every time.Duration, tries int) { + for i := 0; i < tries; i++ { + if _, done := m.RunImageRetentionOnce(); done { + return + } + select { + case <-ctx.Done(): + return + case <-time.After(every): + } + } + m.logger.Printf("[WARN] [stacks] image retention (one-time): not run after %d tries — tried again at the next start", tries) } func sortedKeys(m map[string]bool) []string { diff --git a/controller/internal/stacks/image_retention_r863_test.go b/controller/internal/stacks/image_retention_r863_test.go new file mode 100644 index 0000000..e972eb9 --- /dev/null +++ b/controller/internal/stacks/image_retention_r863_test.go @@ -0,0 +1,109 @@ +package stacks + +import ( + "fmt" + "os" + "path/filepath" + "strings" + "sync" + "testing" + "time" + + "gitea.dooplex.hu/admin/felhom-controller/internal/dockerexec" +) + +// R-863 (v0.294.0) — THE NIGHT'S EXACT SHAPE (2026-10-04, a fresh box): the household's first install is inside +// `compose up`; compose has pulled `mariadb@sha256:…` (stored untagged, `mariadb:`) and not yet created the +// container; the controller's one-time image clean-up fires (3 minutes after its first start). v0.293.0 deleted +// the image — no container, installed app or undo named it — and `compose up` failed one second later. +// COMPANION RED-PROOF: drop the dockerexec.TryImageCleanup check in deleteUnkeptImages → the clean-up deletes +// sha256:MDB and the install fails ("the install failed"). +func TestR863_OneTimeCleanupDuringFirstInstallKeepsThePulledImage(t *testing.T) { + m := gateManager(t, "display_name: Book\ndeploy_fields:\n - env_var: DOMAIN\n type: domain\n - env_var: SUBDOMAIN\n type: subdomain\n default: gapp\n") + m.cfg.Paths.DataDir = filepath.Join(t.TempDir(), "data") + cat := filepath.Join(m.cfg.Paths.DataDir, "catalog-cache", "templates", "bookstack") + must(t, os.MkdirAll(cat, 0o755)) + must(t, os.WriteFile(filepath.Join(cat, "docker-compose.yml"), []byte("services:\n db:\n image: mariadb:11.4@sha256:mdb\n"), 0o644)) + + f := &fakeImages{containers: map[string]string{}} + var fmu sync.Mutex + prev := imageDocker + imageDocker = func(args ...string) (string, error) { fmu.Lock(); defer fmu.Unlock(); return f.run(args...) } + t.Cleanup(func() { imageDocker = prev }) + + var cleanupDone bool + m.composeExecFn = func(_ string, _ map[string]string, args ...string) (string, error) { + if len(args) == 0 || args[0] != "up" { + return "", nil + } + // compose pulls by digest: the image exists, untagged, named by no container yet + fmu.Lock() + f.imgs = append(f.imgs, localImage{ID: "sha256:MDB", Repo: "mariadb", Tag: "", Digest: "sha256:mdb", Size: "334MB"}) + fmu.Unlock() + // the one-time clean-up fires NOW, from its own goroutine, as at 19:45:04 + res := make(chan bool, 1) + go func() { _, done := m.RunImageRetentionOnce(); res <- done }() + select { + case cleanupDone = <-res: + case <-time.After(10 * time.Second): + return "", fmt.Errorf("the clean-up blocked") + } + // compose creates the container from the pulled image — if it is still there + fmu.Lock() + defer fmu.Unlock() + for _, im := range f.imgs { + if im.ID == "sha256:MDB" { + f.containers["c-db"] = "sha256:MDB" + return "", nil + } + } + return "", fmt.Errorf("exit code 1\nstderr: Error response from daemon: No such image: mariadb@sha256:mdb") + } + done := make(chan bool, 1) + m.SetDeployDoneHook(func(_ string, ok bool, _ string) { done <- ok }) + if _, err := m.DeployStack(DeployRequest{StackName: "gapp"}); err != nil { + t.Fatal(err) + } + select { + case ok := <-done: + if !ok { + t.Fatalf("the install failed: the clean-up deleted the image compose had just pulled (rmi %v)", f.rmi) + } + case <-time.After(20 * time.Second): + t.Fatal("the deploy never ended") + } + if len(f.rmi) != 0 { + t.Fatalf("the clean-up deleted during the install: %v", f.rmi) + } + if cleanupDone { + t.Fatal("the clean-up reported done although it did not run — its marker would end it for good") + } + if _, err := os.Stat(m.imageRetentionMarker()); err == nil { + t.Fatal("marker written for a pass that did not run") + } + // After the install the retried clean-up runs, and the app's image is kept (a container names it). + if _, done := m.RunImageRetentionOnce(); !done { + t.Fatal("the retried clean-up did not run once nothing was pulling") + } + if strings.Contains(strings.Join(f.rmi, ","), "sha256:MDB") { + t.Fatal("the installed app's database image was deleted") + } +} + +// Image-pulling verbs hold the lock; others do not (a `ps` or `down` must never hold off a clean-up). +func TestR863_OnlyPullingVerbsHoldTheLock(t *testing.T) { + for _, c := range []struct { + args []string + want bool + }{ + {[]string{"up", "-d"}, true}, {[]string{"compose", "up", "-d", "--remove-orphans"}, true}, + {[]string{"pull"}, true}, {[]string{"-p", "x", "create"}, true}, {[]string{"run", "--rm", "x"}, true}, + {[]string{"ps"}, false}, {[]string{"down"}, false}, {[]string{"stop"}, false}, {[]string{"-p", "up", "down"}, false}, + } { + if got := imagePullingForTest(c.args); got != c.want { + t.Errorf("%v: pulling=%v, want %v", c.args, got, c.want) + } + } +} + +func imagePullingForTest(args []string) bool { return dockerexec.ImagePulling(args) } diff --git a/controller/internal/stacks/image_retention_test.go b/controller/internal/stacks/image_retention_test.go index ddf3d6a..d59bfc3 100644 --- a/controller/internal/stacks/image_retention_test.go +++ b/controller/internal/stacks/image_retention_test.go @@ -1,6 +1,7 @@ package stacks import ( + "errors" "fmt" "os" "path/filepath" @@ -214,7 +215,7 @@ func TestImageRetention_OneTimeSweepOnlyCatalogRepos(t *testing.T) { cat := filepath.Join(m.cfg.Paths.DataDir, "catalog-cache", "templates", "gone") must(t, os.MkdirAll(cat, 0o755)) must(t, os.WriteFile(filepath.Join(cat, "docker-compose.yml"), []byte("services:\n gone:\n image: acme/gone:6\n"), 0o644)) - deleted := m.RunImageRetentionOnce() + deleted, _ := m.RunImageRetentionOnce() got := strings.Join(f.rmi, ",") if !strings.Contains(got, "sha256:OLD") { t.Fatalf("an earlier-removed app's image was not swept: %v", deleted) @@ -242,8 +243,8 @@ func TestImageRetention_NoPassWhileAnUpdateRuns(t *testing.T) { m.stacks["docs"].Updating = true m.mu.Unlock() st, _ := m.GetStack("web") - if _, err := m.deleteUnkeptImages("test", appImageRepos(filepath.Dir(st.ComposePath), st.AppConfig), ""); err != nil { - t.Fatal(err) + if _, err := m.deleteUnkeptImages("test", appImageRepos(filepath.Dir(st.ComposePath), st.AppConfig), ""); !errors.Is(err, errImageRetentionBusy) { + t.Fatalf("err = %v, want errImageRetentionBusy (the caller tries again later)", err) } if len(f.rmi) != 0 { t.Fatalf("a pass ran while docs was updating: %v", f.rmi) diff --git a/controller/internal/stacks/manager.go b/controller/internal/stacks/manager.go index f7462f2..8380587 100644 --- a/controller/internal/stacks/manager.go +++ b/controller/internal/stacks/manager.go @@ -14,6 +14,7 @@ import ( "strings" "sync" "time" + "unicode/utf8" "gitea.dooplex.hu/admin/felhom-controller/internal/appbackup" "gitea.dooplex.hu/admin/felhom-controller/internal/config" @@ -1446,6 +1447,7 @@ func (m *Manager) composeExec(dir string, args ...string) (string, error) { } func (m *Manager) composeExecCustomEnv(dir string, env []string, args ...string) (string, error) { + defer dockerexec.BeginImageWork(args)() // R-863: no image clean-up while this may pull var cmd *exec.Cmd if m.composeCmd == "docker compose" { @@ -1511,10 +1513,12 @@ func (m *Manager) composeExecCustomEnv(dir string, env []string, args ...string) if stdoutStr := truncateStr(stdout.String(), 500); stdoutStr != "" { m.logger.Printf("[ERROR] [stacks] stdout: %s", stdoutStr) } - if stderrStr := truncateStr(stderr.String(), 500); stderrStr != "" { - m.logger.Printf("[ERROR] [stacks] stderr: %s", stderrStr) + // R-864 (v0.294.0): the TAIL of stderr — compose prints its pull progress first and the reason last, so + // the head (v0.293.0 and earlier) logged "Image … Pulling" and cut the error itself. + if stderrStr := tailStr(stderr.String(), 500); stderrStr != "" { + m.logger.Printf("[ERROR] [stacks] stderr (last part): %s", stderrStr) } - return stdout.String(), fmt.Errorf("exit code %d\nstderr: %s", exitCode, truncateStr(stderr.String(), 500)) + return stdout.String(), fmt.Errorf("exit code %d\nstderr: %s", exitCode, tailStr(stderr.String(), 500)) } m.logger.Printf("[DEBUG] Command completed: %s %s (took %.1fs)", m.composeCmd, strings.Join(args, " "), time.Since(start).Seconds()) @@ -1549,6 +1553,20 @@ func (m *Manager) isDebug() bool { } // truncateStr truncates a string to maxLen characters, appending "..." if truncated. +// tailStr keeps the LAST maxLen bytes of s (an error is printed last), marked with a leading "...". The cut +// moves forward to a UTF-8 boundary so a Hungarian letter is never split. Pinned by TestR864_*. +func tailStr(s string, maxLen int) string { + s = strings.TrimSpace(s) + if len(s) <= maxLen { + return s + } + i := len(s) - maxLen + for i < len(s) && !utf8.RuneStart(s[i]) { + i++ + } + return "..." + s[i:] +} + func truncateStr(s string, maxLen int) string { s = strings.TrimSpace(s) if len(s) <= maxLen { diff --git a/controller/internal/stacks/r864_stderr_tail_test.go b/controller/internal/stacks/r864_stderr_tail_test.go new file mode 100644 index 0000000..057d3bf --- /dev/null +++ b/controller/internal/stacks/r864_stderr_tail_test.go @@ -0,0 +1,61 @@ +package stacks + +import ( + "bytes" + "log" + "os" + "path/filepath" + "strings" + "testing" +) + +// R-864 (v0.294.0): a failed compose command logs and returns the TAIL of stderr. THE NIGHT'S SHAPE (2026-10-04, +// BookStack on the fresh Tester 1 box, audits/night-2026-10-04/tester1/t8-*): the stderr opened with the pull +// progress below (the first line is verbatim from that night) and the reason came last; v0.293.0 kept the first +// 500 bytes and logged only "Image … Pulling" — the reason was lost. The night's last line itself was lost by +// exactly this defect; the one here is Docker's message for an image deleted under compose (R-863). +// COMPANION RED-PROOF: use truncateStr instead of tailStr for stderr in composeExecCustomEnv → "the reason was cut". +func TestR864_FailedComposeLogsTheReasonNotThePullProgress(t *testing.T) { + var lines []string + lines = append(lines, "Image lscr.io/linuxserver/bookstack:26.09.1@sha256:99cd1f5707c1911afad213adec5c9739763b76f843d1477142231834ecdcb6f7 Pulling") + lines = append(lines, "Image mariadb:11.4@sha256:dfff46ef3f9d Pulling") + for i := 0; i < 16; i++ { + lines = append(lines, " a1b2c3d4e5f6 Pull complete") + } + lines = append(lines, "Image mariadb:11.4@sha256:dfff46ef3f9d Pulled") + reason := "Error response from daemon: No such image: mariadb@sha256:dfff46ef3f9d — árvíztűrő" + lines = append(lines, reason) + stderr := strings.Join(lines, "\n") + if len(stderr) < 700 { + t.Fatalf("the fixture must exceed the 500-byte cut (%d)", len(stderr)) + } + m := gateManager(t, "display_name: G\n") + dir := t.TempDir() // a stub under os.TempDir(): R-650's sanctioned seam, never this host's Docker + errf := filepath.Join(dir, "stderr.txt") + must(t, os.WriteFile(errf, []byte(stderr), 0o644)) + must(t, os.WriteFile(filepath.Join(dir, "docker"), []byte("#!/bin/sh\nwhile IFS= read -r l || [ -n \"$l\" ]; do printf '%s\\n' \"$l\" >&2; done < "+errf+"\nexit 1\n"), 0o755)) + t.Setenv("PATH", dir) + var buf bytes.Buffer + m.logger = log.New(&buf, "", 0) + _, err := m.composeExecCustomEnv(dir, []string{"PATH=" + dir}, "up", "-d") + if err == nil { + t.Fatal("no error from a failed compose") + } + if !strings.Contains(err.Error(), reason) { + t.Fatalf("the reason was cut from the returned error: %q", err.Error()) + } + if !strings.Contains(buf.String(), reason) { + t.Fatalf("the reason was cut from the log:\n%s", buf.String()) + } +} + +func TestR864_TailStrKeepsTheEndOnARuneBoundary(t *testing.T) { + s := strings.Repeat("x", 10) + "őőő" + got := tailStr(s, 5) // the cut falls inside "ő" (2 bytes each) + if got != "...őő" { + t.Fatalf("tailStr = %q", got) + } + if tailStr("short", 500) != "short" { + t.Fatal("a short string must pass unchanged") + } +} diff --git a/controller/internal/stacks/update.go b/controller/internal/stacks/update.go index e505feb..b8a5b12 100644 --- a/controller/internal/stacks/update.go +++ b/controller/internal/stacks/update.go @@ -9,6 +9,7 @@ import ( "strings" "time" + "gitea.dooplex.hu/admin/felhom-controller/internal/dockerexec" "gitea.dooplex.hu/admin/felhom-controller/internal/i18n" "gitea.dooplex.hu/admin/felhom-controller/internal/system" "gitea.dooplex.hu/admin/felhom-controller/internal/util" @@ -690,6 +691,7 @@ func (m *Manager) UpdateErrorFor(st Stack, lang string) string { } func (m *Manager) updateCompose(dir string, env []string, args ...string) (string, error) { + defer dockerexec.BeginImageWork(args)() // R-863 if m.updateComposeFn != nil { return m.updateComposeFn(dir, env, args...) } diff --git a/controller/internal/web/handlers.go b/controller/internal/web/handlers.go index f3c05b2..ad2c439 100644 --- a/controller/internal/web/handlers.go +++ b/controller/internal/web/handlers.go @@ -3661,7 +3661,10 @@ func (s *Server) syncFileBrowserMounts(resetDBOnChange bool) { } cmd := dockerexec.CommandContext(ctx, "docker", args...) cmd.Dir = stackDir - if out, err := cmd.CombinedOutput(); err != nil { + endImageWork := dockerexec.BeginImageWork(args) // R-863 + out, err := cmd.CombinedOutput() + endImageWork() + if err != nil { s.logger.Printf("[ERROR] [web] Failed to bring up FileBrowser: %s — %v", string(out), err) } else if changed { s.logger.Printf("[INFO] [web] FileBrowser mounts synced (recreated) — %d storage path(s), config updated", len(paths))