Files
admin fcef8e069c
gates / gates (push) Successful in 12s
one writer at a time, and a check that can run (R-411, R-408, R-407, R-414, R-412a)
THE WALK FOUND THREE MORE ENTRY POINTS THAN THE REPORT DID. R-411 named one missing
acquireRunning. Fixing it and then pinning the invariant with an AST walk surfaced FOUR in
total, all of which issued restic commands with no flag:

  RestoreOffboxScratch      - the reported one
  OffboxRestorePrepareFull  - the SECOND request in the customer's own two-step full-restore
                              flow, and the one that actually shells `restic stats`. The UI
                              reaches it FIRST, so flagging only the restore would have left
                              the collision reachable by the ordinary path.
  RestoreSharesScratch      - R-411's exact shape on the shares tier: unlockStale + resticStep,
                              a live web caller, and its sibling PlaceSharesRestore has always
                              taken the flag.
  RestoreOffbox             - no production caller today, but the same dangerous pattern.
                              Flagged rather than left for a future caller to inherit.

OffsiteInventoryList is REGISTERED EXEMPT with its reason: it issues only `restic snapshots
--json`, measured on demo-hp 2026-08-31 not to take a lock, and flagging it would make
browsing a page refuse during a backup for no safety gain.

THE REAL DELIVERABLE IS THE WALK, not the acquire. offbox_integrity.go:28 asserted "Every
off-site operation takes acquireRunning" since v0.227.0, nothing checked it, and it was false
for months - the ninth instance of this project's most-repeated class. The walk is an AST
pass, not strings.Contains, because a commented-out call still contains the string.
Red-proofed twice: removing the acquire fails it naming RestoreOffboxScratch; an
unregistered fake entry point fails it naming the fake.

R-407: "It NEVER writes to the repository" corrected in place, not deleted (R-360's rule).
`check` takes a lock - and so does `restic stats`, which is the fact nobody had and the one
that made R-411 possible. Both recorded where the next reader will meet them.

R-414: the proof could not run at all on a box with no registered drive. Part 2.1's
determination came out as neither "missed" nor "deliberate": R-356's own test comments say
the scratch resolver "still resolves ... only the DESTINATION moves", so it was OUT OF SCOPE,
and it was never ruled out on state-only grounds - the one comment about a systemDataPath
fallback belonged to PlaceOffsiteRestore, concerned bulk USERDATA, and R-356 overruled even
that. So 07 section 6.3's rule applies and now has a fourth consumer.

The fallback is SCOPED, because the two callers ask different questions and one predicate
answering both is the R-356 defect itself: a UNIT-ONLY restore may fall back to the system
data path (07 section 7 records as FACT that a driveless app's unit already lives there
indefinitely, and that the same-device placement is intended); a FULL restore keeps today's
refusal, because it pulls bulk userdata onto a state-only tier.

And the silence ends either way: a proof that cannot start now records ProofResultCannotRun
rather than an Err, so last_proof_result is never ABSENT - absent already means "controller
too old", and a second meaning on the same field is the StatsKnown trap one level up. It is
recorded WITHOUT advancing per-snapshot due-ness, so the app stays retryable once a drive is
registered.

R-412 leg 1: a per-app push whose unit carried no dump and no tar now says so, at WARN.
Wording only - no guard, and the capture is untouched (08 section 8.2). Leg 2 stays OPEN.

16 new tests, 1689 -> 1705. Full suite 28 packages rc=0, all 13 controller gates OK.
Red-proofs run and reverted byte-identical for A3/B1 (twice), C1 and D1.
2026-09-01 10:19:36 +02:00

406 lines
22 KiB
Go

package backup
import (
"context"
"fmt"
"regexp"
"strings"
"time"
"gitea.dooplex.hu/admin/felhom-controller/internal/settings"
)
// ── R-359 — nothing ever checked that the off-site copies are still readable ─────────────────────
//
// The whole-guest tier has verify jobs. The tier holding the customer's documents and photos had
// none: the complete set of restic verbs this controller used was
// `restore, snapshots, backup, unlock, stats, init, forget, prune, cat, config` — no `check`.
// We would have found out at restore time, with a customer waiting.
//
// On 2026-08-21 one packet in a set-aside store was deliberately damaged and plain `restic check`
// caught it at once. That is an empirical result, not an assumption — it is why this row exists.
//
// ── THE HAZARD THAT SHAPES THIS WHOLE FILE ──────────────────────────────────────────────────────
//
// `resticStep` self-heals a crash lock: when a command fails with "repository is already locked" it
// runs **`unlock --remove-all`** and retries once. Its own doc comment records why that is safe —
// *"the in-process single-flight mutex (held by every caller of this method) proves no sibling
// operation is live"*. Every off-site operation takes `acquireRunning` for exactly that reason.
//
// **THAT SENTENCE WAS FALSE FROM v0.227.0 UNTIL v0.232.0, AND NOTHING CHECKED IT.** `RestoreOffboxScratch`,
// `OffboxRestorePrepareFull`, `RestoreSharesScratch` and `RestoreOffbox` all issued restic commands
// without the flag. R-411 measured the consequence on demo-hp 2026-08-31: a customer full-restore's
// `restic stats` held a repository lock, this check was therefore not blocked, met that lock, and
// `resticStep` removed it with `unlock --remove-all` while logging *"a stale exclusive lock left by a
// previous crash"*. There was no crash.
//
// The sentence is TRUE again as of v0.232.0, and it is now **pinned by
// `TestR408_EveryOffsiteEntryPointTakesTheFlagOrIsRegistered`** — an AST walk over this package that
// fails when a new off-site entry point takes neither the flag nor a registered exemption. Do not
// trust this paragraph; the test is what holds it.
//
// **An integrity check that did not take the flag would break that invariant.** It could meet the
// lock of a `forget --prune` running from this same box, remove it, and retry over the top of a live
// prune. So this check TAKES THE FLAG, and **skips rather than waits** when it cannot get it: waiting
// would pin a nightly backup behind a check, and a skipped check simply runs tomorrow. That is the
// single most important property in this file, and `TestR359_SkipsWhenRunningFlagHeld` asserts it as
// a NON-EFFECT — restic was never invoked, and `unlock` never appeared in any argument list.
// integrityCheckTimeout bounds one check so a hung repository cannot pin the single-writer flag.
//
// CHOSEN, not inherited: a structure check on a store this size is minutes (measured at ~4 s against
// demo-hp's 134 MB store, and it scales with the index rather than the data). 30 minutes is far above
// any plausible structure check and far below "forever", so the failure mode of a wedged SFTP mount is
// a released flag and a retry tomorrow, never a box whose backups stop because a check never returned.
//
// R-399 CHANGED WHAT THIS NUMBER HAS TO COVER, and this paragraph replaces the one that said the
// opposite. Read-data now ships ON at 100% (see defaultIntegrityReadDataSubset below), so a check
// downloads and re-hashes the whole store every week. Measured on demo-hp 2026-08-30: 39.2 s at 100%
// against a 134 MB store, versus 35.0 s at structure depth. 30 minutes is still ~46x the only
// full-depth number that exists, so it is not resized here on the strength of one measurement — but
// it is now the number a LARGE store will meet first, and `integritySlowNoticeThreshold` exists to
// tell the operator long before that happens. R-401 owns the revisit.
const integrityCheckTimeout = 30 * time.Minute
// integritySlowNoticeThreshold is the point at which a COMPLETED check has started costing real time
// and the depth setting needs revisiting (R-401).
//
// CHOSEN, and deliberately imprecise, from the single data point that exists: demo-hp's 134 MB store,
// 2026-08-30, 35.0 s at structure depth and 39.2 s at 100%. 5 minutes is ~7.6x the only full-depth
// number we have, so it cannot fire on anything resembling today's fleet; and it is well under
// integrityCheckTimeout, so the operator hears "this is getting slow" long before a check is killed
// for running too long. A notice changes no behaviour, so an imprecise number is cheap here — whereas
// a precise-looking threshold invented from one measurement on one small store would be the exact
// shape of the four production designs this project has already specced against nothing.
// A var, not a const, for ONE reason: the notice cannot otherwise be proven to fire through the real
// CheckOffboxIntegrity path — no test can make a check take five minutes. Tests lower it and restore
// it with defer. Nothing in production writes it.
var integritySlowNoticeThreshold = 5 * time.Minute
// defaultIntegrityMaxAgeDays is the max age of a SUCCESSFUL check before one is due again.
const defaultIntegrityMaxAgeDays = 7
// defaultIntegrityReadDataSubset is how deep an unconfigured box checks: ALL of it (R-399, Viktor's
// ruling of 2026-08-31).
//
// THE FACT THE DEFAULT RESTS ON, because it is the thing that stops someone turning it back down to
// save four seconds: **the structure check does not detect a size-preserving pack corruption.** On
// 2026-08-30 a pack in demo-hp's store was damaged WITHOUT changing its size; plain `restic check`
// reported `no errors were found` and exited clean, and every read-data form caught it. A store that
// is verified only structurally is a store whose rot is discovered at restore time, with a customer
// waiting.
//
// THE COST, measured the same day on the same store (140 829 678 B / 2 651 blobs / 67 snapshots):
// structure 35.0 s, 10% 35.9 s, 50% 37.3 s, 100% 39.2 s. Four seconds.
//
// WHAT IS NOT ESTABLISHED: how any of that behaves on a store one or two orders of magnitude larger.
// There is exactly ONE data point. That is why this is a constant and a notice (see
// integritySlowNoticeThreshold) rather than a rotation schedule, a size threshold or a bandwidth
// budget — every one of those would be a number invented from a single measurement. R-401.
//
// This default lives HERE and not in config.applyDefaults, deliberately, and defaultIntegrityMaxAgeDays
// beside it is the precedent: both integrity defaults are resolved in this package, in one accessor
// each, next to the reasoning that justifies them. Symmetry with the other Monitoring defaults is
// worth less than having the number and its argument in the same place.
const defaultIntegrityReadDataSubset = "100%"
// integrityOffToken switches the deep check back off without a code change.
//
// A setting with no off switch is not a setting. Without this token there would be no way to return a
// box to structure depth: an EMPTY value means "not configured" and therefore the default (§8), so
// emptiness cannot also mean "off". Matched case-insensitively.
const integrityOffToken = "off"
// readDataSubsetRe accepts the forms restic documents for --read-data-subset: "n/m", a percentage
// like "5%", or a size like "50M". Anything else is refused at read time rather than passed through —
// a typo must not fail the whole check, which is what handing restic an unparsed value would do.
var readDataSubsetRe = regexp.MustCompile(`^([0-9]+/[0-9]+|[0-9]+(\.[0-9]+)?%|[0-9]+[KMGT]?)$`)
// IntegrityResult is what one off-site integrity check did, so every surface — the log, the event, the
// report and the debug endpoint — states the same facts from one place.
//
// Skipped is a first-class outcome, not an error. A check that yielded to a running backup did the
// right thing, and reporting it as a failure would alarm on correct behaviour.
//
// Unreachable is separated from a failed check for the reason §8 of the task records and R-185
// established for a tier the box cannot read: **"I could not look" and "I looked and it is broken" are
// different facts** and must not produce the same alarm. R-339 already alarms on reachability; a
// second alarm for the same fact is noise, and worse, it would train the operator to discount the one
// alarm that means the customer's backups are damaged.
type IntegrityResult struct {
RanAt time.Time
Duration time.Duration
ReadDataSubset string // "" = structure only
OK bool
Skipped bool
SkipReason string
Unreachable bool
// Output is truncated restic output for the LOG. It never reaches a customer message — R-379 is
// the reason: 615 bytes of raw database text reached a customer once.
Output string
}
// integrityReadDataSubset resolves the configured subset spec, refusing anything malformed.
//
// FOUR inputs, three outcomes (§8's table):
// - absent or empty -> defaultIntegrityReadDataSubset. Empty is "not configured", never "off".
// - "off" (any case) -> "" , the structure-and-index check only. The one way to switch it back.
// - a form restic accepts -> itself, unchanged. An explicit value always wins.
// - anything else -> defaultIntegrityReadDataSubset, with a WARN naming the bad value.
//
// THE MALFORMED CASE FALLS BACK TO THE DEFAULT, NOT TO STRUCTURE, and the direction is the point.
// Handing restic `--read-data-subset=banana` fails the whole check, so a typo must not be passed
// through — but downgrading to structure depth on a typo would ALSO silently remove the protection
// R-399 exists to add, which is R-357's shape exactly: a guard that opens quietly. Falling back to the
// default keeps the protection and still says loudly that the config is wrong.
func (m *Manager) integrityReadDataSubset() string {
spec := strings.TrimSpace(m.cfg.Monitoring.Integrity.ReadDataSubset)
if spec == "" {
return defaultIntegrityReadDataSubset
}
if strings.EqualFold(spec, integrityOffToken) {
return ""
}
if !readDataSubsetRe.MatchString(spec) {
m.logger.Printf("[WARN] [offbox] integrity: read_data_subset %q is not a form restic accepts (n/m, N%%, a size like 50M, or %q) — falling back to the DEFAULT depth %q, not to a structure-only check, so a typo cannot quietly remove the protection",
spec, integrityOffToken, defaultIntegrityReadDataSubset)
return defaultIntegrityReadDataSubset
}
return spec
}
// IntegrityDepthCode is the depth as a short RECORDED value, for the persisted verdict and the wire.
//
// "" is reserved to mean NOT RECORDED — a box older than v0.228.0, whose stored verdict cannot say how
// deep it looked. That follows the StatsKnown precedent on the same object: absence means "cannot
// answer", never an answer. So structure depth is written as the word "structure", not as "".
func IntegrityDepthCode(subset string) string {
if subset == "" {
return "structure"
}
return subset
}
// noticeIfSlow logs an operator WARN when a COMPLETED check has started costing real time (R-401).
//
// COMPLETED ONLY. A skip has no duration to judge, and an unreachable store is "I could not look",
// which is not "I looked and it was slow" (§8). Pass and fail BOTH qualify: the notice and the failure
// alarm are independent facts and neither suppresses the other.
//
// It is a log line and NOTHING else — no hub event, no customer alarm. An event type costs the
// severity contract, the grain table and three registers, all to say "this took a while"; 08 §6.2's
// coarse-by-default rule points the other way. And it does NOT change the depth by itself: a notice
// that silently reconfigures the box would be a behaviour change wearing a notice's clothes.
func (m *Manager) noticeIfSlow(res IntegrityResult) {
if res.Skipped || res.Unreachable || res.Duration < integritySlowNoticeThreshold {
return
}
m.logger.Printf("[WARN] [offbox] integrity: the check took %s at depth %s (%s), over the %s notice threshold — R-401: the depth setting needs revisiting for a store this size. Nothing was changed automatically.",
res.Duration.Round(time.Second), IntegrityDepthCode(res.ReadDataSubset),
integrityDepthLabel(res.ReadDataSubset), integritySlowNoticeThreshold)
}
// integrityMaxAge returns the configured max age of a successful check, defaulting to 7 days.
func (m *Manager) integrityMaxAge() time.Duration {
d := m.cfg.Monitoring.Integrity.MaxAgeDays
if d <= 0 {
d = defaultIntegrityMaxAgeDays
}
return time.Duration(d) * 24 * time.Hour
}
// IntegrityDue reports whether a check is due, and the age of the last successful one.
//
// DUE-NESS, NOT A WEEKDAY. A job that fires only on Sundays is a job that silently skips a week every
// time the box is off on a Sunday — which is R-341's exact failure, a dated check quietly missed and
// never caught up. Asking "is the last one older than the max age?" catches up on the next day the box
// is running, whatever day that is.
//
// A repository that has never been checked is DUE. That is the fail-safe direction: an unchecked store
// must not read as a fresh one.
func (m *Manager) IntegrityDue(now time.Time) (due bool, last time.Time) {
t := m.settings.GetOffboxTarget()
if t == nil || strings.TrimSpace(t.LastIntegrityCheck) == "" {
return true, time.Time{}
}
parsed, err := time.Parse(time.RFC3339, t.LastIntegrityCheck)
if err != nil {
m.logger.Printf("[WARN] [offbox] integrity: last-check stamp %q does not parse (%v) — treating the store as never checked", t.LastIntegrityCheck, err)
return true, time.Time{}
}
return now.Sub(parsed) >= m.integrityMaxAge(), parsed
}
// recordIntegrityOutcome persists the verdict and advances due-ness.
//
// Called ONLY when a check actually reached a verdict — pass or fail. A FAILING store advances
// due-ness deliberately: re-checking a broken repository every night is load with no new information,
// the hourly operator cooldown already governs the mail, and the failure is already recorded where a
// surface can read it. A skip or an unreachable repository does NOT reach here, so tomorrow tries
// again.
// RecordIntegrityVerdict is the PRODUCTION entry point: it persists the verdict AND the depth it was
// reached at, in one write. The caller in main.go owns the decision of WHEN a verdict counts, because
// only it knows whether the run was forced or scheduled.
//
// The depth travels with the verdict because a stored result that does not say how deep it looked
// cannot be judged later: "checked, OK" means two different things at structure depth and at 100%,
// and the whole of R-399 is that difference.
func (m *Manager) RecordIntegrityVerdict(res IntegrityResult) {
m.recordIntegrityOutcome(res.RanAt, res.OK, IntegrityDepthCode(res.ReadDataSubset))
}
// RecordIntegrityOutcome records a verdict whose depth is not stated. It writes "" to the depth field,
// which reads as NOT RECORDED rather than as structure depth — see integrityDepthCode. Kept as the
// due-ness surface the R-359 tests drive; production goes through RecordIntegrityVerdict above.
func (m *Manager) RecordIntegrityOutcome(at time.Time, ok bool) { m.recordIntegrityOutcome(at, ok, "") }
func (m *Manager) recordIntegrityOutcome(at time.Time, ok bool, depth string) {
if err := m.settings.UpdateOffboxStatus(func(o *settings.OffboxTarget) {
o.LastIntegrityCheck = at.UTC().Format(time.RFC3339)
o.LastIntegrityOK = ok
o.LastIntegrityDepth = depth
}); err != nil {
m.logger.Printf("[ERROR] [offbox] integrity: could not persist the check outcome: %v — the check RAN and its verdict was ok=%v at depth %q, but due-ness did not advance, so it will run again tomorrow", err, ok, depth)
}
}
// CheckOffboxIntegrity runs one off-site integrity check. It prunes nothing, forgets nothing, unlocks
// nothing and backs up nothing.
//
// **IT DOES, HOWEVER, WRITE A LOCK FILE, and the earlier wording here — "It NEVER writes to the
// repository" — was wrong (R-407).** Observed on demo-hp 2026-08-31 with a lock sampler that was
// positively controlled first: across a real check the repository went `locks=0` -> `locks=1` for nine
// consecutive samples -> `locks=0`. `restic check` takes a lock like most restic verbs; only `--no-lock`
// avoids it, and this check deliberately does not pass it, because the lock is what makes the check
// exclusive against a prune.
//
// **AND THE FACT NOBODY HAD, which is what made R-411 possible: `restic stats` ALSO takes a lock.**
// Measured in a clean room the same night — nothing else running, four invocations, `locks=1`. That is
// why a customer full-restore, whose size probe shells `stats`, could collide with this check at all.
// The sentence is corrected in place rather than deleted, because R-360's rule is that a comment
// claiming a guard is exactly why nobody looks for the missing one.
//
// Due-ness is NOT consulted here — the caller decides. The scheduled job asks IntegrityDue first; the
// operator's debug button deliberately does not, because "run it now" is the whole point of a button.
// Every other guard applies to both, including the single-writer flag.
func (m *Manager) CheckOffboxIntegrity(ctx context.Context) IntegrityResult {
res := IntegrityResult{RanAt: time.Now()}
if !m.OffboxConfigured() {
// A box with no off-site tier has nothing to check. Silent, and not an alarm.
res.Skipped, res.SkipReason = true, "no off-site target configured"
return res
}
// THE HAZARD GATE. See the file header. Skip, never wait: waiting would pin the nightly backup
// behind this check, and a skipped check costs nothing because tomorrow's run tries again.
if err := m.acquireRunning(); err != nil {
res.Skipped, res.SkipReason = true, "a backup or restore is already running"
m.logger.Printf("[INFO] [offbox] integrity: skipped — %s; due-ness is NOT advanced, so this retries on the next run", res.SkipReason)
return res
}
defer m.releaseRunning()
t := m.settings.GetOffboxTarget()
base, env := m.offboxBaseArgs(t)
// Does the repository answer at all? A failure here is UNREACHABLE, not damage — the distinction
// the whole result type exists for.
if err := m.ensureOffboxRepo(ctx, base, env); err != nil {
res.Unreachable = true
res.Output = truncate([]byte(err.Error()))
m.logger.Printf("[WARN] [offbox] integrity: the repository could not be reached, so NOTHING was checked (this is not an integrity failure — R-339 owns reachability): %v", err)
return res
}
args := []string{"check"}
if subset := m.integrityReadDataSubset(); subset != "" {
res.ReadDataSubset = subset
args = append(args, "--read-data-subset="+subset)
}
cctx, cancel := context.WithTimeout(ctx, integrityCheckTimeout)
defer cancel()
start := time.Now()
out, err := m.resticStep(cctx, env, base, "integrity-check", args...)
res.Duration = time.Since(start)
res.Output = truncate(out)
if err == nil {
res.OK = true
m.logger.Printf("[INFO] [offbox] integrity: check PASSED in %s (%s)", res.Duration.Round(time.Second), integrityDepthLabel(res.ReadDataSubset))
m.noticeIfSlow(res)
return res
}
// A timeout is NOT damage. The check did not finish, so it saw nothing, so it may not claim the
// store is broken — and it must not advance due-ness either.
if cctx.Err() != nil {
res.Unreachable = true
m.logger.Printf("[WARN] [offbox] integrity: the check did not finish within %s, so nothing was concluded about the store (NOT reported as damage): %v", integrityCheckTimeout, err)
return res
}
// Connect / credential / lock failures are the repository being unavailable, not unreadable.
// classifyResticProbe already names those causes; reusing it avoids a second classifier that could
// disagree with the first.
if cls := classifyResticProbe(out, err); cls == "other" || cls == "orphaned" || cls == "norepo" {
if !looksLikeRepositoryDamage(out) {
res.Unreachable = true
m.logger.Printf("[WARN] [offbox] integrity: the check could not run to a verdict (%s) — NOT reported as damage: %v: %s", cls, err, res.Output)
return res
}
}
m.logger.Printf("[ERROR] [offbox] integrity: check FAILED after %s — restic reported: %s", res.Duration.Round(time.Second), res.Output)
// A slow FAILING check gets the notice too. The two facts are independent and suppressing one
// because the other fired is how the second fact stops existing.
m.noticeIfSlow(res)
return res
}
// looksLikeRepositoryDamage reports whether restic's output describes a store that is READABLE and
// WRONG, as opposed to one that could not be opened.
//
// The strings are restic's own, from the 2026-08-21 damaged-pack drill and restic's check source. The
// direction is deliberate: an output this does not recognise is treated as "could not look", because
// telling a customer their backups are damaged is the more expensive mistake of the two, and R-339
// already alarms when the store cannot be reached.
func looksLikeRepositoryDamage(out []byte) bool {
s := strings.ToLower(string(out))
// THE SIGNATURES ARE PHRASES, NOT WORDS, AND THE REASON IS A BUG THIS FILE ALREADY HAD.
//
// The first draft matched bare `"pack "`, `"tree "`, `"snapshot "` and `"blob "`. Those appear in
// restic's ORDINARY PROGRESS OUTPUT — a healthy run prints `check all packs` and
// `check snapshots, trees and blobs` — so a check that failed for a NON-damage reason (a dropped
// connection mid-run, say) would have been classified as a corrupted store and alarmed the customer
// that their backups were damaged. Caught by the negative control in
// TestR359_HealthyRealOutputIsNotDamage, using the real bytes of a real passing check.
//
// Every phrase below is restic's own error wording, taken from the 2026-08-30 damaged-pack run on
// demo-hp or from restic's check source — never paraphrased.
for _, sig := range []string{
"does not match", // "Pack ID does not match, want <id>, got <id>" — the measured one
"not found in index", // a blob or pack the index promises and the store lacks
"blob not found", //
"size mismatch", //
"ciphertext verification failed",
"integrity error",
"repository contains errors", // restic's own summary verdict
"failed to load index", //
} {
if strings.Contains(s, sig) {
return true
}
}
return false
}
// integrityDepthLabel names how deep the check went, for a log line.
func integrityDepthLabel(subset string) string {
if subset == "" {
return "structure and index only — no pack data was downloaded"
}
return fmt.Sprintf("structure, index, and %s of the pack data re-read", subset)
}