R-1270 (P2): a restore whose app does not reach running in time is never a success — every restore path returns ErrRestoreNotStarted, the household reads that the data is back but the app has not started yet, one operator alarm; the data stays, the undo copy is kept, a late start turns the record into a success and releases the copy. Red-proved. Commit only.
gates / gates (push) Successful in 1m32s

This commit is contained in:
2026-10-25 09:33:26 +01:00
parent 02daebe9c5
commit b680db85cb
18 changed files with 405 additions and 23 deletions
+2
View File
@@ -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
+19
View File
@@ -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)
}
}
@@ -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
+25
View File
@@ -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()
}
+5 -4
View File
@@ -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
}
+6 -4
View File
@@ -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
}
@@ -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))
}
@@ -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 = &notRunningRecordingProvider{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
}
+6 -4
View File
@@ -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))