Phase 3: VISUAL feed and M-Files drawings in the worker

Migration 0004 (VISUAL and drawing caches, go-live ignored list, resource
map, job tables, order-derived columns with provenance; work order key
includes the operation sequence). The real worker on APScheduler with
settings re-read each fire, pause, run now, advisory locks, job_runs and a
heartbeat. The visual-feed job (five VisualKit reads, COPY and MERGE cache,
suspect-batch guard, the apply in one transaction: drafts, change orders,
retire-moved, work order gone, closed and cancelled observed, projects and
units from order links, auto-release) and the fingerprint. The drawing-lookup
job (queue, budget, download on version change, sha256 into assets, decision
table, staging for rev approval, drawing-origin change orders). Clerical From
VISUAL panel, flags, rev approval, hand uploads, change-order review; Admin
Feed settings and resource map. Synthetic fixture generator and a
fixture-driven worker in CI with a Playwright scenario. Docs updated.

Verified: 3249 server tests and 13 Playwright scenarios on the docker-1 CI
stack, 76 frontend tests, doctor at 0004; one feed and one drawing run
against VISUAL DEV and the vault from the developer machine (counts in the
changelog).

Co-Authored-By: Claude Fable 5.1 <[email protected]>

server/packetstation/worker/__init__.py

@@ -0,0 +1,63 @@
+"""The background worker: the job scheduler plus a heartbeat (beat file and worker_heartbeat row).
+
+`run(beat_file, build, stop=None, interval=BEAT_SECONDS, settings=None)` blocks until SIGTERM, SIGINT or `stop`.
+With settings it builds and starts a Scheduler; without (the CLI tests) it only beats the file.
+"""
+
+from __future__ import annotations
+
+import logging
+import signal
+import threading
+from pathlib import Path
+from typing import TYPE_CHECKING
+
+from .heartbeat import BEAT_SECONDS, STALE_SECONDS, beat_age, touch
+
+if TYPE_CHECKING:
+    from ..settings import Settings
+
+log = logging.getLogger("packetstation.worker")
+
+__all__ = ["BEAT_SECONDS", "STALE_SECONDS", "beat_age", "run", "touch"]
+
+
+def run(
+    beat_file: Path,
+    build: str,
+    stop: threading.Event | None = None,
+    interval: float = BEAT_SECONDS,
+    settings: Settings | None = None,
+) -> int:
+    stop = stop or threading.Event()
+
+    def _stop(signum: int, _frame: object) -> None:
+        log.info("worker stopping on signal %s", signum)
+        stop.set()
+
+    if threading.current_thread() is threading.main_thread():
+        signal.signal(signal.SIGTERM, _stop)
+        signal.signal(signal.SIGINT, _stop)
+    log.info("worker started", extra={"ps": {"build": build, "beat_file": str(beat_file)}})
+    sched = None
+    if settings is not None:
+        from .scheduler import Scheduler
+
+        sched = Scheduler(settings, build=build)
+        sched.start()
+    try:
+        if sched is not None:
+            sched.serve(beat_file, stop, interval)
+        else:
+            while not stop.is_set():
+                try:
+                    touch(beat_file)
+                except OSError as e:
+                    log.error("can't touch beat file %s: %s", beat_file, e.strerror)
+                log.info("heartbeat", extra={"ps": {"build": build}})
+                stop.wait(interval)
+    finally:
+        if sched is not None:
+            sched.shutdown(wait=True)
+    log.info("worker stopped")
+    return 0

server/packetstation/worker/heartbeat.py

@@ -0,0 +1,36 @@
+"""The worker's heartbeat: a touched beat file for the container healthcheck and a worker_heartbeat row."""
+
+from __future__ import annotations
+
+import os
+import time
+from collections.abc import Iterable
+from pathlib import Path
+from typing import Any
+
+BEAT_SECONDS = 30
+STALE_SECONDS = 90
+
+
+def touch(path: Path) -> None:
+    path.parent.mkdir(parents=True, exist_ok=True)
+    path.touch(exist_ok=True)
+    now = time.time()
+    os.utime(path, (now, now))
+
+
+def beat_age(beat_file: Path) -> float | None:
+    try:
+        return time.time() - beat_file.stat().st_mtime
+    except OSError:
+        return None
+
+
+def write_row(conn: Any, *, build: str, host: str, pid: int, running: Iterable[str]) -> None:
+    """Upsert the single worker_heartbeat row."""
+    conn.execute(
+        "INSERT INTO worker_heartbeat (id, at, build, host, pid, running) VALUES (1, now(), %s, %s, %s, %s)"
+        " ON CONFLICT (id) DO UPDATE SET at = EXCLUDED.at, build = EXCLUDED.build, host = EXCLUDED.host,"
+        " pid = EXCLUDED.pid, running = EXCLUDED.running",
+        (build, host, pid, sorted(running)),
+    )

server/packetstation/worker/jobs/__init__.py

@@ -0,0 +1,146 @@
+"""The job registry and the shapes every job uses.
+
+Jobs import `from packetstation.worker.jobs import JobContext, JobSpec, register` and expose `SPEC`. The feed and
+drawing jobs are imported lazily by `load_jobs`, so the worker runs before they exist.
+"""
+
+from __future__ import annotations
+
+import importlib
+import logging
+import threading
+from collections.abc import Callable
+from dataclasses import dataclass, field
+from datetime import UTC, date, datetime, time, timedelta
+from typing import Any
+from zoneinfo import ZoneInfo
+
+from ...feed.config import FeedSettings
+from ...settings import Settings
+from ..redaction import MAX_ERRORS, clip, redact
+
+log = logging.getLogger(__name__)
+
+Counts = dict[str, Any]
+Cadence = Callable[[FeedSettings, datetime], int | None]
+TRIGGERS = ("schedule", "request", "chain", "cli")
+
+
+@dataclass
+class Stack:
+    """Per-process state shared by every run: the startup guard result and long-lived objects (the M-Files vault)."""
+
+    guard: Any = None
+    cache: dict[str, Any] = field(default_factory=dict)
+    lock: threading.Lock = field(default_factory=threading.Lock)
+
+    def cached(self, key: str, factory: Callable[[], Any]) -> Any:
+        """The object under `key`, made once by `factory`. A factory that raises leaves nothing cached."""
+        with self.lock:
+            if key not in self.cache:
+                self.cache[key] = factory()
+            return self.cache[key]
+
+    def drop(self, key: str) -> None:
+        with self.lock:
+            self.cache.pop(key, None)
+
+
+@dataclass
+class JobContext:
+    """What a run gets. `conn` is the run's own autocommit connection as the worker role."""
+
+    conn: Any
+    settings: Settings
+    feed_settings: FeedSettings
+    run_id: int
+    trigger: str
+    started_at: datetime
+    log: logging.Logger
+    stack: Stack
+    degraded: bool = False
+    errors: list[str] = field(default_factory=list)
+    visual_target: str | None = None
+
+    def error(self, text: str, *, degrade: bool = True) -> None:
+        """Record one error (redacted, clipped). It makes the run degraded unless degrade is False."""
+        if len(self.errors) < MAX_ERRORS:
+            self.errors.extend(clip([text]))
+        if degrade:
+            self.degraded = True
+
+    def degrade(self, reason: str | None = None) -> None:
+        self.degraded = True
+        if reason:
+            self.error(reason)
+
+    @property
+    def tz(self) -> ZoneInfo:
+        return ZoneInfo(self.settings.site_tz)
+
+    def now_site(self) -> datetime:
+        return datetime.now(self.tz)
+
+    def today_site(self) -> date:
+        return self.now_site().date()
+
+
+@dataclass(frozen=True)
+class JobSpec:
+    name: str
+    run: Callable[[JobContext], Counts]
+    cadence: Cadence  # seconds to the next run, or None for "no schedule"
+    pausable: bool  # the feed pause skips scheduled fires (requests still run)
+    chain: tuple[str, ...] = ()  # moved to now after a run that did not fail
+
+
+JOBS: dict[str, JobSpec] = {}
+_loaded = False
+_load_lock = threading.Lock()
+LAZY = ("visual_feed", "drawing_lookup")
+
+
+def register(spec: JobSpec) -> JobSpec:
+    JOBS[spec.name] = spec
+    return spec
+
+
+def load_jobs() -> dict[str, JobSpec]:
+    """Register every job once and return the registry. A job module that cannot import is logged and left out."""
+    global _loaded
+    with _load_lock:
+        if not _loaded:
+            from . import housekeeping
+
+            register(housekeeping.SPEC)
+            for mod in LAZY:
+                try:
+                    m = importlib.import_module(f"{__name__}.{mod}")
+                    register(m.SPEC)
+                except ImportError as e:
+                    log.warning("job module %s not loaded: %s", mod, redact(str(e)))
+            _loaded = True
+    return JOBS
+
+
+def seconds_until(now_site: datetime, at: time) -> int:
+    """Seconds from now_site to the next `at` (site wall clock), at least 1."""
+    target = datetime.combine(now_site.date(), at, tzinfo=now_site.tzinfo)
+    if target <= now_site:
+        target = datetime.combine(now_site.date() + timedelta(days=1), at, tzinfo=now_site.tzinfo)
+    # Aware datetimes sharing a tzinfo subtract as wall clock; through UTC a DST change counts right
+    return max(1, int((target.astimezone(UTC) - now_site.astimezone(UTC)).total_seconds()))
+
+
+__all__ = [
+    "JOBS",
+    "TRIGGERS",
+    "Cadence",
+    "Counts",
+    "JobContext",
+    "JobSpec",
+    "Stack",
+    "load_jobs",
+    "register",
+    "seconds_until",
+]

server/packetstation/worker/jobs/drawing_lookup.py

@@ -0,0 +1,536 @@
+"""The drawing-lookup job: look drawings up in M-Files (read-only), copy released PDFs into assets, and attach,
+flag, stage or open a change order on the packets that use them.
+
+Per run: the queue (drawings/queue.py) cut to `drawing_budget`; per drawing one `Lookup.status`, a fetch when a
+released file exists (drawings/fetch.py downloads only when its M-Files identity changed), the `drawing_lookups`
+row, then `decide` for every live packet that uses the drawing (its own drawing, or the target of its pending feed
+change order), applied through `feed.writes.system_write`. A busy packet is left for the next run.
+
+Never writes to M-Files.
+"""
+
+from __future__ import annotations
+
+import logging
+from dataclasses import dataclass
+from datetime import UTC, datetime
+from typing import Any
+
+from psycopg.rows import dict_row
+from psycopg.types.json import Jsonb
+
+from ... import audit, policy
+from ...domain import pipeline
+from ...drawings import DRAWING_FLAGS, decide, queue
+from ...drawings import lookup as lookups
+from ...drawings.fetch import FetchError, FetchResult, fetch
+from ...drawings.lookup import Found, Lookup
+from ...feed import changes, writes
+from . import Counts, JobContext, JobSpec
+
+log = logging.getLogger(__name__)
+
+A = policy.Action
+D = decide
+
+FEED_ORIGINS = ("visual", "drawing")
+
+
+class _Stale(Exception):
+    """The packet changed between the read and the lock; the next run decides again."""
+
+
+def new_counts() -> Counts:
+    return {
+        "checked": 0,
+        "fetched": 0,
+        "unchanged": 0,
+        "attached": 0,
+        "flagged": {},
+        "lookup_failed": 0,
+        "cos_opened": 0,
+        "cos_reaimed": 0,
+        "staged": 0,
+        "budget_left": 0,
+        "fetch_failed": 0,
+        "busy": 0,
+        "refused": 0,
+        "no_file": 0,
+    }
+
+
+# ---------------------------------------------------------------- the run
+
+
+def run(ctx: JobContext) -> Counts:
+    counts = new_counts()
+    fs = ctx.feed_settings
+    budget = int(getattr(fs, "drawing_budget", 60))
+    try:
+        lk = lookups.make(ctx.settings, ctx.stack.cache)
+    except Exception as e:  # any failure to open M-Files skips the run
+        ctx.error(f"M-Files could not be opened: {type(e).__name__}: {e}")
+        counts["reason"] = "mfiles unavailable"
+        counts["budget_left"] = budget
+        return counts
+    now = datetime.now(UTC)
+    items = queue.queue(ctx.conn, fs, now, limit=budget)
+    counts["budget_left"] = max(0, budget - len(items))
+    counts["source"] = lk.describe()
+    for item in items:
+        try:
+            _drawing(ctx, lk, item, counts, now)
+        except Exception as e:  # one bad drawing must not stop the others
+            log.exception("drawing %s failed", item.dwg)
+            ctx.error(f"drawing {item.dwg}: {type(e).__name__}: {e}")
+    return counts
+
+
+def _drawing(ctx: JobContext, lk: Lookup, item: queue.QueueItem, counts: Counts, now: datetime) -> None:
+    conn = ctx.conn
+    try:
+        found = lk.status(item.dwg)
+    except Exception as e:  # a lookup error is a failed lookup, never a crash
+        found = lookups.failed(item.dwg, f"M-Files lookup failed: {type(e).__name__}: {e}")
+    counts["checked"] += 1
+    fetched: FetchResult | None = None
+    fetch_failed = False
+    if found.ok and found.rev is not None:
+        try:
+            fetched = fetch(conn, ctx.settings, lk, found, dwg=item.dwg)
+        except FetchError as e:
+            fetch_failed = True
+            counts["fetch_failed"] += 1
+            ctx.error(str(e))
+        else:
+            if fetched.downloaded:
+                counts["fetched"] += 1
+                audit.append(
+                    conn,
+                    action="drawing.fetched",
+                    role_snapshot="system",
+                    subject_type="asset",
+                    subject_id=str(fetched.asset_id),
+                    detail={
+                        "dwg": item.dwg,
+                        "rev": found.rev,
+                        "sha256": fetched.sha256.hex(),
+                        "reused": fetched.reused,
+                    },
+                )
+    if not found.ok:
+        counts["lookup_failed"] += 1
+        ctx.error(f"drawing {item.dwg}: {D.failed_note(found)}")
+    vrev_seen = item.visual_rev if item.co_id is None else own_rev(conn, item.dwg)
+    save_lookup(conn, item, found, fetched, now, fetch_failed=fetch_failed, visual_rev_seen=vrev_seen)
+    scope = [str(d) for d in (getattr(ctx.feed_settings, "departments", None) or [])]
+    for pid, relations in sharing(conn, item.dwg, scope):
+        _packet(ctx, item.dwg, found, fetched, pid, relations, counts)
+
+
+# ---------------------------------------------------------------- drawing_lookups
+
+
+def save_lookup(
+    conn: Any,
+    item: queue.QueueItem,
+    found: Found,
+    fetched: FetchResult | None,
+    now: datetime,
+    *,
+    fetch_failed: bool,
+    visual_rev_seen: str | None,
+) -> None:
+    """Upsert the drawing_lookups row for this lookup.
+
+    A failed lookup keeps everything known before (rev, file, asset) and backs off. A good one stores what M-Files
+    has; the file identity and the asset are stored together, and cleared when there is no released file or the
+    copy failed (so the next run downloads again).
+    """
+    with conn.transaction():
+        prev = conn.execute("SELECT fail_count FROM drawing_lookups WHERE dwg = %s FOR UPDATE", (item.dwg,)).fetchone()
+        if not found.ok:
+            fails = (int(prev[0]) if prev else 0) + 1
+            conn.execute(
+                "INSERT INTO drawing_lookups (dwg, checked_at, ok, note, fail_count, failing_since, next_check_at,"
+                " visual_rev_seen) VALUES (%(dwg)s, %(now)s, false, %(note)s, %(fails)s, %(now)s, %(next)s, %(vrev)s)"
+                " ON CONFLICT (dwg) DO UPDATE SET checked_at = EXCLUDED.checked_at, ok = false, note = EXCLUDED.note,"
+                " fail_count = EXCLUDED.fail_count,"
+                " failing_since = coalesce(drawing_lookups.failing_since, EXCLUDED.failing_since),"
+                " next_check_at = EXCLUDED.next_check_at, visual_rev_seen = EXCLUDED.visual_rev_seen",
+                {
+                    "dwg": item.dwg,
+                    "now": now,
+                    "note": D.failed_note(found),
+                    "fails": fails,
+                    "next": now + queue.backoff(fails),
+                    "vrev": visual_rev_seen,
+                },
+            )
+            return
+        has_file = fetched is not None
+        conn.execute(
+            "INSERT INTO drawing_lookups (dwg, checked_at, ok, rev, name, obj_id, obj_version, file_id, file_version,"
+            " file_size, base, draft_rev, draft_where, in_drafting, note, fail_count, failing_since, asset_id, sha256,"
+            " visual_rev_seen, next_check_at) VALUES (%(dwg)s, %(now)s, true, %(rev)s, %(name)s, %(obj_id)s,"
+            " %(obj_version)s, %(file_id)s, %(file_version)s, %(file_size)s, %(base)s, %(draft_rev)s,"
+            " %(draft_where)s, %(in_drafting)s, %(note)s, 0, NULL, %(asset_id)s, %(sha)s, %(vrev)s, %(next)s)"
+            " ON CONFLICT (dwg) DO UPDATE SET checked_at = EXCLUDED.checked_at, ok = true, rev = EXCLUDED.rev,"
+            " name = EXCLUDED.name, obj_id = EXCLUDED.obj_id, obj_version = EXCLUDED.obj_version,"
+            " file_id = EXCLUDED.file_id, file_version = EXCLUDED.file_version, file_size = EXCLUDED.file_size,"
+            " base = EXCLUDED.base, draft_rev = EXCLUDED.draft_rev, draft_where = EXCLUDED.draft_where,"
+            " in_drafting = EXCLUDED.in_drafting, note = EXCLUDED.note, fail_count = 0, failing_since = NULL,"
+            " asset_id = EXCLUDED.asset_id, sha256 = EXCLUDED.sha256,"
+            " visual_rev_seen = coalesce(EXCLUDED.visual_rev_seen, drawing_lookups.visual_rev_seen),"
+            " next_check_at = EXCLUDED.next_check_at",
+            {
+                "dwg": item.dwg,
+                "now": now,
+                "rev": found.rev,
+                "name": found.name,
+                "obj_id": found.obj_id if has_file else None,
+                "obj_version": found.obj_version if has_file else None,
+                "file_id": found.file_id if has_file else None,
+                "file_version": found.file_version if has_file else None,
+                "file_size": found.file_size,
+                "base": found.base,
+                "draft_rev": found.draft_rev,
+                "draft_where": found.draft_where or None,
+                "in_drafting": found.in_drafting,
+                "note": found.note or None,
+                "asset_id": fetched.asset_id if fetched else None,
+                "sha": fetched.sha256 if fetched else None,
+                "vrev": visual_rev_seen,
+                "next": now + queue.backoff(1) if fetch_failed else None,
+            },
+        )
+
+
+# ---------------------------------------------------------------- packets
+
+
+def own_rev(conn: Any, dwg: str) -> str | None:
+    """The rev a live VISUAL packet with this drawing carries (for visual_rev_seen when the item came from a CO)."""
+    row = conn.execute(
+        "SELECT coalesce(btrim(rev), '') FROM packets WHERE removed_at IS NULL AND source_kind = 'visual'"
+        " AND status <> 'filed' AND btrim(drawing) = %s ORDER BY id LIMIT 1",
+        (dwg,),
+    ).fetchone()
+    return None if row is None else str(row[0])
+
+
+SHARING_SQL = """
+SELECT p.id, 'own' AS rel FROM packets p
+WHERE p.removed_at IS NULL AND p.source_kind = 'visual' AND p.status <> 'filed' AND btrim(p.drawing) = %(dwg)s
+  AND (cardinality(%(depts)s::text[]) = 0 OR p.dept_code = ANY(%(depts)s::text[]))
+UNION
+SELECT p.id, 'co' AS rel FROM change_orders c JOIN packets p ON p.id = c.packet_id
+WHERE c.review = 'pending' AND c.origin IN ('visual', 'drawing') AND jsonb_typeof(c.waiting) = 'object'
+  AND btrim(c.waiting->>'dwg') = %(dwg)s AND p.removed_at IS NULL AND p.status NOT IN ('draft', 'filed')
+  AND (cardinality(%(depts)s::text[]) = 0 OR p.dept_code = ANY(%(depts)s::text[]))
+ORDER BY 1
+"""
+
+
+def sharing(conn: Any, dwg: str, depts: list[str]) -> list[tuple[int, set[str]]]:
+    """Live packets that use the drawing: as their own drawing ('own') or as a pending feed CO's target ('co')."""
+    out: dict[int, set[str]] = {}
+    for pid, rel in conn.execute(SHARING_SQL, {"dwg": dwg, "depts": depts}).fetchall():
+        out.setdefault(int(pid), set()).add(str(rel))
+    return sorted(out.items())
+
+
+@dataclass
+class PacketFacts:
+    row: dict[str, Any]
+    visual: dict[str, Any]
+    attached_rev: str | None
+    attached_shas: set[bytes]
+    co: dict[str, Any] | None
+    rejected_sha: bytes | None
+
+
+def _sha(value: Any) -> bytes | None:
+    if not isinstance(value, str) or not value:
+        return None
+    try:
+        return bytes.fromhex(value)
+    except ValueError:
+        return None
+
+
+def facts(conn: Any, pid: int) -> PacketFacts | None:
+    with conn.cursor(row_factory=dict_row) as cur:
+        row = cur.execute(
+            "SELECT id, status::text AS status, drawing, rev, drawing_state::text AS drawing_state, flags, visual,"
+            " version FROM packets WHERE id = %s AND removed_at IS NULL",
+            (pid,),
+        ).fetchone()
+        if row is None:
+            return None
+        pages = cur.execute(
+            "SELECT pg.rev, a.sha256 FROM packet_pages pg LEFT JOIN assets a ON a.id = pg.asset_id"
+            " WHERE pg.packet_id = %s AND pg.type = 'drawing' AND pg.void_at IS NULL ORDER BY pg.n",
+            (pid,),
+        ).fetchall()
+        co = cur.execute(
+            "SELECT id, co_no, origin::text AS origin, waiting, staged FROM change_orders"
+            " WHERE packet_id = %s AND review = 'pending' AND origin IN ('visual', 'drawing') ORDER BY id DESC LIMIT 1",
+            (pid,),
+        ).fetchone()
+        rej = cur.execute(
+            "SELECT staged FROM change_orders WHERE packet_id = %s AND origin = 'drawing' AND review = 'rejected'"
+            " ORDER BY id DESC LIMIT 1",
+            (pid,),
+        ).fetchone()
+    visual = row["visual"] if isinstance(row["visual"], dict) else {}
+    attached_rev = None
+    if pages:
+        attached_rev = str(pages[0]["rev"] or "").strip()
+    shas = {bytes(p["sha256"]) for p in pages if p["sha256"] is not None}
+    rejected = None
+    if rej is not None and isinstance(rej["staged"], dict):
+        rejected = _sha(rej["staged"].get("sha256"))
+    return PacketFacts(dict(row), dict(visual), attached_rev, shas, dict(co) if co else None, rejected)
+
+
+def _dwg_rev(value: Any) -> tuple[str, str] | None:
+    if isinstance(value, dict) and value.get("dwg") and value.get("rev") is not None:
+        return (str(value["dwg"]).strip(), str(value["rev"]).strip())
+    return None
+
+
+def target_for(dwg: str, pf: PacketFacts, *, own: bool) -> D.Target:
+    row, visual, co = pf.row, pf.visual, pf.co
+    waiting = co.get("waiting") if co else None
+    staged = co.get("staged") if co else None
+    co_waiting = _dwg_rev(waiting)
+    co_staged = _dwg_rev(staged)
+    packet_rev = str(row["rev"] or "").strip()
+    rev_ok = None
+    ro = visual.get("rev_ok")
+    if isinstance(ro, dict) and ro.get("rev") is not None and str(ro.get("vis_rev") or "").strip() == packet_rev:
+        rev_ok = str(ro["rev"]).strip()
+    visual_rev = packet_rev if own or co_waiting is None else co_waiting[1]
+    return D.Target(
+        dwg=dwg,
+        visual_rev=visual_rev,
+        attached_rev=pf.attached_rev,
+        attached_sha=next(iter(sorted(pf.attached_shas)), None),
+        status=str(row["status"]),
+        drawing_state=str(row["drawing_state"]),
+        has_hand_drawing=row["drawing_state"] == "hand" or bool(visual.get("manual_dwg")),
+        rev_ok=rev_ok,
+        co_waiting=co_waiting,
+        co_staged=co_staged,
+        co_pending=co is not None,
+        co_staged_sha=_sha(staged.get("sha256")) if isinstance(staged, dict) else None,
+        rejected_sha=pf.rejected_sha,
+    )
+
+
+def appr_of(t: D.Target, f: Found, now: datetime) -> dict[str, Any]:
+    return {
+        "ok": f.ok,
+        "rev": f.rev,
+        "vrev": t.visual_rev,
+        "name": f.name,
+        "note": f.note or "",
+        "base": f.base,
+        "draft_rev": f.draft_rev,
+        "draft_where": f.draft_where,
+        "in_drafting": f.in_drafting,
+        "at": now.isoformat(),
+    }
+
+
+def _same_appr(a: Any, b: dict[str, Any]) -> bool:
+    if not isinstance(a, dict):
+        return False
+    return {k: v for k, v in a.items() if k != "at"} == {k: v for k, v in b.items() if k != "at"}
+
+
+def new_flags(flags: list[str], d: D.Decision) -> list[str]:
+    """Every flag but the drawing ones, then the decision's flag."""
+    out = [f for f in flags if f not in DRAWING_FLAGS]
+    if d.flag and d.flag not in out:
+        out.append(d.flag)
+    return out
+
+
+def _packet(
+    ctx: JobContext,
+    dwg: str,
+    found: Found,
+    fetched: FetchResult | None,
+    pid: int,
+    relations: set[str],
+    counts: Counts,
+) -> None:
+    conn = ctx.conn
+    pf = facts(conn, pid)
+    if pf is None:
+        return
+    own = "own" in relations
+    t = target_for(dwg, pf, own=own)
+    same_file = fetched is not None and fetched.sha256 in pf.attached_shas
+    d = D.decide(t, found, same_file=same_file, fetched_sha=fetched.sha256 if fetched else None)
+    if not own and d.kind != D.STAGE_FOR_CO:
+        return  # only the CO's target drawing: nothing to do until it can be staged
+    if d.kind in (D.ATTACH, D.OPEN_CO, D.STAGE_FOR_CO) and fetched is None:
+        counts["no_file"] += 1  # the copy failed this run; try again next run
+        return
+    now = datetime.now(UTC)
+    row, visual = pf.row, pf.visual
+    flags = list(row["flags"] or [])
+    flags_after = new_flags(flags, d) if own else flags
+    patch: dict[str, Any] = {}
+    if own:
+        appr = appr_of(t, found, now)
+        if not _same_appr(visual.get("appr"), appr):
+            patch["appr"] = appr
+        if found.ok:
+            confirmed = D.rev_confirmed(t, found)
+            if bool(visual.get("rev_confirmed")) != confirmed:
+                patch["rev_confirmed"] = confirmed
+    state_after = d.drawing_state if own else str(row["drawing_state"])
+    material = (
+        d.kind in (D.ATTACH, D.OPEN_CO, D.STAGE_FOR_CO)
+        or flags_after != flags
+        or state_after != row["drawing_state"]
+        or bool(patch)
+    )
+    if not material:
+        counts["unchanged"] += 1
+        return
+    action = A.VIS_UPDATE_DRAFT if row["status"] == "draft" else A.VIS_OPEN_CO
+    label, note = "Drawing status from M-Files", d.note or None
+    if d.kind == D.ATTACH and fetched is not None:
+        label = "Drawing attached from M-Files"
+        note = "; ".join(x for x in (fetched.name or found.name or "", d.note) if x) or None
+    detail = {"dwg": dwg, "rev": found.rev, "kind": d.kind, "asset_id": str(fetched.asset_id) if fetched else None}
+    try:
+        with writes.system_write(conn, pid, action, label=label, note=note, detail=detail) as sw:
+            if int(sw.packet["version"]) != int(row["version"]):
+                raise _Stale
+            if d.kind == D.ATTACH and fetched is not None:
+                _attach(sw, pid, dwg, found, fetched, d, flags_after, patch, now)
+                counts["attached"] += 1
+            else:
+                _status(sw, pid, state_after, flags_after, patch)
+                if d.flag:
+                    fl = counts["flagged"]
+                    fl[d.kind] = fl.get(d.kind, 0) + 1
+                if d.kind == D.OPEN_CO and fetched is not None:
+                    _open_co(sw, t, dwg, found, fetched, d, counts)
+                elif d.kind == D.STAGE_FOR_CO and fetched is not None and pf.co is not None:
+                    _stage(sw, pf.co, dwg, found, fetched)
+                    counts["staged"] += 1
+                elif d.kind == D.UNCHANGED:
+                    counts["unchanged"] += 1
+    except (_Stale, writes.Busy, writes.Missing):
+        counts["busy"] += 1
+    except writes.Refused as e:
+        counts["refused"] += 1
+        ctx.error(f"packet {pid}: {d.kind} refused: {e}", degrade=False)
+
+
+def _staged(dwg: str, found: Found, fetched: FetchResult) -> dict[str, Any]:
+    return {
+        "asset_id": str(fetched.asset_id),
+        "name": fetched.name or found.name,
+        "rev": str(found.rev),
+        "dwg": dwg,
+        "sha256": fetched.sha256.hex(),
+        "pages": fetched.pages,
+    }
+
+
+def _attach(
+    sw: Any,
+    pid: int,
+    dwg: str,
+    found: Found,
+    fetched: FetchResult,
+    d: D.Decision,
+    flags: list[str],
+    patch: dict[str, Any],
+    now: datetime,
+) -> None:
+    conn = sw.conn
+    pages = max(1, int(fetched.pages))
+    conn.execute("DELETE FROM packet_pages WHERE packet_id = %s AND type = 'drawing'", (pid,))
+    n0 = pipeline.next_counter(conn, pid, "page", pages)
+    rev = str(found.rev)
+    with conn.cursor() as cur:
+        cur.executemany(
+            "INSERT INTO packet_pages (packet_id, n, type, asset_id, pn, dwg, rev) VALUES (%s, %s, 'drawing', %s, %s,"
+            " %s, %s)",
+            [(pid, n0 + i, fetched.asset_id, i + 1, dwg, rev) for i in range(pages)],
+        )
+    vault = {
+        "asset_id": str(fetched.asset_id),
+        "name": fetched.name or found.name,
+        "rev": found.rev,
+        "note": d.note,
+        "at": now.isoformat(),
+    }
+    merged = {**patch, "rev_confirmed": True, "vault": vault}
+    conn.execute(
+        "UPDATE packets SET drawing_state = 'attached', flags = %s, visual = (visual - 'manual_dwg') || %s"
+        " WHERE id = %s",
+        (flags, Jsonb(merged), pid),
+    )
+    sw.changed("pages", "drawing_state", "flags", "visual")
+
+
+def _status(sw: Any, pid: int, state: str, flags: list[str], patch: dict[str, Any]) -> None:
+    sw.conn.execute(
+        "UPDATE packets SET drawing_state = %s::drawing_state, flags = %s, visual = visual || %s WHERE id = %s",
+        (state, flags, Jsonb(patch), pid),
+    )
+    sw.changed("drawing_state", "flags", "visual")
+
+
+def _open_co(sw: Any, t: D.Target, dwg: str, found: Found, fetched: FetchResult, d: D.Decision, counts: Counts) -> None:
+    vis = {
+        "from_dwg": dwg,
+        "to_dwg": dwg,
+        "dwg": dwg,
+        "from_rev": t.attached_rev,
+        "to_rev": str(found.rev),
+        "dwg_change": True,
+        "changes": [d.note],
+    }
+    res = changes.open_or_reaim(
+        sw,
+        origin="drawing",
+        reason=d.note,
+        vis=vis,
+        waiting=None,
+        staged=_staged(dwg, found, fetched),
+        target_fp=None,
+        minor=False,
+    )
+    # open_or_reaim writes the packet_log label itself
+    counts["cos_opened" if res.fresh else "cos_reaimed"] += 1
+
+
+def _stage(sw: Any, co: dict[str, Any], dwg: str, found: Found, fetched: FetchResult) -> None:
+    staged = _staged(dwg, found, fetched)
+    sw.conn.execute(
+        "UPDATE change_orders SET staged = %s, waiting = NULL, row_version = row_version + 1"
+        " WHERE id = %s AND review = 'pending'",
+        (Jsonb(staged), co["id"]),
+    )
+    sw.changed("change_orders")
+    sw.log(f"Drawing for change order {co['co_no']} ready for Clerical", staged["name"])
+
+
+def _cadence(fs: Any, now: datetime) -> int | None:
+    return int(fs.drawing_interval_minutes) * 60
+
+
+SPEC = JobSpec(name="drawing-lookup", run=run, cadence=_cadence, pausable=True)
+
+__all__ = ["SPEC", "new_flags", "run", "save_lookup", "sharing", "target_for"]

server/packetstation/worker/jobs/housekeeping.py

@@ -0,0 +1,60 @@
+"""Housekeeping, nightly at 03:30 site time: prune the VISUAL change rows and gone cache rows, old job runs and
+old claimed run requests. It never touches packets, the audit log or anything append-only."""
+
+from __future__ import annotations
+
+from datetime import datetime, time
+
+from ...feed.config import FeedSettings
+from . import Counts, JobContext, JobSpec, seconds_until
+
+AT = time(3, 30)
+CACHE_DAYS = 90
+RUNS_DAYS = 180
+REQUESTS_DAYS = 30
+
+STEPS: tuple[tuple[str, str, int], ...] = (
+    ("row_changes", "DELETE FROM visual_row_changes WHERE at < now() - make_interval(days => %s)", CACHE_DAYS),
+    (
+        "material_changes",
+        "DELETE FROM visual_material_changes WHERE at < now() - make_interval(days => %s)",
+        CACHE_DAYS,
+    ),
+    (
+        "gone_rows",
+        "DELETE FROM visual_rows WHERE gone_batch IN"
+        " (SELECT id FROM visual_batches WHERE started_at < now() - make_interval(days => %s))",
+        CACHE_DAYS,
+    ),
+    (
+        "gone_materials",
+        "DELETE FROM visual_materials WHERE gone_batch IN"
+        " (SELECT id FROM visual_batches WHERE started_at < now() - make_interval(days => %s))",
+        CACHE_DAYS,
+    ),
+    (
+        "job_runs",
+        "DELETE FROM job_runs WHERE started_at < now() - make_interval(days => %s) AND status <> 'running'",
+        RUNS_DAYS,
+    ),
+    (
+        "job_requests",
+        "DELETE FROM job_requests WHERE claimed_at IS NOT NULL AND claimed_at < now() - make_interval(days => %s)",
+        REQUESTS_DAYS,
+    ),
+)
+
+
+def run(ctx: JobContext) -> Counts:
+    counts: Counts = {}
+    for name, sql, days in STEPS:
+        with ctx.conn.transaction():
+            counts[name] = ctx.conn.execute(sql, (days,)).rowcount
+    return counts
+
+
+def cadence(_: FeedSettings, now_site: datetime) -> int:
+    return seconds_until(now_site, AT)
+
+
+SPEC = JobSpec(name="housekeeping", run=run, cadence=cadence, pausable=False)

server/packetstation/worker/jobs/visual_feed.py

@@ -0,0 +1,141 @@
+"""The visual-feed job: read VISUAL (or the fixture files), record the read in the cache, build the candidates
+from the cache and apply them.
+
+Per run: the feed settings; the tracked keys (every work order of a live VISUAL packet that is not filed, plus the
+go-live rows Clerical pulled in); the window from today in site time; one read through the source (labor at most
+every 30 minutes); `cache.write_batch`; `cache.rows_for_apply`; `candidates.build`; `apply.apply`. The run is
+degraded when a read section failed or the batch is suspect.
+
+VisualKit: one `Visual.from_env()` per run, closed after, and the stack guard checked against its settings before
+the first read. Read-only: VisualKit enforces it.
+"""
+
+from __future__ import annotations
+
+from datetime import UTC, datetime, timedelta
+from typing import Any
+
+from ... import guard
+from ...feed import apply as feed_apply
+from ...feed import cache, candidates, config
+from ...feed.config import FeedSettings
+from ...feed.source import FeedSource, FixtureSource, VisualKitSource
+from ...feed.types import FeedData, WoKey
+from . import Counts, JobContext, JobSpec
+
+LABOR_EVERY = timedelta(minutes=30)
+
+
+def tracked_keys(conn: Any) -> list[WoKey]:
+    """Work orders of live VISUAL packets that are not filed, plus pulled-in go-live rows."""
+    rows = conn.execute(
+        "SELECT DISTINCT w.wo_base, w.lot, w.split, w.sub FROM packet_work_orders w JOIN packets p"
+        " ON p.id = w.packet_id WHERE p.removed_at IS NULL AND p.status <> 'filed' AND p.source_kind = 'visual'"
+        " UNION SELECT wo_base, lot, split, sub FROM visual_ignored_wos WHERE pulled_in_at IS NOT NULL"
+    ).fetchall()
+    return sorted({WoKey(r[0], r[1], r[2], r[3]) for r in rows}, key=lambda k: k.as_tuple())
+
+
+def resource_map(conn: Any) -> dict[str, str]:
+    return {r[0]: r[1] for r in conn.execute("SELECT resource, target FROM visual_resource_map")}
+
+
+def _labor_due(conn: Any, fs: FeedSettings) -> bool:
+    if not fs.labor_tickets:
+        return False
+    last = cache.last_labor_read(conn)
+    return last is None or datetime.now(UTC) - last >= LABOR_EVERY
+
+
+def _read(source: FeedSource, ctx: JobContext, tracked: list[WoKey], window: tuple[Any, Any], labor: bool) -> FeedData:
+    return source.read(
+        site=ctx.settings.site_id,
+        since=window[0],
+        until=window[1],
+        tracked=tracked,
+        with_materials=True,
+        with_orders=True,
+        with_labor=labor,
+        labor_since=None,
+    )
+
+
+def run(ctx: JobContext) -> Counts:
+    conn = ctx.conn
+    fs = ctx.feed_settings
+    today = ctx.today_site()
+    window = config.window(fs, today)
+    tracked = tracked_keys(conn)
+    labor_due = _labor_due(conn, fs)
+
+    if ctx.settings.feed_source == "fixture":
+        fixture = FixtureSource(ctx.settings.fixture_dir)
+        describe = fixture.describe()
+        data = _read(fixture, ctx, tracked, window, labor_due)
+    else:
+        from visualkit import Visual
+
+        with Visual.from_env() as v:
+            # The stack guard against this run's own VisualKit settings, before the first read.
+            result = guard.check_stack(ctx.settings, v.settings)
+            ctx.visual_target = ctx.visual_target or result.target
+            vk = VisualKitSource(v)
+            describe = vk.describe()
+            data = _read(vk, ctx, tracked, window, labor_due)
+    for e in data.errors:
+        ctx.error(e)
+
+    batch = cache.write_batch(conn, ctx.run_id, data, describe, window)
+    if batch.suspect:
+        ctx.degrade(f"suspect read: {batch.reason}; nothing marked gone")
+
+    in_play = {r.key for r in data.rows} | set(tracked)
+    rows, mats, mat_legs = cache.rows_for_apply(conn, in_play)
+    if data.material_legs:
+        mat_legs |= data.material_legs
+    built = candidates.build(
+        rows,
+        mats,
+        mat_legs,
+        resource_map=resource_map(conn),
+        window=window,
+        golive=fs.golive_date,
+        departments=fs.departments,
+        tracked_keys=set(tracked),
+        today=today,
+    )
+    bases = {r.wo for r in rows}
+    projects = {candidates.project_of(b) for b in bases} | {c.project for c in built.candidates.values()}
+    orders = cache.orders(conn, bases=bases | projects, projects=projects)
+    counts = feed_apply.apply(
+        conn,
+        ctx=ctx,
+        batch=batch,
+        feed_settings=fs,
+        built=built,
+        orders=orders,
+        labor=cache.labor_hours(conn),
+        today=today,
+        seen={r.key: r.st for r in data.rows},
+        missing=() if batch.suspect else data.tracked_missing,
+    )
+    counts["wos_window"] = data.window_count
+    counts["wos_tracked"] = len(tracked)
+    counts["rows"] = len(data.rows)
+    counts["materials"] = len(data.materials) if data.materials is not None else 0
+    counts["orders"] = int(batch.counts.get("orders", 0))
+    counts["labor_legs"] = int(batch.counts.get("labor_legs", 0))
+    counts["batch_id"] = batch.id
+    if batch.suspect:
+        counts["suspect_reason"] = batch.reason
+    cache.finish_batch(conn, batch.id, counts)
+    return counts
+
+
+def _cadence(fs: FeedSettings, now_site: datetime) -> int | None:
+    return config.interval_seconds(fs, now_site)
+
+
+SPEC = JobSpec(name="visual-feed", run=run, cadence=_cadence, pausable=True, chain=("drawing-lookup",))
+
+__all__ = ["SPEC", "resource_map", "run", "tracked_keys"]

server/packetstation/worker/redaction.py

@@ -0,0 +1,62 @@
+"""Redaction for job errors and log lines: no password, key or token ever reaches job_runs or a log."""
+
+from __future__ import annotations
+
+import os
+import re
+
+MAX_ERRORS = 20
+MAX_ERROR_CHARS = 500
+
+# Environment variables whose values are secrets when set (MFilesKit reads MFILES_PASSWORD; VisualKit may read
+# VISUAL_PASSWORD). They are read only to strip them from text, never logged.
+SECRET_ENV = ("VISUAL_PASSWORD", "MFILES_PASSWORD", "PGPASSWORD", "LDAP_PASSWORD")
+SECRET_FILE_ENV = ("VISUAL_PASSWORD_FILE", "MFILES_PASSWORD_FILE")
+
+_PATTERNS = (
+    re.compile(r"(?i)\b(password|passwd|pwd|secret|token|api[_-]?key)\s*[=:]\s*(\"[^\"]*\"|'[^']*'|[^\s;,&]+)"),
+    re.compile(r"(?i)\bauthorization\s*:\s*[^\r\n]*"),
+    re.compile(r"(?i)\bx-authentication\s*:\s*[^\r\n]*"),
+    re.compile(r"(?i)(\w+://[^:/\s@]+:)([^@\s]+)(@)"),
+)
+
+
+def _secrets() -> list[str]:
+    out = []
+    for name in SECRET_ENV:
+        v = os.environ.get(name)
+        if v and len(v) >= 4:
+            out.append(v)
+    for name in SECRET_FILE_ENV:
+        path = os.environ.get(name)
+        if not path:
+            continue
+        try:
+            with open(path, encoding="utf-8") as f:
+                v = f.read().rstrip("\r\n")
+        except OSError:
+            continue
+        if v and len(v) >= 4:
+            out.append(v)
+    return out
+
+
+def redact(text: str) -> str:
+    """Strip anything that looks like a credential, plus the VISUAL and M-Files passwords if set."""
+    s = str(text)
+    for secret in _secrets():
+        s = s.replace(secret, "[redacted]")
+    s = _PATTERNS[0].sub(lambda m: f"{m.group(1)}=[redacted]", s)
+    s = _PATTERNS[1].sub("Authorization: [redacted]", s)
+    s = _PATTERNS[2].sub("X-Authentication: [redacted]", s)
+    s = _PATTERNS[3].sub(lambda m: f"{m.group(1)}[redacted]{m.group(3)}", s)
+    return s
+
+
+def clip(errors: list[str]) -> list[str]:
+    """At most MAX_ERRORS redacted strings of at most MAX_ERROR_CHARS each."""
+    out = []
+    for e in errors[:MAX_ERRORS]:
+        r = redact(e)
+        out.append(r if len(r) <= MAX_ERROR_CHARS else r[: MAX_ERROR_CHARS - 3] + "...")
+    return out

server/packetstation/worker/runs.py

@@ -0,0 +1,173 @@
+"""One run of one job: advisory lock, job_runs row, request claiming, the job itself, the result.
+
+`run_job` works with a started Scheduler (the worker) or an unstarted one (the CLI, the tests): it only needs
+`settings`, `jobs`, `stack`, `host`, `build`, `connect()`, `set_feed()`, `running_add()`, `running_discard()`
+and `after_run()`.
+"""
+
+from __future__ import annotations
+
+import json
+import logging
+import traceback
+from datetime import datetime
+from typing import TYPE_CHECKING, Any
+
+from psycopg.rows import dict_row
+from psycopg.types.json import Jsonb
+
+from .. import guard
+from ..feed import config
+from .jobs import JobContext, JobSpec
+from .redaction import clip, redact
+
+if TYPE_CHECKING:
+    from .scheduler import Scheduler
+
+log = logging.getLogger("packetstation.worker.runs")
+
+LOCK_SPACE = 7310
+FEED_JOB = "visual-feed"
+
+__all__ = ["LOCK_SPACE", "redact", "run_job"]
+
+
+def _jsonable(value: Any) -> Any:
+    return json.loads(json.dumps(value if value is not None else {}, default=str))
+
+
+def _row(conn: Any, run_id: int) -> dict[str, Any]:
+    with conn.cursor(row_factory=dict_row) as cur:
+        row = cur.execute("SELECT * FROM job_runs WHERE id = %s", (run_id,)).fetchone()
+    return dict(row) if row else {"id": run_id}
+
+
+def _insert(conn: Any, sch: Scheduler, name: str, trigger: str, *, status: str = "running", counts: Any = None) -> int:
+    rid = conn.execute(
+        "INSERT INTO job_runs (job, trigger, status, counts, build_version, host, finished_at)"
+        " VALUES (%s, %s, %s, %s, %s, %s, CASE WHEN %s THEN now() END) RETURNING id",
+        (name, trigger, status, Jsonb(_jsonable(counts)), sch.build, sch.host, status != "running"),
+    ).fetchone()[0]
+    return int(rid)
+
+
+def _finish(conn: Any, run_id: int, *, status: str, counts: Any, errors: list[str], visual_target: str | None) -> None:
+    conn.execute(
+        "UPDATE job_runs SET status = %s, counts = %s, errors = %s, visual_target = coalesce(%s, visual_target),"
+        " finished_at = now() WHERE id = %s",
+        (status, Jsonb(_jsonable(counts)), Jsonb(clip(errors)), visual_target, run_id),
+    )
+
+
+def _target(result: Any) -> str:
+    """ "<server> / <database>" from a guard result, without the (DEV) or (PRODUCTION) suffix."""
+    text = str(getattr(result, "target", "") or "")
+    return text.rsplit(" (", 1)[0] if text.endswith(")") else text
+
+
+def run_job(sch: Scheduler, name: str, trigger: str) -> dict[str, Any]:
+    """Run `name` once and return its job_runs row. Never raises for a job failure; raises when the database
+    cannot be reached at all (the caller logs it)."""
+    spec: JobSpec = sch.jobs[name]
+    s = sch.settings
+    conn = sch.connect()
+    locked = False
+    run_id: int | None = None
+    status, counts, errors = "failed", {}, []  # type: tuple[str, Any, list[str]]
+    visual_target: str | None = None
+    pending_after = False
+    sch.running_add(name)
+    try:
+        feed = config.load(conn)
+        sch.set_feed(feed)
+        locked = bool(conn.execute("SELECT pg_try_advisory_lock(%s, hashtext(%s))", (LOCK_SPACE, name)).fetchone()[0])
+        if not locked:
+            rid = _insert(conn, sch, name, trigger, status="skipped", counts={"reason": "already running"})
+            log.info("job %s skipped: already running", name)
+            return _row(conn, rid)
+
+        with conn.transaction():
+            run_id = _insert(conn, sch, name, trigger)
+            claimed = conn.execute(
+                "UPDATE job_requests SET claimed_run_id = %s, claimed_at = now()"
+                " WHERE job = %s AND claimed_at IS NULL RETURNING requested_by",
+                (run_id, name),
+            ).fetchall()
+            if claimed:
+                trigger = "request"
+                who = sorted({r[0] for r in claimed if r[0] is not None}, key=str)
+                conn.execute("UPDATE job_runs SET trigger = 'request', requested_by = %s WHERE id = %s", (who, run_id))
+
+        if trigger == "schedule" and spec.pausable and feed.paused:
+            status, counts = "skipped", {"reason": "paused"}
+        else:
+            ctx = JobContext(
+                conn=conn,
+                settings=s,
+                feed_settings=feed,
+                run_id=run_id,
+                trigger=trigger,
+                started_at=datetime.now(sch.tz),
+                log=logging.getLogger(f"packetstation.worker.jobs.{name}"),
+                stack=sch.stack,
+            )
+            log.info("job %s started", name, extra={"ps": {"run_id": run_id, "trigger": trigger}})
+            try:
+                if name == FEED_JOB and s.feed_source == "visualkit":
+                    # The stack guard again with fresh VisualKit settings: a test stack never reads production
+                    ctx.visual_target = _target(guard.check_stack(s))
+                counts = spec.run(ctx) or {}
+                status = "degraded" if ctx.degraded else "ok"
+            except Exception as e:
+                status = "failed"
+                ctx.errors.append(f"{type(e).__name__}: {e}")
+                log.error("job %s failed: %s", name, redact(traceback.format_exc()))
+            errors, visual_target = ctx.errors, ctx.visual_target
+        try:
+            _finish(conn, run_id, status=status, counts=counts, errors=errors, visual_target=visual_target)
+        except Exception:
+            # The run's connection is broken: write the result on a fresh one
+            with sch.connect() as c2:
+                _finish(c2, run_id, status=status, counts=counts, errors=errors, visual_target=visual_target)
+        try:
+            pending_after = bool(
+                conn.execute(
+                    "SELECT EXISTS (SELECT 1 FROM job_requests WHERE job = %s AND claimed_at IS NULL)", (name,)
+                ).fetchone()[0]
+            )
+            row = _row(conn, run_id)
+        except Exception:
+            with sch.connect() as c2:
+                row = _row(c2, run_id)
+        log.info(
+            "job %s finished: %s", name, status, extra={"ps": {"run_id": run_id, "status": status, "counts": counts}}
+        )
+        return row
+    except Exception as e:
+        status = "failed"
+        if run_id is not None:
+            try:
+                with sch.connect() as c2:
+                    _finish(
+                        c2,
+                        run_id,
+                        status="failed",
+                        counts=counts,
+                        errors=[f"{type(e).__name__}: {e}"],
+                        visual_target=visual_target,
+                    )
+            except Exception as e2:
+                log.error("job %s: can't record the failure: %s", name, type(e2).__name__)
+        raise
+    finally:
+        if locked:
+            try:
+                conn.execute("SELECT pg_advisory_unlock(%s, hashtext(%s))", (LOCK_SPACE, name))
+            except Exception as e:
+                log.warning("job %s: unlock failed (%s); closing the connection releases it", name, type(e).__name__)
+        try:
+            conn.close()
+        finally:
+            sch.running_discard(name)
+            if run_id is not None:
+                sch.after_run(name, status, pending_after)

server/packetstation/worker/scheduler.py

@@ -0,0 +1,395 @@
+"""The worker's scheduler: APScheduler 3 in site time, settings read on every fire, "run now" over NOTIFY.
+
+Each job has a SettingsTrigger whose next fire time comes from the job's cadence and the current feed settings,
+so a changed interval applies on the next fire. A save NOTIFYs `ps_settings` and the listener calls
+`reschedule()` so it applies at once. A "run now" NOTIFYs `ps_job_request` and the listener moves the job to now.
+After a run the job's next fire is measured from the end of the run.
+"""
+
+from __future__ import annotations
+
+import contextlib
+import json
+import logging
+import os
+import socket
+import threading
+from collections.abc import Callable, Iterable
+from datetime import datetime, timedelta
+from pathlib import Path
+from typing import Any
+from zoneinfo import ZoneInfo
+
+from apscheduler.executors.pool import ThreadPoolExecutor
+from apscheduler.schedulers.background import BackgroundScheduler
+from apscheduler.triggers.base import BaseTrigger
+
+from .. import db
+from ..feed import config
+from ..feed.config import FeedSettings
+from ..settings import Settings
+from . import heartbeat, runs
+from .jobs import JobSpec, Stack, load_jobs
+from .redaction import redact
+
+log = logging.getLogger("packetstation.worker")
+
+CHANNELS = ("ps_settings", "ps_job_request")
+IDLE_RECHECK_SECONDS = 3600  # a job with no schedule wakes this often and does nothing
+BACKOFF_MAX = 30.0
+THREADS = 4
+MISFIRE_GRACE = 300
+
+
+class SettingsTrigger(BaseTrigger):
+    """Fires `seconds(now)` after now. `seconds` reads the current settings, so a change applies on the next fire.
+    None means "no schedule": the trigger wakes again after an hour and the fire does nothing."""
+
+    __slots__ = ("seconds",)
+
+    def __init__(self, seconds: Callable[[datetime], int | None]):
+        self.seconds = seconds
+
+    def get_next_fire_time(self, previous_fire_time: datetime | None, now: datetime) -> datetime:
+        secs = self.seconds(now)
+        return now + timedelta(seconds=max(1, IDLE_RECHECK_SECONDS if secs is None else int(secs)))
+
+    def __str__(self) -> str:
+        return "settings"
+
+
+def next_due(
+    spec: JobSpec, feed: FeedSettings, now_site: datetime, last_end_site: datetime | None = None
+) -> datetime | None:
+    """When the job is next due: its cadence measured from the end of its last run (or from now when it never ran),
+    never before now. None when the cadence says "no schedule"."""
+    base = last_end_site if last_end_site is not None and last_end_site <= now_site else now_site
+    secs = spec.cadence(feed, base)
+    if secs is None:
+        return None
+    due = base + timedelta(seconds=max(1, int(secs)))
+    return due if due > now_site else now_site
+
+
+class Scheduler:
+    def __init__(
+        self,
+        settings: Settings,
+        *,
+        build: str | None = None,
+        jobs: dict[str, JobSpec] | None = None,
+        connect: Callable[[], Any] | None = None,
+    ):
+        self.settings = settings
+        self.build = build or settings.ps_build
+        self.jobs = dict(jobs) if jobs is not None else dict(load_jobs())
+        self.tz = ZoneInfo(settings.site_tz)
+        self._connect = connect or (lambda: db.connect_as("worker", settings, autocommit=True))
+        self.stack = Stack()
+        self.host = socket.gethostname()
+        self.pid = os.getpid()
+        self.feed = FeedSettings()
+        self._lock = threading.Lock()
+        self._running: set[str] = set()
+        self._next_trigger: dict[str, str] = {}
+        self._again: dict[str, str] = {}
+        self._last_end: dict[str, datetime] = {}
+        self._db_ready = False
+        self._stop = threading.Event()
+        self._listener: threading.Thread | None = None
+        self.listening = False
+        self.aps = BackgroundScheduler(
+            executors={"default": ThreadPoolExecutor(THREADS)},
+            job_defaults={"coalesce": True, "max_instances": 1, "misfire_grace_time": MISFIRE_GRACE},
+            timezone=self.tz,
+        )
+        self.started = False
+
+    # ------------------------------------------------ small helpers used by runs.run_job
+
+    def connect(self) -> Any:
+        return self._connect()
+
+    def now(self) -> datetime:
+        return datetime.now(self.tz)
+
+    def set_feed(self, feed: FeedSettings) -> None:
+        self.feed = feed
+
+    def running(self) -> list[str]:
+        with self._lock:
+            return sorted(self._running)
+
+    def running_add(self, name: str) -> None:
+        with self._lock:
+            self._running.add(name)
+
+    def running_discard(self, name: str) -> None:
+        with self._lock:
+            self._running.discard(name)
+
+    # ------------------------------------------------ lifecycle
+
+    def start(self) -> None:
+        """Set up the database side when it is reachable, add the jobs and start the scheduler and listener."""
+        self._setup_db()
+        now = self.now()
+        for name, spec in self.jobs.items():
+            self.aps.add_job(
+                self._fire,
+                trigger=SettingsTrigger(self._seconds_for(spec)),
+                args=(name,),
+                id=name,
+                name=name,
+                next_run_time=self._next_time(spec, now),
+                replace_existing=True,
+            )
+        self.aps.start()
+        self.started = True
+        self._write_schedule(self.jobs)
+        self._stop.clear()
+        self._listener = threading.Thread(target=self._listen, name="ps-worker-listen", daemon=True)
+        self._listener.start()
+        log.info("scheduler started", extra={"ps": {"jobs": sorted(self.jobs), "host": self.host}})
+
+    def shutdown(self, wait: bool = True) -> None:
+        self._stop.set()
+        if self.started:
+            self.aps.shutdown(wait=wait)
+            self.started = False
+        if self._listener is not None:
+            self._listener.join(5.0)
+            self._listener = None
+
+    def _setup_db(self) -> bool:
+        """Seed the feed settings, mark this host's leftover runs abandoned, load the settings and the last run
+        ends. Safe to call again; returns False when the database is not reachable."""
+        if self._db_ready:
+            return True
+        try:
+            with self.connect() as conn:
+                with conn.transaction():
+                    if config.seed(conn):
+                        log.info("feed settings seeded with the defaults")
+                self._abandon(conn)
+                self.feed = config.load(conn)
+                for job, end in conn.execute(
+                    "SELECT job, max(finished_at) FROM job_runs WHERE finished_at IS NOT NULL"
+                    " AND status <> 'skipped' GROUP BY job"
+                ).fetchall():
+                    if end is not None:
+                        self._last_end[job] = end.astimezone(self.tz)
+        except Exception as e:
+            log.warning("worker database setup deferred: %s", redact(f"{type(e).__name__}: {e}"))
+            return False
+        self._db_ready = True
+        return True
+
+    def _abandon(self, conn: Any) -> None:
+        """Runs left `running` by a dead worker become `abandoned`: this host's always, another host's when no
+        session holds that job's advisory lock (a container recreated with a new host name)."""
+        rows = conn.execute("SELECT id, job, host FROM job_runs WHERE status = 'running'").fetchall()
+        for rid, job, host in rows:
+            if host != self.host:
+                got = conn.execute("SELECT pg_try_advisory_lock(%s, hashtext(%s))", (runs.LOCK_SPACE, job)).fetchone()[
+                    0
+                ]
+                if not got:
+                    continue
+                conn.execute("SELECT pg_advisory_unlock(%s, hashtext(%s))", (runs.LOCK_SPACE, job))
+            conn.execute(
+                "UPDATE job_runs SET status = 'abandoned', finished_at = now(),"
+                " errors = errors || '[\"The worker stopped during this run.\"]'::jsonb"
+                " WHERE id = %s AND status = 'running'",
+                (rid,),
+            )
+            log.warning("job run %s (%s) marked abandoned", rid, job)
+
+    # ------------------------------------------------ timing
+
+    def _seconds_for(self, spec: JobSpec) -> Callable[[datetime], int | None]:
+        def seconds(now: datetime) -> int | None:
+            return spec.cadence(self.feed, now.astimezone(self.tz))
+
+        return seconds
+
+    def _next_time(self, spec: JobSpec, now: datetime) -> datetime:
+        due = next_due(spec, self.feed, now, self._last_end.get(spec.name))
+        return due if due is not None else now + timedelta(seconds=IDLE_RECHECK_SECONDS)
+
+    def reschedule(self, names: Iterable[str] | None = None) -> None:
+        """Recompute the next run of every job (or of `names`) from the current settings."""
+        if not self.started:
+            return
+        now = self.now()
+        todo = list(names) if names is not None else list(self.jobs)
+        for name in todo:
+            spec = self.jobs.get(name)
+            if spec is None:
+                continue
+            with contextlib.suppress(Exception):  # JobLookupError during shutdown
+                self.aps.modify_job(name, next_run_time=self._next_time(spec, now))
+        self._write_schedule(todo)
+
+    def run_soon(self, name: str, trigger: str = "request") -> None:
+        """Move a job to now. A job that is running now runs again right after."""
+        if name not in self.jobs:
+            log.warning("ignoring a run request for unknown job %r", name[:60])
+            return
+        with self._lock:
+            if name in self._running:
+                self._again[name] = trigger
+                return
+            self._next_trigger[name] = trigger
+        if self.started:
+            with contextlib.suppress(Exception):
+                self.aps.modify_job(name, next_run_time=self.now())
+
+    def after_run(self, name: str, status: str, pending: bool) -> None:
+        """Called by run_job when a run ends: chain, run again for new requests, else time the next run from now."""
+        self._last_end[name] = self.now()
+        spec = self.jobs[name]
+        with self._lock:
+            again = self._again.pop(name, None)
+        if status in ("ok", "degraded"):
+            for c in spec.chain:
+                self.run_soon(c, "chain")
+        if pending or again:
+            self.run_soon(name, again or "request")
+            self._write_schedule([name])
+        else:
+            self.reschedule([name])
+
+    def _fire(self, name: str) -> None:
+        with self._lock:
+            trigger = self._next_trigger.pop(name, "schedule")
+        spec = self.jobs[name]
+        if not self._db_ready and not self._setup_db():
+            log.warning("job %s not run: database not reachable", name)
+            return
+        if trigger == "schedule" and spec.cadence(self.feed, self.now()) is None:
+            self._write_schedule([name])
+            return
+        try:
+            runs.run_job(self, name, trigger)
+        except Exception as e:
+            log.error("job %s could not run: %s", name, redact(f"{type(e).__name__}: {e}"))
+
+    def _write_schedule(self, names: Iterable[str]) -> None:
+        """job_schedule rows for the Admin and Clerical screens. Best effort."""
+        if not self.started:
+            return
+        rows = []
+        now = self.now()
+        for name in names:
+            spec = self.jobs.get(name)
+            if spec is None:
+                continue
+            job = self.aps.get_job(name)
+            nxt = job.next_run_time if job is not None else None
+            secs = spec.cadence(self.feed, now)
+            if secs is None:
+                nxt = None
+            rows.append((name, nxt, secs, bool(spec.pausable and self.feed.paused)))
+        if not rows:
+            return
+        try:
+            with self.connect() as conn:
+                for r in rows:
+                    conn.execute(
+                        "INSERT INTO job_schedule (job, next_run_at, interval_seconds, paused, updated_at)"
+                        " VALUES (%s, %s, %s, %s, now()) ON CONFLICT (job) DO UPDATE SET"
+                        " next_run_at = EXCLUDED.next_run_at, interval_seconds = EXCLUDED.interval_seconds,"
+                        " paused = EXCLUDED.paused, updated_at = now()",
+                        r,
+                    )
+        except Exception as e:
+            log.warning("job_schedule not written: %s", type(e).__name__)
+
+    # ------------------------------------------------ settings
+
+    def reload_settings(self, conn: Any | None = None) -> None:
+        try:
+            if conn is not None:
+                self.feed = config.load(conn)
+            else:
+                with self.connect() as c:
+                    self.feed = config.load(c)
+        except Exception as e:
+            log.warning("feed settings not reloaded: %s", type(e).__name__)
+            return
+        self.reschedule()
+
+    # ------------------------------------------------ listener
+
+    def _on_connect(self, conn: Any) -> None:
+        """After every (re)connect: catch up on what was missed while not listening."""
+        self._setup_db()
+        self.reload_settings(conn)
+        for (job,) in conn.execute("SELECT DISTINCT job FROM job_requests WHERE claimed_at IS NULL").fetchall():
+            self.run_soon(job, "request")
+
+    def _notified(self, channel: str, payload: str) -> None:
+        if channel == "ps_settings":
+            self.reload_settings()
+            return
+        try:
+            data = json.loads(payload)
+        except ValueError:
+            log.warning("ignoring a non-JSON ps_job_request payload")
+            return
+        job = data.get("job") if isinstance(data, dict) else None
+        if isinstance(job, str):
+            self.run_soon(job, "request")
+
+    def _listen(self) -> None:
+        delay = 1.0
+        while not self._stop.is_set():
+            conn = None
+            try:
+                conn = self.connect()
+                for ch in CHANNELS:
+                    conn.execute(f"LISTEN {ch}")
+                self.listening = True
+                delay = 1.0
+                log.info("worker listening on %s", ", ".join(CHANNELS))
+                self._on_connect(conn)
+                while not self._stop.is_set():
+                    for n in conn.notifies(timeout=1.0):
+                        self._notified(n.channel, n.payload)
+            except Exception as e:
+                if not self._stop.is_set():
+                    log.warning("worker listener: %s; retrying in %.0f s", type(e).__name__, delay)
+            finally:
+                self.listening = False
+                if conn is not None:
+                    with contextlib.suppress(Exception):
+                        conn.close()
+            if self._stop.wait(delay):
+                break
+            delay = min(delay * 2, BACKOFF_MAX)
+
+    # ------------------------------------------------ heartbeat loop (main thread)
+
+    def serve(self, beat_file: Path, stop: threading.Event, interval: float) -> None:
+        """Beat until `stop`: the beat file and the worker_heartbeat row."""
+        conn = None
+        while not stop.is_set():
+            try:
+                heartbeat.touch(beat_file)
+            except OSError as e:
+                log.error("can't touch beat file %s: %s", beat_file, e.strerror)
+            try:
+                if conn is None or conn.closed:
+                    conn = self.connect()
+                heartbeat.write_row(conn, build=self.build, host=self.host, pid=self.pid, running=self.running())
+            except Exception as e:
+                log.warning("heartbeat row not written: %s", type(e).__name__)
+                if conn is not None:
+                    with contextlib.suppress(Exception):
+                        conn.close()
+                conn = None
+            stop.wait(interval)
+        if conn is not None:
+            with contextlib.suppress(Exception):
+                conn.close()