D49 = A follow-ups: (A) the undo copy is released only after a stable start — 3 min of running, healthy, no restart, one rule for the first verdict and the late-start watch; a watch ends only for a restore begun after it; (B, R-1279) the .fab import downloads first with the restores' D48 helper, before it removes anything. Red-proved. Commit only.
gates / gates (push) Successful in 1m26s

This commit is contained in:
2026-10-25 12:45:33 +01:00
parent e8d2151a77
commit 7720439440
16 changed files with 549 additions and 27 deletions
+6
View File
@@ -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
@@ -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
}
@@ -40,6 +40,9 @@ type liveVolumeCopy struct {
copied []string // volumes that existed and were copied (each <dir>/<vol>.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 {
@@ -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)
}
}
@@ -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 {
@@ -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
@@ -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
}
+162 -23
View File
@@ -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)
}
@@ -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)
}
@@ -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")
}
}