diff --git a/CHANGELOG.md b/CHANGELOG.md index 6edd9934..a01088a9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -22,6 +22,25 @@ brief 2026-10-24, Part 4 (commit only; the release rides the next normal train). `…OnlyWhenTheAgentWaitsAndAnAppRuns`, `…QBLimitRuleSkipsAHeldLimit`, `…TheTwoAppsReadAndWriteTheirLimit`, `TestLineTestRunOutlastsTheClientTimeout`, `TestStartUpwatchRecoversTheHoldFirst`, `TestUpwatchHoldGetsBothAgentCalls`. +### A restore whose app does not start is never „success" (R-1270, P2) — 2026-10-25, commit only + +- **Measured before (9202, 0.342.0 = `e1613ae` for these files; `audits/restore-truth-2026-10-25/before/`):** the + Tandoor restore whose app stayed `starting` was recorded `ok: true`, „A(z) tandoor: 3 adatkötet és az adatbázis + visszaállítva — az alkalmazás újraindult." The health timeout was a WARN on every restore path. +- **Now (`internal/backup/restore_verdict.go`):** the unit restore (so the second drive's unit and whole restore, a + kept load and a set-aside unit), the off-site restore, the second drive's file restore and the no-unit fallback + return `ErrRestoreNotStarted` when the app does not reach running in time. The household reads „A(z) %s: az + adatokat visszatöltöttük, de az alkalmazás még nem indult el. Várj pár percet, majd nyisd meg újra. Ha így marad, + szólj nekünk." alone (the record is `ok: false`, `not_started: true`); the operator gets one `backup_run_failures` + line (leg `restore-not-started`). +- **The safest reading (the operator may change it):** a timeout does NOT pour the old data back (a slow first start + is common). The data stays restored; the restore's undo copy is KEPT, like a failed put-back's copy for support — + no new retention rule. A watcher looks 30 more minutes: when the app runs, the record turns to success („…elindult: + a visszaállítás kész.") and the copy is removed, as after any successful restore. +- Tests (each seen failing with the old WARN): `TestR1270_AUnitRestoreWhoseAppDoesNotStartIsNotASuccess`, + `…ALateStartTurnsTheRecordIntoASuccess`, `…TheOffsiteRestoreToo`, web `…TheRecordOfANotStartedRestore`; controls + `…AHealthyRestoreIsASuccessAsBefore`, `…MarkLateStartTouchesOnlyItsOwnRecord`. + ### A new install never writes into an earlier install's backup (D47, R-1269, P2) — 2026-10-25, commit only Operator ruling D47 (2026-10-25 08:38, `09` §3): a recovery unit's definition and its data are written only together, diff --git a/controller/cmd/controller/main.go b/controller/cmd/controller/main.go index 3584db87..0568fd79 100644 --- a/controller/cmd/controller/main.go +++ b/controller/cmd/controller/main.go @@ -1541,6 +1541,14 @@ func main() { }) // R-893 option A (D20 = A): a failed off-site restore that was PUT BACK — the live volumes and definition poured // back and the app started. The same operator-tier event as the hold above (no new event type), its own leg. + // R-1270: a restore whose data is back but whose app did not start in time — one operator line, its own leg. + backupMgr.SetRestoreNotStartedNotify(func(stack, kind string, cause error) { + d := notify.BackupRunFailuresDetails{RunKind: "restore", Failed: 1, Attempted: 1} + d.Apps = append(d.Apps, notify.RunFailureDetail{App: stack, Leg: "restore-not-started", Reason: cause.Error()}) + msg := fmt.Sprintf("App %q: its %s put the data back, but the app did not start in time (R-1270). The household was told it has not "+ + "started yet; the pre-restore copy is kept. If it does not start by itself within 30 minutes, it needs a look. Error: %v", stack, kind, cause) + notifier.NotifyBackupRunFailures(msg, d) + }) backupMgr.SetRestorePutBackNotify(func(stack string, replayErr error) { d := notify.BackupRunFailuresDetails{RunKind: "offsite-reconstitute", Failed: 1, Attempted: 1} d.Apps = append(d.Apps, notify.RunFailureDetail{App: stack, Leg: "restore-put-back", Reason: "restore failed; the pre-restore copy was put back"}) diff --git a/controller/internal/backup/backup.go b/controller/internal/backup/backup.go index cf748ada..a39e6ab9 100644 --- a/controller/internal/backup/backup.go +++ b/controller/internal/backup/backup.go @@ -241,6 +241,8 @@ type Manager struct { // restorePutBackNotify (R-893 option A) is called once when a failed off-site restore was put back and the app // started again. Operator-tier, the same seam shape as restoreHoldNotify. restorePutBackNotify func(stack string, replayErr error) + // restoreNotStartedNotify (R-1270) is called once when a restore's data is back but its app did not start in time. + restoreNotStartedNotify func(stack, kind string, cause error) // R-403 unit-REHYDRATE seam — the copy that refills the primary unit from the Tier-2 mirror after // a restore, overridable so the "only when hollow" condition and the byte-identical non-effect are diff --git a/controller/internal/backup/kept_load.go b/controller/internal/backup/kept_load.go index f63c45e2..c7b66bdd 100644 --- a/controller/internal/backup/kept_load.go +++ b/controller/internal/backup/kept_load.go @@ -278,6 +278,10 @@ func (m *Manager) LoadKeptOffsite(app, drive string, c KeptCopy, prepare func() } res, err := m.keptUnitRestore()(app, unitDir) cleanup() + if errors.Is(err, ErrRestoreNotStarted) { + m.keptLoadNotStarted(app, err, after) + return + } if err != nil { fail(err) return @@ -320,6 +324,10 @@ func (m *Manager) LoadKeptApp(app, unitDir string, okMsg, failMsg func(err error go func() { start := time.Now() res, err := m.keptUnitRestore()(app, unitDir) + if errors.Is(err, ErrRestoreNotStarted) { + m.keptLoadNotStarted(app, err, after) + return + } if err != nil { m.logger.Printf("[ERROR] [backup] kept load %s from %s FAILED after %s: %v", app, unitDir, time.Since(start).Round(time.Second), err) m.EndRestoreOp(false, failMsg(err)) @@ -336,3 +344,14 @@ func (m *Manager) LoadKeptApp(app, unitDir string, okMsg, failMsg func(err error } }() } + +// keptLoadNotStarted (R-1270): the kept data is loaded but the app did not start in time. Never „done": the record says +// so (a late start turns it into a success); after(true) still runs — the data DID land, so the app's after_load (it +// waits for the app) and the kept folder's tidy-up belong to it. +func (m *Manager) keptLoadNotStarted(app string, err error, after func(ok bool)) { + m.logger.Printf("[WARN] [backup] kept load %s: the data is loaded, the app did not start in time — not reported as done", app) + m.EndRestoreOpNotStarted(m.noteErr(err)) + if after != nil { + after(true) + } +} diff --git a/controller/internal/backup/offbox_reconstitute.go b/controller/internal/backup/offbox_reconstitute.go index f7290406..2ae4e69d 100644 --- a/controller/internal/backup/offbox_reconstitute.go +++ b/controller/internal/backup/offbox_reconstitute.go @@ -1160,8 +1160,9 @@ func (m *Manager) ReconstituteFromOffsite(ctx context.Context, stack string, ack // so without this line a successful off-site restore would leave the app refusing its next start. // 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 { - m.logger.Printf("[WARN] [offbox] %s reconstituted but health check failed: %v", stack, err) + return res, m.restoreNotStarted(stack, "off-site restore", err, undo) } // R-382: VolumesReplayed was set above and never printed, so the operator log said diff --git a/controller/internal/backup/opstatus.go b/controller/internal/backup/opstatus.go index 553b6422..adcedb87 100644 --- a/controller/internal/backup/opstatus.go +++ b/controller/internal/backup/opstatus.go @@ -25,6 +25,9 @@ type RestoreOpResult struct { // PutBackWaiting (R-1251) marks an interrupted restore whose put-back waits for the app's drive: the message says the // box puts the data back when the drive is there — not „start it again", which would restore the backup over it. PutBackWaiting bool `json:"put_back_waiting,omitempty"` + // NotStarted (R-1270) marks a restore whose data is back but whose app did not start in time: not a success. A late + // start turns the record to success (markLateStart). + NotStarted bool `json:"not_started,omitempty"` } // RestoreResultWindow bounds how long a finished restore still counts as "what just happened". @@ -108,3 +111,25 @@ func (m *Manager) RestoreStatus() RestoreOpStatus { } return st } + +// EndRestoreOpNotStarted records a restore whose data is back but whose app did not start in time (R-1270): not ok, the +// household's sentence, and the mark a late start reads. +func (m *Manager) EndRestoreOpNotStarted(message string) { + m.mu.Lock() + defer m.mu.Unlock() + m.opLast = &RestoreOpResult{Op: m.opName, Stack: m.opStack, OK: false, Message: message, FinishedAt: time.Now(), NotStarted: true} + m.opRunning = false + m.persistRestoreRecordLocked() +} + +// markLateStart turns the latest record of stack to success when it is still that restore's not-started record and no +// restore runs now (R-1270). Anything else is left as it is. +func (m *Manager) markLateStart(stack, message string) { + m.mu.Lock() + defer m.mu.Unlock() + if m.opRunning || m.opLast == nil || m.opLast.Stack != stack || !m.opLast.NotStarted { + return + } + m.opLast = &RestoreOpResult{Op: m.opLast.Op, Stack: stack, OK: true, Message: message, FinishedAt: time.Now()} + m.persistRestoreRecordLocked() +} diff --git a/controller/internal/backup/restore.go b/controller/internal/backup/restore.go index 9a91bb2e..ab550e0e 100644 --- a/controller/internal/backup/restore.go +++ b/controller/internal/backup/restore.go @@ -143,14 +143,15 @@ func (m *Manager) RestoreApp(stackName, snapshotID string) error { m.logger.Printf("[WARN] RESTORE could not restart %s after restore: %v", stackName, err) } - // Verify app started successfully - if err := m.waitForHealthy(stackName, healthTimeout); err != nil { - m.logger.Printf("[WARN] [backup] Restore completed but app health check failed: %v", err) - } + // Verify app started successfully — R-1270: a timeout is not a success. + healthErr := m.waitForHealthy(stackName, healthTimeout) if dataErr != nil { return fmt.Errorf("restore of %s completed with data errors: %w", stackName, dataErr) } + if healthErr != nil { + return m.restoreNotStarted(stackName, "volume-only restore", healthErr, nil) + } m.logger.Printf("[INFO] RESTORE completed: stack=%s", stackName) return nil } diff --git a/controller/internal/backup/restore_unit.go b/controller/internal/backup/restore_unit.go index 81be0da0..22cabc70 100644 --- a/controller/internal/backup/restore_unit.go +++ b/controller/internal/backup/restore_unit.go @@ -564,15 +564,17 @@ func (m *Manager) RestoreFromRecoveryUnitAtWith(stackName, unitDir string, opt U m.logger.Printf("[ERROR] [backup] starting %s after restore from unit: %v — putting the live data back", stackName, err) return putBack(err, "err.backup.restore_failed_held_mixed", false) } + // Slice 4: the app is back on its unit's definition and data and was started — the route back an + // update hold names. Lift that hold (and only that kind; see clearUpdateHoldAfterRestore). + 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 { - m.logger.Printf("[WARN] [backup] %s restored but health check failed: %v", stackName, err) + return res, m.restoreNotStarted(stackName, "unit restore", err, undo) } 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) - // Slice 4: the app is back on its unit's definition and data and was started — the route back an - // update hold names. Lift that hold (and only that kind; see clearUpdateHoldAfterRestore). - m.clearUpdateHoldAfterRestore(stackName) return res, nil } diff --git a/controller/internal/backup/restore_verdict.go b/controller/internal/backup/restore_verdict.go new file mode 100644 index 00000000..fb8c4409 --- /dev/null +++ b/controller/internal/backup/restore_verdict.go @@ -0,0 +1,93 @@ +package backup + +import ( + "errors" + "os" + "path/filepath" + "time" + + "gitea.dooplex.hu/admin/felhom-controller/internal/util" +) + +// ── R-1270: the verdict follows the app (brief 2026-10-25, Part 3) ───────────────────────────────────────────────── +// +// MEASURED BEFORE (catalog sweep 2026-10-24; again on 9202 2026-10-25, `audits/restore-truth-2026-10-25/before/`): the +// controller logged „tandoor restored but health check failed: stack tandoor did not reach running state within 1m30s" +// at WARN, the restore function returned success, and the page the household reads said `ok: true` — „…visszaállítva — +// az alkalmazás újraindult." The app was `starting` and never came up. Every restore path had the same WARN-and-succeed +// shape: the unit restore, the off-site restore, the second drive's file restore and the no-unit fallback. +// +// THE RULE. A restore whose app does not reach running in time NEVER reports success. It returns ErrRestoreNotStarted +// and the household reads „Az adatokat visszatöltöttük, de az alkalmazás még nem indult el. Várj pár percet, majd nyisd +// meg újra. Ha így marad, szólj nekünk." The operator gets one alarm (backup_run_failures, leg `restore-not-started`). +// +// THE SAFEST READING (brief 2026-10-25 Part 3.2 — the operator may change it). A health timeout does NOT pour the old +// data back: a slow first start (a database migration) is common, and a put-back would throw away a correct restore. +// The data stays restored and the restore's undo copy is KEPT (the same „kept for support" state a failed put-back +// leaves, `07` §8 — no new retention rule). A watcher looks for the app for lateStartWatch more: when it runs, the +// record turns to success („…elindult") and the copy is released by the normal rule (removed, as after any successful +// restore). If it never runs, the copy stays for support, as a failed put-back's does. + +// ErrRestoreNotStarted is the KIND of a restore whose data is back but whose app did not reach running in time. +var ErrRestoreNotStarted = errors.New("the data is restored but the app did not start in time") + +// lateStartWatch / lateStartPoll bound the watcher after a not-started verdict (tests shorten them). +var ( + lateStartWatch = 30 * time.Minute + lateStartPoll = 30 * time.Second +) + +// SetRestoreNotStartedNotify wires the operator alarm for a restore whose app did not start (main.go). +func (m *Manager) SetRestoreNotStartedNotify(fn func(stack, kind string, cause error)) { + m.restoreNotStartedNotify = fn +} + +// restoreNotStarted is the verdict of a restore whose health check failed: the undo copy is kept, the operator is told +// once, the watcher starts, and the household's sentence is returned as the error. kind names the path (log + alarm). +func (m *Manager) restoreNotStarted(stack, kind string, healthErr error, undo *liveVolumeCopy) error { + copyDir := "" + if undo != nil && undo.dir != "" { + undo.keep = true + copyDir = undo.dir + } + m.logger.Printf("[ERROR] [backup] %s: the %s put the data back, but the app did not start: %v — NOT reported as a success; the restore copy is kept (%s); watching %s for a late start (R-1270)", + stack, kind, healthErr, orNone(copyDir), lateStartWatch) + if m.restoreNotStartedNotify != nil { + m.restoreNotStartedNotify(stack, kind, healthErr) + } + go m.watchLateStart(stack, copyDir, time.Now()) + return util.MsgErrorf(ErrRestoreNotStarted, "err.backup.restore_not_started", stack) +} + +func orNone(s string) string { + if s == "" { + return "no copy" + } + 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)) + 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)) +} diff --git a/controller/internal/backup/restore_verdict_test.go b/controller/internal/backup/restore_verdict_test.go new file mode 100644 index 00000000..ded34867 --- /dev/null +++ b/controller/internal/backup/restore_verdict_test.go @@ -0,0 +1,150 @@ +package backup + +import ( + "context" + "errors" + "os" + "strings" + "sync/atomic" + "testing" + "time" + + "gitea.dooplex.hu/admin/felhom-controller/internal/util" +) + +// R-1270 (brief 2026-10-25 Part 3) — the verdict follows the app. Measured before (9202, 0.342.0 = `e1613ae` for these +// files, `audits/restore-truth-2026-10-25/before/`): the Tandoor restore whose app never came up was recorded `ok: true`, +// „…visszaállítva — az alkalmazás újraindult." +// COMPANION RED-PROOF (REPORT.md): with the health failure back to a WARN (restoreNotStarted not called), +// TestR1270_AUnitRestoreWhoseAppDoesNotStartIsNotASuccess and TestR1270_TheOffsiteRestoreToo fail — the restore +// returns nil and the copy is removed. + +// r1270Provider is the D22 rig's provider whose app reaches running only when told to (the late start). +type r1270Provider struct { + *r1177Provider + up atomic.Bool +} + +func (p *r1270Provider) RefreshAndIsRunning(string) bool { return p.up.Load() } + +func r1270Rig(t *testing.T) (*Manager, *r1270Provider, *r1177Rig, *[]string) { + t.Helper() + m, p, rig, alarms := r1177Fixture(t) + np := &r1270Provider{r1177Provider: p} + m.stackProvider = np + var got []string + m.SetRestoreNotStartedNotify(func(stack, kind string, cause error) { got = append(got, stack+" "+kind) }) + _ = alarms + return m, np, rig, &got +} + +// Health fails → not ok, the household's own sentence, the undo copy STAYS, one operator alarm. +func TestR1270_AUnitRestoreWhoseAppDoesNotStartIsNotASuccess(t *testing.T) { + lateStartWatch = 0 // no watcher in this test + defer func() { lateStartWatch = 30 * time.Minute }() + m, _, rig, alarms := r1270Rig(t) + _, err := m.RestoreFromRecoveryUnit("app") + if !errors.Is(err, ErrRestoreNotStarted) { + t.Fatalf("a restore whose app did not start must not be a success, got %v", err) + } + if want := util.MsgError("err.backup.restore_not_started", "app").Error(); err.Error() != want { + t.Fatalf("the household reads the not-started sentence, got %q", err.Error()) + } + if left := undoCopies(t, rig.undoRoot); len(left) != 1 { + t.Fatalf("the restore's copy must be KEPT (not released) while the app has not started, found %v", left) + } + if len(*alarms) != 1 || !strings.Contains((*alarms)[0], "unit restore") { + t.Fatalf("the operator gets exactly one alarm, got %v", *alarms) + } + if len(rig.poured) != 0 { + t.Fatalf("a health timeout must NOT pour the old data back (a slow first start is common): %v", rig.poured) + } +} + +// Health passes → as before: success, the copy released. +func TestR1270_AHealthyRestoreIsASuccessAsBefore(t *testing.T) { + m, p, rig, alarms := r1270Rig(t) + p.up.Store(true) + 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 { + t.Fatalf("the copy is released after a healthy restore, found %v", left) + } + if len(*alarms) != 0 { + t.Fatalf("no alarm for a healthy restore: %v", *alarms) + } +} + +// A late start turns the record into a success and releases the kept copy (the normal rule). +func TestR1270_ALateStartTurnsTheRecordIntoASuccess(t *testing.T) { + lateStartWatch, lateStartPoll = 2*time.Second, 5*time.Millisecond + defer func() { lateStartWatch, lateStartPoll = 30*time.Minute, 30*time.Second }() + m, p, rig, _ := r1270Rig(t) + m.BeginRestoreOp("restore", "app") + _, err := m.RestoreFromRecoveryUnit("app") + if !errors.Is(err, ErrRestoreNotStarted) { + t.Fatalf("precondition: not started, got %v", err) + } + m.EndRestoreOpNotStarted(err.Error()) + if st := m.RestoreStatus(); st.Last == nil || st.Last.OK || !st.Last.NotStarted { + t.Fatalf("the record must say not ok / not started: %+v", st.Last) + } + p.up.Store(true) + deadline := time.Now().Add(2 * time.Second) + for time.Now().Before(deadline) { + if st := m.RestoreStatus(); st.Last != nil && st.Last.OK { + break + } + time.Sleep(5 * time.Millisecond) + } + st := m.RestoreStatus() + if st.Last == nil || !st.Last.OK || st.Last.NotStarted { + t.Fatalf("a late start must turn the record into a success: %+v", st.Last) + } + for i := 0; i < 100 && len(undoCopies(t, rig.undoRoot)) != 0; i++ { + time.Sleep(5 * time.Millisecond) + } + if left := undoCopies(t, rig.undoRoot); len(left) != 0 { + t.Fatalf("the kept copy is released once the app runs, found %v", left) + } +} + +// The off-site restore: the same verdict, its undo copy kept. +func TestR1270_TheOffsiteRestoreToo(t *testing.T) { + lateStartWatch = 0 + defer func() { lateStartWatch = 30 * time.Minute }() + m, prov, _ := reconFixture(t, "20260719T060000Z", "2026-07-19T06:00:00Z", pgDump(1)) + m.stackProvider = ¬RunningRecordingProvider{prov} + _, err := m.ReconstituteFromOffsite(context.Background(), "immich", false) + if !errors.Is(err, ErrRestoreNotStarted) { + t.Fatalf("an off-site restore whose app did not start must not be a success, got %v", err) + } +} + +type notRunningRecordingProvider struct{ *recordingProvider } + +func (p *notRunningRecordingProvider) RefreshAndIsRunning(string) bool { return false } + +// The record a late start may change is only that app's not-started record, and never while a restore runs. +func TestR1270_MarkLateStartTouchesOnlyItsOwnRecord(t *testing.T) { + m := &Manager{} + m.BeginRestoreOp("restore", "a") + m.EndRestoreOp(false, "a failed") + m.markLateStart("a", "started") + if st := m.RestoreStatus(); st.Last.OK { + t.Fatal("a plain failure must not become a success") + } + m.BeginRestoreOp("restore", "a") + m.EndRestoreOpNotStarted("not yet") + m.markLateStart("b", "started") + if st := m.RestoreStatus(); st.Last.OK { + t.Fatal("another app's start must not change this record") + } + m.BeginRestoreOp("restore", "a") + m.markLateStart("a", "started") + if st := m.RestoreStatus(); !st.Running { + t.Fatal("a running restore must stay running") + } + _ = os.Getpid +} diff --git a/controller/internal/backup/tier2_restore.go b/controller/internal/backup/tier2_restore.go index e0324554..9339d6e0 100644 --- a/controller/internal/backup/tier2_restore.go +++ b/controller/internal/backup/tier2_restore.go @@ -2,6 +2,7 @@ package backup import ( "context" + "errors" "fmt" "gitea.dooplex.hu/admin/felhom-controller/internal/util" "os" @@ -241,7 +242,7 @@ func (m *Manager) RestoreTier2Unit(stackName string) (UnitRestoreResult, error) // It is best-effort by design and says so in the log either way, because an absent log line is not // evidence that it ran. func (m *Manager) rehydratePrimaryUnit(stackName, mirrorUnitDir string, restoreErr error) { - if restoreErr != nil { + if restoreErr != nil && !errors.Is(restoreErr, ErrRestoreNotStarted) { // R-1270: the data DID land then m.logger.Printf("[INFO] [backup] %s: primary unit NOT refilled — the restore itself failed (R-403: a package from a failed run is worse than none)", stackName) return } @@ -440,9 +441,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) } - if healthErr := m.waitForHealthy(stackName, healthTimeout); healthErr != nil { - m.logger.Printf("[WARN] [backup] %s Tier-2 file restore done but health check failed: %v", stackName, healthErr) - } + healthErr := m.waitForHealthy(stackName, healthTimeout) if copyErr != nil { return filesRestored, util.MsgError("err.backup.fajlmasolas_sikertelen", copyErr) @@ -450,6 +449,9 @@ func (m *Manager) RestoreTier2Files(stackName string) (filesRestored int, err er if startErr != nil { return filesRestored, util.MsgError("err.backup.fajl_visszaallitva_de_az_alkalmazas_ujrainditasa", filesRestored, startErr) } + if healthErr != nil { // R-1270: the files are back, the app is not — never a success + return filesRestored, m.restoreNotStarted(stackName, "second-drive file restore", healthErr, nil) + } // Privacy: count + duration only — customer file names never at INFO. m.logger.Printf("[INFO] [backup] Tier-2 file restore completed for %s: %d file(s) restored (%s)", stackName, filesRestored, time.Since(start).Round(time.Second)) diff --git a/controller/internal/i18n/locales/en.json b/controller/internal/i18n/locales/en.json index 60360fc5..0461e86d 100644 --- a/controller/internal/i18n/locales/en.json +++ b/controller/internal/i18n/locales/en.json @@ -2860,5 +2860,7 @@ "kept.reason.earlier_install": "the backup of an earlier install (made before a reinstall)", "backups_restore.megorzott_visszaallitas_megerosites": "This loads the backup of the earlier install into the app. It replaces the data the app has now. Continue?", "flash.kept.restore_needs_confirmation": "Confirm the question to restore it.", - "note.tier2.unit_other_install_kept": "The second drive holds the data package of an earlier install, and we could not set it aside now, so we did not overwrite it. The data package of the copy is therefore older than this backup." + "note.tier2.unit_other_install_kept": "The second drive holds the data package of an earlier install, and we could not set it aside now, so we did not overwrite it. The data package of the copy is therefore older than this backup.", + "err.backup.restore_not_started": "%s: we loaded the data back, but the app has not started yet. Wait a few minutes, then open it again. If it stays like this, tell us.", + "note.restore.late_started": "%s has started: the restore is done." } diff --git a/controller/internal/i18n/locales/hu.json b/controller/internal/i18n/locales/hu.json index 8aec4f21..de99b314 100644 --- a/controller/internal/i18n/locales/hu.json +++ b/controller/internal/i18n/locales/hu.json @@ -2848,5 +2848,7 @@ "kept.reason.earlier_install": "egy korábbi telepítés mentése (újratelepítés előtt készült)", "backups_restore.megorzott_visszaallitas_megerosites": "Ezzel a korábbi telepítés mentését töltjük vissza az alkalmazásba. A mostani adatai helyére ez kerül. Folytatod?", "flash.kept.restore_needs_confirmation": "A visszaállításhoz erősítsd meg a kérdést.", - "note.tier2.unit_other_install_kept": "A második meghajtón egy korábbi telepítés adatcsomagja van, és most nem tudtuk félretenni, ezért nem írtuk felül. A másolat adatcsomagja ezért régebbi, mint ez a mentés." + "note.tier2.unit_other_install_kept": "A második meghajtón egy korábbi telepítés adatcsomagja van, és most nem tudtuk félretenni, ezért nem írtuk felül. A másolat adatcsomagja ezért régebbi, mint ez a mentés.", + "err.backup.restore_not_started": "A(z) %s: az adatokat visszatöltöttük, de az alkalmazás még nem indult el. Várj pár percet, majd nyisd meg újra. Ha így marad, szólj nekünk.", + "note.restore.late_started": "A(z) %s elindult: a visszaállítás kész." } diff --git a/controller/internal/web/handlers.go b/controller/internal/web/handlers.go index 497db476..156f5b8e 100644 --- a/controller/internal/web/handlers.go +++ b/controller/internal/web/handlers.go @@ -1900,7 +1900,7 @@ func (s *Server) backupRestoreHandler(w http.ResponseWriter, r *http.Request) { res, err := s.backupMgr.RestoreFromRecoveryUnit(stackName) if err != nil { s.logger.Printf("[ERROR] [web] Restore failed (async): stack=%s: %v", stackName, err) - s.backupMgr.EndRestoreOp(false, s.note("note.restore.unit_failed", s.noteErr(err))) + s.endRestoreFailed("note.restore.unit_failed", err, "") return } s.logger.Printf("[INFO] [web] Restore completed (async): stack=%s in %s (volumes %d/%d, dbs %d/%d)", @@ -1916,11 +1916,25 @@ func (s *Server) backupRestoreHandler(w http.ResponseWriter, r *http.Request) { } // restoreFailedNote is the household's sentence for a restore that returned an error: key's „…sikertelen: %s" -// around the error's own sentence. +// around the error's own sentence — except a restore whose data is back but whose app did not start (R-1270), which is +// neither a success nor a failure and reads its own sentence alone. func (s *Server) restoreFailedNote(key string, err error) string { + if errors.Is(err, backup.ErrRestoreNotStarted) { + return s.noteErr(err) + } return s.note(key, s.noteErr(err)) } +// endRestoreFailed records a restore that returned an error: a not-started one (R-1270) as such — never ok, and a late +// start can still turn it into a success — everything else as a failure. +func (s *Server) endRestoreFailed(key string, err error, suffix string) { + if errors.Is(err, backup.ErrRestoreNotStarted) { + s.backupMgr.EndRestoreOpNotStarted(s.noteErr(err) + suffix) + return + } + s.backupMgr.EndRestoreOp(false, s.note(key, s.noteErr(err))+suffix) +} + // unitRestoreOutcomeMsg builds the OUTCOME sentence for a completed LOCAL recovery-unit restore. Pure, // so the wording is unit-testable — this string is the customer's only evidence that the operation did // what its label promised. @@ -2232,7 +2246,7 @@ func (s *Server) backupTier2RestoreHandler(w http.ResponseWriter, r *http.Reques return } s.logger.Printf("[ERROR] [web] Tier-2 file restore failed (async): stack=%s: %v", stackName, err) - s.backupMgr.EndRestoreOp(false, s.note("note.restore.file_failed", s.noteErr(err))) + s.endRestoreFailed("note.restore.file_failed", err, "") return } // C9-F1 (the quiet half): even where the restore DOES cover something it covers only the @@ -2302,7 +2316,7 @@ func (s *Server) backupTier2UnitRestoreHandler(w http.ResponseWriter, r *http.Re files := s.note("note.restore.whole_files", res.Files.Restored, res.Files.Replaced, res.Files.KeptNewer, res.Files.Unchanged) if err != nil { s.logger.Printf("[ERROR] [web] Tier-2 whole restore failed (async): stack=%s: %v", stackName, err) - s.backupMgr.EndRestoreOp(false, s.note("note.restore.full_unit_failed", s.noteErr(err))+" "+files) + s.endRestoreFailed("note.restore.full_unit_failed", err, " "+files) return } s.logger.Printf("[INFO] [web] Tier-2 whole restore completed (async): stack=%s in %s (files restored %d, replaced %d, kept-newer %d, unchanged %d; volumes %d/%d, dbs %d/%d)", @@ -2336,7 +2350,7 @@ func (s *Server) backupTier2UnitRestoreHandler(w http.ResponseWriter, r *http.Re res, err := s.backupMgr.RestoreTier2Unit(stackName) if err != nil { s.logger.Printf("[ERROR] [web] Tier-2 unit restore failed (async): stack=%s: %v", stackName, err) - s.backupMgr.EndRestoreOp(false, s.note("note.restore.full_unit_failed", s.noteErr(err))) + s.endRestoreFailed("note.restore.full_unit_failed", err, "") return } s.logger.Printf("[INFO] [web] Tier-2 unit restore completed (async): stack=%s in %s (volumes %d/%d, dbs %d/%d)", diff --git a/controller/internal/web/kept_copies.go b/controller/internal/web/kept_copies.go index fea5904d..0e2ade28 100644 --- a/controller/internal/web/kept_copies.go +++ b/controller/internal/web/kept_copies.go @@ -111,7 +111,7 @@ func (s *Server) keptUnitRestoreHandler(w http.ResponseWriter, r *http.Request) app, res, err := s.backupMgr.RestoreSetAsideUnit(id) if err != nil { s.logger.Printf("[ERROR] [web] Restore from the set-aside unit failed (async): stack=%s: %v", app, err) - s.backupMgr.EndRestoreOp(false, s.restoreFailedNote("note.restore.unit_failed", err)) + s.endRestoreFailed("note.restore.unit_failed", err, "") return } s.backupMgr.EndRestoreOp(true, s.restoredVersionPrefix(app, res.VersionChanged, res.DataPins, res.DataAt)+s.unitRestoreOutcomeMsg(app, res)) diff --git a/controller/internal/web/offbox_handlers.go b/controller/internal/web/offbox_handlers.go index b049d219..ab4bd4bf 100644 --- a/controller/internal/web/offbox_handlers.go +++ b/controller/internal/web/offbox_handlers.go @@ -545,7 +545,7 @@ func (s *Server) offboxReconstituteHandler(w http.ResponseWriter, r *http.Reques res, err := s.backupMgr.ReconstituteFromOffsite(ctx, app, ackPlacement) if err != nil { s.logger.Printf("[ERROR] [web] off-box reconstitute %s (async): %v", app, err) - s.backupMgr.EndRestoreOp(false, s.note("note.restore.full_failed", s.noteErr(err))) + s.endRestoreFailed("note.restore.full_failed", err, "") return } s.logger.Printf("[INFO] [web] off-box reconstitute %s completed (async): files=%d dbs=%d snapshot=%s", diff --git a/controller/internal/web/r1270_not_started_test.go b/controller/internal/web/r1270_not_started_test.go new file mode 100644 index 00000000..ffc595d3 --- /dev/null +++ b/controller/internal/web/r1270_not_started_test.go @@ -0,0 +1,40 @@ +package web + +import ( + "errors" + "io" + "log" + "strings" + "testing" + + "gitea.dooplex.hu/admin/felhom-controller/internal/backup" + "gitea.dooplex.hu/admin/felhom-controller/internal/config" + "gitea.dooplex.hu/admin/felhom-controller/internal/util" +) + +// R-1270 — a restore whose data is back but whose app did not start is recorded as NOT ok, with its own sentence +// alone (never „Visszaállítás sikertelen: …", never „…az alkalmazás újraindult."); any other error stays a failure. +// COMPANION RED-PROOF (REPORT.md): drop the errors.Is branch in endRestoreFailed → this fails on the „sikertelen" prefix +// and on NotStarted. +func TestR1270_TheRecordOfANotStartedRestore(t *testing.T) { + lg := log.New(io.Discard, "", 0) + cfg := &config.Config{} + cfg.Paths.DataDir = t.TempDir() + s := &Server{cfg: cfg, backupMgr: backup.NewManager(cfg, nil, lg), logger: lg} + + s.backupMgr.BeginRestoreOp("restore", "tandoor") + s.endRestoreFailed("note.restore.unit_failed", util.MsgErrorf(backup.ErrRestoreNotStarted, "err.backup.restore_not_started", "tandoor"), "") + st := s.backupMgr.RestoreStatus() + if st.Last == nil || st.Last.OK || !st.Last.NotStarted { + t.Fatalf("a not-started restore is recorded not ok and not started: %+v", st.Last) + } + if strings.Contains(st.Last.Message, "sikertelen") || strings.Contains(st.Last.Message, "újraindult") || !strings.Contains(st.Last.Message, "még nem indult el") { + t.Fatalf("the household reads the not-started sentence alone: %q", st.Last.Message) + } + + s.backupMgr.BeginRestoreOp("restore", "tandoor") + s.endRestoreFailed("note.restore.unit_failed", errors.New("boom"), "") + if st := s.backupMgr.RestoreStatus(); st.Last.OK || st.Last.NotStarted || !strings.Contains(st.Last.Message, "sikertelen") { + t.Fatalf("any other error stays a failure: %+v", st.Last) + } +} diff --git a/controller/scripts/i18n_go_keys.json b/controller/scripts/i18n_go_keys.json index 7953381e..9d43645d 100644 --- a/controller/scripts/i18n_go_keys.json +++ b/controller/scripts/i18n_go_keys.json @@ -322,7 +322,9 @@ "note.offsite.retry_next_night": "BORN AS A KEY (W25, rehearsal word table, 2026-10-21) -- the household's sentence after a failed off-site run, built from the failure classifier (07 §6.7) and the run's result; the raw error stays in the log and the operator's event. A NEW sentence, never a Go literal. Pinned by TestW25_FailedOffsiteRunSpeaksToTheHousehold.", "note.offsite.shares_name": "BORN AS A KEY (W25, rehearsal word table, 2026-10-21) -- the household's sentence after a failed off-site run, built from the failure classifier (07 §6.7) and the run's result; the raw error stays in the log and the operator's event. A NEW sentence, never a Go literal. Pinned by TestW25_FailedOffsiteRunSpeaksToTheHousehold.", "flash.kept.restore_needs_confirmation": "BORN AS A KEY (D47, operator ruling 2026-10-25; R-1269) -- the unit of an earlier install is set aside whole and restorable from the restore page; its confirm flash and the second-drive note when it cannot be set aside. Pinned by internal/web/kept_copies_test.go TestD47_* and internal/backup/unit_owner_test.go.", - "note.tier2.unit_other_install_kept": "BORN AS A KEY (D47, operator ruling 2026-10-25; R-1269) -- the unit of an earlier install is set aside whole and restorable from the restore page; its confirm flash and the second-drive note when it cannot be set aside. Pinned by internal/web/kept_copies_test.go TestD47_* and internal/backup/unit_owner_test.go." + "note.tier2.unit_other_install_kept": "BORN AS A KEY (D47, operator ruling 2026-10-25; R-1269) -- the unit of an earlier install is set aside whole and restorable from the restore page; its confirm flash and the second-drive note when it cannot be set aside. Pinned by internal/web/kept_copies_test.go TestD47_* and internal/backup/unit_owner_test.go.", + "err.backup.restore_not_started": "BORN AS A KEY (R-1270, brief 2026-10-25 Part 3) -- a restore whose data is back but whose app did not start in time is never a success; its sentence, and the late start that turns it into one. Pinned by internal/backup/restore_verdict_test.go TestR1270_*.", + "note.restore.late_started": "BORN AS A KEY (R-1270, brief 2026-10-25 Part 3) -- a restore whose data is back but whose app did not start in time is never a success; its sentence, and the late start that turns it into one. Pinned by internal/backup/restore_verdict_test.go TestR1270_*." }, "flash.share.already_on": "A megosztás már be van kapcsolva.", "flash.share.enable_failed": "A megosztás bekapcsolása nem sikerült.",