R-1251: sync the restore copy's folders before the marker names it (a cut left undo.json as .tmp on Tester 1); the interrupted-restore record says the put-back waits, not 'run it again'. Commit only.
gates / gates (push) Successful in 1m24s
gates / gates (push) Successful in 1m24s
This commit is contained in:
@@ -42,6 +42,16 @@ brief 2026-10-24, Part 4 (commit only; the release rides the next normal train).
|
||||
holds the same way.
|
||||
- **Stop pressed during a restore no longer skips the put-back after a cut (H7):** the data is put back; the app stays
|
||||
stopped as the household asked.
|
||||
- **The copy is on disk before the marker names it** (found by the live proof on Tester 1, 2026-10-24: a power cut
|
||||
2.1 s after „the restore copy is recorded" left the 1.5 GB tar whole but the journal as `undo.json.tmp` — the rename
|
||||
lived only in the page cache, the marker on the other filesystem was durable, and the start could not read the
|
||||
copy; the new H2 hold kept the app stopped). `persistUndoForCrash` now syncs the copy's folders up to `backups/`
|
||||
(`syncUndoDirs`) before `SetUndo`, and `atomicWriteFile` syncs the folder after its rename. Pinned by
|
||||
`TestR1251_TheCopyIsOnDiskBeforeTheMarkerNamesIt` (seen failing with the sync removed).
|
||||
- **The household is no longer told to run the restore again while its put-back waits** — that would restore the backup
|
||||
over the data the box is about to put back. The restore record (`PutBackWaiting`,
|
||||
`note.restore.interrupted_put_back_waiting`) and the `restore_interrupted` event say the box puts the data back when
|
||||
the drive is there. Pinned by `TestR1251_TheRecordSaysThePutBackWaits` (seen failing).
|
||||
- A removal clears a waiting put-back (it belongs to the install); a later restore that completes drops it (the
|
||||
household chose that data; the copy stays on disk).
|
||||
- Tests (each seen failing with its rule taken out): `TestR1251_DriveCutRestoreWaitsForTheDriveThenPutsBackBeforeAnyStart`
|
||||
|
||||
@@ -602,11 +602,11 @@ func main() {
|
||||
logger.Printf("[ERROR] [backup] leftover second-drive copy check: %v", err)
|
||||
}
|
||||
// R-550: load the persisted restore record BEFORE any page can ask for it.
|
||||
var putBack []string
|
||||
var putBack, waiting []string
|
||||
if appStopRecovery != nil {
|
||||
putBack = appStopRecovery.PutBack
|
||||
putBack, waiting = appStopRecovery.PutBack, appStopRecovery.Waiting
|
||||
}
|
||||
interruptedRestore = loadRestoreRecordAtStartup(backupMgr, cfg.Paths.DataDir, logger, putBack)
|
||||
interruptedRestore = loadRestoreRecordAtStartup(backupMgr, cfg.Paths.DataDir, logger, putBack, waiting)
|
||||
// R-519: an app-data run the stop cut off is said on the backup pages until the next complete run.
|
||||
loadRunRecordAtStartup(backupMgr, cfg.Paths.DataDir, logger)
|
||||
// R-166: use the guard that already ran Recover at startup, not a second one over the same
|
||||
|
||||
@@ -24,14 +24,15 @@ type restoreEventPusher interface {
|
||||
}
|
||||
|
||||
// loadRestoreRecordAtStartup wires persistence and returns the restore the last stop interrupted.
|
||||
// putBack names the apps the crash recovery put back (AppStopRecovery.PutBack, D22 / R-1195).
|
||||
func loadRestoreRecordAtStartup(mgr *backup.Manager, dataDir string, logger *log.Logger, putBack []string) *backup.RestoreOpResult {
|
||||
// putBack names the apps the crash recovery put back (AppStopRecovery.PutBack, D22 / R-1195); waiting those whose
|
||||
// put-back waits for their drive (AppStopRecovery.Waiting, R-1251).
|
||||
func loadRestoreRecordAtStartup(mgr *backup.Manager, dataDir string, logger *log.Logger, putBack, waiting []string) *backup.RestoreOpResult {
|
||||
if mgr == nil {
|
||||
return nil
|
||||
}
|
||||
path := filepath.Join(dataDir, restoreRecordFileName)
|
||||
mgr.SetRestoreRecordPath(path)
|
||||
res := mgr.LoadRestoreRecordAfterRecovery(putBack)
|
||||
res := mgr.LoadRestoreRecordAfterRecovery(putBack, waiting)
|
||||
if logger != nil {
|
||||
logger.Printf("[INFO] [backup] restore record wired: %s (interrupted at startup: %t)", path, res != nil)
|
||||
}
|
||||
@@ -43,10 +44,11 @@ func reportInterruptedRestore(p restoreEventPusher, res *backup.RestoreOpResult)
|
||||
if p == nil || res == nil {
|
||||
return
|
||||
}
|
||||
if res.PutBack {
|
||||
if res.PutBack || res.PutBackWaiting {
|
||||
// D22 / R-1195: the data is back as before the restore — the record's own sentence, in the box's language.
|
||||
// R-1251: or it is put back when the drive is there; „start it again" would restore the backup over it.
|
||||
p.PushEvent("restore_interrupted", "warning", res.Stack+": "+res.Message,
|
||||
map[string]any{"stack": res.Stack, "op": res.Op, "put_back": true})
|
||||
map[string]any{"stack": res.Stack, "op": res.Op, "put_back": res.PutBack, "put_back_waiting": res.PutBackWaiting})
|
||||
return
|
||||
}
|
||||
p.PushEvent("restore_interrupted", "warning",
|
||||
|
||||
@@ -33,13 +33,13 @@ func TestRestoreRecordAtStartup_RaisesInterruptedOnce(t *testing.T) {
|
||||
before.BeginRestoreOp("restore", "gokapi") // the box stops here
|
||||
|
||||
rec := &pushRecorder{}
|
||||
reportInterruptedRestore(rec, loadRestoreRecordAtStartup(new(backup.Manager), dir, lg, nil))
|
||||
reportInterruptedRestore(rec, loadRestoreRecordAtStartup(new(backup.Manager), dir, lg, nil, nil))
|
||||
if len(rec.got) != 1 || rec.got[0].eventType != "restore_interrupted" || rec.got[0].severity != "warning" {
|
||||
t.Fatalf("an interrupted restore raised no restore_interrupted (warning): %+v", rec.got)
|
||||
}
|
||||
|
||||
again := &pushRecorder{}
|
||||
reportInterruptedRestore(again, loadRestoreRecordAtStartup(new(backup.Manager), dir, lg, nil))
|
||||
reportInterruptedRestore(again, loadRestoreRecordAtStartup(new(backup.Manager), dir, lg, nil, nil))
|
||||
if len(again.got) != 0 {
|
||||
t.Fatalf("the same interruption was raised again on the next start: %+v", again.got)
|
||||
}
|
||||
|
||||
@@ -22,6 +22,9 @@ type RestoreOpResult struct {
|
||||
// PutBack marks an interrupted restore that the start-up put the data back for (D22, R-1195): the message then
|
||||
// says the app's data is as it was before the restore, not „start it again".
|
||||
PutBack bool `json:"put_back,omitempty"`
|
||||
// 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"`
|
||||
}
|
||||
|
||||
// RestoreResultWindow bounds how long a finished restore still counts as "what just happened".
|
||||
|
||||
@@ -318,3 +318,44 @@ func TestR1251_ACompletedRestoreDropsTheWaitingPutBack(t *testing.T) {
|
||||
t.Fatal("a completed restore must drop the waiting put-back hold")
|
||||
}
|
||||
}
|
||||
|
||||
// MEASURED on Tester 1 (2026-10-24, audits/restore-holes-2026-10-24/P1-tester1/): a power cut 2.1 s after the copy was
|
||||
// recorded left its journal as undo.json.tmp — the marker named a copy the start could not read. The copy's folders
|
||||
// must be synced BEFORE the marker names it. RED-PROOF: with the syncUndoDirs call removed from persistUndoForCrash this
|
||||
// fails on „no folder was synced before the marker named the copy".
|
||||
func TestR1251_TheCopyIsOnDiskBeforeTheMarkerNamesIt(t *testing.T) {
|
||||
root := t.TempDir()
|
||||
marker := filepath.Join(root, "appstop-state.json")
|
||||
copyDir := filepath.Join(root, "drive", "backups", "restore-undo", "app", "20261024T171928Z")
|
||||
if err := os.MkdirAll(copyDir, 0o700); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
g := NewAppStopGuard(marker, log.New(io.Discard, "", 0))
|
||||
if err := g.Begin("unit-restore:app", ReasonUnitRestore, []string{"app"}); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
m := &Manager{logger: log.New(io.Discard, "", 0), appStop: g}
|
||||
var synced []string
|
||||
markerNamedCopyAtSync := false
|
||||
orig := syncUndoDirs
|
||||
t.Cleanup(func() { syncUndoDirs = orig })
|
||||
syncUndoDirs = func(dir string) error {
|
||||
b, _ := os.ReadFile(marker)
|
||||
markerNamedCopyAtSync = strings.Contains(string(b), dir)
|
||||
synced = append(synced, dir)
|
||||
return orig(dir)
|
||||
}
|
||||
m.persistUndoForCrash("app", &liveVolumeCopy{dir: copyDir, copied: []string{"app_data"}})
|
||||
if len(synced) != 1 || synced[0] != copyDir {
|
||||
t.Fatalf("no folder was synced before the marker named the copy: %v", synced)
|
||||
}
|
||||
if markerNamedCopyAtSync {
|
||||
t.Fatal("the marker already named the copy when its folders were synced — the order is the fix")
|
||||
}
|
||||
if b, _ := os.ReadFile(marker); !strings.Contains(string(b), copyDir) {
|
||||
t.Fatal("the copy must still be recorded in the marker")
|
||||
}
|
||||
if _, err := os.Stat(filepath.Join(copyDir, "undo.json")); err != nil {
|
||||
t.Fatal("the journal must be in place")
|
||||
}
|
||||
}
|
||||
|
||||
@@ -73,6 +73,15 @@ func (m *Manager) persistUndoForCrash(stack string, c *liveVolumeCopy) {
|
||||
m.logger.Printf("[WARN] [backup] %s: the restore copy's journal could not be written: %v — a power cut would restart the app without putting it back", stack, err)
|
||||
return
|
||||
}
|
||||
// MEASURED 2026-10-24 on Tester 1 (audits/restore-holes-2026-10-24/P1-tester1/): a power cut 2.1 s after this
|
||||
// record left the copy's tar whole but its journal as undo.json.tmp — the rename lived only in the page cache, and
|
||||
// the marker (another filesystem, already synced) named a copy no start could read. The copy's folders are new
|
||||
// (copyLiveVolumes made them), so their own entries are not durable either. Every folder from the copy up to
|
||||
// backups/ is synced BEFORE the marker names the copy; a sync that fails is logged and the copy is still recorded
|
||||
// (an unreadable copy at start holds the app for support, R-1251 H2 — never a start on unknown data).
|
||||
if err := syncUndoDirs(c.dir); err != nil {
|
||||
m.logger.Printf("[WARN] [backup] %s: the restore copy's folders could not be synced to disk: %v — a power cut in the next seconds may leave a copy the start cannot read (the app is then held)", stack, err)
|
||||
}
|
||||
if err := m.appStop.SetUndo(stack, c.dir); err != nil {
|
||||
m.logger.Printf("[WARN] [backup] %s: the restore copy could not be recorded for a power cut: %v", stack, err)
|
||||
return
|
||||
@@ -100,7 +109,38 @@ func copyDefinitionFiles(stackDir, dst string) error {
|
||||
return nil
|
||||
}
|
||||
|
||||
// atomicWriteFile writes data to path through a synced temp file and a rename (0600).
|
||||
// syncUndoDirs makes a restore copy's folder entries durable: its definition/ folder, the copy folder, and each parent
|
||||
// up to and including backups/ (restoreUndoDir = <ns>/backups/restore-undo/<app>/<stamp>). A seam for tests.
|
||||
var syncUndoDirs = func(copyDir string) error {
|
||||
dirs := []string{filepath.Join(copyDir, undoDefinitionIn), copyDir}
|
||||
for d, i := copyDir, 0; i < 3; i++ { // <app>, restore-undo, backups
|
||||
d = filepath.Dir(d)
|
||||
dirs = append(dirs, d)
|
||||
}
|
||||
var first error
|
||||
for _, d := range dirs {
|
||||
if err := syncDir(d); err != nil && !os.IsNotExist(err) && first == nil {
|
||||
first = err
|
||||
}
|
||||
}
|
||||
return first
|
||||
}
|
||||
|
||||
// syncDir fsyncs one directory, so the entries created or renamed in it survive a power cut.
|
||||
func syncDir(dir string) error {
|
||||
f, err := os.Open(dir)
|
||||
if err != nil {
|
||||
return err
|
||||
}
|
||||
if err := f.Sync(); err != nil {
|
||||
f.Close()
|
||||
return err
|
||||
}
|
||||
return f.Close()
|
||||
}
|
||||
|
||||
// atomicWriteFile writes data to path through a synced temp file and a rename (0600), then syncs the folder so the
|
||||
// rename itself survives a power cut (R-1251: a journal left as .tmp was measured after a cut).
|
||||
func atomicWriteFile(path string, data []byte) error {
|
||||
tmp := path + ".tmp"
|
||||
f, err := os.OpenFile(tmp, os.O_WRONLY|os.O_CREATE|os.O_TRUNC, 0o600)
|
||||
@@ -121,7 +161,10 @@ func atomicWriteFile(path string, data []byte) error {
|
||||
os.Remove(tmp)
|
||||
return err
|
||||
}
|
||||
return os.Rename(tmp, path)
|
||||
if err := os.Rename(tmp, path); err != nil {
|
||||
return err
|
||||
}
|
||||
return syncDir(filepath.Dir(path))
|
||||
}
|
||||
|
||||
// CrashPutBack is the InterruptedRestorePutBacker the controller wires at start, before the backup manager exists.
|
||||
|
||||
@@ -33,6 +33,9 @@ const RestoreInterruptedKey = "note.restore.interrupted"
|
||||
// (D22, R-1195): the data is as it was before the restore.
|
||||
const RestoreInterruptedPutBackKey = "note.restore.interrupted_put_back"
|
||||
|
||||
// RestoreInterruptedWaitingKey (R-1251): the interrupted restore's put-back waits for the app's drive.
|
||||
const RestoreInterruptedWaitingKey = "note.restore.interrupted_put_back_waiting"
|
||||
|
||||
// restoreRecordFile is the on-disk shape.
|
||||
type restoreRecordFile struct {
|
||||
Running bool `json:"running"`
|
||||
@@ -53,12 +56,12 @@ func (m *Manager) SetRestoreRecordPath(path string) {
|
||||
// LoadRestoreRecord restores the record at startup. It returns the restore that was interrupted by the
|
||||
// stop — non-nil exactly once per interruption — so the caller can log it and raise restore_interrupted.
|
||||
func (m *Manager) LoadRestoreRecord() *RestoreOpResult {
|
||||
return m.LoadRestoreRecordAfterRecovery(nil)
|
||||
return m.LoadRestoreRecordAfterRecovery(nil, nil)
|
||||
}
|
||||
|
||||
// LoadRestoreRecordAfterRecovery is LoadRestoreRecord told which apps the start-up crash recovery put back
|
||||
// (AppStopRecovery.PutBack, D22 / R-1195): for those the interrupted restore reads „the data is as before".
|
||||
func (m *Manager) LoadRestoreRecordAfterRecovery(putBack []string) *RestoreOpResult {
|
||||
func (m *Manager) LoadRestoreRecordAfterRecovery(putBack, waiting []string) *RestoreOpResult {
|
||||
m.mu.Lock()
|
||||
defer m.mu.Unlock()
|
||||
if m.opRecordPath == "" {
|
||||
@@ -95,6 +98,11 @@ func (m *Manager) LoadRestoreRecordAfterRecovery(putBack []string) *RestoreOpRes
|
||||
res.Message, res.PutBack = m.note(RestoreInterruptedPutBackKey), true
|
||||
}
|
||||
}
|
||||
for _, w := range waiting {
|
||||
if w == rec.Stack {
|
||||
res.Message, res.PutBackWaiting = m.note(RestoreInterruptedWaitingKey), true
|
||||
}
|
||||
}
|
||||
m.opLast = &res
|
||||
if m.opInterrupted == nil {
|
||||
m.opInterrupted = map[string]RestoreOpResult{}
|
||||
|
||||
@@ -102,7 +102,7 @@ func TestRestoreRecord_NextRestoreOfThatAppClearsTheNotice(t *testing.T) {
|
||||
func TestR1195_TheRecordSaysTheDataIsAsBefore(t *testing.T) {
|
||||
path := filepath.Join(t.TempDir(), "restore-status.json")
|
||||
recordManager(path).BeginRestoreOp("offbox-restore", "bookstack")
|
||||
got := recordManager(path).LoadRestoreRecordAfterRecovery([]string{"bookstack"})
|
||||
got := recordManager(path).LoadRestoreRecordAfterRecovery([]string{"bookstack"}, nil)
|
||||
if got == nil || !got.PutBack || !got.Interrupted {
|
||||
t.Fatalf("want an interrupted, put-back record, got %+v", got)
|
||||
}
|
||||
@@ -112,8 +112,23 @@ func TestR1195_TheRecordSaysTheDataIsAsBefore(t *testing.T) {
|
||||
|
||||
path2 := filepath.Join(t.TempDir(), "restore-status.json")
|
||||
recordManager(path2).BeginRestoreOp("restore", "gokapi")
|
||||
other := recordManager(path2).LoadRestoreRecordAfterRecovery([]string{"bookstack"})
|
||||
other := recordManager(path2).LoadRestoreRecordAfterRecovery([]string{"bookstack"}, nil)
|
||||
if other == nil || other.PutBack || !strings.Contains(other.Message, "megszakadt") {
|
||||
t.Fatalf("an app that was not put back keeps the old sentence, got %+v", other)
|
||||
}
|
||||
}
|
||||
|
||||
// R-1251: a restore whose put-back waits for the app's drive must not tell the household to run it again (that restores
|
||||
// the backup over the data the box is about to put back). MEASURED 2026-10-24 on Tester 1: the event said „indítsd el
|
||||
// újra". RED-PROOF: with the waiting loop removed from LoadRestoreRecordAfterRecovery this fails on the old sentence.
|
||||
func TestR1251_TheRecordSaysThePutBackWaits(t *testing.T) {
|
||||
path := filepath.Join(t.TempDir(), "restore-status.json")
|
||||
recordManager(path).BeginRestoreOp("restore", "metube")
|
||||
got := recordManager(path).LoadRestoreRecordAfterRecovery(nil, []string{"metube"})
|
||||
if got == nil || !got.PutBackWaiting || got.PutBack || !got.Interrupted {
|
||||
t.Fatalf("want an interrupted, put-back-waiting record, got %+v", got)
|
||||
}
|
||||
if !strings.Contains(got.Message, "meghajt") || strings.Contains(got.Message, "indítsd el újra") {
|
||||
t.Fatalf("message %q must say the box puts the data back when the drive is there", got.Message)
|
||||
}
|
||||
}
|
||||
|
||||
@@ -1872,6 +1872,7 @@
|
||||
"note.restore.full_failed": "The full restore failed: %s",
|
||||
"note.restore.full_unit_failed": "Full restore failed: %s",
|
||||
"note.restore.interrupted": "The restore was interrupted (the box restarted) — start it again.",
|
||||
"note.restore.interrupted_put_back_waiting": "The restore was interrupted (a power cut). The app does not start until its drive is back: then the box puts its data from before the restore back and starts it. Do not run the restore again, because that puts the backup in place of your data.",
|
||||
"note.restore.interrupted_put_back": "The restore was interrupted (a power cut). The data of the app is as it was before the restore.",
|
||||
"note.restore.no_db_at_all": " This app has no database.",
|
||||
"note.restore.no_db_in_backup": " WARNING: this app HAS a database, but the backup held no database dump, so the database did NOT come back. The state from before the restore is backed up: %s",
|
||||
|
||||
@@ -1860,6 +1860,7 @@
|
||||
"note.restore.full_failed": "A teljes visszaállítás sikertelen: %s",
|
||||
"note.restore.full_unit_failed": "Teljes visszaállítás sikertelen: %s",
|
||||
"note.restore.interrupted": "A visszaállítás megszakadt (a doboz újraindult) — indítsd el újra.",
|
||||
"note.restore.interrupted_put_back_waiting": "A visszaállítás félbeszakadt (áramszünet). Az alkalmazás nem indul el, amíg a meghajtója vissza nem tér: akkor a doboz visszateszi a visszaállítás előtti adatait, és elindítja. Ne indítsd újra a visszaállítást, mert az a mentést tölti vissza az adataid helyére.",
|
||||
"note.restore.interrupted_put_back": "A visszaállítás félbeszakadt (áramszünet). Az alkalmazás adatai a visszaállítás előtti állapotban vannak.",
|
||||
"note.restore.no_db_at_all": " Ennek az alkalmazásnak nincs adatbázisa.",
|
||||
"note.restore.no_db_in_backup": " FIGYELEM: ennek az alkalmazásnak VAN adatbázisa, de a mentés nem tartalmazott adatbázis-mentést, ezért az adatbázis NEM állt vissza. A visszaállítás előtti állapot mentése megvan: %s",
|
||||
|
||||
@@ -10,6 +10,7 @@
|
||||
"recovery_info.body": "BORN AS A KEY (R-554, 2026-10-12, `09` §3 decision 222) -- the NEW text of recovery-info.txt, pointing at the dashboard's Restore page and the recovery code instead of the deleted setup wizard. The operator approves the Hungarian before release. Pinned by internal/recovery TestRecoveryInfo_PointsAtDashboardNotWizard.",
|
||||
"err.backup.db_restore_failed_held_mixed": "BORN AS A KEY (R-893, 2026-10-08) -- a NEW sentence for a failed off-site replay whose database rollback worked but whose files/volumes/version had already moved; the app is held. Never a Go literal; pinned by internal/backup/r893_mixed_restore_test.go.",
|
||||
"err.backup.restore_failed_held_mixed": "BORN AS A KEY (R-893, 2026-10-08, security review) -- a restore that stopped half-way (placement, volume replay or DB start failed) after files/volumes/version had moved; the app is HELD. Pinned by internal/backup/r893_mixed_restore_test.go.",
|
||||
"note.restore.interrupted_put_back_waiting": "BORN AS A KEY (R-1251, 2026-10-24) -- the restore record sentence for an interrupted restore whose put-back waits for the app's drive. Never a Go literal; pinned by TestR1251_TheRecordSaysThePutBackWaits.",
|
||||
"hold.putback_pending": "BORN AS A KEY (R-1251, 2026-10-24) -- the hold sentence for an app whose cut restore waits for its drive before its pre-restore data is put back (HoldReasonPutBackPending). Never a Go literal; pinned by internal/backup/r1251_putback_waits_test.go.",
|
||||
"note.reconstitute.held_mixed": "BORN AS A KEY (R-893, 2026-10-08) -- the hold sentence for that held app (HoldReasonRestoreMixed). Never a Go literal; pinned by internal/backup/r893_mixed_restore_test.go.",
|
||||
"recovery.older_unchecked": "BORN AS A KEY (R-304, 2026-10-08) -- a NEW sentence of the recovery screen for the agent's 424 (earlier sealed packages not all checked), never a Go literal; pinned by TestR304_OlderUnchecked_IsNotAWrongCode.",
|
||||
|
||||
Reference in New Issue
Block a user