Skip to content

fix: crash recovery must not block the HTTP surface at startup - #99

Merged
Diego Colombo (colombod) merged 2 commits into
mainfrom
fix/startup-must-not-block-http
Sep 9, 2026
Merged

fix: crash recovery must not block the HTTP surface at startup#99
Diego Colombo (colombod) merged 2 commits into
mainfrom
fix/startup-must-not-block-http

Conversation

@colombod

Copy link
Copy Markdown
Collaborator

Problem — /status and /version can be unreachable for minutes, and no health signal shows it

/version returns a constant string. /status reads in-memory counters. Neither touches Neo4j. Both were unreachable on the team-shared deployment for over an hour today.

Why: uvicorn runs the ASGI lifespan to completion before it handles a single request —
uvicorn/server.py: await self.startup() and only then await self.main_loop(). gunicorn binds
the listening socket before that. So during startup the process accepts TCP connections and
answers none
, however cheap the route.

lifespan() did crash recovery inline, before yield:

1. recovery_reconcile_dead()   for key in _all_worker_keys()     ← unbounded
2. recovery_seed_counts()      for key in _all_worker_keys()     ← unbounded
3. recover()                   for log in _dir.glob("*.log")     ← unbounded
4. respawn loop                recovered[:respawn_limit]         ← the only bounded phase

Captured from the live deployment, 2026-09-09:

18:57:33  Listening at: http://0.0.0.0:8000     ← port open
18:57:34  Waiting for application startup.
18:57:34  lifespan_startup: Neo4j schema initialized
18:58:27  dead_letter_unparseable key=...       ← 53s in, still in phase 2
18:59:05  dead_letter_unparseable key=...       ← 91s in, still in phase 2
19:09:31  Application startup complete: 0       ← 12 min in, never served a request

A ~5000-file spool (~1700 session keys) on Azure Files SMB kept phases 1–3 busy for minutes.
Meanwhile:

  • All three ACA probes are tcpSocket:8000, which only proves the port is open — something
    gunicorn guarantees before the app does any work. ACA reported ready: True,
    healthState: Healthy for a replica that had answered zero requests.
  • The liveness probe killed the container three times; each restart began phase 1 again from the
    top on the same spool.
  • Requests sat in the socket backlog until the APIM gateway returned its own
    500 - The request timed out at 231s.
  • Clients failed to deliver for 3352s and dropped 1493 events to their local events.jsonl.

crash_recovery_respawn_limit does not help: it bounds phase 4 only, and the process never
reached phase 4. The dead_letter_unparseable lines above are emitted from
queue_manager.py:889, inside recovery_seed_counts (phase 2).

Fix — recovery still starts at startup, but it cannot gate serving

lifespan() now does only what must be true before serving (logging, drivers, schema), then:

app.state.recovery_complete = asyncio.Event()
_recovery_task = asyncio.create_task(_startup_recovery(app))
try:
    yield
finally:
    _recovery_task.cancel()
    with suppress(asyncio.CancelledError):
        await _recovery_task
    ...

All four phases move into a new module-level _startup_recovery(app). Startup completes in ~1s and
the HTTP surface opens regardless of spool size; recovery marches on behind it.

This is safe because respawn is idempotent by construction_crash_recovery_topup is already
documented as safe to call repeatedly against a live server, and the sweep loop has always called it
on a serving process. The sweep is now awaited inside the same task rather than spawned as a
second one, so there is one task to cancel and no way for it to outlive its parent. Cancellation
happens before shutdown_workers(), so recovery cannot spawn drainers into a quiescing registry.

/status gains recovery_complete, so a caller reading it mid-recovery is told the conservation
counters have not been seeded yet rather than reading in-flight numbers as settled.

Also: the untagged-:Node boot guard is removed

Startup no longer counts untagged nodes or refuses to boot on them. Two reasons:

  1. Nothing in this service can create one. Every node-creating statement in neo4j_store is
    label-scoped — the node MERGE, both edge-endpoint MERGEs, and the session write path all
    MERGE (n:Node {node_id, workspace}).
  2. They are invisible to every read. Since get_node()/get_edge() became :Node-scoped
    (fix(neo4j): scope get_node's fallback MATCH to :Node so it seeks instead of scanning #98), read and write paths agree. A stray untagged node is inert dead data, not a correctness
    hazard — and refusing to serve over inert data is disproportionate, especially in a change whose
    whole purpose is that the server must come up.

The capability is not lost: doctor still reports untagged nodes via diagnose() /
count_untagged_nodes, and doctor --fix still repairs them. Detection moved to the operator path,
where it belongs. (Historically this check was itself an AllNodesScan that caused a 25–30s boot
stall until PR #67 made it O(1) — a second reason not to keep it on the startup path.)

Tests

  • Group A (5) — recovery-effect tests now await app.state.recovery_complete inside the
    async with lifespan(...) block before asserting. Every existing assertion kept; only the
    observation point moved.
  • Group B (3 → 1) — the three tests patching main.count_untagged_nodes are deleted and
    replaced by test_lifespan_does_not_gate_boot_on_untagged_nodes, which asserts the guard is
    genuinely gone (hasattr(main_module, "count_untagged_nodes") is False) and boot completes with
    no untagged-count patching. Its docstring records why, so the next reader does not read the
    deletion as an accident.
  • Group C (1)test_lifespan_calls_ensure_schema_with_fail_on_data_conflict drops only the
    count_untagged_nodes patch; all ensure_schema assertions unchanged.
  • tests/neo4j/test_node_identity_migration.py — comment-only correction. That test never calls
    lifespan(); it exercises ensure_neo4j_schema / count_untagged_nodes directly and is
    unaffected. Its stale "Step 2 (lifespan): the O(1) untagged guard DOES catch it" comments now
    attribute the signal to doctor / run_repair. No assertions or logic touched.

No assertion was weakened.

Results: pytest -m "not neo4j"1980 passed, 7 skipped, 92 deselected;
tests/test_main.py85 passed.

Follow-ups, deliberately not in this PR

  1. The ACA probes should become HTTP GET /version, not tcpSocket:8000. That change only
    becomes meaningful once this PR guarantees the route answers — until then an HTTP probe would
    fail during recovery and kill the container. Config, not code; land this first.
  2. The spool is never trimmed while draining. commit() writes only the .offset; the .log
    is unlinked solely by delete_drained() on graceful finalization. _all_worker_keys() globs
    every *.log and *.dead.jsonl with no filter, so phases 1–2 re-walk fully-drained sessions
    on every boot. Recovery cost therefore grows with total historical sessions rather than with
    pending work. Worth its own change.

Background-task failures fail loud

A background task's unhandled exception vanishes until garbage collection
("Task exception was never retrieved"). On the old inline path the same failure aborted boot
loudly; moving recovery off that path would have converted a loud failure into a silent one —
counters unseeded, no drainers respawned, behind a server that looks perfectly healthy.

So _startup_recovery is a thin wrapper around _startup_recovery_body: it re-raises
CancelledError (shutdown, not failure), and on any other exception records
app.state.recovery_error, logs via logger.exception, and in a finally always sets
recovery_complete so /status cannot report "in progress" forever. /status reports
recovery_error alongside recovery_complete — "complete" alone would be a lie by omission
when recovery failed.

Tests for the new guarantee

The reworked tests above prove recovery still works. These four prove the thing this PR
actually changes:

Test Guards
test_status_and_version_respond_while_recovery_is_still_running The load-bearing one. Blocks recovery on a test-controlled event, then issues real GET /version and GET /status over httpx.ASGITransport while recovery is genuinely in flight — both 200, recovery_complete: false. Releases the gate and re-checks: recovery_complete: true, recovery_error: null.
test_recovery_failure_is_logged_and_does_not_take_down_the_server A raising recovery body sets recovery_error, is surfaced on /status, is logged at ERROR, and leaves the server serving.
test_recovery_task_is_cancelled_on_shutdown No _startup_recovery task survives lifespan exit — a survivor would race shutdown_workers() and dead-letter healthy events.
test_status_reports_recovery_state_before_lifespan_has_run /status degrades gracefully (200, false/null) when the state attributes are absent, rather than raising AttributeError.

All four verified RED against main's inline-recovery source (source reverted, tests kept),
alongside the five reworked recovery tests and the untagged-guard replacement — 10 failures on
the old source, 89 passed on the new.

Final: pytest -m "not neo4j"1984 passed, 7 skipped, 92 deselected.

Move all four crash recovery phases into an asyncio.create_task() so the HTTP
surface (serving /version and /status) opens immediately, regardless of spool size.

Production incident 2026-09-09: recovery phases walked ~1700 session keys across
5000+ files on Azure Files SMB, blocking uvicorn lifespan completion and the HTTP
socket binding. TCP probes saw the port open but no requests were answered for
231s, causing APIM gateway timeouts and 1493 event drops.

Changes:
- All four recovery phases move into new _startup_recovery(app) via create_task.
  The sweep loop is awaited inside the same task; the task is cancelled before
  shutdown_workers() so recovery cannot spawn drainers into a quiescing registry.
- _startup_recovery wraps _startup_recovery_body: re-raises CancelledError,
  records recovery_error on app.state, logs via logger.exception, and sets
  recovery_complete in finally (fail-loud, not silent garbage collection).
- /status gains recovery_complete and recovery_error for observability.
- Untagged-:Node boot guard removed (inert dead data; all node-creating statements
  use MERGE with :Node tag). Detection moved to operator diagnostic path.

Verification performed:
- pytest -m "not neo4j": 1984 passed, 7 skipped, 92 deselected
- tests/test_main.py: 89 passed
- 4 new guards + 5 reworked recovery tests verified RED against main (10 failures
  on old source, 89 passed on new)
- ruff format --check: clean on all touched files

Generated with [Amplifier](https://github.com/microsoft/amplifier)

Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com>
…a /version and /status

PR #99 fixes crash-recovery blocking ASGI startup, leaving /version, /status, and
POST /events unreachable for over an hour. This version bump ensures deployed
instances are identifiable — `GET /version` and `/status` both read
importlib.metadata(pyproject.toml [project].version) via SERVER_VERSION, and
tests/routers/test_version.py pins the entire chain.

Verification:
  ✓ Editable package reinstalled; SERVER_VERSION=6.7.3
  ✓ tests/routers/test_version.py (6 passed)
  ✓ pytest -m 'not neo4j' (1984 passed, 7 skipped, 92 deselected)
  ✓ pytest -m neo4j (92 passed)

Generated with [Amplifier](https://github.com/microsoft/amplifier)

Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com>
@colombod
Diego Colombo (colombod) merged commit 1657ada into main Sep 9, 2026
3 checks passed
@colombod
Diego Colombo (colombod) deleted the fix/startup-must-not-block-http branch September 9, 2026 19:45
Diego Colombo (colombod) added a commit that referenced this pull request Sep 10, 2026
… are processed

(1) /status was calling spool_stats() inline, which scanned the entire queue
directory — stat() per file plus open+read of every .log's .offset. On a
~5000-file SMB share this caused thousands of round trips per request, with
only a 5s cache TTL to spare subsequent callers. Measured today: /version
returns in 0s, /status times out at 180s on the same replica.

Fix: spool_stats() is now synchronous cache-only (never touches filesystem,
never raises). New refresh_spool_stats() performs the scan; new
_spool_stats_refresher background task runs it on its own cadence (default
60.0s), following the create_task/cancel-in-finally pattern established in
PR #99. A failed refresh is logged; the loop continues. /status's spool
block now includes as_of_seconds to state staleness explicitly. Result:
/status is O(1) regardless of spool size.

(2) commit() writes only .offset; .log files were never trimmed. Only
delete_drained() (called solely from _finalize_session) reclaimed space.
A session never finalized cleanly kept files forever; every boot re-walked
them. The drain loop's idle branch now also calls delete_drained() — the
same safe, idempotent, file_lock-guarded call finalization already makes,
just earlier and repeatedly. Logic is conservative: refuses while
uncommitted bytes remain, keeps .dead.jsonl, anticipates log recreation.
Dead-letter files are deliberately NOT auto-purged (they are the failure
record).

Version: 6.7.4 -> 6.7.5

Generated with Amplifier

Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com>
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