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