From 0fc994f676835342b136a99993c3f59d503ebae5 Mon Sep 17 00:00:00 2001 From: sudolulo Date: Wed, 26 Aug 2026 04:36:23 +0000 Subject: [PATCH] Re-apply and verify the patch before the deferred restart MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Patching at PREINIT and restarting minutes later is only sound while the patched files are still on the live path when middlewared re-imports them, and PREINIT cannot guarantee that. The overlay sits inside /usr, so anything that remounts that hierarchy detaches it — a systemd-sysext merge/refresh from another PREINIT hook, or middlewared's own docker.configure_nvidia at runtime. Init scripts run sequentially in id order, so a hook registered after this one always wins, and reordering them would not help because docker.configure_nvidia fires long after PREINIT is done. Observed on 25.10.6: the overlay was mounted at 16:41:56, a sysext refresh unmerged and remerged /usr four seconds later, and the deferred restart at 16:47:24 loaded stock modules. Every B2 cloud_backup task then failed with NotImplementedError for nineteen hours across four scheduled runs while apply.log and hook_status.json both reported the patch active. wait_restart.sh now re-applies immediately before restarting — after boot has settled, which is also after every sysext merge and docker nvidia configuration — verifies the marker is on the live path, restarts, and verifies again, retrying once. It is no longer exec'd, so something can run after the restart to find out what it loaded. apply.sh records the resolved middlewared directory in .mw_dir for that check, and honours TRUECLOUD_REAPPLY so the re-apply pass does not schedule a second restart. _ensure_writable treated "one of our overlays is listed here" as "already done", but it only reaches that check when the directory is not writable, and a live overlay of ours always is — a shadowed overlay was indistinguishable from a healthy one. It is now detached and re-mounted, reusing the upperdir so files patched earlier in the boot survive, with a fresh workdir and a retry on a private one, since overlayfs refuses a workdir a detached mount still holds. Add a CRITICAL hourly alert for the case none of this can prevent: the patch being on disk but not in the running process. apply.log can only report the first. The alert asks the second question from inside middlewared, where the patch's own stamps make it exact, and checks both halves since either can go missing alone. It stays quiet when the kill switch is set or the providers module has been retired as native, and is not muted by update_alerts_disabled. wait_restart.sh also logs to apply.log now: journald retention on a busy box is easily shorter than the interval between reboots, and the boot that caused this had already rotated away by the time it was investigated. --- .gitignore | 4 + CHANGELOG.md | 56 +++++++++ README.md | 11 ++ docs/how-it-works.md | 38 ++++-- docs/recovery.md | 35 +++++- patch/alert_source.py | 102 ++++++++++++++++ patch/apply.sh | 57 ++++++++- patch/wait_restart.sh | 90 +++++++++++++- tests/test_not_loaded_alert.py | 210 +++++++++++++++++++++++++++++++++ tests/test_wait_restart.py | 160 +++++++++++++++++++++++++ uninstall.sh | 5 + 11 files changed, 750 insertions(+), 18 deletions(-) create mode 100644 tests/test_not_loaded_alert.py create mode 100644 tests/test_wait_restart.py diff --git a/.gitignore b/.gitignore index 006be31..9382a4a 100644 --- a/.gitignore +++ b/.gitignore @@ -3,6 +3,10 @@ /apply.log.1 /apply.log.2 /hook_status.json +# The resolved middlewared directory, recorded by apply.sh so wait_restart.sh can +# check whether the patched modules are still on the live path without +# re-deriving site-packages. +/.mw_dir /disabled /nested_snapshots_enabled # Written by apply.sh when a module's assumptions no longer fit the installed diff --git a/CHANGELOG.md b/CHANGELOG.md index 39c23b2..09e8ceb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -39,6 +39,62 @@ worse than no alert, because one day it carries a security fix. ### Fixed +- **The patch survived being applied and then silently stopped existing, because + something else remounted `/usr` four seconds later.** On a box running + TrueNAS 25.10.6 the boot of 2026-08-19 went: 16:41:56 `apply.sh` mounts its + overlay on `/usr/lib/python3/dist-packages`, patches `b2.py`/`restic.py`, logs + every step `OK`; **16:42:00** a second PREINIT hook runs `systemd-sysext + refresh` over `/usr` — `Unmerged '/usr'.` / `Merged extensions into '/usr'.` — + and our overlay, which lives *inside* that hierarchy, is torn off with it; + 16:47:24 our own deferred restart fires exactly as designed and middlewared + imports the **stock** modules. Every B2 TrueCloud Backup task then failed with + `NotImplementedError` from stock `rclone/base.py` for nineteen hours, across + four scheduled runs, while `apply.log` and `hook_status.json` both said the + patch was active. + + Nothing in the patch was wrong, which is the point: applying at PREINIT and + restarting later is only sound if the patched files are still on the live path + when middlewared re-imports them, and **that is not something PREINIT can + guarantee**. Init scripts run sequentially in id order, so any hook registered + after ours always wins. Worse, hook ordering cannot fix it either — + middlewared's own `docker.configure_nvidia` merges a sysext over `/usr` at + *runtime*, long after every PREINIT hook is finished. + + So the deferred restart no longer trusts the PREINIT pass. `wait_restart.sh` + now re-applies immediately before it restarts middlewared — after boot has + settled, which is also after every sysext merge and docker nvidia + configuration — verifies the marker is genuinely on the live path, restarts, + and verifies again, retrying once if the patch was torn off in between. It is + no longer `exec systemctl try-restart middlewared`, because something has to + run afterwards to find out what that restart actually loaded. + + Two supporting fixes fell out of the same failure. `_ensure_writable` treated + "one of our overlays is listed on this directory" as "already done" — but it + only ever reaches that check when the directory is **not** writable, and a live + overlay of ours always is. A shadowed overlay was therefore indistinguishable + from a healthy one; it is now detached and re-mounted, reusing the same + upperdir so everything patched earlier in the boot reappears intact, with a + fresh workdir because overlayfs refuses one left behind by a detached mount. + +- **middlewared now says so when it is running stock.** The gap that let this + cost nineteen hours was not the remount, it was that nothing could tell the + difference between "patched on disk" and "patched in the running process". + `apply.log` can only ever report the first. A new CRITICAL alert asks the + second question from inside middlewared, hourly, where it is exact: the patch + stamps the objects it replaces, so a missing stamp means this interpreter + imported stock code. It checks both halves — `restic.py`'s `_truecloud_patched` + marker and whether `B2RcloneRemote.get_restic_config` is still the base class's + — since either can go missing alone. It stays quiet when the kill switch is + set or the providers module has been retired as native, and it is deliberately + **not** silenced by `update_alerts_disabled`: that mutes release notifications, + not a broken backup path. + + Boot-time diagnosis also no longer depends on the journal. `wait_restart.sh` + logged only to the journal, and journald retention on a busy box is easily + shorter than the interval between reboots — the 2026-08-19 boot had already + rotated away by the time it was investigated. It now writes to `apply.log` + alongside everything else. + - **The next maintenance release was never checked, and it is the one that reaches users.** Shipped versions were discovered from `TS-*` tags and unreleased ones from `release/*` branches carrying `-BETA`/`-RC`. A branched-but-untagged *maintenance* diff --git a/README.md b/README.md index 3474fb1..be3eceb 100644 --- a/README.md +++ b/README.md @@ -156,6 +156,17 @@ alert, which both take the newest plain `vX.Y.Z` tag. That is what lets debuggin happen in `-rc` tags instead of in your notification bell — see [Releasing](docs/releasing.md). +**A second alert reports the patch not being loaded**, and this one you cannot +turn off with `--no-update-alerts` — it is CRITICAL, hourly, and it means B2/S3 +backup tasks are about to fail. Being patched *on disk* and being patched *in the +running middlewared* are different facts, and only middlewared can answer the +second one: the patch stamps the objects it replaces, so a missing stamp means +the process imported stock code. It fires if something detaches the patch overlay +(a `systemd-sysext` merge over `/usr`, for instance) and the self-healing re-apply +in the deferred restart could not put it back. `bash install.sh` clears it. It +stays quiet when the kill switch is set, or when the providers module has been +retired because TrueNAS went native. + The changelog is read from whichever forge `origin` points at, derived from the remote rather than hard-coded. That is not cosmetic: when the changelog cannot be read, the alert deliberately fires **anyway** rather than risk hiding a security diff --git a/docs/how-it-works.md b/docs/how-it-works.md index ef2ca0a..b53ebd6 100644 --- a/docs/how-it-works.md +++ b/docs/how-it-works.md @@ -74,22 +74,46 @@ Two different things must survive two different events: and creates a transient systemd unit (`truecloud-mw-restart`, via `systemd-run --no-block`) running `patch/wait_restart.sh` — detached so it cannot disrupt the remainder of the boot sequence. -5. **Once boot has settled, middlewared restarts once** and imports the - patched modules from the overlay. `wait_restart.sh` holds the restart until - the systemd boot job queue has drained (so in-flight `ix-*` units like - `ix-reporting` finish first) *and* middlewared's docker/apps startup has - reached a terminal state — plain unit ordering cannot see either, and - restarting middlewared while they run kills apps and dashboard reporting +5. **Once boot has settled, the patch is re-applied and middlewared restarts + once**, importing the patched modules from the overlay. `wait_restart.sh` + holds the restart until the systemd boot job queue has drained (so in-flight + `ix-*` units like `ix-reporting` finish first) *and* middlewared's docker/apps + startup has reached a terminal state — plain unit ordering cannot see either, + and restarting middlewared while they run kills apps and dashboard reporting for the whole boot. S3/B2 backup support is then active until the next reboot, when the cycle repeats. + The **re-apply** in that sentence is load-bearing, not a safety blanket. The + overlay from step 3 sits *inside* `/usr`, so anything that remounts that + hierarchy detaches it, and two ordinary things do exactly that after our hook + has finished: another PREINIT script running `systemd-sysext merge`/`refresh` + over `/usr` (an out-of-tree nvidia driver, say), and middlewared's own + `docker.configure_nvidia` when it brings docker up. Init scripts run + sequentially in id order, so a hook registered after ours always wins — and + ordering them differently would still not help, because `docker.configure_nvidia` + fires at runtime. `wait_restart.sh` therefore re-runs `apply.sh` at the point + where boot has settled and every such remount is behind it, re-mounting the + overlay if it was torn off (same upper layer, so files patched in step 3 + reappear intact), then verifies the patch is really on the live path, restarts, + and verifies again — retrying once if it was lost in between. + + This is the failure that made it necessary: on 2026-08-19 the overlay was + mounted at 16:41:56 and a sysext refresh unmerged and remerged `/usr` four + seconds later. The restart at 16:47:24 loaded stock modules, and every B2 + backup failed for nineteen hours while `apply.log` said `OK` — because + `apply.log` can only report what was written to disk, never what the restart + imported. That second question is now asked from inside middlewared by an + hourly CRITICAL alert (see [Update alerts](../README.md#update-alerts)). + What you will observe: one middlewared restart shortly after every boot (a brief web UI/API blip; running services are unaffected). Between steps 3 and 5 there is a short window — typically well under a minute — where the UI already shows S3/B2 (the JS bundle is read from disk per request) but the backend is still stock. A backup job that fires inside that window fails once with `NotImplementedError` and succeeds on its next run; see -[Troubleshooting](recovery.md) if it persists beyond boot. +[Troubleshooting](recovery.md) if it persists beyond boot. If the backend is +still stock an hour after boot, middlewared raises the "installed but NOT +loaded" alert rather than leaving you to notice via a failed backup. Manual runs of `bash patch/apply.sh` never trigger the restart — that only happens in boot context. `install.sh` and `recover.sh` perform their own diff --git a/docs/recovery.md b/docs/recovery.md index 03c3c50..546d68e 100644 --- a/docs/recovery.md +++ b/docs/recovery.md @@ -120,8 +120,9 @@ If a module shows `[FAIL]`: The traceback ends in `rclone/base.py` → `raise NotImplementedError` and contains no `_tc_` frames: the running middlewared is executing stock code. -Either the deferred restart never fired, or the patch never landed on disk -this boot. Diagnose in this order: +Either the deferred restart never fired, the patch never landed on disk this +boot, or it landed and was then torn off before the restart. Diagnose in this +order: ```bash # Did apply.sh run this boot, at which version, and did it schedule the restart? @@ -130,11 +131,21 @@ tail -40 /mnt/tank/truenas-truecloud-patch/apply.log # Full check — compares the running process against the patch timestamp python3 /mnt/tank/truenas-truecloud-patch/patch/create_task.py verify -# Did the deferred restart unit run, fail, or never get created? -systemctl status truecloud-mw-restart.service +# What the deferred restart did -- re-apply, restart, and what it verified. +# apply.log is the durable record; journald retention on a busy box is often +# shorter than the gap between reboots, so the journal may have nothing left. +grep wait_restart /mnt/tank/truenas-truecloud-patch/apply.log | tail -20 journalctl -u truecloud-mw-restart.service --no-pager | tail -20 + +# Did something remount /usr and detach the patch overlay? +systemd-sysext status +findmnt -o TARGET,SOURCE /usr/lib/python3/dist-packages ``` +`systemctl status truecloud-mw-restart.service` reporting *"could not be +found"* is **normal** — the unit is transient and is collected once it exits. +It is not evidence that the restart was skipped. + - `verify` reports the process started **before** the patch → the restart didn't happen. `systemctl restart middlewared` fixes it immediately; the journal output above tells you why it was missed. @@ -145,6 +156,22 @@ journalctl -u truecloud-mw-restart.service --no-pager | tail -20 - `apply.log` header shows `[v0.0.3]` or older → update: `git pull && bash install.sh` (v0.0.4 fixed patches not loading after reboot). +- `apply.log` says the patch applied, but `findmnt` shows no `truecloud-mw` + overlay on the dist-packages path → something remounted `/usr` after our + PREINIT hook and detached it. `systemd-sysext status` names the culprit if it + is a sysext (the `SINCE` column will sit a few seconds *after* the `apply.log` + timestamp). Releases from 2026-08-26 on re-apply and verify immediately before + the restart, so this should self-heal; if you are seeing it, update first. + +**TrueNAS raises "truecloud-patch is installed but NOT loaded"** + +The definitive symptom, and it does not depend on a backup failing first: the +running middlewared has stock cloud_backup modules even though the patch is +installed and its providers module is meant to be active. `bash install.sh` +re-applies and restarts. The alert clears within the hour. It is silent when the +kill switch is set or the providers module has been retired as native, and it is +deliberately not muted by `update_alerts_disabled` — that silences release +notifications, not a broken backup path. **Apply log** (check after each reboot or install): ```bash diff --git a/patch/alert_source.py b/patch/alert_source.py index 85762ad..bb3cd46 100644 --- a/patch/alert_source.py +++ b/patch/alert_source.py @@ -21,6 +21,7 @@ the way a `git fetch` from middlewared (running as root) would. import datetime import importlib.util +import json import logging import os import re @@ -77,6 +78,107 @@ class TrueCloudPatchSecurityUpdateAlertClass(AlertClass): ) +class TrueCloudPatchNotLoadedAlertClass(AlertClass): + category = AlertCategory.SYSTEM + level = AlertLevel.CRITICAL + title = "truecloud-patch is installed but NOT loaded" + text = ( + "truecloud-patch patched middlewared on disk, but this middlewared is " + "running the STOCK cloud_backup modules -- B2 and S3 TrueCloud Backup " + "tasks will fail with NotImplementedError. Something remounted /usr " + "after the patch was applied (a systemd-sysext merge, or " + "docker.configure_nvidia), detaching the patch overlay. Re-apply with: " + "bash %(dir)s/install.sh" + ) + + +class TrueCloudPatchNotLoadedAlertSource(ThreadedAlertSource): + """Does the middlewared running this check actually have the patch in it? + + This is the one question apply.log cannot answer. apply.sh reports what it + wrote to disk; whether the restart that followed imported those files is a + separate fact, and on 2026-08-19 the two disagreed silently for nineteen + hours while every B2 backup task failed. Asking from inside the process is + exact -- the patch stamps the objects it replaces, so a missing stamp means + this interpreter imported stock code. + + Deliberately NOT silenced by the update-alert marker: that mutes release + notifications, not a broken backup path. Only the patch's own kill switch + (the `disabled` file, meaning the operator turned the patch off) stops it. + """ + + schedule = IntervalSchedule(datetime.timedelta(hours=1)) + run_on_backup_node = False + + def check_sync(self): + try: + return self._check() + except Exception: + # An alert source must never take middlewared down with it. + logger.debug("truecloud-patch loaded check failed", exc_info=True) + return None + + # -- internals ------------------------------------------------------------ + + def _check(self): + if os.path.exists(os.path.join(PATCH_DIR, "disabled")): + return None + + # Only the providers module puts B2/S3 on the restic path. If it was + # never applied here, or TrueNAS went native and it was retired, then + # "not loaded" is the correct state and not a fault. + status = self._hook_status() + if not status: + return None + providers = status.get("patches", {}).get("providers", {}) + if not providers.get("active"): + return None + + if self._providers_loaded(): + return None + + return Alert( + TrueCloudPatchNotLoadedAlertClass, + {"dir": PATCH_DIR}, + key=None, + ) + + def _hook_status(self): + try: + with open(os.path.join(PATCH_DIR, "hook_status.json")) as f: + return json.load(f) + except (OSError, ValueError): + return None + + def _providers_loaded(self): + """True when THIS interpreter holds the patched provider objects. + + Two independent stamps, because the two halves are written separately + and either can be missing on its own: + + * restic.py -- apply.sh sets `_truecloud_patched` on the wrapper it + installs over `get_restic_config`. + * b2.py -- apply.sh binds a B2-specific `get_restic_config` onto + `B2RcloneRemote`. Comparing it against the base implementation is + exact and survives renames of the patch's own helper. + """ + try: + from middlewared.plugins.cloud_backup.restic import get_restic_config + except Exception: + return False + if not getattr(get_restic_config, "_truecloud_patched", False): + return False + + try: + from middlewared.rclone.base import BaseRcloneRemote + from middlewared.rclone.remote.b2 import B2RcloneRemote + except Exception: + return False + base = getattr(BaseRcloneRemote, "get_restic_config", None) + b2 = getattr(B2RcloneRemote, "get_restic_config", None) + return b2 is not None and b2 is not base + + class TrueCloudPatchUpdateAlertSource(ThreadedAlertSource): schedule = IntervalSchedule(datetime.timedelta(hours=24)) run_on_backup_node = False diff --git a/patch/apply.sh b/patch/apply.sh index 84bbf95..29f31b6 100755 --- a/patch/apply.sh +++ b/patch/apply.sh @@ -64,17 +64,45 @@ _ensure_writable() { rm -f "$dir/.truecloud-probe" return 0 fi - # Already our overlay on this exact directory from an earlier run this boot? + # Not writable, so any overlay of ours listed on this directory is a + # SHADOWED leftover rather than a working mount: something remounted the + # hierarchy above it -- a systemd-sysext merge/refresh over /usr, or + # middlewared's own docker.configure_nvidia -- and buried it. A live + # overlay of ours is always writable, so this must never be treated as + # "already done"; doing so is what let a buried overlay pass for a healthy + # one and left the backend patch on disk but never loaded. if mount | grep -qF "truecloud-${tag} on ${dir} "; then - return 0 + echo "NOTICE: a previous truecloud-${tag} overlay on $dir is shadowed --" + echo "NOTICE: the hierarchy above it was remounted. Detaching and re-mounting." + umount -l "$dir" 2>/dev/null fi + # Keep the SAME upperdir across re-mounts: it holds everything patched + # earlier this boot, so re-mounting restores those files intact instead of + # re-deriving them. The workdir is scratch and must be empty, so it is + # recreated -- a stale one left behind by a detached mount fails the mount. local upper="/run/truecloud-${tag}-upper" work="/run/truecloud-${tag}-work" - mkdir -p "$upper" "$work" + mkdir -p "$upper" + rm -rf "$work" 2>/dev/null + mkdir -p "$work" if mount -t overlay "truecloud-${tag}" \ -o "lowerdir=$dir,upperdir=$upper,workdir=$work" "$dir" 2>/dev/null; then echo "OK: Mounted writable overlay on $dir" return 0 fi + # A lazily-detached overlay releases its workdir only once its last user is + # gone, and overlayfs refuses a workdir that is still in use. That would turn + # the re-mount this function exists to perform into a hard failure, so retry + # once on a private workdir. It is scratch in /run (tmpfs) and goes away at + # the next boot; the upperdir, which holds the patched files, is unchanged. + work="/run/truecloud-${tag}-work.$$" + rm -rf "$work" 2>/dev/null + mkdir -p "$work" + if mount -t overlay "truecloud-${tag}" \ + -o "lowerdir=$dir,upperdir=$upper,workdir=$work" "$dir" 2>/dev/null; then + echo "OK: Mounted writable overlay on $dir (fresh workdir)" + return 0 + fi + rmdir "$work" 2>/dev/null echo "WARNING: overlay mount failed on $dir — backend patch will be skipped." return 1 } @@ -196,6 +224,13 @@ _tc_native_nested=$(printf '%s' "$_tc_info" | sed -n '2p') SITE_PKG=$(printf '%s' "$_tc_info" | sed -n '3p') _MW_DIR=$(printf '%s' "$_tc_info" | sed -n '4p') +# Record the resolved middlewared directory so patch/wait_restart.sh can check, +# without re-deriving any of this, whether the patched modules are still on the +# live filesystem path at the moment it restarts middlewared. +if [ -n "$_MW_DIR" ]; then + printf '%s\n' "$_MW_DIR" > "$PATCH_DIR/.mw_dir" 2>/dev/null +fi + # Nested support is opt-in; if it was never enabled, it cannot be the reason to # keep the patch alive. if [ -f "$PATCH_DIR/nested_snapshots_enabled" ]; then @@ -999,8 +1034,13 @@ fi # runs (install.sh, recovery) never trigger a restart. # # The unit runs wait_restart.sh, which blocks until boot has actually -# settled (systemd job queue drained, docker/apps state terminal) before -# restarting. systemd ordering alone (After=multi-user.target, ≤ v0.0.4) +# settled (systemd job queue drained, docker/apps state terminal), then +# RE-APPLIES this script before restarting. The re-apply is not belt-and- +# braces: our overlay lives inside /usr, and a systemd-sysext merge or +# middlewared's docker.configure_nvidia remounts /usr *after* PREINIT and +# detaches it, so what we patch here can be gone by restart time (seen +# 2026-08-19). wait_restart.sh re-mounts and re-verifies at the moment it +# matters. systemd ordering alone (After=multi-user.target, ≤ v0.0.4) # fired while ix-reporting and the docker/apps startup were still in flight # and killed both — apps and dashboard stats stayed down until the next # boot. No Type=oneshot: a oneshot's start job would hold the boot queue @@ -1015,7 +1055,12 @@ echo "--- deferred restart ---" # # "No module active at all" cannot reach here: that is the kill-switch branch # above, which exits. -if ! grep -aq middlewared "/proc/$PPID/cmdline" 2>/dev/null; then +if [ "${TRUECLOUD_REAPPLY:-0}" = "1" ]; then + # Invoked by patch/wait_restart.sh as its pre-restart re-apply pass. That + # unit already exists to do the restart and verifies the result, so + # scheduling another one here would be a loop. + echo "Re-apply pass from wait_restart.sh — that unit owns the restart." +elif ! grep -aq middlewared "/proc/$PPID/cmdline" 2>/dev/null; then echo "Manual run (parent is not middlewared) — no restart scheduled." elif [ "$_backend_ok" != "1" ]; then echo "Nothing landed on disk — no restart scheduled (nothing new to load)." diff --git a/patch/wait_restart.sh b/patch/wait_restart.sh index 325a3b7..2347998 100755 --- a/patch/wait_restart.sh +++ b/patch/wait_restart.sh @@ -27,6 +27,50 @@ # --wait` below waits for that same queue to drain — the unit would deadlock # on itself until the timeout. apply.sh schedules this with the default # service type, whose start job completes at fork. +# +# THE RE-APPLY PASS (added 2026-08-26). Applying the patch at PREINIT and +# restarting later is only sound if the patched files are still on the live +# path at the moment middlewared re-imports them. They may not be: our patch +# lives in an overlay mounted *inside* /usr, and anything that remounts the +# hierarchy above it detaches or buries that overlay. Two things on a normal +# TrueNAS box do exactly that, both AFTER our PREINIT hook has run: +# +# - `systemd-sysext merge/refresh` over /usr (an nvidia sysext, for +# instance) — `Unmerged '/usr'` then `Merged extensions into '/usr'`; +# - middlewared's own `docker.configure_nvidia`, which merges the stock +# nvidia sysext over /usr when it brings docker up. +# +# PREINIT scripts run sequentially in id order, so a hook registered after +# ours always wins the race, silently. Observed 2026-08-19: our overlay was +# mounted at 16:41:56 and a sysext refresh tore /usr down four seconds later; +# the restart at 16:47:24 then loaded stock modules and every B2 cloud_backup +# job failed for the next nineteen hours while apply.log said "OK". +# +# Ordering the hooks cannot fix this — docker.configure_nvidia re-merges at +# runtime, long after every PREINIT hook is done. So instead of trusting the +# PREINIT pass, re-apply immediately before the restart (apply.sh is +# idempotent and re-mounts a lost overlay, keeping the same upperdir so +# already-patched files survive), verify the marker is really on the live +# path, and verify again afterwards. + +PATCH_DIR="$(cd "$(dirname "$0")/.." && pwd)" +LOG="$PATCH_DIR/apply.log" + +_log() { echo "[wait_restart] $*" >> "$LOG" 2>/dev/null; } + +# Is the providers patch visible on the live filesystem path -- i.e. would a +# middlewared starting right now import it? Reads the marker apply.sh leaves +# in restic.py. Returns 0 when patched, 1 when stock, 2 when we cannot tell +# (no recorded middlewared dir yet, or the file is gone). +_patch_visible() { + local mw_dir restic_py + mw_dir=$(cat "$PATCH_DIR/.mw_dir" 2>/dev/null) + [ -n "$mw_dir" ] || return 2 + restic_py="$mw_dir/plugins/cloud_backup/restic.py" + [ -f "$restic_py" ] || return 2 + grep -q "TRUECLOUD_PATCH" "$restic_py" 2>/dev/null && return 0 + return 1 +} # 1. systemd layer: wait for the boot job queue to drain. This covers every # ix-* oneshot still activating, including ix-reporting's in-flight midclt @@ -39,6 +83,9 @@ timeout 900 systemctl is-system-running --wait > /dev/null 2>&1 # transitional states (PENDING/INITIALIZING/STOPPING/MIGRATING — see # middlewared/plugins/docker/state_utils.py). An empty answer means # midclt could not respond at all; keep waiting. Cap at 10 minutes. +# This also covers docker.configure_nvidia, the runtime /usr re-merge: +# waiting for docker to reach a terminal state means the merge that would +# bury our overlay has already happened by the time we re-apply below. for _ in $(seq 1 120); do _status=$(midclt call docker.status 2>/dev/null \ | grep -oE '"status": "[A-Z_]+"' | cut -d'"' -f4) @@ -52,4 +99,45 @@ done # queryable state (smb.configure and friends). Bounded insurance. sleep 30 -exec systemctl try-restart middlewared +# 4. Re-apply pass. Boot has settled, so every sysext merge and docker nvidia +# configuration that could bury our overlay is behind us. Re-running +# apply.sh is cheap and idempotent: it re-mounts the overlay if it was +# detached (same upperdir, so files patched at PREINIT reappear intact) +# and re-patches anything that reverted to stock. +_patch_visible +case $? in + 0) _log "providers patch still visible on the live path before restart" ;; + 1) _log "PATCH LOST since PREINIT (something remounted /usr) — re-applying" ;; + *) _log "cannot confirm patch state before restart — re-applying anyway" ;; +esac + +TRUECLOUD_REAPPLY=1 /bin/bash "$PATCH_DIR/patch/apply.sh" + +if ! _patch_visible; then + _log "WARNING: patch is STILL not on the live path after the re-apply pass;" + _log "WARNING: restarting anyway, but middlewared will load stock modules." +fi + +# 5. The restart itself. +systemctl try-restart middlewared + +# 6. Verify what the restart actually loaded, and retry once if the patch was +# torn off in the window between the re-apply and the restart. A silent +# "on disk but never loaded" is the exact failure this whole script exists +# to prevent, so it must never pass unreported. +if _patch_visible; then + _log "OK: providers patch present on the live path across the restart" +else + _log "patch missing again after the restart — one more re-apply and restart" + TRUECLOUD_REAPPLY=1 /bin/bash "$PATCH_DIR/patch/apply.sh" + systemctl try-restart middlewared + if _patch_visible; then + _log "OK: providers patch loaded after the second attempt" + else + _log "ERROR: the patch could not be kept on the live path. TrueNAS is" + _log "ERROR: running STOCK cloud_backup — B2/S3 backup tasks will fail." + _log "ERROR: middlewared raises the 'not loaded' alert for this." + fi +fi + +_log "=== deferred restart complete ===" diff --git a/tests/test_not_loaded_alert.py b/tests/test_not_loaded_alert.py new file mode 100644 index 0000000..8435de1 --- /dev/null +++ b/tests/test_not_loaded_alert.py @@ -0,0 +1,210 @@ +"""Behavioural tests for the "installed but NOT loaded" alert. + +apply.log can only report what was written to disk. Whether the middlewared that +restarted afterwards actually imported those files is a different fact, and when +the two disagree nothing else notices: on 2026-08-19 every B2 backup failed for +nineteen hours while the log said OK. This alert is the only thing that closes +that gap, so it is tested against real objects rather than by reading source. + +The middlewared package does not exist off-box, so the modules the alert source +imports are stubbed here. +""" + +import importlib.util +import json +import os +import sys +import types + +import pytest + +ALERT_SRC = os.path.join(os.path.dirname(__file__), "..", "patch", "alert_source.py") + + +class _StubAlertClass: + pass + + +class _StubThreadedAlertSource: + pass + + +class _StubAlert: + def __init__(self, klass, args=None, key=None): + self.klass = klass + self.args = args + self.key = key + + +def _module(name): + mod = types.ModuleType(name) + sys.modules[name] = mod + return mod + + +@pytest.fixture +def alert_source(monkeypatch, tmp_path): + """Load patch/alert_source.py against stubbed middlewared modules.""" + for name in list(sys.modules): + if name == "middlewared" or name.startswith("middlewared."): + monkeypatch.delitem(sys.modules, name, raising=False) + + _module("middlewared") + _module("middlewared.alert") + base = _module("middlewared.alert.base") + base.Alert = _StubAlert + base.AlertClass = _StubAlertClass + base.ThreadedAlertSource = _StubThreadedAlertSource + base.AlertCategory = types.SimpleNamespace(SYSTEM="SYSTEM") + base.AlertLevel = types.SimpleNamespace( + INFO="INFO", WARNING="WARNING", CRITICAL="CRITICAL" + ) + schedule = _module("middlewared.alert.schedule") + schedule.IntervalSchedule = lambda delta: ("interval", delta) + + spec = importlib.util.spec_from_file_location("_tc_alert_source", ALERT_SRC) + mod = importlib.util.module_from_spec(spec) + spec.loader.exec_module(mod) + mod.PATCH_DIR = str(tmp_path) + return mod + + +def _write_status(tmp_path, providers_active=True): + payload = { + "patched_at": "2026-08-26T00:00:00Z", + "patches": { + "providers": {"ok": True, "active": providers_active, "detail": "x"}, + "nested_snapshots": {"ok": True, "active": True, "detail": "x"}, + }, + } + (tmp_path / "hook_status.json").write_text(json.dumps(payload)) + + +def _install_provider_modules(monkeypatch, *, restic_patched, b2_patched): + """Stub the two modules the alert inspects, in the requested state.""" + plugins = _module("middlewared.plugins") + _module("middlewared.plugins.cloud_backup") + restic = _module("middlewared.plugins.cloud_backup.restic") + + def get_restic_config(task): + return None + + if restic_patched: + get_restic_config._truecloud_patched = True + restic.get_restic_config = get_restic_config + + rclone_base = _module("middlewared.rclone.base") + _module("middlewared.rclone") + _module("middlewared.rclone.remote") + b2_mod = _module("middlewared.rclone.remote.b2") + + class BaseRcloneRemote: + def get_restic_config(self, task): + raise NotImplementedError + + class B2RcloneRemote(BaseRcloneRemote): + pass + + if b2_patched: + B2RcloneRemote.get_restic_config = staticmethod(lambda task: ("url", {})) + + rclone_base.BaseRcloneRemote = BaseRcloneRemote + b2_mod.B2RcloneRemote = B2RcloneRemote + b2_mod.BaseRcloneRemote = BaseRcloneRemote + plugins.__path__ = [] + + for name in ( + "middlewared.plugins", + "middlewared.plugins.cloud_backup", + "middlewared.plugins.cloud_backup.restic", + "middlewared.rclone", + "middlewared.rclone.base", + "middlewared.rclone.remote", + "middlewared.rclone.remote.b2", + ): + monkeypatch.setitem(sys.modules, name, sys.modules[name]) + + +def _source(alert_source): + cls = alert_source.TrueCloudPatchNotLoadedAlertSource + return cls.__new__(cls) + + +def test_no_alert_when_patch_is_loaded(alert_source, monkeypatch, tmp_path): + _write_status(tmp_path) + _install_provider_modules(monkeypatch, restic_patched=True, b2_patched=True) + assert _source(alert_source)._check() is None + + +def test_alert_when_middlewared_loaded_stock_modules(alert_source, monkeypatch, tmp_path): + """The exact 2026-08-19 state: patched on disk, stock in the process.""" + _write_status(tmp_path) + _install_provider_modules(monkeypatch, restic_patched=False, b2_patched=False) + alert = _source(alert_source)._check() + assert alert is not None + assert alert.klass is alert_source.TrueCloudPatchNotLoadedAlertClass + + +def test_alert_when_only_b2_half_is_missing(alert_source, monkeypatch, tmp_path): + # b2.py is the half that supplies B2's get_restic_config. restic.py alone + # being patched still means every B2 task raises NotImplementedError. + _write_status(tmp_path) + _install_provider_modules(monkeypatch, restic_patched=True, b2_patched=False) + assert _source(alert_source)._check() is not None + + +def test_alert_when_only_restic_half_is_missing(alert_source, monkeypatch, tmp_path): + _write_status(tmp_path) + _install_provider_modules(monkeypatch, restic_patched=False, b2_patched=True) + assert _source(alert_source)._check() is not None + + +def test_silent_when_the_kill_switch_is_set(alert_source, monkeypatch, tmp_path): + # The operator turned the patch off on purpose; stock is the intended state. + _write_status(tmp_path) + (tmp_path / "disabled").write_text("") + _install_provider_modules(monkeypatch, restic_patched=False, b2_patched=False) + assert _source(alert_source)._check() is None + + +def test_silent_when_providers_module_is_retired(alert_source, monkeypatch, tmp_path): + # TrueNAS went native for B2: not loading our providers patch is correct. + _write_status(tmp_path, providers_active=False) + _install_provider_modules(monkeypatch, restic_patched=False, b2_patched=False) + assert _source(alert_source)._check() is None + + +def test_silent_when_the_patch_was_never_applied_here(alert_source, monkeypatch, tmp_path): + # No hook_status.json at all -- nothing claims a patch, so nothing is broken. + _install_provider_modules(monkeypatch, restic_patched=False, b2_patched=False) + assert _source(alert_source)._check() is None + + +def test_update_alert_silencer_does_not_mute_a_broken_backup_path( + alert_source, monkeypatch, tmp_path +): + # update_alerts_disabled mutes release notifications. It must not hide the + # fact that TrueCloud backups are silently running stock. + _write_status(tmp_path) + (tmp_path / "update_alerts_disabled").write_text("") + _install_provider_modules(monkeypatch, restic_patched=False, b2_patched=False) + assert _source(alert_source)._check() is not None + + +def test_check_sync_never_raises(alert_source, monkeypatch, tmp_path): + """An alert source that raises is polled forever inside middlewared.""" + _write_status(tmp_path) + + def boom(self): + raise RuntimeError("provider import exploded") + + monkeypatch.setattr( + alert_source.TrueCloudPatchNotLoadedAlertSource, "_check", boom, raising=True + ) + assert _source(alert_source).check_sync() is None + + +def test_alert_is_critical_and_names_the_recovery_command(alert_source): + klass = alert_source.TrueCloudPatchNotLoadedAlertClass + assert klass.level == "CRITICAL" + assert "install.sh" in klass.text diff --git a/tests/test_wait_restart.py b/tests/test_wait_restart.py new file mode 100644 index 0000000..5eefc16 --- /dev/null +++ b/tests/test_wait_restart.py @@ -0,0 +1,160 @@ +"""The deferred restart must re-apply the patch before it restarts middlewared. + +Patching at PREINIT and restarting minutes later is only sound while the patched +files are still on the live path when middlewared re-imports them. They may not +be: the patch lives in an overlay mounted inside /usr, and anything that +remounts that hierarchy detaches it. On 2026-08-19 a systemd-sysext refresh over +/usr ran four seconds after apply.sh mounted its overlay; the deferred restart +then loaded stock modules and every B2 cloud_backup job failed for nineteen +hours while apply.log reported "OK". + +These tests pin the ordering that makes that non-recoverable failure impossible: +re-apply, verify, restart, verify again. +""" + +import os +import re +import subprocess + +import pytest + +HERE = os.path.dirname(__file__) +WAIT_RESTART = os.path.join(HERE, "..", "patch", "wait_restart.sh") +APPLY_SH = os.path.join(HERE, "..", "patch", "apply.sh") + + +def wait_restart_source(): + with open(WAIT_RESTART, encoding="utf-8") as fh: + return fh.read() + + +def apply_source(): + with open(APPLY_SH, encoding="utf-8") as fh: + return fh.read() + + +def test_wait_restart_is_executable(): + # apply.sh schedules it as `/bin/bash