From 3cce15fa811e9a5174a874e0f4bbe524465180b6 Mon Sep 17 00:00:00 2001 From: jochen Date: Thu, 22 Oct 2026 18:30:16 +0200 Subject: [PATCH] restic: let the thinning wait up to ten minutes for a held repository lock (issue 620) A restic outside the night's lock, such as a listing while a delivery plan backs up data modules before their moves, held the lock 246 ms before the thinning asked for it, and the thinning failed at once, raising an urgent condition for a timing collision. restic's --retry-lock now waits up to ten minutes on both of the thinning's forgets; past that it fails with restic's words as before. --- modules/restic/README.md | 6 ++ modules/restic/cmd/restic-backups/backups.go | 13 ++- .../restic/cmd/restic-backups/backups_test.go | 2 +- .../restic/cmd/restic-backups/hand_test.go | 4 +- .../restic/cmd/restic-backups/lock_test.go | 100 ++++++++++++++++++ .../cmd/restic-backups/retention_test.go | 2 +- 6 files changed, 121 insertions(+), 6 deletions(-) create mode 100644 modules/restic/cmd/restic-backups/lock_test.go diff --git a/modules/restic/README.md b/modules/restic/README.md index 1ec851b8..c415262e 100644 --- a/modules/restic/README.md +++ b/modules/restic/README.md @@ -18,6 +18,12 @@ Against mistakes, not disasters: nothing leaves the machine. kept for good. That is a choice: deleting a module's last restore point is a person's act, and until then it costs only space. +**A repository another restic holds** (a listing of the restore points, say, while a delivery plan backs up +the machine's modules before their moves) is waited for: the thinning asks restic to retry the lock for up to +ten minutes (`--retry-lock`, novox/hq issue 620), and fails only after that. A failed thinning keeps every +restore point, and the module's health stays unhealthy until a thinning succeeds: the next night's, or one +after `node-backup.now`. + `node-backup.backed-up` lists each module's restore points taken by hand under `handTaken`: when each was taken, the time it is kept at least until, whether it still waits for a later good night, and a sentence saying so. diff --git a/modules/restic/cmd/restic-backups/backups.go b/modules/restic/cmd/restic-backups/backups.go index 4485b9d5..876c73ac 100644 --- a/modules/restic/cmd/restic-backups/backups.go +++ b/modules/restic/cmd/restic-backups/backups.go @@ -406,6 +406,15 @@ func (b *Backups) backUp(ctx context.Context, only string, hand bool) (map[strin return outcome, nil } +// thinningWaitsForALock is how long the thinning waits for a repository another restic holds, with restic's own +// --retry-lock, before it fails as it did before (novox/hq issue 620). The night's lock keeps out this module's own +// backups and restores, not a restic outside it: a listing of the restore points, asked while a delivery plan backs +// up a machine's data modules before their moves (ADR 0233), held the lock 246 ms before a thinning asked for it. +// Ten minutes outlasts such a plan's backups of every data module on a machine (a whole night of fifteen modules +// took under five minutes) and stays well within the half hour after which restic takes a lock as stale; a lock +// held longer than this is not a passing collision, and is said the same night. +const thinningWaitsForALock = 10 * time.Minute + // thin forgets the restore points taken by hand that are past their days and have a later night of their // module, by id, then thins the rest by the counts, keeping every one still tagged as taken by hand (novox/hq // issue 453). It answers the short ids it let go — on an error of the counts' thinning too, for those are gone. A list that does not read thins nothing: a restore point @@ -420,14 +429,14 @@ func (b *Backups) thin(ctx context.Context, keep Retention) ([]string, error) { ids, letGo = append(ids, s.ID), append(letGo, s.ShortID) } if len(ids) > 0 { - if _, err := b.restic(ctx, append([]string{"forget"}, ids...)...); err != nil { + if _, err := b.restic(ctx, append([]string{"forget", "--retry-lock", thinningWaitsForALock.String()}, ids...)...); err != nil { return nil, err } b.Say("let go the restore points taken by hand past %d days with a later night: %s", keep.Hand, strings.Join(letGo, ", ")) } _, err = b.restic(ctx, "forget", "--prune", "--group-by", "host,tags", "--keep-daily", fmt.Sprint(keep.Daily), "--keep-weekly", fmt.Sprint(keep.Weekly), "--keep-monthly", fmt.Sprint(keep.Monthly), - "--keep-tag", HandTag) + "--keep-tag", HandTag, "--retry-lock", thinningWaitsForALock.String()) return letGo, err } diff --git a/modules/restic/cmd/restic-backups/backups_test.go b/modules/restic/cmd/restic-backups/backups_test.go index 24930540..3a545185 100644 --- a/modules/restic/cmd/restic-backups/backups_test.go +++ b/modules/restic/cmd/restic-backups/backups_test.go @@ -108,7 +108,7 @@ func TestANightDumpsBeforeEachSnapshotAndOneFailingModuleFailsOnlyItself(t *test "sh -c fail-it", "restic backup --json --tag module=mail /", "restic snapshots --json", - "restic forget --prune --group-by host,tags --keep-daily 14 --keep-weekly 8 --keep-monthly 6 --keep-tag hand", + "restic forget --prune --group-by host,tags --keep-daily 14 --keep-weekly 8 --keep-monthly 6 --keep-tag hand --retry-lock 10m0s", } if !reflect.DeepEqual(calls, want) { t.Errorf("ran\n%s\nwant\n%s", strings.Join(calls, "\n"), strings.Join(want, "\n")) diff --git a/modules/restic/cmd/restic-backups/hand_test.go b/modules/restic/cmd/restic-backups/hand_test.go index 22af7160..afd4637b 100644 --- a/modules/restic/cmd/restic-backups/hand_test.go +++ b/modules/restic/cmd/restic-backups/hand_test.go @@ -74,7 +74,7 @@ func TestAHandTakenBackupIsTaggedAndTheThinningKeepsThatTag(t *testing.T) { if got := h.with("restic backup"); len(got) != 2 || got[1] != "restic backup --json --tag module=pg /" { t.Errorf("the night backed up with %q, want it tagged with its module alone", got) } - want := "restic forget --prune --group-by host,tags --keep-daily 14 --keep-weekly 8 --keep-monthly 6 --keep-tag hand" + want := "restic forget --prune --group-by host,tags --keep-daily 14 --keep-weekly 8 --keep-monthly 6 --keep-tag hand --retry-lock 10m0s" for _, f := range h.with("restic forget") { if f != want { t.Errorf("thinned with %q, want %q", f, want) @@ -134,7 +134,7 @@ func TestTheThinningForgetsAnExpiredHandTakenRestorePointByItsId(t *testing.T) { _, err := b.BackUp(context.Background(), "") must(t, err) forgets := h.with("restic forget") - if len(forgets) != 2 || forgets[0] != "restic forget aaaaaaaa11" || !strings.HasPrefix(forgets[1], "restic forget --prune") { + if len(forgets) != 2 || forgets[0] != "restic forget --retry-lock 10m0s aaaaaaaa11" || !strings.HasPrefix(forgets[1], "restic forget --prune") { t.Fatalf("thinned with %q, want the expired one forgotten by id, then the rotation", forgets) } th := b.LastRun().Thinned diff --git a/modules/restic/cmd/restic-backups/lock_test.go b/modules/restic/cmd/restic-backups/lock_test.go new file mode 100644 index 00000000..c474f30c --- /dev/null +++ b/modules/restic/cmd/restic-backups/lock_test.go @@ -0,0 +1,100 @@ +package main + +// The thinning waits for a repository another restic holds (novox/hq issue 620): met three times, each when a +// restic process outside the night's lock — a listing of the restore points while a delivery plan backs up a +// machine's data modules before their moves (ADR 0233) — held the repository's lock a few hundred milliseconds +// before the thinning asked for it, and the thinning failed at once. + +import ( + "context" + "errors" + "slices" + "strings" + "testing" + "time" +) + +// lockedRestic is a fake restic whose repository another process holds for heldFor, as restic answers it: a +// forget without --retry-lock fails at once; one with it waits up to its bound, and succeeds when the lock is +// let go within it, else fails with restic's words. waited is how long the forgets it was asked waited. +type lockedRestic struct { + handRestic + heldFor time.Duration + waited []time.Duration +} + +const lockSaid = "unable to create lock in backend: repository is already locked by PID 4242 on the-machine by root " + + "(UID 0, GID 0) / lock was created at 2026-10-22 18:14:22 (246 ms ago)" + +func (l *lockedRestic) run(ctx context.Context, name string, args ...string) (string, error) { + if name != "restic" || args[5] != "forget" { + return l.handRestic.run(ctx, name, args...) + } + l.calls = append(l.calls, "restic "+strings.Join(args[5:], " ")) + bound := time.Duration(0) + if i := slices.Index(args, "--retry-lock"); i >= 0 && i+1 < len(args) { + d, err := time.ParseDuration(args[i+1]) + if err != nil { + return "", errors.New("invalid argument for --retry-lock: " + args[i+1]) + } + bound = d + } + if l.heldFor > bound { + l.waited = append(l.waited, bound) + return "", errors.New(lockSaid) + } + l.waited = append(l.waited, l.heldFor) + l.heldFor = 0 + return "", nil +} + +func TestTheThinningWaitsForALockHeldBriefly(t *testing.T) { + for _, held := range []time.Duration{3 * time.Second, 5 * time.Minute} { + l := &lockedRestic{heldFor: held} + b := &Backups{Where: placed(t, "# pg\npath /\n"), Run: l.run, Now: time.Now, Say: quiet} + _, err := b.BackUp(context.Background(), "") + must(t, err) + if th := b.LastRun().Thinned; th == nil || !th.OK { + t.Errorf("held for %s: recorded %+v, want the thinning to wait for the lock and succeed", held, th) + } + if why := b.Health(context.Background()).Why; strings.Contains(why, "Thinning the restore points failed") { + t.Errorf("held for %s: the health says %q", held, why) + } + } +} + +func TestTheThinningStillFailsOnALockHeldPastItsBound(t *testing.T) { + l := &lockedRestic{heldFor: thinningWaitsForALock + time.Minute} + b := &Backups{Where: placed(t, "# pg\npath /\n"), Run: l.run, Now: time.Now, Say: quiet} + _, err := b.BackUp(context.Background(), "") + must(t, err) + th := b.LastRun().Thinned + if th == nil || th.OK || !strings.Contains(th.Error, "already locked") { + t.Fatalf("recorded %+v, want the thinning failed on the lock", th) + } + if !slices.Equal(l.waited, []time.Duration{thinningWaitsForALock}) { + t.Errorf("waited %v, want once, for %s", l.waited, thinningWaitsForALock) + } + why := b.Health(context.Background()).Why + for _, want := range []string{"Thinning the restore points failed at", "already locked", "Nothing was forgotten", + "node-backup.now on this machine thins again"} { + if !strings.Contains(why, want) { + t.Errorf("the health says %q, want %q in it", why, want) + } + } +} + +// A restore point taken by hand that is let go by its id waits for the lock as well: it is the thinning too. +func TestTheThinningForgetsByIdWaitingForTheLock(t *testing.T) { + now := time.Date(2026, 10, 20, 3, 0, 0, 0, time.UTC) + l := &lockedRestic{heldFor: 3 * time.Second, handRestic: handRestic{made: "bbbbbbbb11", snaps: []Snapshot{ + {ID: "aaaaaaaa11", ShortID: "aaaaaaaa", Time: now.AddDate(0, 0, -9), Tags: []string{"module=pg", HandTag}}, + {ID: "bbbbbbbb11", ShortID: "bbbbbbbb", Time: now, Tags: []string{"module=pg"}}, + }}} + b := &Backups{Where: placed(t, "# pg\npath /\n"), Run: l.run, Now: func() time.Time { return now }, Say: quiet} + _, err := b.BackUp(context.Background(), "") + must(t, err) + if th := b.LastRun().Thinned; th == nil || !th.OK || !slices.Equal(th.LetGo, []string{"aaaaaaaa"}) { + t.Errorf("recorded %+v, want aaaaaaaa let go after waiting for the lock", th) + } +} diff --git a/modules/restic/cmd/restic-backups/retention_test.go b/modules/restic/cmd/restic-backups/retention_test.go index 2e0ce490..58a7ced4 100644 --- a/modules/restic/cmd/restic-backups/retention_test.go +++ b/modules/restic/cmd/restic-backups/retention_test.go @@ -51,7 +51,7 @@ func thinning(t *testing.T, retention *string) (string, []string) { func TestANightThinsByTheRetentionTheMeshWrote(t *testing.T) { conf := "# Written by the mesh.\ndaily=7\nweekly=4\nmonthly=24\nhand=10\n" got, _ := thinning(t, &conf) - if want := "restic forget --prune --group-by host,tags --keep-daily 7 --keep-weekly 4 --keep-monthly 24 --keep-tag hand"; got != want { + if want := "restic forget --prune --group-by host,tags --keep-daily 7 --keep-weekly 4 --keep-monthly 24 --keep-tag hand --retry-lock 10m0s"; got != want { t.Errorf("ran %q, want %q", got, want) } }