Re-apply and verify the patch before the deferred restart
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.
This commit is contained in:
@@ -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
|
||||
@@ -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 <script>`, but install.sh ships exec
|
||||
# bits and a mode-only diff once blocked update.sh outright (v0.6.0).
|
||||
assert os.access(WAIT_RESTART, os.X_OK)
|
||||
|
||||
|
||||
def test_wait_restart_is_syntactically_valid():
|
||||
subprocess.run(["bash", "-n", WAIT_RESTART], check=True)
|
||||
|
||||
|
||||
def test_reapply_runs_before_the_restart():
|
||||
src = wait_restart_source()
|
||||
reapply = src.index("TRUECLOUD_REAPPLY=1")
|
||||
restart = src.index("systemctl try-restart middlewared")
|
||||
assert reapply < restart, "the re-apply pass must precede the restart"
|
||||
|
||||
|
||||
def test_restart_is_not_exec_so_verification_can_follow():
|
||||
# Up to v0.7.0 the script ended in `exec systemctl try-restart middlewared`,
|
||||
# which replaces the shell -- nothing could run afterwards. The post-restart
|
||||
# verification only exists if the restart is a plain call.
|
||||
src = wait_restart_source()
|
||||
assert not re.search(r"^\s*exec\s+systemctl", src, re.M)
|
||||
|
||||
|
||||
def test_patch_is_verified_after_the_restart():
|
||||
src = wait_restart_source()
|
||||
restart = src.index("systemctl try-restart middlewared")
|
||||
assert "_patch_visible" in src[restart:], (
|
||||
"the script must check what the restart actually loaded"
|
||||
)
|
||||
|
||||
|
||||
def test_verification_reads_the_marker_apply_sh_writes():
|
||||
# _patch_visible greps restic.py for TRUECLOUD_PATCH; apply.sh must still be
|
||||
# the thing that puts it there, or the check silently always fails.
|
||||
assert "TRUECLOUD_PATCH" in wait_restart_source()
|
||||
assert "TRUECLOUD_PATCH" in apply_source()
|
||||
|
||||
|
||||
def test_verification_uses_the_recorded_middlewared_dir():
|
||||
# wait_restart.sh must not re-derive site-packages; apply.sh records it.
|
||||
assert ".mw_dir" in wait_restart_source()
|
||||
assert ".mw_dir" in apply_source()
|
||||
|
||||
|
||||
def test_apply_sh_records_the_middlewared_dir():
|
||||
src = apply_source()
|
||||
assert re.search(r'>\s*"\$PATCH_DIR/\.mw_dir"', src), (
|
||||
"apply.sh must write the resolved middlewared dir for wait_restart.sh"
|
||||
)
|
||||
|
||||
|
||||
def test_reapply_pass_does_not_schedule_another_restart():
|
||||
# wait_restart.sh owns the restart. If the re-apply pass scheduled its own
|
||||
# transient unit, each boot would spawn restarts recursively.
|
||||
src = apply_source()
|
||||
guard = src.index('if [ "${TRUECLOUD_REAPPLY:-0}" = "1" ]; then')
|
||||
systemd_run = src.index("systemd-run --no-block")
|
||||
assert guard < systemd_run, (
|
||||
"the TRUECLOUD_REAPPLY branch must short-circuit before systemd-run"
|
||||
)
|
||||
|
||||
|
||||
def test_shadowed_overlay_is_remounted_not_accepted():
|
||||
"""A buried overlay must never pass for a healthy one.
|
||||
|
||||
_ensure_writable reaches its mount-table check only when the directory is
|
||||
NOT writable -- and a live overlay of ours is always writable. So a
|
||||
truecloud mount listed at that point is shadowed, and returning 0 there is
|
||||
exactly how a detached overlay used to masquerade as applied.
|
||||
"""
|
||||
src = apply_source()
|
||||
start = src.index("_ensure_writable()")
|
||||
end = src.index("\n}", start)
|
||||
body = src[start:end]
|
||||
|
||||
check = body.index('mount | grep -qF "truecloud-${tag} on ${dir} "')
|
||||
following = body[check:]
|
||||
# The old code did `return 0` immediately inside this branch.
|
||||
branch_end = following.index("fi")
|
||||
assert "return 0" not in following[:branch_end]
|
||||
assert "umount -l" in following[:branch_end]
|
||||
|
||||
|
||||
def test_workdir_is_recreated_before_mounting():
|
||||
# overlayfs refuses a workdir left behind by a detached mount, so a stale
|
||||
# one would turn every re-mount attempt into "overlay mount failed".
|
||||
src = apply_source()
|
||||
start = src.index("_ensure_writable()")
|
||||
end = src.index("\n}", start)
|
||||
body = src[start:end]
|
||||
assert re.search(r'rm -rf "\$work"', body)
|
||||
|
||||
|
||||
def test_upperdir_is_preserved_across_remounts():
|
||||
# The upperdir holds everything patched earlier this boot; reusing it is
|
||||
# what lets a re-mount restore those files instead of re-deriving them.
|
||||
src = apply_source()
|
||||
start = src.index("_ensure_writable()")
|
||||
end = src.index("\n}", start)
|
||||
body = src[start:end]
|
||||
assert 'rm -rf "$upper"' not in body
|
||||
|
||||
|
||||
@pytest.mark.parametrize("state", ["0", "1", "2"])
|
||||
def test_patch_visible_returns_three_distinct_states(state):
|
||||
# patched / stock / cannot-tell must stay distinguishable: "cannot tell"
|
||||
# has to re-apply rather than assume the patch is fine.
|
||||
src = wait_restart_source()
|
||||
assert f"return {state}" in src or f") return {state}" in src
|
||||
|
||||
|
||||
def test_mount_retries_on_a_private_workdir():
|
||||
"""A lazily-detached overlay can still pin the shared workdir.
|
||||
|
||||
overlayfs refuses a workdir that is in use, so without a retry the re-mount
|
||||
this whole fix depends on would fail exactly when it is most needed.
|
||||
"""
|
||||
src = apply_source()
|
||||
start = src.index("_ensure_writable()")
|
||||
end = src.index("\n}", start)
|
||||
body = src[start:end]
|
||||
assert body.count("mount -t overlay") == 2, "expected a retry mount"
|
||||
assert 'work="/run/truecloud-${tag}-work.$$"' in body
|
||||
Reference in New Issue
Block a user