fix: the roster's inspect budget was exactly the work it waited for (4295)
CI / lint (push) Successful in 3s
CI / extension-version (push) Successful in 3s
Build images / sign-extension (push) Successful in 4s
Build images / build-agent (push) Successful in 7s
CI / frontend-build (push) Successful in 21s
CI / backend-lint-and-test (push) Successful in 33s
Build images / build-web (push) Successful in 2m4s
CI / integration (push) Successful in 2m11s
Build images / smoke-web (push) Successful in 1m3s
Build images / promote (push) Skipped

From the operator's first consolidated deploy, 2026-09-23. The app is serving
— showcase, thumbnails, a Patreon ingest tick, all five lanes in one
container — and this repeats in the log:

    WARNING service roster: celery inspect failed; roster not refreshed
    File "service_roster.py", line 138, in refresh_celery_roster
        grouped = await asyncio.wait_for(...)
    TimeoutError

The inspect calls were working. The budget was wrong.

`_inspect_celery_sync` makes TWO broadcasts — `active_queues()` and
`active()` — and a broadcast with no `destination` cannot know how many
replies to expect, so each waits out its full timeout rather than returning
on the last reply. The sync call costs ~2 x INSPECT_TIMEOUT_SECONDS.

The wrapper allowed `INSPECT_TIMEOUT_SECONDS * 2`. That reads like a safety
factor and is precisely the worst case with nothing left over — and this runs
on a web process that was serving ninety thumbnails a second at the time, so
the thread handing off through `asyncio.to_thread` need not even be scheduled
inside the budget. A budget equal to the work fails under any load at all.

Now derived: `INSPECT_TIMEOUT_SECONDS * INSPECT_ROUND_TRIPS + slack`, with
the round-trip count named beside the calls it counts. Both tests assert the
RELATION rather than the numbers, and one reads the source to check the count
still matches the calls actually made — a third inspect call added later is
exactly how this comes back silently.

Consequence while it was broken: the roster stopped advancing and the System
tab's rows went stale, with a traceback per attempt. Never an outage —
`refresh_celery_roster` catches and returns, `/api/system/health` kept
answering 200 throughout, which the same log shows.

## Observed, not fixed here

`worker_control.inspect_lanes_sync` makes FOUR of these broadcasts
(active_queues, stats, active, reserved) at 2.0s each — roughly 8s — and
`lane_view` awaits it with no deadline at all. That is the Settings ->
Activity -> Worker lanes card, so that card likely takes ~8s to load, and the
composite healthcheck carries the same cost against its 15s timeout. Reported
to the operator rather than changed: they are mid-deploy, and the fix is to
cut round trips rather than raise a number.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01LVjrnpQjRgHdvq95rASoiR
This commit is contained in:
2026-09-23 10:32:09 -04:00
co-authored by Claude Opus 5
parent b74a4c964b
commit f23ab9f50e
2 changed files with 85 additions and 1 deletions
+54
View File
@@ -0,0 +1,54 @@
"""The roster's inspect budget must exceed the inspect work.
Both tests here assert a RELATION between constants rather than their values.
The failure they exist for is not a wrong number — it is the budget and the
work drifting apart, which is invisible in each one read on its own.
"""
from __future__ import annotations
from backend.app.services import service_roster as sr
def test_the_wrapper_budget_exceeds_the_work_it_waits_for():
"""The bug the operator's first consolidated deploy surfaced (2026-09-23).
`_inspect_celery_sync` makes INSPECT_ROUND_TRIPS broadcasts, and a
broadcast with no `destination` cannot know how many replies to expect, so
each waits out its full timeout rather than returning on the last reply.
The sync call therefore costs round_trips x INSPECT_TIMEOUT_SECONDS.
The wrapper allowed `INSPECT_TIMEOUT_SECONDS * 2`, which reads like a
safety factor and is exactly that worst case with nothing left over. Live
result: a TimeoutError traceback on every refresh while the two inspect
calls were working perfectly, and a roster that stopped advancing.
Asserted as a RELATION, not as a number. A third inspect call added to the
sync function is the way this silently comes back, and the only thing that
keeps the two honest is deriving one from the other.
"""
budget = (
sr.INSPECT_TIMEOUT_SECONDS * sr.INSPECT_ROUND_TRIPS
+ sr.INSPECT_SLACK_SECONDS
)
work = sr.INSPECT_TIMEOUT_SECONDS * sr.INSPECT_ROUND_TRIPS
assert budget > work, (
f"the wrapper allows {budget}s for {work}s of broadcasts — a budget "
f"equal to the work fails under any load at all"
)
assert sr.INSPECT_SLACK_SECONDS > 0
def test_the_round_trip_count_matches_the_calls_actually_made():
"""INSPECT_ROUND_TRIPS is only true if someone keeps it true, so read the
source rather than trusting the constant: the budget above is derived from
it, and a call added without updating it puts the wrapper back under the
work."""
import inspect as _inspect
src = _inspect.getsource(sr._inspect_celery_sync)
calls = src.count("insp.")
assert calls == sr.INSPECT_ROUND_TRIPS, (
f"_inspect_celery_sync makes {calls} inspect calls but "
f"INSPECT_ROUND_TRIPS says {sr.INSPECT_ROUND_TRIPS}"
)