From 0ad459e14caa4000ff8afe4062e4428565e538ef Mon Sep 17 00:00:00 2001 From: Catubba <40827997+catubba@users.noreply.github.com> Date: Mon, 3 Aug 2026 00:56:40 +0200 Subject: [PATCH] fix(backend): resolve the nine findings of the backend-block review The three silent ones first. A 0.9 config that fails to convert used to boot an empty config that looks exactly like a fresh install: the reason now reaches the UI (GET /api/status.config_error), the activity log and an ERROR line, and the .bak parachute is written on the failure branch too, so a later save from the Advanced tab cannot destroy the original. "PBS left powered on" was wrong in both directions -- every successful run against an always-on PBS warned, and a sync route that left its target awake did not. lease.release() returned one False for four situations, only two of which cost power; it now returns a ReleaseOutcome that names the reason, which becomes both the POWEROFF step's detail and RunContext.left_on. The interrupted-run path keeps a step-derived rule, now paired per device and filtered by managed_power. 422 bodies echoed the whole config, secrets included: a config-level validator raises at loc=(), so pydantic attached every token, the secret key, the password hash, the SMTP and bot tokens as the error's input. One helper with include_input=False now serves all three config-shaped 422 sites. Also: a redaction placeholder with nothing to resolve against is rejected instead of silently clearing the credential (a renamed device id, or a create from a copied body); the ad-hoc "Run verify" asks for outdated_after=0, since None meant "only never-verified" and skipped exactly the snapshots the button exists for; the manual power-off holds the single-run lock so it cannot cut a vzdump that started in the check-then-act gap; _current_run_id is cleared when a run ends, so a stop landing between two runs cannot hit the wrong one; and the pre-migration .bak is chmod 0600 like every other secret-bearing file. Tests: 617 passed, 2 skipped. Every finding was reproduced against the real code before the fix, and each new test confirmed failing on the pre-fix code. --- backend/app/api/_config_edit.py | 24 ++++++- backend/app/api/config.py | 8 +-- backend/app/api/devices.py | 57 +++++++++++----- backend/app/api/status.py | 7 ++ backend/app/config.py | 64 ++++++++++++++---- backend/app/config_migrate.py | 15 ++++- backend/app/jobs/lease.py | 47 ++++++++++--- backend/app/jobs/route_cycle.py | 8 ++- backend/app/jobs/service.py | 36 ++++++---- backend/app/main.py | 6 ++ backend/app/notify/messages.py | 76 +++++++++++++++------ backend/tests/test_api.py | 9 +++ backend/tests/test_api_devices.py | 63 +++++++++++++++++- backend/tests/test_config.py | 25 +++++++ backend/tests/test_config_migrate.py | 36 +++++++++- backend/tests/test_lease.py | 24 +++---- backend/tests/test_notify.py | 99 ++++++++++++++++------------ backend/tests/test_queue.py | 99 +++++++++++++++++++++++++++- backend/tests/test_service.py | 17 +++++ 19 files changed, 578 insertions(+), 142 deletions(-) diff --git a/backend/app/api/_config_edit.py b/backend/app/api/_config_edit.py index 426e35f..3923a02 100644 --- a/backend/app/api/_config_edit.py +++ b/backend/app/api/_config_edit.py @@ -21,6 +21,25 @@ from ..core.config_store import ConfigStore from ..core.scheduler import Scheduler, validate_cron +def validation_error(exc: ValidationError) -> HTTPException: + """A 422 carrying pydantic's error list — **without** the values that failed. + + ``include_input=False`` is the whole point: a ``model_validator(mode="after")`` on + ``Config`` raises at ``loc=()``, so pydantic attaches the entire validated config as the + error's ``input``. Serialised, that ships every API token, ``app.secret_key``, the + password hash, the SMTP password and the bot token to the browser's network tab and any + proxy log in between. The config-level cross-checks (a route pointing at a device that + doesn't exist, an External route onto an unmanaged PBS) are ordinary user mistakes, so + this is a body users really do see. ``include_url`` only drops a docs link. + + Every config-shaped 422 goes through here so a new endpoint inherits the safe default. + """ + return HTTPException( + status_code=422, # the literal avoids the deprecated HTTP_422_UNPROCESSABLE_ENTITY + detail=jsonable_encoder(exc.errors(include_input=False, include_url=False)), + ) + + def save_section( store: ConfigStore, scheduler: Scheduler, section: str, value: list[dict[str, Any]] ) -> Config: @@ -34,9 +53,8 @@ def save_section( try: new_config = Config.model_validate(raw) except ValidationError as exc: - # 422 mirrors FastAPI's own body-validation responses (the literal avoids the - # deprecated HTTP_422_UNPROCESSABLE_ENTITY constant name). - raise HTTPException(status_code=422, detail=jsonable_encoder(exc.errors())) from exc + # 422 mirrors FastAPI's own body-validation responses. + raise validation_error(exc) from exc check_route_crons(new_config, store.config) try: store.replace(new_config) diff --git a/backend/app/api/config.py b/backend/app/api/config.py index eb2e5dc..dd19fcb 100644 --- a/backend/app/api/config.py +++ b/backend/app/api/config.py @@ -11,7 +11,6 @@ from typing import Any import yaml from fastapi import APIRouter, Depends, HTTPException, status -from fastapi.encoders import jsonable_encoder from pydantic import BaseModel, ValidationError from ..config import ( @@ -25,7 +24,7 @@ from ..config import ( from ..connectors.errors import WolError from ..connectors.wol import normalize_mac from ..core.config_store import ConfigStore -from ._config_edit import check_route_crons +from ._config_edit import check_route_crons, validation_error from .deps import Scheduler, get_config_store, get_scheduler, require_auth router = APIRouter(dependencies=[Depends(require_auth)], tags=["config"]) @@ -66,9 +65,8 @@ def _apply_config( try: new_config = Config.model_validate(merged) except ValidationError as exc: - # 422 to mirror FastAPI's own body-validation responses (literal avoids the - # deprecated HTTP_422_UNPROCESSABLE_ENTITY constant name). - raise HTTPException(status_code=422, detail=jsonable_encoder(exc.errors())) from exc + # 422 to mirror FastAPI's own body-validation responses. + raise validation_error(exc) from exc # Reject a newly-set unparseable route cron before it can be persisted (BE-B1): the # route would silently never fire, which is the failure mode hardest to notice. diff --git a/backend/app/api/devices.py b/backend/app/api/devices.py index af312d3..72827bb 100644 --- a/backend/app/api/devices.py +++ b/backend/app/api/devices.py @@ -17,15 +17,14 @@ from __future__ import annotations from typing import Any, Literal from fastapi import APIRouter, Depends, HTTPException, status -from fastapi.encoders import jsonable_encoder from pydantic import BaseModel, ValidationError -from ..config import PbsDevice, PveDevice, redact, restore_secrets_from +from ..config import PbsDevice, PveDevice, RedactionError, redact, restore_secrets_from from ..connectors.errors import ConnectorError, WolError from ..core.config_store import ConfigStore from ..db.models import RunTrigger from ..jobs import AlreadyRunningError -from ._config_edit import save_section +from ._config_edit import save_section, validation_error from .deps import ( JobService, Scheduler, @@ -101,7 +100,12 @@ def create_device( scheduler: Scheduler = Depends(get_scheduler), ) -> dict[str, Any]: section, model = _kind(kind) - device = _validate(model, body) + # Against an empty stored mapping: a *new* device has no secrets to restore, so any + # ***REDACTED*** in the body — a "duplicate this device" action, or a body copy-pasted + # from GET /api/devices — fails loudly here instead of being stored as the literal + # placeholder, which GET then re-masks so the corruption is invisible until a + # connection test fails with a 502 that gives no hint why. + device = _validate(model, _resolve(body, {})) if any(d.id == device.id for d in getattr(store.config, section)): raise HTTPException( status_code=status.HTTP_409_CONFLICT, detail=f"Device '{device.id}' already exists" @@ -124,7 +128,7 @@ def update_device( index = _find(store, section, device_id) # Resolve ***REDACTED*** against *this* device's stored values: the client only ever # echoes back a secret it didn't change. - device = _validate(model, restore_secrets_from(body, _dump(store, section)[index])) + device = _validate(model, _resolve(body, _dump(store, section)[index])) devices = _dump(store, section) devices[index] = device.model_dump(mode="python") save_section(store, scheduler, section, devices) @@ -238,19 +242,27 @@ def power( ) from exc return PowerResult(ok=True) - # Power-off. The lease is the authority on "is anything using this box": a run holding - # it would be cut off mid-vzdump. - # ponytail: a run could still take the lease in the gap between this check and the SSH - # command. Harmless in practice — the lease probes the box, finds it down and wakes it - # again — and closing it properly means holding the lease from here, which would let a - # failed HTTP request strand it. - if job_service.lease.state(pbs_id).holders: - raise HTTPException( - status_code=status.HTTP_409_CONFLICT, - detail=f"A run is using '{pbs_id}'; cannot power it off", - ) + # Power-off, under the single-run lock. `exclusive()` exists for exactly this: a run + # holds that lock for its whole life, so while we hold it none can start — and + # `power_off_now` has no idle-wait and no refcount check by design ("a click means + # now"). Without the lock the check is a check-then-act: a scheduled route starts in + # the gap, `_bring_up` probes, finds the box still up, skips the Wake-on-LAN, vzdump + # begins, and the SSH poweroff lands mid-backup. The lease's own self-healing can't + # help there — the probe has already happened. + # ponytail: the lock is held for the seconds an SSH connect takes, so a scheduled run + # firing in that window waits its turn instead of being rejected. Fine for a button. try: - job_service.lease.power_off_now(device) + with job_service.exclusive(): + # Belt and braces: a lease is only ever taken inside the lock we now hold, so + # this cannot fire in production — but it names the box when it does. + if job_service.lease.state(pbs_id).holders: + raise HTTPException( + status_code=status.HTTP_409_CONFLICT, + detail=f"A run is using '{pbs_id}'; cannot power it off", + ) + job_service.lease.power_off_now(device) + except AlreadyRunningError as exc: + raise HTTPException(status_code=status.HTTP_409_CONFLICT, detail=str(exc)) from exc except ConnectorError as exc: raise HTTPException(status_code=status.HTTP_502_BAD_GATEWAY, detail=str(exc)) from exc return PowerResult(ok=True) @@ -304,10 +316,19 @@ def run_maintenance( # --- helpers ----------------------------------------------------------------- +def _resolve(body: dict[str, Any], stored: dict[str, Any]) -> dict[str, Any]: + """Fill in the ***REDACTED*** placeholders the client echoed back, 422 if one can't be + resolved. ``stored`` is the device being edited, or ``{}`` for a create.""" + try: + return restore_secrets_from(body, stored) + except RedactionError as exc: + raise HTTPException(status_code=422, detail=str(exc)) from exc + + def _validate(model: type[PveDevice] | type[PbsDevice], body: dict[str, Any]): """Validate a device body by hand rather than as a typed parameter: the handlers are shared between the two kinds, so which model applies is only known at call time.""" try: return model.model_validate(body) except ValidationError as exc: - raise HTTPException(status_code=422, detail=jsonable_encoder(exc.errors())) from exc + raise validation_error(exc) from exc diff --git a/backend/app/api/status.py b/backend/app/api/status.py index fd53d3c..18840f7 100644 --- a/backend/app/api/status.py +++ b/backend/app/api/status.py @@ -14,6 +14,7 @@ from fastapi import APIRouter, Depends from pydantic import BaseModel from sqlalchemy.orm import Session +from .. import config as config_mod from ..core.config_store import ConfigStore from ..db import get_session from . import _probe @@ -91,6 +92,10 @@ class StatusResponse(BaseModel): pves: list[PveState] = [] pbss: list[PbsState] = [] last_run: RunSummary | None = None + #: Set when the 0.9 -> 1.0 config migration was refused at startup: the config in use + #: has no devices and no routes, so the UI must say why instead of looking like a fresh + #: install. Rendered as a persistent banner under the header. + config_error: str | None = None @router.get("/status", response_model=StatusResponse) @@ -139,6 +144,8 @@ def get_status( pves=[PveState(id=pve.id, online=pve_online.get(pve.id, False)) for pve in config.pves], pbss=[_pbs_state(pbs, pbs_probes, job_service) for pbs in config.pbss], last_run=RunSummary.of(last) if last else None, + # Read live, not captured at import: a reload after the user fixes the file clears it. + config_error=config_mod.MIGRATION_ERROR, ) diff --git a/backend/app/config.py b/backend/app/config.py index 996c0a7..b09d27c 100644 --- a/backend/app/config.py +++ b/backend/app/config.py @@ -38,6 +38,13 @@ SECRET_KEYS: frozenset[str] = frozenset( REDACTED = "***REDACTED***" +#: Why the 0.9 -> 1.0 migration was refused on the last :func:`load_config`, or ``None``. +#: A failed migration boots on a config with no devices and no routes, which looks exactly +#: like a fresh install — so the reason has to outlive the log line: ``GET /api/status`` +#: reports it to the UI and startup writes it to the activity log. Process-wide because the +#: fact is process-wide; every load clears it and decides again. +MIGRATION_ERROR: str | None = None + class _Base(BaseModel): # Reject unknown keys so typos in config.yaml surface as clear validation errors. @@ -460,6 +467,8 @@ def load_config(path: Path | None = None) -> Config: raise FileNotFoundError( f"Config file not found at {p}. Copy config.example.yaml to config.yaml." ) + global MIGRATION_ERROR + MIGRATION_ERROR = None # re-decided below; a reload after a fix must clear it with p.open("r", encoding="utf-8") as fh: raw = yaml.safe_load(fh) or {} if not isinstance(raw, dict): @@ -479,19 +488,28 @@ def _migrate_0_9(raw: dict[str, Any], path: Path) -> Config | None: """Convert a 0.9 config to the route model, back it up and save it. Returns ``None`` — meaning "carry on with the config as it is on disk" — if anything at - all goes wrong. A failed migration must never stop the app from booting (BE-B1), and it - costs nothing to defer: the 0.9 sections are still what the app reads, and the next - start will try again. + all goes wrong. A failed migration must never stop the app from booting (BE-B1). + + But it is not a harmless deferral any more: in 0.9 the app kept running on the old + sections, while in 1.0 nothing reads them, so the fallback boots a config with no + devices and no routes — indistinguishable from a fresh install, with every schedule + silently gone. Hence :data:`MIGRATION_ERROR` (surfaced by ``GET /api/status`` and the + activity log) and the ``.bak``: the user can still rewrite ``config.yaml`` from the + Advanced tab while running empty, and without the copy that would destroy the only + 0.9 config they have. """ try: cfg = Config.model_validate(config_migrate.migrate(raw)) except Exception as exc: # noqa: BLE001 — any failure here degrades to "don't migrate" - log.warning( - "config: could not convert %s to the 1.0 route model (%s); starting on the " - "existing config and leaving it untouched", - path, - exc, + global MIGRATION_ERROR + MIGRATION_ERROR = ( + f"Could not convert {path} to the 1.0 route model: {exc}. Joulenap started " + "with no devices and no routes — nothing is scheduled and no backup will run " + "until this is fixed. The file is untouched; a copy is at " + f"{path.name}{config_migrate.BACKUP_SUFFIX}." ) + log.error("config: %s", MIGRATION_ERROR) + config_migrate.write_backup(path) return None config_migrate.write_backup(path) try: @@ -661,7 +679,7 @@ def _restore_in_place(node: Any, current: Any) -> Any: for key, value in node.items(): cur = current.get(key) if isinstance(current, dict) else None if key in SECRET_KEYS: - node[key] = _unmask(value, cur) + node[key] = _unmask(value, cur, key) else: _restore_in_place(value, cur) elif isinstance(node, list): @@ -687,7 +705,15 @@ def _match(item: Any, current: Any, index: int) -> Any: return current[index] if index < len(current) else None -def _unmask(value: Any, current: Any) -> Any: +def _unmask(value: Any, current: Any, key: str = "") -> Any: + """Resolve one secret field: ``REDACTED`` -> the stored value, anything else verbatim. + + An unresolvable placeholder is an **error**, never an empty string. ``current`` is None + when the incoming item has no stored counterpart — a device whose ``id`` was renamed in + the YAML editor, or one being created — and the client is then echoing back a mask over + a secret we do not have. Turning that into ``""`` validates fine, returns 200, and + leaves the credential gone with nothing on screen to suggest it. + """ if isinstance(value, list): # List secrets (custom_urls) are write-only and all-or-nothing to avoid the # index-positional corruption of the old per-entry masking: @@ -701,7 +727,9 @@ def _unmask(value: Any, current: Any) -> Any: if not value: return [] if all(v == REDACTED for v in value): - return list(current) if isinstance(current, list) else [] + if not isinstance(current, list): + raise _unresolvable(key) + return list(current) if any(v == REDACTED for v in value): raise RedactionError( "custom_urls must be sent in full (all real values) or left unchanged " @@ -709,5 +737,17 @@ def _unmask(value: Any, current: Any) -> Any: ) return value if value == REDACTED: - return current if current is not None else "" + if current is None: + raise _unresolvable(key) + return current return value + + +def _unresolvable(key: str) -> RedactionError: + field = f"'{key}'" if key else "a secret" + return RedactionError( + f"{field} was sent as {REDACTED} but there is no stored value to restore it from. " + "This happens when an entry's id is renamed (the old entry's secrets don't follow " + "the new id) or when a new one is created from a copy. Send the real value, or an " + "empty string to clear it." + ) diff --git a/backend/app/config_migrate.py b/backend/app/config_migrate.py index 76ca0a8..2ee6b38 100644 --- a/backend/app/config_migrate.py +++ b/backend/app/config_migrate.py @@ -87,16 +87,27 @@ def migrate(raw: dict[str, Any]) -> dict[str, Any]: def write_backup(path: Path) -> None: """Copy the pre-migration config beside itself as the rollback parachute. + Written whether the migration succeeded or was refused: a refused one leaves the app + running on an empty config, and the next save from the Advanced tab would overwrite + the 0.9 original with it. + An existing backup is never overwritten: the first migration wins, so re-running this can't lose the true 0.9 original. A backup that can't be written (read-only mount) is - logged, not fatal — the migration only *adds* sections, so the old ones stay as the - in-file fallback either way. + logged, not fatal — the same mount stops the migrated config from being saved too, so + the file on disk stays 0.9 either way. """ bak = path.with_name(path.name + BACKUP_SUFFIX) if bak.exists(): return + # Local import: config.py imports this module, so a top-level one would be circular. + from .config import restrict_secret_file + try: shutil.copyfile(path, bak) + # copyfile copies contents, not mode bits, so the copy would land 0644 under a + # container's default umask — holding every API token, secret_key, password hash, + # SMTP password and bot token, indefinitely (an existing .bak is never overwritten). + restrict_secret_file(bak) log.info("config: saved a pre-migration copy at %s", bak) except OSError as exc: log.warning("config: could not write %s (%s) — migrating anyway", bak, exc) diff --git a/backend/app/jobs/lease.py b/backend/app/jobs/lease.py index 6ed2797..4bf9dac 100644 --- a/backend/app/jobs/lease.py +++ b/backend/app/jobs/lease.py @@ -18,6 +18,7 @@ import ssl import threading from collections.abc import Callable from dataclasses import dataclass +from enum import StrEnum from ..config import PbsDevice from ..connectors import net, tls @@ -32,6 +33,21 @@ class PbsUnreachableError(RuntimeError): """The PBS never answered: it could not be woken, or it is an unmanaged box that is off.""" +class ReleaseOutcome(StrEnum): + """What became of a box when a run dropped its lease. + + Only :attr:`LEFT_ON` means "still burning power, and nothing is going to fix that" — + the others are boxes Joulenap either put to sleep, never powers, or will power off at + the end of the run that still holds them. The value doubles as the POWEROFF step's + detail in the run timeline. + """ + + POWERED_OFF = "powered off" + STILL_NEEDED = "left on: still needed by another run" + UNMANAGED = "left on: Joulenap does not manage this box's power" + LEFT_ON = "left powered on" + + # --- device-shaped connector calls ------------------------------------------- # jobs/deps.py has the same four operations bound to the 0.9 single-PBS ``Config``. These # take the device a route points at; the Config-shaped originals die with the old cycle. @@ -180,37 +196,48 @@ class PowerLease: held.holders += 1 return was_awake - def release(self, pbs: PbsDevice, *, power_off: bool = True) -> bool: - """Drop this run's hold and power the box down if it is now safe to. Returns whether - it actually powered off. + def release(self, pbs: PbsDevice, *, power_off: bool = True) -> ReleaseOutcome: + """Drop this run's hold and power the box down if it is now safe to. Returns *why* + the box ended up in the state it did. ``power_off`` is the caller's policy (a failed run leaves the PBS on for inspection, a manual run honours the "power off when finished" toggle). The lease adds the conditions the caller cannot see: no other holder, and no *queued* route that still needs this box. + + Four outcomes rather than a bool because only two of them cost the user power, and + the lease is the only place that can tell them apart — a caller re-deriving "was + that a real 'left on'?" would have to duplicate every condition below. """ with self._lock: held = self._state.get(pbs.id) if held is None or not held.holders: log.warning("Release of an unheld lease on PBS %s — ignoring", pbs.id) - return False + # A bug, not a policy: say "left on" so it is at least visible. + return ReleaseOutcome.LEFT_ON held.holders -= 1 remaining = held.holders if not remaining: del self._state[pbs.id] + # Order matters for the *reason*, not for the action — every branch below stops the + # power-off equally. The caller's policy is checked last on purpose: "this run + # doesn't want to power off" is only the real explanation once the box is one we + # could have powered off and nobody else needs it. if remaining: log.info("PBS %s still held by %d run(s); leaving it on", pbs.id, remaining) - return False - if not power_off: - return False + return ReleaseOutcome.STILL_NEEDED if not pbs.managed_power: # An always-on / cloud-hosted PBS: Joulenap never touches its power. - return False + return ReleaseOutcome.UNMANAGED if pbs.id in self._pending(): log.info("PBS %s is needed by a queued route; leaving it on", pbs.id) - return False - return self._power_off(pbs) + return ReleaseOutcome.STILL_NEEDED + if not power_off: + return ReleaseOutcome.LEFT_ON + # False here is a busy box we declined to cut off, or a poweroff that errored — both + # leave it burning power. + return ReleaseOutcome.POWERED_OFF if self._power_off(pbs) else ReleaseOutcome.LEFT_ON # --- internals ----------------------------------------------------------- diff --git a/backend/app/jobs/route_cycle.py b/backend/app/jobs/route_cycle.py index db0d229..a9fb6fd 100644 --- a/backend/app/jobs/route_cycle.py +++ b/backend/app/jobs/route_cycle.py @@ -265,9 +265,11 @@ def run_pbs_maintenance( if action == "gc": _route_gc_step(pbs, recorder, deps) elif action == "verify": - # Everything, not just the recently-changed: an ad-hoc verify is a deliberate - # "check this box now", and reverify_days is a per-route pacing knob. - _route_verify_step(pbs, recorder, deps, outdated_after=None) + # 0 means "everything" — see _route_verify_step. An ad-hoc verify is a deliberate + # "check this box now" after a restore or a disk scare, so it must re-read the + # older snapshots too; None would mean "only never-verified", i.e. skip exactly + # the ones the user is worried about. reverify_days is the per-route pacing knob. + _route_verify_step(pbs, recorder, deps, outdated_after=0) else: raise CycleAbort(f"unsupported maintenance action '{action}'") return _route_read_datastore(pbs, recorder, deps) diff --git a/backend/app/jobs/service.py b/backend/app/jobs/service.py index 359b45a..ee7ab0d 100644 --- a/backend/app/jobs/service.py +++ b/backend/app/jobs/service.py @@ -31,7 +31,7 @@ from ..db.models import LogLevel, RunKind, RunStatus, RunTrigger, StepName, Step from ..db.prune import PruneResult, prune_history from ..notify.messages import RunContext from .deps import CycleDeps -from .lease import LeaseDeps, PbsUnreachableError, PowerLease +from .lease import LeaseDeps, PbsUnreachableError, PowerLease, ReleaseOutcome from .recorder import RunRecorder from .route_cycle import RUN_KINDS, run_pbs_maintenance, run_route @@ -276,6 +276,11 @@ class JobService: finally: with self._state_lock: self._current = None + # Cleared with it, or a stop aimed at the run that just ended would pass + # cancel()'s guard and land on the next one (or be swallowed): _start + # sets the new id only after the DB insert, leaving a window where the + # stale id still matches while another run holds the lock. + self._current_run_id = None def _execute(self, item: QueuedRun) -> None: """Take the run's power leases, do its job, release them, then notify. @@ -314,9 +319,10 @@ class JobService: # The cycle sets the run's final status itself and hands back what to say # about it (None = cancelled, say nothing). ctx = item.job(config, subject, recorder, self.deps) - self._release_all(item, held, recorder) + left_on = self._release_all(item, held, recorder) held = [] if ctx is not None: + ctx.left_on = left_on self._notify(ctx, recorder) finally: # Only reached with leases still held when the job raised out of the block. @@ -364,30 +370,38 @@ class JobService: def _release_all( self, item: QueuedRun, devices: list[PbsDevice], recorder: RunRecorder | None - ) -> None: - """Drop every lease this run holds, recording each power-off decision. + ) -> list[str]: + """Drop every lease this run holds, recording each power-off decision. Returns the + ids of the boxes genuinely left burning power, for the notification's warning. Devices are released independently: a sync route holds two leases and each box may - have a different answer (another holder, a queued route, unmanaged power). + have a different answer (another holder, a queued route, unmanaged power) — which + is why the warning cannot be a single fact about the run. ``recorder=None`` is the crash path — the leases must still be dropped, but the run row is already being finalised, so there is nothing left to record against. """ succeeded = recorder is not None and recorder.run.status == RunStatus.SUCCESS power_off = self._power_off_policy(item, succeeded=succeeded) multi = len(devices) > 1 + left_on: list[str] = [] for device in devices: if recorder is None: - self.lease.release(device, power_off=power_off) + if self.lease.release(device, power_off=power_off) is ReleaseOutcome.LEFT_ON: + left_on.append(device.id) continue with recorder.step(StepName.POWEROFF, label=device.id if multi else None) as step: - if self.lease.release(device, power_off=power_off): + outcome = self.lease.release(device, power_off=power_off) + step.detail = str(outcome) + if outcome is ReleaseOutcome.POWERED_OFF: continue # Not a failure: leaving the box on is the *correct* outcome after a failed - # run, for an unmanaged device, or while another route still needs it. The - # notification's "PBS left powered on" warning keys on this step not being - # SUCCESS, so the user still hears about it when it costs them power. + # run, for an unmanaged device, or while another route still needs it — the + # detail says which. Only LEFT_ON costs the user power with nobody left to + # fix it, so only that one earns the notification's warning. step.status = StepStatus.SKIPPED - step.detail = "left powered on" + if outcome is ReleaseOutcome.LEFT_ON: + left_on.append(device.id) + return left_on def _notify(self, ctx: RunContext, recorder: RunRecorder) -> None: """Send the result notification. A delivery failure is logged, never fatal — the run diff --git a/backend/app/main.py b/backend/app/main.py index ff6063b..7ce207a 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -19,6 +19,7 @@ from fastapi.staticfiles import StaticFiles from starlette.middleware.sessions import SessionMiddleware from . import __version__ +from . import config as config_mod from .api import api_router from .api import metrics as metrics_api from .config import Config @@ -26,6 +27,7 @@ from .core.config_store import ConfigStore from .core.ratelimit import LoginRateLimiter from .core.scheduler import Scheduler from .db import init_db, session_scope +from .db.models import LogEvent, LogLevel from .db.startup import sweep_orphaned_runs from .jobs import JobService from .notify import NotificationService @@ -59,6 +61,10 @@ async def lifespan(app: FastAPI) -> AsyncIterator[None]: with session_scope() as session: swept = sweep_orphaned_runs(session) interrupted_alerts = [build_interrupted_message(store.config, run) for run in swept] + # The config was loaded before the DB existed, so a refused 0.9 migration can only + # reach the activity log from here. Run-less row: it belongs to no cycle. + if config_mod.MIGRATION_ERROR: + session.add(LogEvent(level=LogLevel.ERROR, message=config_mod.MIGRATION_ERROR)) if swept: log.warning("Marked %d interrupted run(s) as failed at startup", len(swept)) service = JobService(store) diff --git a/backend/app/notify/messages.py b/backend/app/notify/messages.py index a0722cd..8bd92f6 100644 --- a/backend/app/notify/messages.py +++ b/backend/app/notify/messages.py @@ -58,6 +58,11 @@ class RunContext: guests: GuestSummary | None = None #: When this route next fires, for the "Next scheduled run" line. next_at: datetime | None = None + #: PBS ids this run left awake and burning power, with nothing queued to shut them + #: down. Filled in by ``JobService`` after the leases are released: it is the only + #: place that knows *why* a box stayed on, and only some of the reasons cost energy + #: (an always-on box, or one another run still holds, cost nothing). + left_on: list[str] = field(default_factory=list) # event keys: success | failure | aborted | test @@ -279,25 +284,52 @@ def _step_is(step: RunStep, name: StepName) -> bool: return step.name.split(":", 1)[0] == name.value -def _pbs_left_on(run: Run) -> bool: - """True if the cycle woke a PBS but never powered it back off — so a box is still - burning energy and the user should check it. +def _step_label(step: RunStep) -> str | None: + """The device a step names (``poweroff:pbs-02`` -> ``pbs-02``), or None when unlabelled + — a single-device run doesn't repeat which box it means.""" + _, _, label = step.name.partition(":") + return label or None - The rule: a WAIT step succeeded (a PBS actually came up) **and** no POWEROFF step - succeeded. That single condition covers every "left on" case uniformly: - * success but power-off failed / was skipped (PBS busy) — POWEROFF present, not SUCCESS; - * failure after the PBS woke (vzdump/GC/verify errored) — no POWEROFF step at all; - * abort after wake (preflight free-space, no guests selected) — no POWEROFF step. +def _pbs_left_on(config: Config, run: Run) -> bool: + """True if a PBS came up and nothing ever powered it back off — a box still burning + energy that the user should go and check. - An abort *before* the box came up (wake/wait timeout) leaves the WAIT step non-SUCCESS, so - the PBS is off and this correctly returns False — hence why it keys on WAIT, not on the - run status.""" - woke = any(_step_is(s, StepName.WAIT) and s.status == StepStatus.SUCCESS for s in run.steps) - powered_off = any( - _step_is(s, StepName.POWEROFF) and s.status == StepStatus.SUCCESS for s in run.steps - ) - return woke and not powered_off + Only for a run a restart interrupted: there the run row is all there is, and no + POWEROFF step was ever reached. A run that *finished* knows the answer exactly and + reports it through ``RunContext.left_on``, because "was it left on?" depends on facts + the timeline doesn't carry (whether another queued route still needs the box). + + Two things the steps alone get wrong, both introduced by this same release: + + * an **unmanaged** box (``managed_power: false``) is never Joulenap's to power down, + so a run against one must not warn — hence taking ``config``; + * a run holding **several** leases needs the WAIT and POWEROFF steps paired *per + device*, or one box's successful power-off hides another's that stayed up. + + An abort *before* the box came up leaves the WAIT step non-SUCCESS, so the PBS is off + and this correctly returns False — hence why it keys on WAIT, not on the run status. + """ + managed = {p.id for p in config.pbss if p.managed_power} + route = next((r for r in config.routes if r.id == run.route_id), None) + # An unlabelled step belongs to the run's only box — a route's target (a sync route + # labels both sides). An ad-hoc GC/verify records neither a label nor a route, so its + # box cannot be named: warn rather than stay silent about a box that may be awake. + default = route.target if route else None + powered_off = { + _step_label(s) + for s in run.steps + if _step_is(s, StepName.POWEROFF) and s.status == StepStatus.SUCCESS + } + for step in run.steps: + if not _step_is(step, StepName.WAIT) or step.status != StepStatus.SUCCESS: + continue + pbs_id = _step_label(step) or default + if pbs_id is not None and pbs_id not in managed: + continue + if _step_label(step) not in powered_off: + return True + return False #: Route kinds, for the body's ``Route:`` line. Localized because the kind is a user-facing @@ -368,7 +400,9 @@ def build_run_message(ctx: RunContext) -> tuple[str, str]: if run.error: lines.append(f"{labels['error']}: {run.error}") - if _pbs_left_on(run): + # From the service, not from the steps: a finished run knows exactly which boxes it + # left burning power, and only those warrant the warning. + if ctx.left_on: lines.append(labels["pbs_left_on"]) if next_at is not None: @@ -432,15 +466,15 @@ def build_interrupted_message(config: Config, run: Run) -> tuple[str, str]: """``(title, body)`` for a run that a restart interrupted (swept to FAILURE at startup, BE-R2), in the configured language. - Adds the "PBS left powered on" warning when the box had actually woken before the crash - (WAIT succeeded, no POWEROFF) — the whole point of the alert: a normally-off box that a - crash left awake and burning power.""" + Adds the "PBS left powered on" warning when a box Joulenap powers had actually woken + before the crash (WAIT succeeded, no matching POWEROFF) — the whole point of the alert: + a normally-off box that a crash left awake and burning power.""" pack = _pack(config.app.language) labels = pack["_labels"] lines = [pack["interrupted"]["intro"]] if run.error: lines.append(f"{labels['error']}: {run.error}") - if _pbs_left_on(run): + if _pbs_left_on(config, run): lines.append(labels["pbs_left_on"]) # This alert has no Duration line (the run's own span would span the whole downtime, # not the work), so the one interval worth reporting is how long the box has been diff --git a/backend/tests/test_api.py b/backend/tests/test_api.py index 72c6689..5ef83a6 100644 --- a/backend/tests/test_api.py +++ b/backend/tests/test_api.py @@ -12,6 +12,7 @@ import pytest from fakes import FakeBox, FakePve, UnreachablePve, make_deps from fastapi.testclient import TestClient +from app import config from app.config import load_config from app.connectors.pve import Guest from app.db import session_scope @@ -106,6 +107,14 @@ def test_status_lists_the_next_run_of_every_armed_route(app_ctx): assert times == sorted(times) +def test_status_reports_a_refused_config_migration(app_ctx, monkeypatch): + """An empty config looks exactly like a fresh install, so the UI has to be told why.""" + client, _app = app_ctx + assert client.get("/api/status").json()["config_error"] is None + monkeypatch.setattr(config, "MIGRATION_ERROR", "routes.0.options.bwlimit: bad") + assert client.get("/api/status").json()["config_error"] == "routes.0.options.bwlimit: bad" + + def test_status_pill_says_paused_when_the_kill_switch_is_off(app_ctx): client, app = app_ctx app.state.config_store.update(lambda c: setattr(c.app, "scheduler_enabled", False)) diff --git a/backend/tests/test_api_devices.py b/backend/tests/test_api_devices.py index 91e0b55..e9bed7c 100644 --- a/backend/tests/test_api_devices.py +++ b/backend/tests/test_api_devices.py @@ -161,6 +161,45 @@ def test_delete_404s_on_an_unknown_device(app_ctx): assert client.delete("/api/devices/pbss/nope").status_code == 404 +def test_a_validation_failure_does_not_echo_the_config_back(app_ctx): + """A config-level cross-check raises at loc=(), so pydantic attaches the *whole* + validated config as the error's ``input`` — every API token, the secret key, the + password hash, the SMTP and bot tokens — and the 422 shipped it to the browser.""" + client, app = app_ctx + client.post( + "/api/routes", + json={"id": "watch", "kind": "external", "target": "pbs-02", "schedule": {"time": "03:00"}}, + ) + # An External route watches a box Joulenap wakes, so making that box unmanaged is + # exactly the cross-check that fires. + r = client.put("/api/devices/pbss/pbs-02", json={"id": "pbs-02", "host": "192.0.2.21", + "datastore": "offsite", + "api_token_id": "root@pam!joulenap", + "api_token_secret": REDACTED, + "managed_power": False}) + assert r.status_code == 422 + assert "managed_power" in r.text # the reason still reaches the user + stored = app.state.config_store.config + for secret in ( + stored.app.secret_key, + stored.app.auth.password_hash, + *[d.api_token_secret for d in stored.pves], + *[d.api_token_secret for d in stored.pbss], + ): + assert secret and secret not in r.text + + +def test_create_rejects_the_redaction_placeholder(app_ctx): + """A body copy-pasted from GET /api/devices carries ***REDACTED*** as the token. Storing + it verbatim is invisible — GET re-masks it (it is non-empty) — until a connection test + fails with a 502 that gives no hint the stored token is the placeholder text itself.""" + client, app = app_ctx + r = client.post("/api/devices/pbss", json={**NEW_PBS, "api_token_secret": REDACTED}) + assert r.status_code == 422 + assert "api_token_secret" in r.text + assert [d.id for d in app.state.config_store.config.pbss] == ["pbs-01", "pbs-02"] + + # --- test --------------------------------------------------------------------- @@ -228,6 +267,25 @@ def test_power_off_409s_while_a_run_holds_the_box(app_ctx): assert "pbs-01" in r.json()["detail"] +def test_power_off_409s_while_a_run_holds_the_single_run_lock(app_ctx): + """The lease check alone was a check-then-act: a scheduled route could start in the gap, + find the box still up (so no wake), and begin vzdump — then the SSH poweroff, which has + no idle-wait and no refcount check, cut it off mid-backup. Holding the same lock a run + holds for its whole life is what closes that window.""" + client, app = app_ctx + box = FakeBox() + service = _inject(app, box) + service._lock.acquire() # stand in for a run in flight; no lease taken yet + try: + r = client.post("/api/devices/pbss/pbs-01/power", json={"action": "poweroff"}) + finally: + service._lock.release() + + assert r.status_code == 409 + assert "in progress" in r.json()["detail"] + assert box.poweroffs == [] # the SSH command never ran + + def test_power_409s_on_an_unmanaged_device(app_ctx): client, app = app_ctx app.state.config_store.update( @@ -296,7 +354,10 @@ def test_verify_queues_a_verify_run(app_ctx): assert pbs.verify_started is True # An ad-hoc verify checks everything, rather than pacing itself like a Verify route. - assert pbs.verify_args["outdated_after"] is None + # "Everything" reaches PBS as ignore-verified: 0. The bug was asking for + # outdated_after=None, which means "only never-verified" — skipping precisely the old + # snapshots the user clicked the button about. + assert pbs.verify_args["ignore_verified"] is False def test_maintenance_works_on_an_always_on_box(app_ctx): diff --git a/backend/tests/test_config.py b/backend/tests/test_config.py index bc10bdb..4be745b 100644 --- a/backend/tests/test_config.py +++ b/backend/tests/test_config.py @@ -231,6 +231,31 @@ def test_a_new_device_keeps_the_secret_it_was_sent(): assert out["pbss"][0]["api_token_secret"] == "brand-new" +def test_renaming_a_device_id_rejects_its_unresolvable_placeholder(): + """The Advanced tab shows ``id: pbs-01`` with ``api_token_secret: ***REDACTED***``. Fix a + typo in the id and save: nothing matches by id any more, so the placeholder used to + resolve to "" — 200 OK, credential gone, nothing on screen to suggest it.""" + cfg = Config() + cfg.pbss = [PbsDevice(id="pbs-01", api_token_secret="first", managed_power=False)] + incoming = {"pbss": [{"id": "pbs01", "api_token_secret": cfgmod.REDACTED}]} + with pytest.raises(cfgmod.RedactionError, match="api_token_secret"): + restore_secrets(incoming, cfg) + + +def test_a_placeholder_with_nothing_stored_is_rejected(): + # Same guard one level up: restore_secrets_from({}) is what a *create* resolves against. + with pytest.raises(cfgmod.RedactionError): + cfgmod.restore_secrets_from({"api_token_secret": cfgmod.REDACTED}, {}) + + +def test_an_empty_string_still_clears_a_secret(): + # The escape hatch the rejection points at: "" means clear, and must keep working. + cfg = Config() + cfg.pbss = [PbsDevice(id="pbs-01", api_token_secret="first", managed_power=False)] + out = restore_secrets({"pbss": [{"id": "pbs-01", "api_token_secret": ""}]}, cfg) + assert out["pbss"][0]["api_token_secret"] == "" + + def test_session_defaults(): s = Config().app.session assert s.https_only is False and s.max_age_days == 14 diff --git a/backend/tests/test_config_migrate.py b/backend/tests/test_config_migrate.py index 8b39d8b..48a4416 100644 --- a/backend/tests/test_config_migrate.py +++ b/backend/tests/test_config_migrate.py @@ -7,12 +7,14 @@ quietly disappearing from a real user's config. from __future__ import annotations +import os +import stat from pathlib import Path import pytest import yaml -from app import config_migrate +from app import config, config_migrate from app.config import REDACTED, Config, load_config, save_config FIXTURE = Path(__file__).parent / "fixtures" / "config-0.9.yaml" @@ -21,6 +23,7 @@ BAK = "config.yaml" + config_migrate.BACKUP_SUFFIX def _write(tmp_path: Path, **overrides) -> Path: """Drop the 0.9 fixture into tmp_path, deep-merging any section overrides.""" + tmp_path.mkdir(parents=True, exist_ok=True) raw = yaml.safe_load(FIXTURE.read_text(encoding="utf-8")) for section, values in overrides.items(): for key, value in values.items(): @@ -163,7 +166,36 @@ def test_a_config_that_cannot_be_converted_is_left_alone(tmp_path: Path, monkeyp # dropped at load, so the app boots on defaults rather than failing to start. assert cfg.routes == [] assert path.read_text(encoding="utf-8") == original - assert not (tmp_path / BAK).exists() + # ...but the parachute still opens: the app is now running on an empty config, and the + # next save from the Advanced tab would overwrite the only 0.9 config the user has. + assert (tmp_path / BAK).read_text(encoding="utf-8") == original + + +def test_a_refused_migration_is_reported_not_just_logged(tmp_path: Path): + # An empty config is indistinguishable from a fresh install, so the reason has to + # outlive the log line: GET /api/status and the activity log both read this. + path = _write(tmp_path, backup={"bwlimit": -1}) + cfg = load_config(path) + assert (cfg.pves, cfg.pbss, cfg.routes) == ([], [], []) + assert config.MIGRATION_ERROR is not None + assert "bwlimit" in config.MIGRATION_ERROR + assert str(path) in config.MIGRATION_ERROR + + +def test_a_later_good_load_clears_the_reported_error(tmp_path: Path): + load_config(_write(tmp_path, backup={"bwlimit": -1})) + assert config.MIGRATION_ERROR is not None + load_config(_write(tmp_path / "fixed", backup={})) + assert config.MIGRATION_ERROR is None + + +@pytest.mark.skipif(os.name == "nt", reason="POSIX permission bits") +def test_the_backup_is_owner_only(tmp_path: Path): + # It holds every API token, secret_key, password hash, SMTP and bot token — and is + # never overwritten, so a 0644 copy would sit there forever. + path = _write(tmp_path) + load_config(path) + assert stat.S_IMODE((tmp_path / BAK).stat().st_mode) == 0o600 def test_an_unwritable_config_still_boots(tmp_path: Path, monkeypatch): diff --git a/backend/tests/test_lease.py b/backend/tests/test_lease.py index f9a0b61..231b010 100644 --- a/backend/tests/test_lease.py +++ b/backend/tests/test_lease.py @@ -6,7 +6,7 @@ import pytest from fakes import FakeBox from app.config import PbsDevice -from app.jobs.lease import PbsUnreachableError, PowerLease +from app.jobs.lease import PbsUnreachableError, PowerLease, ReleaseOutcome def make_pbs(**over) -> PbsDevice: @@ -84,7 +84,7 @@ def test_unmanaged_pbs_is_only_probed(): pbs = make_pbs(managed_power=False, mac="") assert lease.acquire(pbs) is True - assert lease.release(pbs) is False # never powered off + assert lease.release(pbs) is ReleaseOutcome.UNMANAGED # never Joulenap's to power assert box.wol == [] assert box.poweroffs == [] @@ -108,7 +108,7 @@ def test_last_holder_powers_the_box_off(): pbs = make_pbs() lease.acquire(pbs) - assert lease.release(pbs) is True + assert lease.release(pbs) is ReleaseOutcome.POWERED_OFF assert box.poweroffs == ["pbs1"] assert lease.state("pbs1").holders == 0 @@ -120,9 +120,9 @@ def test_release_with_another_holder_leaves_the_box_on(): lease.acquire(pbs) lease.acquire(pbs) - assert lease.release(pbs) is False + assert lease.release(pbs) is ReleaseOutcome.STILL_NEEDED assert box.poweroffs == [] - assert lease.release(pbs) is True + assert lease.release(pbs) is ReleaseOutcome.POWERED_OFF def test_a_queued_route_on_the_same_pbs_keeps_it_on(): @@ -131,7 +131,7 @@ def test_a_queued_route_on_the_same_pbs_keeps_it_on(): pbs = make_pbs() lease.acquire(pbs) - assert lease.release(pbs) is False + assert lease.release(pbs) is ReleaseOutcome.STILL_NEEDED assert box.poweroffs == [] @@ -141,7 +141,7 @@ def test_power_off_false_leaves_the_box_on(): pbs = make_pbs() lease.acquire(pbs) - assert lease.release(pbs, power_off=False) is False + assert lease.release(pbs, power_off=False) is ReleaseOutcome.LEFT_ON assert box.poweroffs == [] @@ -151,7 +151,7 @@ def test_a_busy_pbs_is_not_interrupted(): pbs = make_pbs() lease.acquire(pbs) - assert lease.release(pbs) is False + assert lease.release(pbs) is ReleaseOutcome.LEFT_ON assert box.poweroffs == [] @@ -162,7 +162,7 @@ def test_a_failing_idle_check_fails_open(): pbs = make_pbs() lease.acquire(pbs) - assert lease.release(pbs) is True + assert lease.release(pbs) is ReleaseOutcome.POWERED_OFF assert box.poweroffs == ["pbs1"] @@ -172,7 +172,7 @@ def test_the_idle_check_is_skipped_when_the_wait_is_zero(): pbs = make_pbs(poweroff_task_wait=0) lease.acquire(pbs) - assert lease.release(pbs) is True + assert lease.release(pbs) is ReleaseOutcome.POWERED_OFF def test_a_failed_power_off_is_swallowed(): @@ -182,7 +182,7 @@ def test_a_failed_power_off_is_swallowed(): pbs = make_pbs() lease.acquire(pbs) - assert lease.release(pbs) is False + assert lease.release(pbs) is ReleaseOutcome.LEFT_ON assert box.poweroffs == [] @@ -190,7 +190,7 @@ def test_releasing_an_unheld_lease_is_ignored(): box = FakeBox() lease = PowerLease(box.deps()) - assert lease.release(make_pbs()) is False + assert lease.release(make_pbs()) is ReleaseOutcome.LEFT_ON assert lease.state("pbs1").holders == 0 assert box.poweroffs == [] diff --git a/backend/tests/test_notify.py b/backend/tests/test_notify.py index b8ae150..c2865ec 100644 --- a/backend/tests/test_notify.py +++ b/backend/tests/test_notify.py @@ -187,7 +187,7 @@ def _route(route_id: str = "nightly", name: str = "Nightly", **overrides) -> Rou ) -def _msg(config, run, datastore=None, guests=None, next_at=None, route=None): +def _msg(config, run, datastore=None, guests=None, next_at=None, route=None, left_on=()): """``build_run_message`` with the old positional tail, so these tests stay readable. The production seam is a single :class:`RunContext`; spelling that out at ~25 call sites @@ -201,6 +201,7 @@ def _msg(config, run, datastore=None, guests=None, next_at=None, route=None): datastore=datastore, guests=guests, next_at=next_at, + left_on=list(left_on), ) ) @@ -271,6 +272,7 @@ def test_run_message_field_order(): ds, GuestSummary(total=2, ok=1, failed=["web01"]), datetime(2026, 6, 29, 4, 0, tzinfo=UTC), + left_on=["pbs-01"], ) assert [line.split(":")[0] for line in body.splitlines()] == [ "Trigger", @@ -359,51 +361,23 @@ def _woke() -> RunStep: return RunStep(name=StepName.WAIT, status=StepStatus.SUCCESS) -def test_run_message_flags_pbs_left_on_when_poweroff_failed(): - run = _run(RunStatus.SUCCESS) - run.steps = [_woke(), RunStep(name=StepName.POWEROFF, status=StepStatus.FAILURE)] - _title, body = _msg(Config(), run) - assert "left powered on" in body - - -def test_run_message_flags_pbs_left_on_when_poweroff_skipped(): - run = _run(RunStatus.SUCCESS) - run.steps = [_woke(), RunStep(name=StepName.POWEROFF, status=StepStatus.SKIPPED)] - _title, body = _msg(Config(), run) - assert "left powered on" in body - - -def test_run_message_no_pbs_line_when_poweroff_succeeded(): - run = _run(RunStatus.SUCCESS) - run.steps = [_woke(), RunStep(name=StepName.POWEROFF, status=StepStatus.SUCCESS)] - _title, body = _msg(Config(), run) - assert "left powered on" not in body - - -def test_run_message_flags_pbs_left_on_when_backup_fails_after_wake(): - # Failure after the PBS woke: no POWEROFF step at all, box is left on for inspection. +def test_run_message_flags_the_boxes_the_run_left_awake(): + # A finished run doesn't guess from its own timeline: JobService hands it the ids of the + # boxes still burning power (RunContext.left_on), because only the lease knows whether + # "not powered off" meant an always-on box, one another run still holds, or a real + # left-on. Which reason applies is decided (and tested) in tests/test_queue.py. run = _run(RunStatus.FAILURE, error="vzdump failed") run.steps = [_woke(), RunStep(name=StepName.BACKUP, status=StepStatus.FAILURE)] - _title, body = _msg(Config(), run) + _title, body = _msg(Config(), run, left_on=["pbs-01"]) assert "left powered on" in body -def test_run_message_flags_pbs_left_on_when_aborted_after_wake(): - # An abort after wake (e.g. free-space preflight) also leaves the box on. - run = _run(RunStatus.ABORTED, error="datastore too full") - run.steps = [_woke(), RunStep(name=StepName.PRECHECK, status=StepStatus.FAILURE)] - _title, body = _msg(Config(), run) - assert "left powered on" in body - - -def test_run_message_no_pbs_line_when_wait_timed_out(): - # Aborted before the PBS came up (WAIT failed): the box never turned on, so no warning. - run = _run(RunStatus.ABORTED, error="PBS not reachable") - run.steps = [ - RunStep(name=StepName.WAKE, status=StepStatus.SUCCESS), - RunStep(name=StepName.WAIT, status=StepStatus.FAILURE), - ] - _title, body = _msg(Config(), run) +def test_run_message_no_pbs_line_when_nothing_was_left_awake(): + # A SKIPPED power-off is not evidence on its own — an always-on PBS records exactly + # this on every successful run, and used to be warned about every night. + run = _run(RunStatus.SUCCESS) + run.steps = [_woke(), RunStep(name=StepName.POWEROFF, status=StepStatus.SKIPPED)] + _title, body = _msg(Config(), run, left_on=[]) assert "left powered on" not in body @@ -501,6 +475,49 @@ def test_interrupted_message_flags_pbs_left_on_when_it_had_woken(): assert "left powered on" in body +def test_interrupted_message_ignores_a_box_joulenap_never_powers(): + # A crash cannot leave an always-on PBS "burning power" — it was on before and after. + cfg = Config.model_validate( + { + "pbss": [{"id": "pbs-01", "host": "192.0.2.20", "managed_power": False}], + "routes": [{"id": "nightly", "kind": "verify", "target": "pbs-01"}], + } + ) + run = _run(RunStatus.FAILURE, error="Interrupted") + run.route_id = "nightly" + run.steps = [ + RunStep(name=StepName.WAIT, status=StepStatus.SUCCESS), + RunStep(name=StepName.BACKUP, status=StepStatus.FAILURE), + ] + _title, body = build_interrupted_message(cfg, run) + assert "left powered on" not in body + + +def test_interrupted_message_pairs_wake_and_power_off_per_device(): + """A sync route holds two boxes. One powering off must not hide the other staying up — + the old rule ORed both steps across the whole run and went silent.""" + cfg = Config.model_validate( + { + "pbss": [ + {"id": "pbs-01", "host": "192.0.2.20", "mac": "00:11:22:33:44:55"}, + {"id": "pbs-02", "host": "192.0.2.21", "mac": "00:11:22:33:44:66"}, + ], + "routes": [ + {"id": "off", "kind": "sync", "source_pbs": "pbs-01", "target": "pbs-02"} + ], + } + ) + run = _run(RunStatus.FAILURE, error="Interrupted") + run.route_id = "off" + run.steps = [ + RunStep(name="wait:pbs-01", status=StepStatus.SUCCESS), + RunStep(name="wait:pbs-02", status=StepStatus.SUCCESS), + RunStep(name="poweroff:pbs-02", status=StepStatus.SUCCESS), + ] + _title, body = build_interrupted_message(cfg, run) + assert "left powered on" in body # pbs-01 is still up + + def test_interrupted_message_no_pbs_line_when_it_never_woke(): # Crashed during WAIT (PBS never came up): no "left on" warning. run = _run(RunStatus.FAILURE, error="Interrupted") diff --git a/backend/tests/test_queue.py b/backend/tests/test_queue.py index c37f737..9a84252 100644 --- a/backend/tests/test_queue.py +++ b/backend/tests/test_queue.py @@ -12,8 +12,10 @@ from sqlalchemy import select from app.config import PbsDevice, PveDevice, Route, RouteSource from app.core.config_store import ConfigStore from app.db import session_scope -from app.db.models import Run, RunKind, RunStatus, RunTrigger +from app.db.models import Run, RunKind, RunStatus, RunTrigger, StepName, StepStatus +from app.jobs.lease import ReleaseOutcome from app.jobs.service import AlreadyQueuedError, JobService, QueuedRun +from app.notify.messages import RunContext def make_service(box: FakeBox | None = None) -> tuple[JobService, FakeBox]: @@ -284,6 +286,101 @@ def test_an_unreachable_pbs_fails_the_run_without_running_the_job(temp_config, t assert "not reachable" in (run.error or "") +# --- what the run reports as left powered on --------------------------------- +# +# "PBS left powered on" is the notification's energy warning, so it must fire exactly when +# a box is still awake with nothing left to shut it down. The lease is the only place that +# can tell the reasons apart, and it hands its verdict to the message through +# RunContext.left_on (tests/test_notify.py covers the rendering). + + +def notifying_job(status=RunStatus.SUCCESS): + """A job that finishes with ``status`` and asks to be notified about it.""" + + def job(config, subject, recorder, _deps): + recorder.finish(status) + return RunContext(config=config, run=recorder.run) + + return job + + +def sent(service: JobService) -> list[RunContext]: + seen: list[RunContext] = [] + service.deps.notify = seen.append + return seen + + +def test_an_always_on_pbs_is_never_reported_as_left_on(temp_config, temp_db): + # The common false positive: a managed_power: false box records a SKIPPED power-off on + # *every* successful run, so the old step-based rule warned about it every single night. + service, box = make_service() + service._store.config.pbss[0].managed_power = False + seen = sent(service) + + enqueue(service, "r1", notifying_job(), trigger=RunTrigger.SCHEDULED) + drain(service) + + assert box.poweroffs == [] + assert seen[0].left_on == [] + + +def test_a_failed_run_reports_the_box_it_left_awake(temp_config, temp_db): + service, box = make_service() + seen = sent(service) + + enqueue(service, "r1", notifying_job(RunStatus.FAILURE), trigger=RunTrigger.SCHEDULED) + drain(service) + + assert box.poweroffs == [] # left up for inspection + assert seen[0].left_on == ["pbs1"] + + +def test_a_sync_route_reports_only_the_box_that_stayed_up(temp_config, temp_db): + # The old false negative: one box powering off hid the other one staying awake, because + # the rule ORed the steps across the whole run instead of pairing them per device. + service, box = make_service() + service._store.config.pbss[1].managed_power = False # target pbs2 is always on + seen = sent(service) + + enqueue(service, "sync", notifying_job(RunStatus.FAILURE), trigger=RunTrigger.SCHEDULED) + drain(service) + + assert box.poweroffs == [] + assert seen[0].left_on == ["pbs1"] # not pbs2: that one is never ours to power down + + +def test_a_box_a_queued_route_still_needs_is_not_reported_as_left_on(temp_config, temp_db): + # It stays awake on purpose, and the run that follows will close it. + service, box = make_service() + seen = sent(service) + gate = Gate() + + enqueue(service, "r1", gate.job, trigger=RunTrigger.SCHEDULED) + assert gate.started.wait(timeout=5) + enqueue(service, "r2", notifying_job(), trigger=RunTrigger.SCHEDULED) + gate.release.set() + drain(service) + + assert box.poweroffs == ["pbs1"] # only r2, the last holder, closed it + assert seen[0].left_on == [] + + +def test_the_power_off_step_records_why_the_box_stayed_up(temp_config, temp_db): + # The timeline says which of the three "not powered off" reasons applied, so the run + # detail view doesn't just show a bare SKIPPED. + service, _box = make_service() + service._store.config.pbss[0].managed_power = False + + enqueue(service, "r1", ok_job, trigger=RunTrigger.SCHEDULED) + drain(service) + + with session_scope() as session: + run = session.scalars(select(Run)).one() + step = next(s for s in run.steps if s.name == StepName.POWEROFF) + assert step.status == StepStatus.SKIPPED + assert step.detail == ReleaseOutcome.UNMANAGED + + def test_a_run_on_another_pbs_does_not_hold_the_first(temp_config, temp_db): service, box = make_service() diff --git a/backend/tests/test_service.py b/backend/tests/test_service.py index 0dd14ba..22b34f2 100644 --- a/backend/tests/test_service.py +++ b/backend/tests/test_service.py @@ -275,6 +275,23 @@ def test_cancel_is_refused_when_nothing_is_running(temp_config, temp_db): assert service.cancel(run_id) is False +def test_a_finished_run_stops_being_the_cancellable_one(temp_config, temp_db): + """``cancel`` takes a run id precisely so a click landing between two runs can't hit the + wrong one — but the id was only ever *assigned*, never cleared, so it kept naming the + finished run. ``_start`` sets the new id after acquiring the lock and doing the DB + insert, so in that window ``is_running`` is already True while the stale id still + matches: the stop would be swallowed, or set the cancel flag on a run the user never + targeted, which then aborts on its first poll.""" + service, _box = _service() + service.run_route("nightly") + _drain(service) + with session_scope() as session: + run_id = session.scalars(select(Run)).one().id + + assert service._current_run_id is None + assert service.cancel(run_id) is False + + def test_a_stale_cancel_does_not_kill_the_next_run(temp_config, temp_db): # Cancel arrives moments before the run ends on its own; the flag must not leak into # the run that starts next.