From 7720439440d9f73610629672d1fcf891279cb4f8 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Sun, 25 Oct 2026 12:45:33 +0100 Subject: [PATCH] =?UTF-8?q?D49=20=3D=20A=20follow-ups:=20(A)=20the=20undo?= =?UTF-8?q?=20copy=20is=20released=20only=20after=20a=20stable=20start=20?= =?UTF-8?q?=E2=80=94=203=20min=20of=20running,=20healthy,=20no=20restart,?= =?UTF-8?q?=20one=20rule=20for=20the=20first=20verdict=20and=20the=20late-?= =?UTF-8?q?start=20watch;=20a=20watch=20ends=20only=20for=20a=20restore=20?= =?UTF-8?q?begun=20after=20it;=20(B,=20R-1279)=20the=20.fab=20import=20dow?= =?UTF-8?q?nloads=20first=20with=20the=20restores'=20D48=20helper,=20befor?= =?UTF-8?q?e=20it=20removes=20anything.=20Red-proved.=20Commit=20only.?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- CHANGELOG.md | 24 +++ controller/cmd/controller/main.go | 36 ++++ .../cmd/controller/r1279_wiring_test.go | 22 +++ controller/internal/appexport/export.go | 9 + .../appexport/r1279_pull_first_test.go | 94 +++++++++ controller/internal/appexport/restore.go | 21 ++ controller/internal/backup/main_test.go | 6 + .../internal/backup/offbox_reconstitute.go | 1 + .../internal/backup/offbox_restore_undo.go | 5 +- .../backup/r1177_local_putback_test.go | 2 +- .../internal/backup/r893_putback_test.go | 2 +- controller/internal/backup/restore_pull.go | 6 + controller/internal/backup/restore_unit.go | 1 + controller/internal/backup/restore_verdict.go | 185 +++++++++++++++--- .../internal/backup/restore_verdict_test.go | 15 +- .../internal/backup/stable_start_test.go | 147 ++++++++++++++ 16 files changed, 549 insertions(+), 27 deletions(-) create mode 100644 controller/cmd/controller/r1279_wiring_test.go create mode 100644 controller/internal/appexport/r1279_pull_first_test.go create mode 100644 controller/internal/backup/stable_start_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 463bcb4a..d2110e44 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -22,6 +22,30 @@ brief 2026-10-24, Part 4 (commit only; the release rides the next normal train). `…OnlyWhenTheAgentWaitsAndAnAppRuns`, `…QBLimitRuleSkipsAHeldLimit`, `…TheTwoAppsReadAndWriteTheirLimit`, `TestLineTestRunOutlastsTheClientTimeout`, `TestStartUpwatchRecoversTheHoldFirst`, `TestUpwatchHoldGetsBothAgentCalls`. +### The undo copy goes only after a stable start; the `.fab` import downloads first (R-1270 follow-up, R-1279) — 2026-10-26, attended + +Operator ruling D49 = A (2026-10-25 11:44): a restore whose app does not start keeps the restored data and the undo copy, +says „not started yet", alarms the operator; a late start is a success; never a put-back by itself. + +- **Fix A (`backup/restore_verdict.go`):** before, the late-start watcher released the undo copy at the FIRST sample + that read „running", and a restore whose 90 s health wait passed dropped it at once — an app crashing and restarting + reads „running" between crashes. Now ONE rule (`waitStableStart`) for both: for 3 minutes every sample (each 10 s) has + the stack running, every healthcheck `healthy`, the same containers and no RestartCount grown (`ContainerSamples`, a + read-only `docker inspect` in the stack adapter). The page's first verdict is unchanged; the copy is released after + the window (`releaseAfterStableStart`), or stays for support with one operator line if no stable window comes in 30 + minutes. A NEW restore of the app (one begun after the watch started) ends the watch untouched — found while + testing: the watch starts inside its own restore, before the page's record ends, so „a restore of the app runs" + alone ended every watch at once and would have kept every copy (`TestFixA_AStableAppReleasesTheCopyAfterTheWindow` + in the production order, seen failing with the plain check). Each watch reads its timing once, at its start. +- **Fix B (R-1279, `appexport/restore.go`):** the import asks the restores' own D48 helper (`PrepareRestoreImages`, + passed in by main.go — the package may not import `backup`) about the bundle's definition BEFORE step 1 removes the + running app's volumes; a version that cannot be downloaded refuses with the two D48 sentences and nothing changed. +- Tests (each seen failing first — felhom.eu `audits/release-2026-10-26/redproof/`): `TestFixA_AFlappingAppKeepsTheCopy`, + `…AHealthcheckStillStartingKeepsTheCopy`, `…ANewRestoreDuringTheWatchLeavesTheCopy`, + `…TheLateStartWatcherNeedsAStableStart`, control `…AStableAppReleasesTheCopyAfterTheWindow`; + `TestR1279_AnUnpullableImageRefusesTheImportBeforeAnythingIsRemoved`, `…APullableImageIsAskedFirstAndTheImportGoesOn`; + `TestR1279_MainWiresTheImportsDownloadFirst`; `TestR488_HealthWaitDefaultsAreProduction` now pins 3 min / 10 s / 30 min. + ### „Use my kept data" never takes a copy dated in the future (R-1271, P2) — 2026-10-25, commit only - **The cause, read from the code:** the catalog sweep's Tester4 off-site store held the 2026-10-20 rehearsal box's diff --git a/controller/cmd/controller/main.go b/controller/cmd/controller/main.go index 194839a2..99035200 100644 --- a/controller/cmd/controller/main.go +++ b/controller/cmd/controller/main.go @@ -2093,6 +2093,10 @@ func main() { // this the export path would be the uncovered sibling of two covered ones, which is how a reader // concludes the whole class is handled (§2.2). appExporter.SetStopGuard(exportStopGuard{g: appStopGuard}) + // R-1279 (D48 for the import): the import downloads first, with the restores' helper and sentences. + if backupMgr != nil { + appExporter.SetImagePreparer(backupMgr.PrepareRestoreImages) + } apiRouter.SetDebug(cfg.Logging.Level == "debug") // --- Initialize web server --- @@ -3439,6 +3443,38 @@ func (a *stackAdapter) StartStackServices(name string, services []string) error return a.mgr.StartStackServices(name, services) } +// ContainerSamples (R-1270 follow-up, fix A) reads each container of the stack: running, its RestartCount, its health +// ("" without a healthcheck) — the stable-start rule's sample (backup.containerSampler). Read-only docker calls. +func (a *stackAdapter) ContainerSamples(name string) ([]backup.ContainerSample, error) { + out, err := dockerexec.Command("docker", "ps", "-a", "-q", "--no-trunc", "--filter", "label=com.docker.compose.project="+name).Output() + if err != nil { + return nil, err + } + ids := strings.Fields(string(out)) + if len(ids) == 0 { + return nil, nil + } + args := append([]string{"inspect", "-f", "{{.Id}} {{.State.Status}} {{.RestartCount}} {{if .State.Health}}{{.State.Health.Status}}{{end}}"}, ids...) + out, err = dockerexec.Command("docker", args...).Output() + if err != nil { + return nil, err + } + var res []backup.ContainerSample + for _, line := range strings.Split(strings.TrimSpace(string(out)), "\n") { + f := strings.Fields(line) + if len(f) < 3 { + continue + } + n, _ := strconv.Atoi(f[2]) + c := backup.ContainerSample{ID: f[0], Running: f[1] == "running", RestartCount: n} + if len(f) > 3 { + c.Health = f[3] + } + res = append(res, c) + } + return res, nil +} + // RefreshAndIsRunning forces a docker ps scan before checking state. // Called during post-restore health check (~every 5s for up to 90s). // Full refresh is acceptable here since restores are rare operations. diff --git a/controller/cmd/controller/r1279_wiring_test.go b/controller/cmd/controller/r1279_wiring_test.go new file mode 100644 index 00000000..50e2d0f2 --- /dev/null +++ b/controller/cmd/controller/r1279_wiring_test.go @@ -0,0 +1,22 @@ +package main + +import ( + "os" + "strings" + "testing" +) + +// R-1279 — the `.fab` import downloads first only if main.go passes the restores' helper in; an unwired exporter keeps +// the old order (volumes removed before the pull). Seam-built-but-never-wired is a recorded class (REUSE.md). +func TestR1279_MainWiresTheImportsDownloadFirst(t *testing.T) { + b, err := os.ReadFile("main.go") + if err != nil { + t.Fatal(err) + } + if !strings.Contains(string(b), "appExporter.SetImagePreparer(backupMgr.PrepareRestoreImages)") { + t.Fatal("main.go must wire the import's download-first helper (SetImagePreparer)") + } + if !strings.Contains(string(b), "func (a *stackAdapter) ContainerSamples(") { + t.Fatal("main.go's stack adapter must read container samples for the stable-start rule (fix A)") + } +} diff --git a/controller/internal/appexport/export.go b/controller/internal/appexport/export.go index 9373693c..f95aec9b 100644 --- a/controller/internal/appexport/export.go +++ b/controller/internal/appexport/export.go @@ -103,6 +103,9 @@ type Exporter struct { // BOTH packages write ONE marker file — an exporter with its own file would be a second writer // racing the same recovery. Nil = not wired (tests): the export runs exactly as it did before. stopGuard appStopGuard + // prepareImages (R-1279, D48 for the import): resolves and pulls every image of the definition that will run, + // BEFORE the import removes anything; the returned func releases the image-work hold. Nil = unwired (tests). + prepareImages func(app, composePath string) (func(), error) mu sync.Mutex activeJob *Job @@ -137,6 +140,12 @@ func NewExporter(provider ExportStackProvider, logger *log.Logger, version strin // SetStopGuard wires the app-stop crash marker. INIT-ONLY — call once at startup, before any export. func (e *Exporter) SetStopGuard(g appStopGuard) { e.stopGuard = g } +// SetImagePreparer wires the D48 download-first helper (backup.Manager.PrepareRestoreImages — the restores' own, passed +// in so this package needs no import of the backup package). INIT-ONLY, main.go. +func (e *Exporter) SetImagePreparer(fn func(app, composePath string) (func(), error)) { + e.prepareImages = fn +} + // stopGuardBegin records the app-stop marker before an export stops an app. An unwired guard is a // no-op (pre-v0.189.0 behaviour), never an error — a test exporter must not be forced to have one. func (e *Exporter) stopGuardBegin(stackName string) error { diff --git a/controller/internal/appexport/r1279_pull_first_test.go b/controller/internal/appexport/r1279_pull_first_test.go new file mode 100644 index 00000000..9b9479d3 --- /dev/null +++ b/controller/internal/appexport/r1279_pull_first_test.go @@ -0,0 +1,94 @@ +package appexport + +import ( + "errors" + "io" + "log" + "os" + "path/filepath" + "strings" + "testing" + + "gitea.dooplex.hu/admin/felhom-controller/internal/util" +) + +// R-1279 (brief 2026-10-26 fix B) — the `.fab` import downloads first. Before (`e8d2151`): step 1 removed the RUNNING +// app's volumes, and the first pull came later at the database start, so a version that could not be downloaded left +// the app gone. Now the D48 helper runs before step 1 and a refusal changes nothing. +// COMPANION RED-PROOF (REPORT.md): drop the prepareImages call in restore.go → TestR1279_* fails (the volumes are +// removed and the app is stopped before anything is pulled). + +func r1279Bundle(t *testing.T) (fab, stackDir, stacksDir string) { + t.Helper() + tree := t.TempDir() + os.MkdirAll(filepath.Join(tree, "config"), 0755) + os.WriteFile(filepath.Join(tree, "config", "docker-compose.yml"), []byte("services:\n kuma:\n image: louislam/uptime-kuma:0.0.0-missing\n"), 0644) + man := &Manifest{Version: ManifestVersion, AppName: "kuma", DisplayName: "Kuma", ConfigFiles: []string{"docker-compose.yml"}} + data, err := man.Marshal() + if err != nil { + t.Fatal(err) + } + os.WriteFile(filepath.Join(tree, "manifest.json"), data, 0644) + fab = filepath.Join(t.TempDir(), "kuma.fab") + if err := createTarGz(fab, tree); err != nil { + t.Fatal(err) + } + stacksDir = t.TempDir() + stackDir = filepath.Join(stacksDir, "kuma") + os.MkdirAll(stackDir, 0755) + os.WriteFile(filepath.Join(stackDir, "docker-compose.yml"), []byte("LIVE"), 0644) + return fab, stackDir, stacksDir +} + +func TestR1279_AnUnpullableImageRefusesTheImportBeforeAnythingIsRemoved(t *testing.T) { + calls := swapDockerExec(t, func(c dockerCall, stdin io.Reader, stdout io.Writer) (string, error) { return "", nil }) + fab, stackDir, stacksDir := r1279Bundle(t) + prov := &rtProvider{stackDir: stackDir, stacksDir: stacksDir, deployed: true, running: true, volumes: []string{"kuma_data"}} + e := NewExporter(prov, log.New(io.Discard, "", 0), "test") + var asked string + gone := util.MsgErrorf(errors.New("gone"), "err.backup.restore_image_gone", "uptime-kuma:0.0.0-missing") + e.SetImagePreparer(func(app, compose string) (func(), error) { + b, _ := os.ReadFile(compose) + asked = string(b) + return nil, gone + }) + if err := e.StartImport(ImportRequest{FABPath: fab}); err != nil { + t.Fatalf("StartImport: %v", err) + } + msg := jobErr(waitJob(t, e)) + if !strings.Contains(asked, "0.0.0-missing") { + t.Fatalf("the helper must be asked about the BUNDLE's definition (the one that will run), got %q", asked) + } + if !strings.Contains(msg, "nem lehet letölteni") || !strings.Contains(msg, "nem nyúltunk") { + t.Fatalf("the household reads the D48 sentence, got %q", msg) + } + if prov.stopped != 0 || prov.removed != 0 || prov.started || len(*calls) != 0 { + t.Fatalf("a refused import must change nothing: stopped=%d removed=%d started=%t docker=%v", prov.stopped, prov.removed, prov.started, *calls) + } + if b, _ := os.ReadFile(filepath.Join(stackDir, "docker-compose.yml")); string(b) != "LIVE" { + t.Fatalf("the app's files were changed: %q", b) + } +} + +// A pullable image: asked first, then the import goes on as before (the running app's volumes removed after the pull). +func TestR1279_APullableImageIsAskedFirstAndTheImportGoesOn(t *testing.T) { + swapDockerExec(t, func(c dockerCall, stdin io.Reader, stdout io.Writer) (string, error) { return "", nil }) + fab, stackDir, stacksDir := r1279Bundle(t) + prov := &rtProvider{stackDir: stackDir, stacksDir: stacksDir, deployed: true, running: true, volumes: []string{"kuma_data"}} + e := NewExporter(prov, log.New(io.Discard, "", 0), "test") + removedAtAsk, released := -1, false + e.SetImagePreparer(func(string, string) (func(), error) { + removedAtAsk = prov.removed + return func() { released = true }, nil + }) + if err := e.StartImport(ImportRequest{FABPath: fab}); err != nil { + t.Fatalf("StartImport: %v", err) + } + waitJob(t, e) + if removedAtAsk != 0 || prov.removed != 1 { + t.Fatalf("the pull must come BEFORE the running app's volumes are removed: removed at ask %d, after %d", removedAtAsk, prov.removed) + } + if !released { + t.Fatal("the image-work hold must be released when the import ends") + } +} diff --git a/controller/internal/appexport/restore.go b/controller/internal/appexport/restore.go index ff923fe9..bf170cd2 100644 --- a/controller/internal/appexport/restore.go +++ b/controller/internal/appexport/restore.go @@ -338,6 +338,27 @@ func (e *Exporter) executeImport(req ImportRequest, job *Job) { return } + // R-1279 (D48 for the import, brief 2026-10-26 fix B): DOWNLOAD FIRST. Every image of the definition that will run + // (the bundle's compose; the live one when the bundle carries none) is on the box BEFORE step 1 removes the running + // app's volumes — or the import is refused here with the app untouched, in the restores' two sentences (a version + // its maker deleted / a busy or unreachable registry). Measured before: the volumes went first and the pull came at + // the database start, so a version that could not be downloaded left the app gone. + if e.prepareImages != nil { + runCompose := filepath.Join(tmpDir, "config", "docker-compose.yml") + if _, serr := os.Stat(runCompose); serr != nil { + if p, ok := e.provider.GetStackComposePath(manifest.AppName); ok { + runCompose = p + } + } + release, perr := e.prepareImages(manifest.AppName, runCompose) + if perr != nil { + e.logger.Printf("[WARN] Import: REFUSED before anything was touched — an image of %s could not be downloaded: %v (R-1279)", manifest.AppName, perr) + e.failJob(job, step, util.ErrText("hu", perr)) + return + } + defer release() + } + e.debugf("step 0 (open bundle) done in %v", time.Since(stepStart)) job.setStep(step, "done", "") diff --git a/controller/internal/backup/main_test.go b/controller/internal/backup/main_test.go index 3b47343a..631fdb7f 100644 --- a/controller/internal/backup/main_test.go +++ b/controller/internal/backup/main_test.go @@ -14,6 +14,7 @@ import ( // The production values are captured here BEFORE they are shortened, so the pin below reads what a // box runs, not what the tests run. var prodHealthSettle, prodHealthInterval, prodHealthTimeout = healthSettle, healthInterval, healthTimeout +var prodStableWindow, prodStablePoll, prodStableWatch = stableStartWindow, stableStartPoll, stableReleaseWatch func TestMain(m *testing.M) { healthSettle = 0 @@ -22,6 +23,8 @@ func TestMain(m *testing.M) { // D48 / R-650: no test in this package reaches Docker for the restore's pre-pull — every image is present unless a // test says otherwise (m.imagePresentFn / m.imagePullFn). imagePresentDefault = func(string) bool { return true } + // fix A (R-1270 follow-up): the stable-start window, shortened for the package the way the health wait is. + stableStartWindow, stableStartPoll, stableReleaseWatch = 30*time.Millisecond, 2*time.Millisecond, 2*time.Second os.Exit(m.Run()) } @@ -32,6 +35,9 @@ func TestR488_HealthWaitDefaultsAreProduction(t *testing.T) { t.Fatalf("production health wait changed: settle=%v interval=%v timeout=%v (want 3s/5s/1m30s) — "+ "a restored app now gets a different grace on every box", prodHealthSettle, prodHealthInterval, prodHealthTimeout) } + if prodStableWindow != 3*time.Minute || prodStablePoll != 10*time.Second || prodStableWatch != 30*time.Minute { + t.Fatalf("production stable-start rule changed: window=%v poll=%v watch=%v (want 3m/10s/30m)", prodStableWindow, prodStablePoll, prodStableWatch) + } } // The consequence the seam must not break: a stack that never comes up is still reported as a diff --git a/controller/internal/backup/offbox_reconstitute.go b/controller/internal/backup/offbox_reconstitute.go index c5517280..d8043573 100644 --- a/controller/internal/backup/offbox_reconstitute.go +++ b/controller/internal/backup/offbox_reconstitute.go @@ -1184,6 +1184,7 @@ func (m *Manager) ReconstituteFromOffsite(ctx context.Context, stack string, ack // directory — less informative than the customer's own flash, which already named the volumes. m.logger.Printf("[INFO] [offbox] reconstituted %s from snapshot %s: %d file(s) placed, %d volume(s) replayed, %d DB dump(s) replayed, safety dump=%s, skewed=%v", stack, id, res.FilesPlaced, res.VolumesReplayed, res.DBsReplayed, filepath.Base(safety), res.Skewed) + m.releaseAfterStableStart(stack, "off-site restore", undo) // fix A: the way back goes only after a stable start return res, nil } diff --git a/controller/internal/backup/offbox_restore_undo.go b/controller/internal/backup/offbox_restore_undo.go index cf89dce1..53853cda 100644 --- a/controller/internal/backup/offbox_restore_undo.go +++ b/controller/internal/backup/offbox_restore_undo.go @@ -40,6 +40,9 @@ type liveVolumeCopy struct { copied []string // volumes that existed and were copied (each /.tar) absent []string // volumes the snapshot adds that did not exist before (removed on a put-back) keep bool // set when a put-back could not be done: the copy is the support path back, never removed + // deferred (R-1270 follow-up): a restore that succeeded hands the copy to releaseAfterStableStart — it is removed + // only after the app ran stably for stableStartWindow, so the restore's own drop leaves it alone. + deferred bool } // RestoreUndoDir is restoreUndoDir for the app's remove with „delete its backups too" (a kept copy goes with it). @@ -170,7 +173,7 @@ func (m *Manager) copyLiveVolumes(stack, nsRoot string, vols []string, exists ma // drop removes the copy (deferred by the restore). A kept copy (a put-back that failed) stays for support. func (c *liveVolumeCopy) drop(m *Manager, stack string) { - if c == nil || c.dir == "" { + if c == nil || c.dir == "" || c.deferred { return } if c.keep { diff --git a/controller/internal/backup/r1177_local_putback_test.go b/controller/internal/backup/r1177_local_putback_test.go index e3c5dc3b..24dc8821 100644 --- a/controller/internal/backup/r1177_local_putback_test.go +++ b/controller/internal/backup/r1177_local_putback_test.go @@ -185,7 +185,7 @@ func TestR1177_ASuccessfulRestoreIsUnchangedAndLeavesNoCopy(t *testing.T) { if got := strings.Join(p.calls, ","); got != "stop,recreate,startsvc:immich-postgres,start" { t.Fatalf("sequence = %q", got) } - if left := undoCopies(t, rig.undoRoot); len(left) != 0 { + if left := waitNoCopies(t, rig.undoRoot); len(left) != 0 { // fix A: released after the stable window t.Fatalf("the copy must be removed after a successful restore, found %v", left) } } diff --git a/controller/internal/backup/r893_putback_test.go b/controller/internal/backup/r893_putback_test.go index 46f665c8..d880a021 100644 --- a/controller/internal/backup/r893_putback_test.go +++ b/controller/internal/backup/r893_putback_test.go @@ -229,7 +229,7 @@ func TestR893A_ASuccessfulRestoreRemovesTheCopy(t *testing.T) { if len(rig.poured) != 0 || *putBack != 0 { t.Errorf("nothing may be poured back after a restore that worked: poured %v, notices %d", rig.poured, *putBack) } - if left := undoCopies(t, rig.undoRoot); len(left) != 0 { + if left := waitNoCopies(t, rig.undoRoot); len(left) != 0 { // fix A: released after the stable window t.Errorf("the copy must be removed after a restore that worked, left %v", left) } if !vp.fullStarted { diff --git a/controller/internal/backup/restore_pull.go b/controller/internal/backup/restore_pull.go index 61da0e59..6a621e45 100644 --- a/controller/internal/backup/restore_pull.go +++ b/controller/internal/backup/restore_pull.go @@ -105,6 +105,12 @@ func (m *Manager) prepareRestoreImages(stack, composePath string) (release func( return end, nil } +// PrepareRestoreImages is prepareRestoreImages for a caller outside this package — the `.fab` import (R-1279), wired in +// main.go so the import refuses before it removes anything, in the restores' own words. +func (m *Manager) PrepareRestoreImages(stack, composePath string) (func(), error) { + return m.prepareRestoreImages(stack, composePath) +} + // SetRestorePullRefusedNotify wires the operator notice for a restore refused because an image could not be downloaded. func (m *Manager) SetRestorePullRefusedNotify(fn func(stack, ref string, cause error)) { m.restorePullRefusedNotify = fn diff --git a/controller/internal/backup/restore_unit.go b/controller/internal/backup/restore_unit.go index 5591df07..2f808f1b 100644 --- a/controller/internal/backup/restore_unit.go +++ b/controller/internal/backup/restore_unit.go @@ -590,6 +590,7 @@ func (m *Manager) RestoreFromRecoveryUnitAtWith(stackName, unitDir string, opt U m.logger.Printf("[INFO] [backup] Restore-from-unit completed: %s — %d volume(s) of %d listed, %d database(s) of %d listed", stackName, res.VolumesReplayed, res.ManifestVolumes, res.DBsReplayed, res.ManifestDBs) + m.releaseAfterStableStart(stackName, "unit restore", undo) // fix A: the way back goes only after a stable start return res, nil } diff --git a/controller/internal/backup/restore_verdict.go b/controller/internal/backup/restore_verdict.go index fb8c4409..cdc9cc28 100644 --- a/controller/internal/backup/restore_verdict.go +++ b/controller/internal/backup/restore_verdict.go @@ -2,6 +2,7 @@ package backup import ( "errors" + "fmt" "os" "path/filepath" "time" @@ -55,7 +56,7 @@ func (m *Manager) restoreNotStarted(stack, kind string, healthErr error, undo *l if m.restoreNotStartedNotify != nil { m.restoreNotStartedNotify(stack, kind, healthErr) } - go m.watchLateStart(stack, copyDir, time.Now()) + go m.watchLateStart(stack, copyDir, time.Now(), lateStartWatch) return util.MsgErrorf(ErrRestoreNotStarted, "err.backup.restore_not_started", stack) } @@ -66,28 +67,166 @@ func orNone(s string) string { return s } -// watchLateStart waits for the app after a not-started verdict. When it runs: the record says so and the kept copy is -// removed (the normal rule after a successful restore). A new restore of the app ends the watch untouched. -func (m *Manager) watchLateStart(stack, copyDir string, since time.Time) { - deadline := since.Add(lateStartWatch) - for time.Now().Before(deadline) { - time.Sleep(lateStartPoll) - if m.restoreRunningFor(stack) { - return // a new restore of this app owns it now - } - if m.stackProvider == nil || !m.stackProvider.RefreshAndIsRunning(stack) { - continue - } - if copyDir != "" { - if err := os.RemoveAll(copyDir); err != nil { - m.logger.Printf("[WARN] [backup] %s: started late; the kept restore copy %s could not be removed: %v", stack, copyDir, err) - } else { - _ = os.Remove(filepath.Dir(copyDir)) - } - } - m.markLateStart(stack, m.note("note.restore.late_started", stack)) - m.logger.Printf("[INFO] [backup] %s: the app started %s after its restore — the restore is a success now; the restore copy is released (R-1270)", stack, time.Since(since).Round(time.Second)) +// watchLateStart waits for the app after a not-started verdict. When it has run STABLY (stableStart): the record says +// so and the kept copy is removed (the normal rule after a successful restore). A new restore of the app ends the watch +// untouched. +func (m *Manager) watchLateStart(stack, copyDir string, since time.Time, watch time.Duration) { + switch m.waitStableStart(stack, since, since.Add(watch)) { + case stableAborted: + return // a new restore of this app owns it now + case stableNot: + m.logger.Printf("[WARN] [backup] %s: still not running stably %s after its restore — the restore copy stays for support (%s) (R-1270)", stack, lateStartWatch, orNone(copyDir)) return } - m.logger.Printf("[WARN] [backup] %s: still not running %s after its restore — the restore copy stays for support (%s) (R-1270)", stack, lateStartWatch, orNone(copyDir)) + removeCopyDir(m, stack, copyDir) + m.markLateStart(stack, m.note("note.restore.late_started", stack)) + m.logger.Printf("[INFO] [backup] %s: the app started %s after its restore and ran stably for %s — the restore is a success now; the restore copy is released (R-1270)", stack, time.Since(since).Round(time.Second), stableStartWindow) +} + +func removeCopyDir(m *Manager, stack, copyDir string) { + if copyDir == "" { + return + } + if err := os.RemoveAll(copyDir); err != nil { + m.logger.Printf("[WARN] [backup] %s: the restore copy %s could not be removed: %v", stack, copyDir, err) + return + } + _ = os.Remove(filepath.Dir(copyDir)) +} + +// ── R-1270 follow-up (brief 2026-10-26, fix A): the undo copy goes only after a STABLE start ───────────────────────── +// +// MEASURED (code at `e8d2151`): the watcher deleted the undo copy on the FIRST sample in which the stack read +// „running", and a restore whose health wait passed (one running sample, waitForHealthy) dropped it at once. An app +// that crashes and restarts reads „running" for a few seconds between crashes, so its way back could go while it was +// still broken. +// +// THE RULE (one helper for both places). „Started" means: for stableStartWindow, every sample (each stableStartPoll) +// has the stack running, every container with a healthcheck `healthy`, the same containers, and no container's +// RestartCount grown. The first verdict may still say success at once (the page; the 90 s health wait is unchanged) — +// the copy is RELEASED only after the window (releaseAfterStableStart). The verdict and the release are therefore two +// moments; `07` §6.3 says so. The window: 3 minutes — Docker's restart back-off grows to one minute, so a container +// that crashes after up to a minute of running restarts at least once inside it, and RestartCount catches every restart +// whatever its timing; it costs the household nothing (the app runs meanwhile), only the copy's disk for 3 minutes more. + +var ( + stableStartWindow = 3 * time.Minute + stableStartPoll = 10 * time.Second + stableReleaseWatch = 30 * time.Minute +) + +// ContainerSample is one container of a stack as a stable-start sample sees it. +type ContainerSample struct { + ID string + Running bool + RestartCount int + Health string // "" when the container has no healthcheck +} + +// containerSampler is the optional provider half that reads the stack's containers (restart counts, health). A provider +// without it is judged on RefreshAndIsRunning alone. +type containerSampler interface { + ContainerSamples(name string) ([]ContainerSample, error) +} + +type stableResult int + +const ( + stableYes stableResult = iota + stableNot + stableAborted +) + +// stableSample is one look: ok, and the fingerprint (container id → restart count) a stable window must keep. +func (m *Manager) stableSample(stack string) (bool, map[string]int) { + if m.stackProvider == nil || !m.stackProvider.RefreshAndIsRunning(stack) { + return false, nil + } + cs, ok := m.stackProvider.(containerSampler) + if !ok { + return true, map[string]int{} + } + samples, err := cs.ContainerSamples(stack) + if err != nil || len(samples) == 0 { + return false, nil + } + fp := make(map[string]int, len(samples)) + for _, c := range samples { + if !c.Running || (c.Health != "" && c.Health != "healthy") { + return false, nil + } + fp[c.ID] = c.RestartCount + } + return true, fp +} + +func sameRestartFingerprint(a, b map[string]int) bool { + if len(a) != len(b) { + return false + } + for k, v := range a { + if bv, ok := b[k]; !ok || bv != v { + return false + } + } + return true +} + +// waitStableStart waits until deadline for a stable window. stableAborted when a NEW restore of the app begins — one +// that began after this watch did. (The watch starts inside its own restore, before the handler ends that restore's +// record, so „a restore of the app is running" alone would end every watch at once.) +func (m *Manager) waitStableStart(stack string, watchFrom, deadline time.Time) stableResult { + var since time.Time + var fp0 map[string]int + window, poll := stableStartWindow, stableStartPoll // read once: the rule this watch began under + for time.Now().Before(deadline) { + if m.restoreBegunAfter(stack, watchFrom) { + return stableAborted + } + ok, fp := m.stableSample(stack) + switch { + case !ok: + since, fp0 = time.Time{}, nil + case since.IsZero() || !sameRestartFingerprint(fp0, fp): + since, fp0 = time.Now(), fp + case time.Since(since) >= window: + return stableYes + } + time.Sleep(poll) + } + return stableNot +} + +// releaseAfterStableStart is the success path's release: the copy stays until the app ran stably for the window, then +// it is removed. If the app does not run stably within stableReleaseWatch, the copy stays for support and the operator +// is told once (the page already said the restore worked — the app's own status shows what it does now). +func (m *Manager) releaseAfterStableStart(stack, kind string, undo *liveVolumeCopy) { + if undo == nil || undo.dir == "" { + return + } + undo.deferred = true + dir := undo.dir + from := time.Now() // taken HERE, before the goroutine: a restore begun after this moment is a new one + until := from.Add(stableReleaseWatch) + go func() { + switch m.waitStableStart(stack, from, until) { + case stableYes: + removeCopyDir(m, stack, dir) + m.logger.Printf("[INFO] [backup] %s: ran stably for %s after its %s — the restore copy is released (R-1270)", stack, stableStartWindow, kind) + case stableAborted: + m.logger.Printf("[INFO] [backup] %s: a new restore began before the %s's start was stable — its restore copy stays for support (%s)", stack, kind, dir) + default: + m.logger.Printf("[ERROR] [backup] %s: did not run stably within %s after its %s — the restore copy stays for support (%s) (R-1270)", stack, stableReleaseWatch, kind, dir) + if m.restoreNotStartedNotify != nil { + m.restoreNotStartedNotify(stack, kind+" (not stable after its start)", fmt.Errorf("no stable %s within %s", stableStartWindow, stableReleaseWatch)) + } + } + }() +} + +// restoreBegunAfter reports whether a restore of stack is running that began after t. +func (m *Manager) restoreBegunAfter(stack string, t time.Time) bool { + m.mu.Lock() + defer m.mu.Unlock() + return m.restoreRunningForLocked(stack) && m.opStartedAt.After(t) } diff --git a/controller/internal/backup/restore_verdict_test.go b/controller/internal/backup/restore_verdict_test.go index ded34867..6a9dfb89 100644 --- a/controller/internal/backup/restore_verdict_test.go +++ b/controller/internal/backup/restore_verdict_test.go @@ -68,7 +68,7 @@ func TestR1270_AHealthyRestoreIsASuccessAsBefore(t *testing.T) { if _, err := m.RestoreFromRecoveryUnit("app"); err != nil { t.Fatalf("a healthy restore is a success: %v", err) } - if left := undoCopies(t, rig.undoRoot); len(left) != 0 { + if left := waitNoCopies(t, rig.undoRoot); len(left) != 0 { t.Fatalf("the copy is released after a healthy restore, found %v", left) } if len(*alarms) != 0 { @@ -148,3 +148,16 @@ func TestR1270_MarkLateStartTouchesOnlyItsOwnRecord(t *testing.T) { } _ = os.Getpid } + +// waitNoCopies waits (bounded) for a deferred release — fix A releases the copy after the stable window, not at return. +func waitNoCopies(t *testing.T, root string) []string { + t.Helper() + deadline := time.Now().Add(3 * time.Second) + for time.Now().Before(deadline) { + if left := undoCopies(t, root); len(left) == 0 { + return nil + } + time.Sleep(5 * time.Millisecond) + } + return undoCopies(t, root) +} diff --git a/controller/internal/backup/stable_start_test.go b/controller/internal/backup/stable_start_test.go new file mode 100644 index 00000000..d9906671 --- /dev/null +++ b/controller/internal/backup/stable_start_test.go @@ -0,0 +1,147 @@ +package backup + +import ( + "io" + "log" + "sync" + "testing" + "time" +) + +// Fix A (brief 2026-10-26; R-1270 follow-up) — the undo copy is released only after a STABLE start. +// COMPANION RED-PROOF (REPORT.md): on `e8d2151` (the copy dropped at the restore's return / at the watcher's first +// running sample) TestFixA_AFlappingAppKeepsTheCopy and TestFixA_AHealthcheckStillStartingKeepsTheCopy fail. + +// sampledProvider is the D22 rig's provider with a scripted container sample per call. +type sampledProvider struct { + *r1177Provider + mu sync.Mutex + n int + running func(n int) bool + sample func(n int) []ContainerSample +} + +func (p *sampledProvider) RefreshAndIsRunning(string) bool { + p.mu.Lock() + defer p.mu.Unlock() + p.n++ + return p.running(p.n) +} + +func (p *sampledProvider) ContainerSamples(string) ([]ContainerSample, error) { + p.mu.Lock() + defer p.mu.Unlock() + return p.sample(p.n), nil +} + +func fixARig(t *testing.T, running func(int) bool, sample func(int) []ContainerSample) (*Manager, *r1177Rig, *[]string) { + t.Helper() + m, p, rig, _ := r1177Fixture(t) + sp := &sampledProvider{r1177Provider: p, running: running, sample: sample} + m.stackProvider = sp + var alarms []string + var mu sync.Mutex + m.SetRestoreNotStartedNotify(func(stack, kind string, _ error) { mu.Lock(); alarms = append(alarms, kind); mu.Unlock() }) + return m, rig, &alarms +} + +func withStable(t *testing.T, window, watch time.Duration) { + t.Helper() + w0, p0, r0 := stableStartWindow, stableStartPoll, stableReleaseWatch + stableStartWindow, stableStartPoll, stableReleaseWatch = window, 2*time.Millisecond, watch + t.Cleanup(func() { stableStartWindow, stableStartPoll, stableReleaseWatch = w0, p0, r0 }) +} + +func healthy(id string, restarts int) ContainerSample { + return ContainerSample{ID: id, Running: true, RestartCount: restarts, Health: "healthy"} +} + +// running → restarting → running: the copy stays, and the operator hears once that the start was not stable. +func TestFixA_AFlappingAppKeepsTheCopy(t *testing.T) { + withStable(t, 60*time.Millisecond, 400*time.Millisecond) + m, rig, alarms := fixARig(t, + func(n int) bool { return n%3 != 0 }, // every third sample: restarting + func(n int) []ContainerSample { return []ContainerSample{healthy("c1", n/3)} }) // and the count grows + if _, err := m.RestoreFromRecoveryUnit("app"); err != nil { + t.Fatalf("the restore itself passes its 90 s health wait (a running sample): %v", err) + } + time.Sleep(600 * time.Millisecond) + if left := undoCopies(t, rig.undoRoot); len(left) != 1 { + t.Fatalf("a flapping app must keep its way back, found %v", left) + } + if len(*alarms) != 1 { + t.Fatalf("the operator hears once that the start was not stable, got %v", *alarms) + } +} + +// A stable stack: the copy is still there right after the restore, and gone after the window. +func TestFixA_AStableAppReleasesTheCopyAfterTheWindow(t *testing.T) { + withStable(t, 150*time.Millisecond, 3*time.Second) + m, rig, alarms := fixARig(t, func(int) bool { return true }, + func(int) []ContainerSample { return []ContainerSample{healthy("c1", 0), {ID: "db", Running: true}} }) + // The production order: the handler begins the record, the restore runs (and starts the watch), the handler ends it. + m.BeginRestoreOp("restore", "app") + if _, err := m.RestoreFromRecoveryUnit("app"); err != nil { + t.Fatal(err) + } + m.EndRestoreOp(true, "ok") + if left := undoCopies(t, rig.undoRoot); len(left) != 1 { + t.Fatalf("the copy is NOT released at the restore's return any more, found %v", left) + } + if left := waitNoCopies(t, rig.undoRoot); len(left) != 0 { + t.Fatalf("a stable app releases the copy after the window, found %v", left) + } + if len(*alarms) != 0 { + t.Fatalf("no alarm for a stable app: %v", *alarms) + } +} + +// A container whose healthcheck still says `starting` is not started. +func TestFixA_AHealthcheckStillStartingKeepsTheCopy(t *testing.T) { + withStable(t, 30*time.Millisecond, 300*time.Millisecond) + m, rig, _ := fixARig(t, func(int) bool { return true }, + func(int) []ContainerSample { return []ContainerSample{{ID: "c1", Running: true, Health: "starting"}} }) + if _, err := m.RestoreFromRecoveryUnit("app"); err != nil { + t.Fatal(err) + } + time.Sleep(500 * time.Millisecond) + if left := undoCopies(t, rig.undoRoot); len(left) != 1 { + t.Fatalf("a healthcheck still starting must keep the copy, found %v", left) + } +} + +// A new restore of the app during the watch ends it untouched (unchanged rule). +func TestFixA_ANewRestoreDuringTheWatchLeavesTheCopy(t *testing.T) { + withStable(t, 400*time.Millisecond, 2*time.Second) + m, rig, alarms := fixARig(t, func(int) bool { return true }, + func(int) []ContainerSample { return []ContainerSample{healthy("c1", 0)} }) + if _, err := m.RestoreFromRecoveryUnit("app"); err != nil { + t.Fatal(err) + } + m.BeginRestoreOp("restore", "app") + time.Sleep(700 * time.Millisecond) + if left := undoCopies(t, rig.undoRoot); len(left) != 1 { + t.Fatalf("a new restore owns the app: the watch ends and the copy stays, found %v", left) + } + if len(*alarms) != 0 { + t.Fatalf("an aborted watch raises no alarm: %v", *alarms) + } +} + +// The late-start watcher (after a not-started verdict) uses the same rule: a flapping app never becomes a success. +func TestFixA_TheLateStartWatcherNeedsAStableStart(t *testing.T) { + withStable(t, 60*time.Millisecond, 2*time.Second) + lateStartWatch = 400 * time.Millisecond + defer func() { lateStartWatch = 30 * time.Minute }() + m := &Manager{logger: log.New(io.Discard, "", 0)} + sp := &sampledProvider{r1177Provider: &r1177Provider{fakeRecoveryProvider: &fakeRecoveryProvider{}}, + running: func(n int) bool { return n%3 != 0 }, + sample: func(n int) []ContainerSample { return []ContainerSample{healthy("c1", n/3)} }} + m.stackProvider = sp + m.BeginRestoreOp("restore", "app") + m.EndRestoreOpNotStarted("not yet") + m.watchLateStart("app", "", time.Now(), lateStartWatch) + if st := m.RestoreStatus(); st.Last.OK { + t.Fatal("a flapping app must never turn the record into a success") + } +}