diff --git a/CHANGELOG.md b/CHANGELOG.md index d2110e44..75085e32 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -31,7 +31,9 @@ says „not started yet", alarms the operator; a late start is a success; never 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 + read-only `docker inspect` in the stack adapter). The page's first verdict also needs a stable 45 s after the 90 s + health wait (`restoredAppStarted`, every restore path), so an app that runs, crashes and restarts reads „not started + yet" on the page as well (`TestFixA_AFlappingAppKeepsTheCopy`, seen failing with the one-sample wait); 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" diff --git a/controller/internal/api/r650_main_test.go b/controller/internal/api/r650_main_test.go index edec5ad6..b9c036b9 100644 --- a/controller/internal/api/r650_main_test.go +++ b/controller/internal/api/r650_main_test.go @@ -4,9 +4,13 @@ import ( "os" "testing" + "gitea.dooplex.hu/admin/felhom-controller/internal/backup" "gitea.dooplex.hu/admin/felhom-controller/internal/dockerexec" ) // TestMain puts a silent docker stub on PATH for every test in this package: R-650, the fixtures // here build a real stacks.Manager, and on the build host (DooPlex) that reached production Docker. -func TestMain(m *testing.M) { os.Exit(dockerexec.RunWithStub(m)) } +func TestMain(m *testing.M) { + backup.ShortenRestoreTimingForTests() // fix A's stable windows in milliseconds here too + os.Exit(dockerexec.RunWithStub(m)) +} diff --git a/controller/internal/backup/main_test.go b/controller/internal/backup/main_test.go index 631fdb7f..7c285509 100644 --- a/controller/internal/backup/main_test.go +++ b/controller/internal/backup/main_test.go @@ -14,7 +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 +var prodStableWindow, prodStablePoll, prodStableWatch, prodVerdictWindow = stableStartWindow, stableStartPoll, stableReleaseWatch, verdictStableWindow func TestMain(m *testing.M) { healthSettle = 0 @@ -25,6 +25,7 @@ func TestMain(m *testing.M) { 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 + verdictStableWindow = 10 * time.Millisecond os.Exit(m.Run()) } @@ -35,7 +36,7 @@ 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 { + if prodStableWindow != 3*time.Minute || prodStablePoll != 10*time.Second || prodStableWatch != 30*time.Minute || prodVerdictWindow != 45*time.Second { t.Fatalf("production stable-start rule changed: window=%v poll=%v watch=%v (want 3m/10s/30m)", prodStableWindow, prodStablePoll, prodStableWatch) } } diff --git a/controller/internal/backup/offbox_reconstitute.go b/controller/internal/backup/offbox_reconstitute.go index d8043573..e3286228 100644 --- a/controller/internal/backup/offbox_reconstitute.go +++ b/controller/internal/backup/offbox_reconstitute.go @@ -1175,7 +1175,7 @@ func (m *Manager) ReconstituteFromOffsite(ctx context.Context, stack string, ack // Pinned by TestR475_OffsiteRestoreClearsAnUpdateHold. m.clearUpdateHoldAfterRestore(stack) // R-1270: never a success over an app that did not start; the data stays, the undo copy (and the safety dump) stay. - if err := m.waitForHealthy(stack, healthTimeout); err != nil { + if err := m.restoredAppStarted(stack); err != nil { return res, m.restoreNotStarted(stack, "off-site restore", err, undo) } diff --git a/controller/internal/backup/restore.go b/controller/internal/backup/restore.go index 5870a337..1cff33c0 100644 --- a/controller/internal/backup/restore.go +++ b/controller/internal/backup/restore.go @@ -153,7 +153,7 @@ func (m *Manager) RestoreApp(stackName, snapshotID string) error { } // Verify app started successfully — R-1270: a timeout is not a success. - healthErr := m.waitForHealthy(stackName, healthTimeout) + healthErr := m.restoredAppStarted(stackName) if dataErr != nil { return fmt.Errorf("restore of %s completed with data errors: %w", stackName, dataErr) diff --git a/controller/internal/backup/restore_unit.go b/controller/internal/backup/restore_unit.go index 2f808f1b..eebee576 100644 --- a/controller/internal/backup/restore_unit.go +++ b/controller/internal/backup/restore_unit.go @@ -584,7 +584,7 @@ func (m *Manager) RestoreFromRecoveryUnitAtWith(stackName, unitDir string, opt U m.clearUpdateHoldAfterRestore(stackName) // R-1270: the verdict follows the app. A health timeout is NOT a success (it used to be a WARN, and the page said // „az alkalmazás újraindult" over an app that never came up); the data stays restored and the undo copy is kept. - if err := m.waitForHealthy(stackName, healthTimeout); err != nil { + if err := m.restoredAppStarted(stackName); err != nil { return res, m.restoreNotStarted(stackName, "unit restore", err, undo) } diff --git a/controller/internal/backup/restore_verdict.go b/controller/internal/backup/restore_verdict.go index cdc9cc28..6486b7a0 100644 --- a/controller/internal/backup/restore_verdict.go +++ b/controller/internal/backup/restore_verdict.go @@ -110,9 +110,13 @@ func removeCopyDir(m *Manager, stack, copyDir string) { // 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 + // verdictStableWindow is the first verdict's own stable window (after the 90 s health wait found the app running): + // 45 s — longer than the 20 s crash cycle of the measured case, so an app that runs, crashes and restarts is + // „not started yet" on the page too, and short enough that a good restore is reported within about two minutes. + verdictStableWindow = 45 * time.Second + 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. @@ -176,9 +180,14 @@ func sameRestartFingerprint(a, b map[string]int) bool { // 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 { + return m.waitStableFor(stack, watchFrom, deadline, stableStartWindow) +} + +// waitStableFor is waitStableStart with an explicit window (the first verdict's is shorter, verdictStableWindow). +func (m *Manager) waitStableFor(stack string, watchFrom, deadline time.Time, window time.Duration) stableResult { var since time.Time var fp0 map[string]int - window, poll := stableStartWindow, stableStartPoll // read once: the rule this watch began under + poll := stableStartPoll // read once: the rule this watch began under for time.Now().Before(deadline) { if m.restoreBegunAfter(stack, watchFrom) { return stableAborted @@ -230,3 +239,27 @@ func (m *Manager) restoreBegunAfter(stack string, t time.Time) bool { defer m.mu.Unlock() return m.restoreRunningForLocked(stack) && m.opStartedAt.After(t) } + +// restoredAppStarted is the restore's first verdict (every path): the 90 s health wait (one running sample, as before) +// AND then a stable verdictStableWindow within another health timeout — so an app that crashes and restarts is not +// reported as started. nil = started (the page says so; the copy is still released only after stableStartWindow). +func (m *Manager) restoredAppStarted(stack string) error { + if err := m.waitForHealthy(stack, healthTimeout); err != nil { + return err + } + from := time.Now() + switch m.waitStableFor(stack, from, from.Add(healthTimeout+verdictStableWindow), verdictStableWindow) { + case stableYes: + return nil + case stableAborted: + return fmt.Errorf("a new restore of %s began", stack) + } + return fmt.Errorf("stack %s did not run stably for %s (it restarted or turned unhealthy) after restore", stack, verdictStableWindow) +} + +// ShortenRestoreTimingForTests (TESTS ONLY — other packages' TestMain) makes the stable-start rule take milliseconds, +// as this package's own TestMain does; a web or api test that runs a real restore then does not wait 45 s per call. +// Never called by production code (pinned by TestR488_HealthWaitDefaultsAreProduction reading the defaults). +func ShortenRestoreTimingForTests() { + verdictStableWindow, stableStartWindow, stableStartPoll = 10*time.Millisecond, 30*time.Millisecond, 2*time.Millisecond +} diff --git a/controller/internal/backup/stable_start_test.go b/controller/internal/backup/stable_start_test.go index d9906671..049b7ce2 100644 --- a/controller/internal/backup/stable_start_test.go +++ b/controller/internal/backup/stable_start_test.go @@ -1,8 +1,12 @@ package backup import ( + "errors" "io" "log" + "os" + "path/filepath" + "strings" "sync" "testing" "time" @@ -62,15 +66,23 @@ func TestFixA_AFlappingAppKeepsTheCopy(t *testing.T) { 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) + lateStartWatch = 400 * time.Millisecond + defer func() { lateStartWatch = 30 * time.Minute }() + m.BeginRestoreOp("restore", "app") + _, err := m.RestoreFromRecoveryUnit("app") + if !errors.Is(err, ErrRestoreNotStarted) { + t.Fatalf("a running → restarting → running app is „not started yet\" on the page too, got %v", err) } + m.EndRestoreOpNotStarted(err.Error()) 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) + t.Fatalf("the operator hears once, got %v", *alarms) + } + if st := m.RestoreStatus(); st.Last.OK { + t.Fatal("the late-start watch must never turn a flapping app into a success") } } @@ -101,8 +113,8 @@ 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) + if _, err := m.RestoreFromRecoveryUnit("app"); !errors.Is(err, ErrRestoreNotStarted) { + t.Fatalf("a healthcheck still starting is not started, got %v", err) } time.Sleep(500 * time.Millisecond) if left := undoCopies(t, rig.undoRoot); len(left) != 1 { @@ -145,3 +157,17 @@ func TestFixA_TheLateStartWatcherNeedsAStableStart(t *testing.T) { t.Fatal("a flapping app must never turn the record into a success") } } + +// ShortenRestoreTimingForTests must never reach production: only test files may call it. +func TestFixA_TheTestTimingSwitchIsNeverCalledByProduction(t *testing.T) { + root := filepath.Join("..", "..") + _ = filepath.Walk(root, func(p string, fi os.FileInfo, err error) error { + if err != nil || fi.IsDir() || !strings.HasSuffix(p, ".go") || strings.HasSuffix(p, "_test.go") || strings.HasSuffix(p, "restore_verdict.go") { + return nil + } + if b, _ := os.ReadFile(p); strings.Contains(string(b), "ShortenRestoreTimingForTests") { + t.Errorf("%s calls the test-only timing switch", p) + } + return nil + }) +} diff --git a/controller/internal/backup/tier2_restore.go b/controller/internal/backup/tier2_restore.go index 55ec4821..1416c2f4 100644 --- a/controller/internal/backup/tier2_restore.go +++ b/controller/internal/backup/tier2_restore.go @@ -450,7 +450,7 @@ func (m *Manager) RestoreTier2Files(stackName string) (filesRestored int, err er if startErr != nil { m.logger.Printf("[ERROR] [backup] failed to restart %s after Tier-2 file restore: %v", stackName, startErr) } - healthErr := m.waitForHealthy(stackName, healthTimeout) + healthErr := m.restoredAppStarted(stackName) if copyErr != nil { return filesRestored, util.MsgError("err.backup.fajlmasolas_sikertelen", copyErr) diff --git a/controller/internal/web/r650_main_test.go b/controller/internal/web/r650_main_test.go index 7c1b7d39..c1d20679 100644 --- a/controller/internal/web/r650_main_test.go +++ b/controller/internal/web/r650_main_test.go @@ -4,9 +4,13 @@ import ( "os" "testing" + "gitea.dooplex.hu/admin/felhom-controller/internal/backup" "gitea.dooplex.hu/admin/felhom-controller/internal/dockerexec" ) // TestMain puts a silent docker stub on PATH for every test in this package: R-650, the fixtures // here build a real stacks.Manager, and on the build host (DooPlex) that reached production Docker. -func TestMain(m *testing.M) { os.Exit(dockerexec.RunWithStub(m)) } +func TestMain(m *testing.M) { + backup.ShortenRestoreTimingForTests() // fix A's stable windows in milliseconds here too + os.Exit(dockerexec.RunWithStub(m)) +}