From 1fcfd47ab6ff6d23f249080548dccedfbdf8c2e3 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Sat, 19 Sep 2026 10:50:57 -0400 Subject: [PATCH] fix(startup): a slow database costs seconds, not the instance (#4181) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Claude-Session: https://claude.ai/code/session_01821k5B3Ysecp9fNYs92Kuy --- src/scribe/app.py | 92 ++++++-- src/scribe/models/__init__.py | 28 +++ .../services/db_maintenance_scheduler.py | 56 ++++- .../test_startup_survives_a_slow_database.py | 222 ++++++++++++++++++ 4 files changed, 371 insertions(+), 27 deletions(-) create mode 100644 tests/test_startup_survives_a_slow_database.py diff --git a/src/scribe/app.py b/src/scribe/app.py index c94b8cf..4b32508 100644 --- a/src/scribe/app.py +++ b/src/scribe/app.py @@ -162,6 +162,13 @@ def create_app() -> Quart: async def startup(): import asyncio + # Set on the last line of this hook; the deferred backfill below waits + # on it. An Event rather than a bare bool so the waiter is woken + # instead of polling, and declared here — inside the hook, where + # `asyncio` is in scope and a running loop exists — rather than in + # `create_app`, which runs before either is true. + _startup_finished = asyncio.Event() + from scribe.services.auth import start_auth_token_retention_loop from scribe.services.embeddings import ( backfill_milestone_embeddings, backfill_note_embeddings, backfill_rule_embeddings, @@ -174,8 +181,23 @@ def create_app() -> Quart: start_auth_token_retention_loop() # Backfill embeddings for any notes that don't have one. Runs in the - # background so it never blocks the server from accepting requests. + # background so it never blocks the server from accepting requests — + # and, since #4181, not until the rest of this hook has finished. + # + # "Background" was true of REQUESTS and false of STARTUP. A task + # created here begins immediately, while `before_serving` is still + # running, so its four passes competed with the startup hook's own + # database reads for the same connection pool. That is survivable on a + # healthy disk and fatal on a sick one: on 2026-09-19 both this + # backfill's first query and the hook's maintenance-hour read were + # cancelled together when Hypercorn killed the worker at its lifespan + # timeout, and the instance stayed down for three hours. + # + # The wait is on the SERVING FLAG rather than a sleep, because a sleep + # would be a guess about how long the rest of the hook takes and would + # be wrong in exactly the conditions that matter. async def _delayed_backfill() -> None: + await _startup_finished.wait() try: await backfill_note_embeddings() except Exception: @@ -202,36 +224,56 @@ def create_app() -> Quart: except Exception: logger.warning("Snippet data backfill failed", exc_info=True) + # Created here but gated on the flag released at the END of this hook, + # so the task exists (nothing can forget to start it) while none of its + # work overlaps startup's own. asyncio.create_task(_delayed_backfill()) - # Recurrence scheduler (recurring-task spawn every 15m) - from scribe.services.recurrence_scheduler import start_recurrence_scheduler - start_recurrence_scheduler(asyncio.get_running_loop()) + # RELEASED IN A `finally`, never after the work (rules 156 and 157). + # The waiter above has no deadline of its own, and the way to make an + # undeadlined wait safe is to make the release unmissable: if anything + # below raises, the flag is still set and the task ends instead of + # living on as a coroutine nobody will ever wake. + try: + # Recurrence scheduler (recurring-task spawn every 15m) + from scribe.services.recurrence_scheduler import start_recurrence_scheduler + start_recurrence_scheduler(asyncio.get_running_loop()) - # Version-pinning scheduler (daily auto-pin scan at 03:00 UTC) - from scribe.services.version_pinning_scheduler import ( - start_version_pinning_scheduler, - ) - start_version_pinning_scheduler(asyncio.get_running_loop()) + # Version-pinning scheduler (daily auto-pin scan at 03:00 UTC) + from scribe.services.version_pinning_scheduler import ( + start_version_pinning_scheduler, + ) + start_version_pinning_scheduler(asyncio.get_running_loop()) - # Trash retention scheduler (daily expired-trash purge at 03:30 UTC) - from scribe.services.trash_scheduler import start_trash_scheduler - start_trash_scheduler(asyncio.get_running_loop()) + # Trash retention scheduler (daily expired-trash purge at 03:30 UTC) + from scribe.services.trash_scheduler import start_trash_scheduler + start_trash_scheduler(asyncio.get_running_loop()) - # DB maintenance scheduler (daily targeted VACUUM ANALYZE, default 04:00 UTC) - from scribe.services.db_maintenance_scheduler import ( - get_maintenance_hour, - start_db_maintenance_scheduler, - ) - start_db_maintenance_scheduler( - asyncio.get_running_loop(), await get_maintenance_hour() - ) + # DB maintenance scheduler (daily targeted VACUUM ANALYZE, default + # 04:00 UTC). `get_maintenance_hour` is the FIRST database read in + # this hook and is bounded for that reason (#4181) — see the long + # comment above `_STARTUP_READ_TIMEOUT`. Anything added here that + # touches the database needs the same treatment: a lifespan hook + # that does not return is a worker that never serves. + from scribe.services.db_maintenance_scheduler import ( + get_maintenance_hour, + start_db_maintenance_scheduler, + ) + start_db_maintenance_scheduler( + asyncio.get_running_loop(), await get_maintenance_hour() + ) - # Diagnostic instrumentation — heartbeat, signal handlers, asyncio - # exception hook. Cheap (~1 log line/min), high diagnostic value when - # the app crashes mysteriously. See services/diagnostics.py. - from scribe.services.diagnostics import start_diagnostics - start_diagnostics(asyncio.get_running_loop()) + # Diagnostic instrumentation — heartbeat, signal handlers, asyncio + # exception hook. Cheap (~1 log line/min), high diagnostic value when + # the app crashes mysteriously. See services/diagnostics.py. + from scribe.services.diagnostics import start_diagnostics + start_diagnostics(asyncio.get_running_loop()) + finally: + # STARTUP IS OVER — release the backfill (#4181). Everything above + # is work the server needs done before it serves; everything the + # backfill does is work that can wait for a server already up. + logger.info("Startup complete; releasing deferred backfill") + _startup_finished.set() @app.after_serving async def shutdown(): diff --git a/src/scribe/models/__init__.py b/src/scribe/models/__init__.py index aa91587..1584b5f 100644 --- a/src/scribe/models/__init__.py +++ b/src/scribe/models/__init__.py @@ -3,11 +3,39 @@ from sqlalchemy.orm import DeclarativeBase from scribe.config import Config +# Named rather than inlined so the deadline below is READABLE. SQLAlchemy +# captures `connect_args` in a closure and merges it at connect time, so an +# inline dict cannot be recovered from the engine — and a guard that cannot +# read the value it guards is a guard that passes forever. +_CONNECT_ARGS: dict = { + # A DEADLINE ON ESTABLISHING A CONNECTION (#4181, rule 156). + # + # asyncpg's `timeout` bounds the CONNECT — the TCP handshake plus session + # setup — and nothing else. Against a host whose storage has wedged, that + # handshake does not fail, it waits, and without this the wait is + # asyncpg's own 60-second default: the entire lifespan budget spent before + # a single query is even sent. Ten seconds is far longer than a healthy + # local connect (single-digit milliseconds) and short enough to leave room + # to fail usefully rather than be killed. + # + # WHAT THIS DOES NOT COVER, said plainly so the next reader doesn't assume + # it does: a query on an already-open connection, which includes + # `pool_pre_ping`'s liveness check. Bounding those is `command_timeout`, + # and that is deliberately NOT set here — it would apply to every + # statement, and this app legitimately runs long ones (the embedding + # backfills, VACUUM ANALYZE). A blanket statement deadline would trade + # this failure mode for a worse one. Callers that must not hang — the + # lifespan hook above all — bound their own await instead; see + # `_STARTUP_READ_TIMEOUT` in services/db_maintenance_scheduler.py. + "timeout": 10, +} + engine = create_async_engine( Config.DATABASE_URL, echo=False, pool_pre_ping=True, pool_recycle=1800, + connect_args=_CONNECT_ARGS, ) async_session = async_sessionmaker(engine, class_=AsyncSession, expire_on_commit=False) diff --git a/src/scribe/services/db_maintenance_scheduler.py b/src/scribe/services/db_maintenance_scheduler.py index 35ff69a..f6b673a 100644 --- a/src/scribe/services/db_maintenance_scheduler.py +++ b/src/scribe/services/db_maintenance_scheduler.py @@ -25,10 +25,62 @@ 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, 0–23), clamped; default 04:00.""" - raw = await get_admin_setting("db_maintenance_hour", str(_DEFAULT_HOUR)) + """The configured run-hour (UTC, 0–23), 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): diff --git a/tests/test_startup_survives_a_slow_database.py b/tests/test_startup_survives_a_slow_database.py new file mode 100644 index 0000000..6f3316b --- /dev/null +++ b/tests/test_startup_survives_a_slow_database.py @@ -0,0 +1,222 @@ +"""A sick database must not stop the app from starting — #4181, rule 156. + +THE INCIDENT THESE GUARD, so a later reader knows what is being defended: + +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 database 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 assertion here is about the SHAPE that made that possible, not about the +stall, which no test can reproduce and no code can prevent: + + - the startup read returns on a schedule of its own rather than the + database's; + - the backfill cannot run while startup is still running; + - the flag that releases it is released even when startup fails, because an + undeadlined wait is only safe if the wake-up is unmissable. +""" +import asyncio +from unittest.mock import AsyncMock, patch + +import pytest + + +# ── the startup read is bounded ────────────────────────────────────────────── + + +@pytest.mark.asyncio +async def test_a_hanging_settings_read_does_not_hang_startup(): + """The load-bearing one. A read that never returns must not become an app + that never starts — the whole distance between a five-minute stall and a + three-hour outage.""" + from scribe.services import db_maintenance_scheduler as sched + + async def _never_returns(*_a, **_kw): + await asyncio.Event().wait() # exactly what the disk stall did + + with patch.object(sched, "get_admin_setting", _never_returns), \ + patch.object(sched, "_STARTUP_READ_TIMEOUT", 0.05): + hour = await asyncio.wait_for(sched.get_maintenance_hour(), timeout=2) + + # It answered, and it answered the value it already uses for "no usable + # setting here" — the timeout adds a new CAUSE, not a new behaviour. + assert hour == sched._DEFAULT_HOUR + + +@pytest.mark.asyncio +async def test_the_timeout_is_logged_loudly_enough_to_find(): + """#4181 cost hours because the app logged three scheduler lines and + stopped; the cause was only recoverable from Postgres's own log. A WARNING + here is the breadcrumb that would have named it in seconds.""" + from scribe.services import db_maintenance_scheduler as sched + + async def _never_returns(*_a, **_kw): + await asyncio.Event().wait() + + with patch.object(sched, "get_admin_setting", _never_returns), \ + patch.object(sched, "_STARTUP_READ_TIMEOUT", 0.05), \ + patch.object(sched.logger, "warning") as warn: + # Bounded here too — a test that awaits a call which is supposed to + # have a deadline must not be the thing without one (rule 156). + await asyncio.wait_for(sched.get_maintenance_hour(), timeout=2) + + assert warn.called + said = " ".join(str(a) for a in warn.call_args.args) + # It must name the symptom, not just report a number — the reader of this + # line is someone whose instance did not come up. + assert "db_maintenance_hour" in said + assert "slow or" in said and "unreachable" in said + + +@pytest.mark.asyncio +async def test_a_healthy_read_is_untouched_by_the_deadline(): + """The bound may not cost the feature. A configured hour still wins.""" + from scribe.services import db_maintenance_scheduler as sched + + with patch.object(sched, "get_admin_setting", AsyncMock(return_value="9")): + assert await sched.get_maintenance_hour() == 9 + + +@pytest.mark.asyncio +async def test_a_failing_read_still_yields_a_usable_hour(): + """A raised exception is the other way a sick database answers, and it must + land in the same place as the timeout rather than escaping into the hook.""" + from scribe.services import db_maintenance_scheduler as sched + + with patch.object(sched, "get_admin_setting", + AsyncMock(side_effect=OSError("connection reset"))): + assert await sched.get_maintenance_hour() == sched._DEFAULT_HOUR + + +def test_the_startup_deadline_leaves_room_inside_the_lifespan_budget(): + """The number has to be smaller than the budget it lives in, or bounding + the read buys nothing. Hypercorn's default `startup_timeout` is 60s; this + read is one small indexed row.""" + from scribe.services.db_maintenance_scheduler import _STARTUP_READ_TIMEOUT + + assert 0 < _STARTUP_READ_TIMEOUT <= 10 + + +# ── the backfill does not race startup ─────────────────────────────────────── + + +@pytest.mark.asyncio +async def test_the_deferred_backfill_waits_for_the_startup_flag(): + """`_delayed_backfill`'s comment said it "never blocks the server from + accepting requests" — true of requests, false of startup, because startup + had not finished and the two competed for one connection pool. Both of + #4181's cancelled statements were in flight together, which is the + evidence this asserts against. + + Written as the SHAPE — a waiter that does no work until released — rather + than by booting the app, which needs a database this suite does not have. + """ + released = asyncio.Event() + did_work = False + + async def _backfill() -> None: + nonlocal did_work + await released.wait() + did_work = True + + task = asyncio.create_task(_backfill()) + await asyncio.sleep(0) # let it reach the wait + assert did_work is False, "the backfill ran while startup was still running" + + released.set() + await asyncio.wait_for(task, timeout=1) + assert did_work is True # …and it is not merely skipped + + +@pytest.mark.asyncio +async def test_the_flag_is_released_even_when_startup_fails(): + """Rules 156 and 157 together. The waiter has no deadline of its own, so + the release has to be unmissable: a `finally`, never a last line. Released + only on success, a startup that raised anywhere below the task would leave + a coroutine nobody will ever wake.""" + flag = asyncio.Event() + + async def _hook_that_blows_up() -> None: + try: + raise RuntimeError("a scheduler failed to start") + finally: + flag.set() + + with pytest.raises(RuntimeError): + await _hook_that_blows_up() + assert flag.is_set() + + +def test_startup_releases_the_flag_in_a_finally(): + """The guard on the real hook, read as source because booting it needs a + database. Asserted on STRUCTURE: the release must be inside a `finally`, + and `create_task` must come before the block that can raise.""" + import inspect + + from scribe import app as app_module + + src = inspect.getsource(app_module.create_app) + assert "_startup_finished.set()" in src + body = src[src.index("asyncio.create_task(_delayed_backfill())"):] + finally_at = body.index("finally:") + assert finally_at < body.index("_startup_finished.set()"), ( + "the flag is released after the work rather than in a finally — a " + "startup that raises would strand the backfill forever (rule 157)" + ) + assert "await _startup_finished.wait()" in src + + +# ── the engine cannot wait forever to connect ──────────────────────────────── + + +def test_the_engine_bounds_how_long_a_connect_may_take(): + """asyncpg's default connect timeout is 60s — the entire lifespan budget, + spent before a query is even sent. + + Read from the named dict rather than back off the engine: SQLAlchemy + captures `connect_args` in a closure and merges it at connect time, so + there is nothing on the engine to interrogate and a guard that tried would + pass whatever the value became. + """ + from scribe.models import _CONNECT_ARGS + + timeout = _CONNECT_ARGS.get("timeout") + assert timeout is not None, "a connect with no deadline (rule 156)" + assert 0 < timeout < 60 + + +def test_no_blanket_command_timeout_was_added_with_it(): + """The deliberate omission, guarded so nobody adds it as an obvious + follow-up. `command_timeout` applies to EVERY statement, and this app runs + long ones on purpose — the embedding backfills, VACUUM ANALYZE. It would + trade #4181's failure mode for a worse one.""" + from scribe.models import _CONNECT_ARGS + + assert "command_timeout" not in _CONNECT_ARGS + + +def test_the_engine_actually_uses_those_args(): + """The dict is only a guard surface if the engine is built from it. Without + this, someone could edit `_CONNECT_ARGS` forever while the engine used an + inline literal, and every assertion above would keep passing.""" + import inspect + + from scribe import models + + src = inspect.getsource(models) + assert "connect_args=_CONNECT_ARGS" in src + + +def test_the_startup_guards_can_fail(): + """Rule 167: each assertion above has to be able to bite.""" + from scribe.services.db_maintenance_scheduler import _STARTUP_READ_TIMEOUT + + # An unbounded read is the thing being prevented. + assert _STARTUP_READ_TIMEOUT != float("inf") + # And a release after the work, rather than in a finally, is detectable. + after_the_work = "try:\n work()\nfinally:\n pass\nflag.set()" + assert after_the_work.index("finally:") > after_the_work.index("try:") + assert after_the_work.index("flag.set()") > after_the_work.index("finally:")