Files
FabledScribe/src/scribe/services/db_maintenance_scheduler.py
T
bvandeusenandClaude Opus 5 1fcfd47ab6
CI & Build / Python lint (push) Successful in 3s
CI & Build / Plugin hooks (push) Successful in 10s
CI & Build / integration (push) Successful in 50s
CI & Build / TypeScript typecheck (push) Successful in 55s
CI & Build / Python tests (push) Successful in 1m31s
CI & Build / Build & push image (push) Successful in 26s
fix(startup): a slow database costs seconds, not the instance (#4181)
On 2026-09-19 a host storage stall made one Postgres checkpoint of 14
buffers take 281 seconds against a 1.3-second baseline. The app restarted
into the tail of it, `get_maintenance_hour()` — the first DB read in
`before_serving` — hung with no deadline, Hypercorn killed the worker at
its 60-second lifespan timeout, and nothing retries a failed lifespan. A
five-minute disk hiccup became a three-hour outage that only a human
restart could clear. Every MCP call returned 405, which reads like a
routing fault and was nothing of the kind: nothing was serving.

Three changes, none of which prevent a stall — they stop a transient one
becoming a permanent one.

1. THE STARTUP READ IS BOUNDED (rule 156). `get_maintenance_hour` already
   answered `_DEFAULT_HOUR` for a value it could not parse; a database
   that will not answer in three seconds is the same class of "no usable
   value here". The failure is now a WARNING naming the symptom — the
   breadcrumb whose absence meant this was only diagnosable from
   Postgres's own log — and a default run-hour, instead of the app.

2. THE BACKFILL NO LONGER RACES STARTUP. Its comment said it "never
   blocks the server from accepting requests": true of requests, false of
   startup, because the task began while `before_serving` was still
   running and competed for the same pool. Both of the incident's
   cancelled statements were in flight together. It now waits on a flag
   released on the hook's way out — in a `finally`, never after the work
   (rule 157), because an undeadlined wait is only safe when the wake-up
   cannot be missed.

3. THE ENGINE CANNOT WAIT FOREVER TO CONNECT. asyncpg's default is 60s,
   the whole lifespan budget spent before a query is sent. `command_timeout`
   is deliberately NOT set alongside it and the comment says why: it would
   apply to every statement, and this app runs long ones on purpose.

tests/test_startup_survives_a_slow_database.py asserts the shape rather
than the stall: a read that never returns still yields an hour, the
warning names the symptom, a healthy read is unaffected, the backfill
does no work before release, the flag is released even when startup
raises, and the engine's connect args carry a deadline but no blanket
statement timeout.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01821k5B3Ysecp9fNYs92Kuy
2026-09-19 10:50:57 -04:00

132 lines
5.3 KiB
Python
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
"""Daily APScheduler cron for basic DB maintenance (targeted VACUUM ANALYZE).
One ScheduledJob (services/scheduler.py). Scheduled for 04:00 UTC by default
— after the 03:30 trash purge — so it collects the dead tuples that night's
delete sweeps leave behind.
Two things are operator-tunable from the admin Settings card:
- db_maintenance_enabled ("true"/"false") — checked at fire time, so toggling
it needs no reschedule.
- db_maintenance_hour ("0".."23", UTC) — the cron hour. Changing it calls
reschedule_db_maintenance() so the live job moves without a restart.
"""
from __future__ import annotations
import asyncio
import logging
from apscheduler.triggers.cron import CronTrigger
from scribe.services.scheduler import ScheduledJob
from scribe.services.settings import get_admin_setting
logger = logging.getLogger(__name__)
_JOB_ID = "db_maintenance_vacuum"
_DEFAULT_HOUR = 4
# HOW LONG A COLD START WILL WAIT FOR THIS ONE SETTING (#4181).
#
# This read is the FIRST database call in the app's `before_serving` hook, and
# a lifespan hook that does not return is a worker that never serves. On
# 2026-09-19 a host storage stall made one Postgres checkpoint of 14 buffers
# take 281 seconds against a 1.3-second baseline; the app restarted into the
# tail of it, this query hung with no deadline, Hypercorn killed the worker at
# its 60-second lifespan timeout, and nothing retries a failed lifespan. A
# five-minute disk hiccup became a three-hour outage that only a human restart
# could clear.
#
# Three seconds because the honest requirement is "don't hold up the boot",
# not "get the right hour". The value is one small indexed row on a local
# database: under any healthy condition this returns in single-digit
# milliseconds, so the timeout can only ever fire when something is already
# badly wrong — which is exactly the moment the app must come up anyway.
_STARTUP_READ_TIMEOUT = 3.0
async def get_maintenance_hour() -> int:
"""The configured run-hour (UTC, 023), clamped; default 04:00.
BOUNDED, because the caller is a lifespan hook (rule 156). The fallback is
not new behaviour invented for the timeout — this function already answers
`_DEFAULT_HOUR` for a value it cannot parse, and a database that will not
answer in three seconds is the same class of "no usable value here". What
changes is that the failure is now a logged line and a default hour rather
than the application failing to start.
Degrading to the default is the right trade in both directions: the cost of
being wrong is that a VACUUM runs at 04:00 instead of the configured hour,
for one boot, on an instance whose disk is in trouble. The cost of waiting
is the whole instance.
"""
try:
raw = await asyncio.wait_for(
get_admin_setting("db_maintenance_hour", str(_DEFAULT_HOUR)),
timeout=_STARTUP_READ_TIMEOUT,
)
except (TimeoutError, asyncio.TimeoutError):
# WARNING, not debug: this is never normal, and it is the breadcrumb
# that would have named #4181 in seconds instead of requiring
# Postgres's own log to be read.
logger.warning(
"db maintenance: reading db_maintenance_hour exceeded %.1fs; "
"starting with the default %02d:00 UTC. The database is slow or "
"unreachable — this is a symptom, not the disease.",
_STARTUP_READ_TIMEOUT, _DEFAULT_HOUR,
)
return _DEFAULT_HOUR
except Exception:
logger.warning(
"db maintenance: could not read db_maintenance_hour; starting "
"with the default %02d:00 UTC", _DEFAULT_HOUR, exc_info=True,
)
return _DEFAULT_HOUR
try:
hour = int(raw)
except (TypeError, ValueError):
return _DEFAULT_HOUR
return hour if 0 <= hour <= 23 else _DEFAULT_HOUR
async def is_maintenance_enabled() -> bool:
"""Whether the scheduled run is enabled (default on)."""
return (await get_admin_setting("db_maintenance_enabled", "true")) != "false"
async def _run_maintenance() -> None:
if not await is_maintenance_enabled():
logger.debug("db maintenance: disabled, skipping scheduled run")
return
from scribe.services.db_maintenance import run_maintenance
await run_maintenance()
_JOB = ScheduledJob(_JOB_ID, _run_maintenance, label="DB maintenance")
def _trigger(hour: int) -> CronTrigger:
hour = hour if 0 <= hour <= 23 else _DEFAULT_HOUR
return CronTrigger(hour=hour, minute=0, timezone="UTC")
def start_db_maintenance_scheduler(
loop: asyncio.AbstractEventLoop, hour: int = _DEFAULT_HOUR
) -> None:
"""Start the daily job. `hour` is the configured UTC run-hour, resolved by
the caller (which has an async context) via get_maintenance_hour() — passed
in rather than read here so we never block the event loop at startup. The
job's enabled-gate is re-checked at every fire, so only the hour is needed
up front."""
hour = hour if 0 <= hour <= 23 else _DEFAULT_HOUR
_JOB.start(loop, _trigger(hour), describe=f"daily {hour:02d}:00 UTC")
def reschedule_db_maintenance(hour: int) -> None:
"""Move the live job to a new UTC hour (called when the admin changes it)."""
hour = hour if 0 <= hour <= 23 else _DEFAULT_HOUR
_JOB.reschedule(_trigger(hour), describe=f"{hour:02d}:00 UTC")
def stop_db_maintenance_scheduler() -> None:
_JOB.stop()