Lessons reach the session that needs them, every kind is a full citizen, and a slow disk no longer takes the instance down #167
+67
-25
@@ -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():
|
||||
|
||||
@@ -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)
|
||||
|
||||
|
||||
@@ -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):
|
||||
|
||||
@@ -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:")
|
||||
Reference in New Issue
Block a user