spencermandClaude Fable 5.1
591fe90076
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]>
396 lines
16 KiB
Python
396 lines
16 KiB
Python
"""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()
|