v0.294.0: off-site clean-up guard follows the policy's own constants (R-867); no image clean-up while compose pulls (R-863); stderr tail (R-864); move-aside destination logged (R-869)
gates / gates (push) Successful in 28s

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0159rPz1ZhFKsS53msqPYxtS
This commit is contained in:
2026-10-05 07:13:02 +02:00
parent 69e914534f
commit 7861bf9dde
16 changed files with 607 additions and 36 deletions
+3 -1
View File
@@ -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.
+1
View File
@@ -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()
+1 -1
View File
@@ -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 {
+36 -11
View File
@@ -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)
}
@@ -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)
}
}
@@ -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
}
+3 -1
View File
@@ -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()
+48 -11
View File
@@ -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 {
@@ -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:<none>`) 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: "<none>", 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) }
@@ -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)
+21 -3
View File
@@ -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 {
@@ -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")
}
}
+2
View File
@@ -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...)
}
+4 -1
View File
@@ -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))