diff --git a/CHANGELOG.md b/CHANGELOG.md index 2eb18c1..2d88b42 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -66,6 +66,30 @@ worse than no alert, because one day it carries a security fix. ### Fixed +- **A few snapshots leaked on every nested run, forever.** Found on real hardware, in + the one place it could be: a 256-snapshot backup of `/mnt/Tap` swept 253 cleanly and + left **3 behind** with `dataset is busy`. + + The cause is ZFS's own automount. Reading anything under + `/.zfs/snapshot//` makes ZFS **automount that snapshot**, and it stays + mounted for `zfs_expire_snapshot` seconds (**300** by default) after the last access. + `teardown()` unmounts *our* bind mounts — but not the automount underneath — so + `zfs destroy` refuses for exactly the datasets restic read most recently. Then + `cleanup_task()` removed the sidecar anyway, destroying the only record that those + snapshots existed. Nothing would ever have reclaimed them. + + Three changes, and the third is the one that makes it safe rather than merely + unlikely: + - `release_snapdirs()` unmounts ZFS's own `.zfs/snapshot` automounts (deepest first) + before deleting, so the snapshots are not busy in the first place. + - `delete_snapshot_tree()` **retries** the transient busy, and **returns the + snapshots it could not delete** instead of swallowing them. + - **The sidecar is now removed only on a confirmed-clean sweep** — including on the + staging-failure path, which used to remove it *before* the caller swept. The + asymmetry is deliberate: a sidecar left behind when the tree is already gone costs + one no-op delete on the next run, while a sidecar removed while the tree still + exists is unrecoverable. Survivors are reclaimed by the next run. + - **Installing the patch permanently blocked updating it.** `install.sh` does `chmod +x update.sh`, and git recorded `update.sh` as `100644` — so the chmod was a *tracked modification*, and `update.sh` refuses to run over a dirty tree. Install diff --git a/patch/truecloud_nested.py b/patch/truecloud_nested.py index f58a1c8..1662f73 100644 --- a/patch/truecloud_nested.py +++ b/patch/truecloud_nested.py @@ -58,6 +58,7 @@ import contextlib import os import stat import subprocess +import time __all__ = [ "STAGING_BASE", @@ -362,6 +363,48 @@ def teardown(staging_root, runner=_run, mounts_file="/proc/self/mounts"): return errors +def snapdir_automounts(snapshot_name, mounts_file="/proc/self/mounts"): + """Every ``/.zfs/snapshot/`` ZFS automount for this snapshot.""" + suffix = "/.zfs/snapshot/" + snapshot_name + found = [] + try: + with open(mounts_file, encoding="utf-8") as fh: + for line in fh: + parts = line.split() + if len(parts) > 1: + mp = parts[1].replace("\\040", " ") + if mp.endswith(suffix): + found.append(mp) + except OSError: + return [] + return sorted(found, key=_depth, reverse=True) # deepest first + + +def release_snapdirs(snapshot_name, runner=_run, mounts_file="/proc/self/mounts"): + """Unmount ZFS's OWN snapshot automounts, so the snapshots can be destroyed. + + Reading anything under ``/.zfs/snapshot//`` makes ZFS **automount** + that snapshot, and it stays mounted for ``zfs_expire_snapshot`` seconds (300 by + default) after the last access. teardown() unmounts OUR bind mounts -- but the + automount underneath them survives, and while it exists ``zfs destroy`` refuses + with *"dataset is busy"*. + + Proven on a real pool: a 256-snapshot recursive tree swept cleanly except for the + three datasets restic had read most recently. Those failed with EBUSY, and because + cleanup_task removed the sidecar anyway, they were orphaned **permanently** -- a + small leak, but a growing one, and exactly the failure this module exists to + prevent. + + Deepest first, so a child's automount is released before its parent's. + """ + errors = [] + for mp in snapdir_automounts(snapshot_name, mounts_file=mounts_file): + res = runner(["umount", mp]) + if res.returncode != 0: + errors.append(f"{mp}: {(res.stderr or '').strip()}") + return errors + + # ── orchestration (middleware is duck-typed; no middlewared import) ─────────── # # These are SYNCHRONOUS and talk to middlewared via `middleware.call_sync`, which @@ -424,15 +467,31 @@ def get_dataset_recursive(datasets, directory): ) -def delete_snapshot_tree(middleware, snapshot, logger=None): +def delete_snapshot_tree(middleware, snapshot, logger=None, attempts=4, + sleep=time.sleep): """Delete the parent snapshot AND every child created by ``zfs snapshot -r``. + Returns the snapshots it could NOT delete -- callers must not throw that away. + ``zfs.snapshot.delete`` is non-recursive by default and stock calls it with no options, so relying on stock would orphan one snapshot per descendant dataset on every run. Idempotent: tolerates the parent already being gone (stock's ``finally`` may have won the race once our mounts were released). + + "dataset is busy" is EXPECTED here and is TRANSIENT. ZFS automounts + ``/.zfs/snapshot/`` when it is read and keeps it mounted for + ``zfs_expire_snapshot`` seconds (300 by default) afterwards. So the datasets restic + touched last are still pinned when we try to destroy them. We release the + automounts explicitly and then retry -- on a real 256-snapshot tree, exactly three + snapshots hit this, and before the fix they were orphaned permanently. """ - dataset = snapshot.partition("@")[0] + dataset, _, snapname = snapshot.partition("@") + + # Release ZFS's own automounts first, or `zfs destroy` refuses with EBUSY on + # everything restic read in the last few minutes. + for err in release_snapdirs(snapname): + if logger: + logger.debug("truecloud-patch: could not release snapdir %s", err) # Fast path: ONE recursive delete removes the parent and every child that # `zfs snapshot -r` created (252 on a real pool). Deleting them individually @@ -441,7 +500,7 @@ def delete_snapshot_tree(middleware, snapshot, logger=None): # exists to prevent. try: middleware.call_sync("zfs.snapshot.delete", snapshot, {"recursive": True}) - return + return [] except Exception as e: # noqa: BLE001 - fall through to the explicit sweep # Usually just "parent already gone" (stock's finally won the race once our # mounts were released), which the sweep below handles. Log it rather than @@ -472,14 +531,53 @@ def delete_snapshot_tree(middleware, snapshot, logger=None): ) names = [snapshot] - for name in names: + def confirm_gone(failed): + """Drop any name ZFS no longer has, even though its delete raised. + + A delete that raised "does not exist" SUCCEEDED as far as we care, and must + not be retried or reported. The query is only a refinement: if it cannot be + answered we keep the delete's own verdict, rather than inventing survivors -- + a false survivor keeps the sidecar forever and is reported as a leak that + isn't there. + """ + if not failed: + return [] try: - middleware.call_sync("zfs.snapshot.delete", name) - except Exception as e: # noqa: BLE001 - already gone is fine - if logger: - logger.warning( - "truecloud-patch: could not delete snapshot %s: %r", name, e - ) + live = middleware.call_sync( + "zfs.snapshot.query", [["name", "^", dataset]], {"select": ["name"]} + ) + except Exception: # noqa: BLE001 - cannot refine; trust the delete's verdict + return list(failed) + live = {s["name"] for s in live} + return [n for n in failed if n in live] + + remaining = list(names) + for attempt in range(attempts): + failed = [] + for name in remaining: + try: + middleware.call_sync("zfs.snapshot.delete", name) + except Exception: # noqa: BLE001 - busy, or already gone; sorted out below + failed.append(name) + + remaining = confirm_gone(failed) + if not remaining: + return [] + + if attempt < attempts - 1: + # EBUSY is the automount expiring. Release again (anything that walks + # .zfs can re-automount a snapshot) and give it a moment. + release_snapdirs(snapname) + sleep(5) + + for name in remaining: + if logger: + logger.warning( + "truecloud-patch: could not delete snapshot %s after %d attempts " + "(still busy?) -- it will be reclaimed on the next run", + name, attempts, + ) + return remaining def stage_nested(middleware, path, snapshot, base_dataset, base_mountpoint, @@ -541,8 +639,18 @@ def stage_nested(middleware, path, snapshot, base_dataset, base_mountpoint, apply_plan(mounts) verify_staged(mounts) except Exception: + # Tear down the mounts, but KEEP the sidecar. + # + # The caller (SNAPSHOT_BLOCK) sweeps the snapshot tree on the way out, and if + # any of it is still busy it will survive -- and the sidecar is the only record + # that it exists. Removing it here would orphan those snapshots permanently. + # + # The asymmetry is deliberate: a sidecar left behind when the tree is already + # gone is harmless (the next run tries to delete a tree that is not there, + # finds nothing, and moves on), while a sidecar removed while the tree still + # exists is unrecoverable. Only a confirmed-clean sweep removes it -- see + # cleanup_task(). teardown(staging_root) - _remove_sidecar(staging_root) raise if logger: @@ -569,8 +677,32 @@ def cleanup_task(middleware, task_name, logger=None): for err in errors: logger.warning("truecloud-patch: staging teardown: %s", err) - if snapshot is not None: - delete_snapshot_tree(middleware, snapshot, logger=logger) + if snapshot is None: + _remove_sidecar(staging_root) + return + + survivors = delete_snapshot_tree(middleware, snapshot, logger=logger) + + # KEEP the sidecar if anything survived. It is the only record that those + # snapshots exist, and removing it orphans them permanently. + # + # That is not theoretical: on a real 256-snapshot tree, three snapshots were still + # pinned by ZFS's own .zfs/snapshot automount (which lingers for 300s after the + # last read), failed to delete with "dataset is busy", and the sidecar was removed + # anyway -- so nothing would ever have reclaimed them. A small leak, but one that + # grows by a few snapshots on every single run, forever. + # + # Left in place, the next run's stage_nested() sees a stale sidecar naming a + # different snapshot and sweeps that tree first -- by which time the automounts are + # long gone and the delete succeeds. + if survivors: + if logger: + logger.warning( + "truecloud-patch: %d snapshot(s) from %s could not be deleted; " + "keeping the sidecar so the next run reclaims them", + len(survivors), snapshot, + ) + return _remove_sidecar(staging_root) diff --git a/tests/test_truecloud_nested.py b/tests/test_truecloud_nested.py index ea7e418..4f18149 100644 --- a/tests/test_truecloud_nested.py +++ b/tests/test_truecloud_nested.py @@ -348,7 +348,14 @@ class TestStageNestedOrdering: assert mw.snapshots == [], "the crashed run's snapshot tree must be reclaimed" - def test_sidecar_is_removed_when_staging_fails(self, tmp_path, monkeypatch): + def test_sidecar_is_KEPT_when_staging_fails(self, tmp_path, monkeypatch): + # The caller sweeps the snapshot tree on the way out, and anything still busy + # SURVIVES that sweep -- with the sidecar as its only record. Removing the + # sidecar here would orphan those snapshots permanently. + # + # The asymmetry is the point: a sidecar left behind when the tree is already + # gone costs one no-op delete on the next run; a sidecar removed while the tree + # still exists is unrecoverable. import truecloud_nested as tn monkeypatch.setattr(tn, "STAGING_BASE", str(tmp_path)) @@ -361,7 +368,12 @@ class TestStageNestedOrdering: "cloud_backup-5", DATASETS, ) - assert not os.path.exists(sidecar_for(root)) + assert os.path.exists(sidecar_for(root)), ( + "sidecar removed on staging failure — any snapshot the caller's sweep " + "cannot delete is now orphaned forever" + ) + with open(sidecar_for(root), encoding="utf-8") as fh: + assert fh.read().strip() == "Tap@snap" class TestCleanupTask: @@ -609,3 +621,165 @@ class TestStagingRootFor: # os.path.join(BASE, "..") normalises to /run — teardown would rmdir it. root = staging_root_for(name) assert os.path.normpath(root).startswith("/run/truecloud-nested/") + + +class TestZfsAutomountKeepsSnapshotsBusy: + """"dataset is busy" is EXPECTED, TRANSIENT, and used to orphan snapshots forever. + + Reading `/.zfs/snapshot//` makes ZFS **automount** that snapshot, + and it stays mounted for zfs_expire_snapshot seconds (300 by default) after the + last access. teardown() unmounts OUR bind mounts, but not the automount underneath + -- so `zfs destroy` refuses with EBUSY for everything restic read recently. + + Observed on a real 256-snapshot tree: 253 swept cleanly, and the 3 datasets restic + had touched last failed with "dataset is busy". cleanup_task then removed the + sidecar anyway, so nothing would ever reclaim them. A few snapshots leaked per run, + forever. + """ + + MOUNTS = ( + "tmpfs /run tmpfs rw 0 0\n" + "Tap/apps/prometheus /mnt/Tap/apps/prometheus/.zfs/snapshot/snap1 zfs ro 0 0\n" + "Tap/apps/standing/data /mnt/Tap/apps/standing/data/.zfs/snapshot/snap1 zfs ro 0 0\n" + "Tap /mnt/Tap/.zfs/snapshot/snap1 zfs ro 0 0\n" + "Tap/other /mnt/Tap/other/.zfs/snapshot/OTHER zfs ro 0 0\n" + ) + + def _mounts_file(self, tmp_path): + p = tmp_path / "mounts" + p.write_text(self.MOUNTS) + return str(p) + + def test_it_finds_the_automounts_for_this_snapshot_only(self, tmp_path): + import truecloud_nested as tn + found = tn.snapdir_automounts("snap1", mounts_file=self._mounts_file(tmp_path)) + assert "/mnt/Tap/other/.zfs/snapshot/OTHER" not in found + assert len(found) == 3 + + def test_deepest_first(self, tmp_path): + # A child's automount must be released before its parent's. + import truecloud_nested as tn + found = tn.snapdir_automounts("snap1", mounts_file=self._mounts_file(tmp_path)) + assert found[-1] == "/mnt/Tap/.zfs/snapshot/snap1" + + def test_release_snapdirs_unmounts_them(self, tmp_path): + import truecloud_nested as tn + called = [] + + class R: + returncode = 0 + stderr = "" + + def runner(cmd): + called.append(cmd) + return R() + + errs = tn.release_snapdirs("snap1", runner=runner, + mounts_file=self._mounts_file(tmp_path)) + assert errs == [] + assert all(c[0] == "umount" for c in called) + assert len(called) == 3 + + +class BusyMiddleware(FakeMiddleware): + """Deletes fail with EBUSY until `busy_until_attempt` passes -- like a ZFS + automount expiring.""" + + def __init__(self, snapshots, busy, busy_for=2): + super().__init__(snapshots) + self.busy = set(busy) + self.busy_for = busy_for + self.attempts = 0 + + def call_sync(self, method, *args): + if method == "zfs.snapshot.delete": + name = args[0] + opts = args[1] if len(args) > 1 else {} + if opts.get("recursive"): + raise RuntimeError("cannot destroy snapshot: dataset is busy") + if name in self.busy: + self.attempts += 1 + if self.attempts <= self.busy_for * len(self.busy): + raise RuntimeError(f"cannot destroy '{name}': dataset is busy") + return super().call_sync(method, *args) + + +class TestDeleteRetriesAndReportsSurvivors: + def test_a_transient_busy_is_retried_and_wins(self, monkeypatch): + import truecloud_nested as tn + monkeypatch.setattr(tn, "release_snapdirs", lambda *a, **k: []) + + mw = BusyMiddleware( + ["Tap@snap", "Tap/apps@snap", "Tap/apps/prometheus@snap"], + busy=["Tap/apps/prometheus@snap"], busy_for=1, + ) + survivors = tn.delete_snapshot_tree(mw, "Tap@snap", sleep=lambda _s: None) + assert survivors == [] + assert mw.snapshots == [] + + def test_a_permanently_busy_snapshot_is_REPORTED_not_swallowed(self, monkeypatch): + import truecloud_nested as tn + monkeypatch.setattr(tn, "release_snapdirs", lambda *a, **k: []) + + mw = BusyMiddleware( + ["Tap@snap", "Tap/apps/prometheus@snap"], + busy=["Tap/apps/prometheus@snap"], busy_for=99, + ) + survivors = tn.delete_snapshot_tree(mw, "Tap@snap", sleep=lambda _s: None) + assert survivors == ["Tap/apps/prometheus@snap"] + assert mw.snapshots == ["Tap/apps/prometheus@snap"] + + def test_the_automounts_are_released_before_deleting(self, monkeypatch): + import truecloud_nested as tn + order = [] + monkeypatch.setattr(tn, "release_snapdirs", + lambda name, **k: order.append(("release", name)) or []) + mw = FakeMiddleware(["Tap@snap"]) + real = mw.call_sync + + def spy(method, *args): + order.append((method, args[0] if args else None)) + return real(method, *args) + + mw.call_sync = spy + tn.delete_snapshot_tree(mw, "Tap@snap", sleep=lambda _s: None) + assert order[0] == ("release", "snap"), order + + +class TestSidecarSurvivesAnIncompleteSweep: + def test_the_sidecar_is_KEPT_when_snapshots_could_not_be_deleted( + self, tmp_path, monkeypatch + ): + # It is the ONLY record those snapshots exist. Removing it orphans them + # permanently -- which is exactly what happened on the real box. + import truecloud_nested as tn + + monkeypatch.setattr(tn, "STAGING_BASE", str(tmp_path)) + monkeypatch.setattr(tn, "release_snapdirs", lambda *a, **k: []) + root = tn.staging_root_for("cloud_backup-5") + os.makedirs(root, exist_ok=True) + with open(sidecar_for(root), "w", encoding="utf-8") as fh: + fh.write("Tap@snap") + + mw = BusyMiddleware(["Tap@snap", "Tap/apps/prometheus@snap"], + busy=["Tap/apps/prometheus@snap"], busy_for=99) + monkeypatch.setattr(tn, "delete_snapshot_tree", + lambda m, s, logger=None: ["Tap/apps/prometheus@snap"]) + + tn.cleanup_task(mw, "cloud_backup-5") + assert os.path.exists(sidecar_for(root)), ( + "sidecar removed despite survivors — they are now orphaned forever" + ) + + def test_the_sidecar_is_removed_on_a_clean_sweep(self, tmp_path, monkeypatch): + import truecloud_nested as tn + + monkeypatch.setattr(tn, "STAGING_BASE", str(tmp_path)) + root = tn.staging_root_for("cloud_backup-5") + os.makedirs(root, exist_ok=True) + with open(sidecar_for(root), "w", encoding="utf-8") as fh: + fh.write("Tap@snap") + + monkeypatch.setattr(tn, "delete_snapshot_tree", lambda m, s, logger=None: []) + tn.cleanup_task(FakeMiddleware(), "cloud_backup-5") + assert not os.path.exists(sidecar_for(root))