Skip to content

fix: /status must never walk the spool — the second unbounded scan PR #101 missed - #102

Merged
Diego Colombo (colombod) merged 1 commit into
mainfrom
fix/serve-guard-must-fail-fast
Sep 10, 2026
Merged

fix: /status must never walk the spool — the second unbounded scan PR #101 missed#102
Diego Colombo (colombod) merged 1 commit into
mainfrom
fix/serve-guard-must-fail-fast

Conversation

@colombod

Copy link
Copy Markdown
Collaborator

/status still hangs in production — PR #101 fixed one of its two unbounded walks

PR #101 claimed "/status is now O(1) regardless of spool size." That claim was false.
Measured on team-shared, on a healthy replica (restarts 0, up 3 hours) running the merged 6.7.5:

/version          200 in 1s
/cypher RETURN 1  200 in 0s
POST /events      202 in 1s
/status           no response (60s, 120s, 150s, 180s)

Neo4j is fast, ingest is fast, only /status hangs. /status had two unbounded per-key
walks. #101 moved spool_stats() off the request path and never looked for a second one.

The one it missed, reached via Registry.pipeline_metrics():

agg = await self.queue_manager.derive_all_stats()

# derive_all_stats(), inline on every request:
for worker_key in self._all_worker_keys():                 # every key
    committed = self._read_committed_offset(worker_key)    # open + read per key
    in_queue  = self._count_newlines(worker_key, committed)# streamed count of each tail
    dead      = self._count_dead(worker_key)               # read each .dead.jsonl

Gated only by a 1-second read-side TTL — which spares the second caller and never the
first. Exactly the flaw #101 fixed in spool_stats, in the same handler, left in place.

Fix

Same split that already landed for spool_stats:

  • refresh_all_stats() — async, does the scan (old body verbatim), populates the cache. No TTL
    gate. The only thing that touches disk for these figures.
  • derive_all_stats() — now synchronous and cache-only. Never touches the filesystem,
    never raises.
  • all_stats_age_seconds() — snapshot age, None before the first refresh.
  • _spool_stats_refresher now drives both refreshes each cycle. Either one left on the
    request path recreates the timeout the loop exists to prevent.

The cold window must not lie

pipeline_metrics computes residual = accepted − written − in_queue − dead. Before the first
refresh, in_queue/dead are 0 because they are unknown, not because they are zero — so a
naive read would inflate the residual by exactly the backlog it cannot see and report a fabricated
loss. A hanging endpoint traded for a lying one is not a fix.

So the cold snapshot carries stats_available: False, and pipeline_metrics uses it to suppress
the determination rather than invent it:

lost     = max(0, residual) if stats_available else 0
degraded = stats_available and (dead > 0 or sustained)
"residual": residual if stats_available else None

Critically, the grace-period timer (_residual_positive_since) is not latched on unknown data.
/status now also reports metrics.stats_available and metrics.as_of_seconds, so a caller can
tell measured zero from not yet measured.

Evidence — measured, not asserted

This is the check I failed to run before calling #101 safe. A/B of the per-request cost against
a synthetic spool of pending keys (offset < size — the expensive shape), on local SSD:

keys=    0   files=    0    OLD (scan per request) =   2.39 ms    NEW (cache read) = 0.0002 ms
keys=  500   files= 1050    OLD                    =  40.11 ms    NEW              = 0.0006 ms
keys= 2000   files= 4200    OLD                    =  99.09 ms    NEW              = 0.0005 ms
keys= 5000   files=10500    OLD                    = 255.99 ms    NEW              = 0.0009 ms

OLD grows linearly with key count — 107× from 0 to 5000 keys. NEW is flat at ~0.0005 ms:
genuinely O(1). And that is on local SSD; on Azure Files SMB every one of those file operations is
a network round trip, which is how it became 60–180 s on team-shared.

End-to-end on the local server (real spool, systemd unit, v6.7.6):

/version -> 200 in 50ms
/status  -> 200 in 45ms
metrics.stats_available: True | residual: 0 | as_of_seconds: 4.9
spool: {pending_sessions: 0, spool_bytes_total: 3017573, as_of_seconds: 4.9}

Also in this PR: the CI serve-guard test flake

test_serve_still_fails_loud_for_a_real_misconfiguration failed on main @ 7c021bc with a 15 s
TimeoutExpired. Not a guard regression. The same tree passed CI twice on its branch
(e58bbcd, 1f60669), and locally the guard fires in 0.74 s with returncode 3, a full
traceback, the correct message, and gunicorn cleanly reporting "Worker failed to boot." On the
runner the subprocess had only reached Starting gunicorn — it never got to worker boot, so the
guard never had the chance to fire.

15 s has to cover spawn + a cold import of the whole server package + gunicorn arbiter start + fork

  • worker load() before the guard can raise at all. On a cold shared runner that is too tight, and
    when it trips, TimeoutExpired says only "15 seconds passed" while SIGKILL discards the child's
    buffered stderr — so a slow runner is indistinguishable from a broken guard.
  • serve gets a 90 s budget (costs nothing on a healthy run — it exits in under a second, and only
    spends real time when something is genuinely wrong, which is exactly when you want the output).
  • A timeout now raises an AssertionError carrying the partial stdout/stderr and stating plainly
    that it is a wall-clock timeout, not proof a guard failed to fire.

The assertions are unchanged: still non-zero exit, still the guard's message.

Tests

Existing tests that relied on derive_all_stats() scanning now call await refresh_all_stats()
first — observation point moved, no assertion weakened. test_derive_all_stats_caches_within_ttl
tested a TTL that no longer exists and is replaced by two tests for the new contract:

Test Guards
test_refresh_all_stats_always_scans_no_ttl_gate two consecutive refreshes both scan
test_derive_all_stats_is_synchronous_read_only_and_never_scans filesystem entry point patched to raise; cold sentinel + populated passthrough, zero access
test_cold_cache_suppresses_residual_and_does_not_latch_grace_timer cold cache with counters implying residual=100 → stats_available: False, residual: None, degraded: False, and _residual_positive_since not latched
test_after_refresh_reports_available_stats_and_age after refresh → stats_available: True, numeric residual, as_of_seconds float ≥ 0

18 tests verified RED against the pre-change source (AttributeError: no attribute 'refresh_all_stats', and KeyError: 'stats_available' for the cold-window pair).

Results: pytest -m "not neo4j"2011 passed, 7 skipped, 92 deselected.
pytest -m neo4j (live containers) → 92 passed. ruff format --check clean.

Version 6.7.5 → 6.7.6.

What I got wrong, so it isn't repeated

I verified spool_stats() with a unit test that patches iterdir to raise — which proves that
function is clean and says nothing about the endpoint. I never called /status against a large
spool and timed it. When I did deploy-test locally, I did it after the reclaim had shrunk the
spool to 796 bytes, so the second walk covered two keys and returned instantly. I gathered evidence
in the one condition that hides the bug, then reported it as proof of an O(1) claim.

The A/B table above is the check that should have gated #101, and it is now the standing guard.

PR #101 claimed '/status is now O(1) regardless of spool size', but the claim was
false. The fix moved spool_stats() off the request path but missed a second
unbounded scan reached via Registry.pipeline_metrics() ->
QueueManager.derive_all_stats(). This path walked every worker key inline,
opening and reading each .offset file and .dead.jsonl tail on each request,
gated only by a 1-second READ-SIDE TTL that spared the second caller but never
the first. On a healthy replica with 5000+ worker keys, /status timed out
(60s/120s/150s+) while other endpoints responded normally.

This fix mirrors the split already applied to spool_stats:
- refresh_all_stats() — async, performs the full scan, populates cache,
  no TTL gate, the only operation that touches disk for these metrics
- derive_all_stats() — now SYNCHRONOUS and cache-only; never touches
  filesystem, never raises
- all_stats_age_seconds() — reports snapshot age (None before first refresh)
- _spool_stats_refresher now drives BOTH refreshes each cycle

Cold-window correctness: before the first refresh, in_queue and dead stats
are UNKNOWN (not zero), so naive reads would fabricate loss. The snapshot
carries stats_available: False, and pipeline_metrics suppresses rather than
invents: residual is None when unavailable, degraded is only computed when
stats are available, and _residual_positive_since is not latched on unknown
data. /status now reports metrics.stats_available and metrics.as_of_seconds
for full visibility.

SECONDARY: test_serve_still_fails_loud_for_a_real_misconfiguration flaked
on main (15s TimeoutExpired). Not a guard regression — the test passed twice
on branch and fires locally in 0.74s. On the runner, the subprocess stalled
during gunicorn startup, never reaching worker boot. Subprocess budget
raised to 90s (zero cost on healthy runs) and timeout now raises AssertionError
carrying partial stdout/stderr and naming it as wall-clock timeout, not proof
of guard failure.

Version: 6.7.5 -> 6.7.6

Generated with Amplifier

Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com>
@colombod
Diego Colombo (colombod) merged commit df5fa32 into main Sep 10, 2026
3 checks passed
@colombod
Diego Colombo (colombod) deleted the fix/serve-guard-must-fail-fast branch September 10, 2026 03:29
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant