|
| 1 | +--- |
| 2 | +title: "One stuck message kills a NATS subject until restart — `domain.list: timeout` and the sequential handler loop" |
| 3 | +lede: "reach-edu's corpora stopped loading, and the cause wasn't the data or the database: every handler in domains.ts consumes its subject with a `for await` loop, so a single request that never settles blocks that subject forever. Silent, total, invisible in the logs, and only a container restart clears it." |
| 4 | +date_created: 2026-08-08 |
| 5 | +date_modified: 2026-08-08 |
| 6 | +authors: |
| 7 | + - Michael Staton |
| 8 | +augmented_with: |
| 9 | + - Claude Code on Claude Opus 5 |
| 10 | +semantic_version: 0.0.0.1 |
| 11 | +tags: |
| 12 | + - Issue |
| 13 | + - Augment-It |
| 14 | + - NATS |
| 15 | + - Record-SurrealDB-Resolver |
| 16 | + - Resilience |
| 17 | + - Error-Handling |
| 18 | +status: Open · Diagnosed |
| 19 | +--- |
| 20 | + |
| 21 | +# One stuck message kills a NATS subject until restart |
| 22 | + |
| 23 | +## Why Care? |
| 24 | + |
| 25 | +The operator saw `domain.list: timeout` and reasonably concluded that reach-edu's |
| 26 | +corpora had failed to load. They had not. All nine were in SurrealDB the whole |
| 27 | +time, reachable in about a second. What had failed was the *service's ability to |
| 28 | +answer any question on that subject at all* — for every client, including an |
| 29 | +empty filter. |
| 30 | + |
| 31 | +This is the worst shape a failure can take in this stack: **silent, total for the |
| 32 | +affected subject, and invisible in the logs.** The container reports healthy, the |
| 33 | +NATS subscription stays registered, the process never crashes, and nothing is |
| 34 | +written to stdout. The only signal is that replies stop coming, and the only |
| 35 | +recovery is a restart. |
| 36 | + |
| 37 | +It will recur. The conditions that cause it are ordinary. |
| 38 | + |
| 39 | +## Symptom |
| 40 | + |
| 41 | +``` |
| 42 | +❯ domain.list: timeout |
| 43 | +``` |
| 44 | + |
| 45 | +Corpora absent from the reach-edu workspace. Every other surface behaving |
| 46 | +normally. |
| 47 | + |
| 48 | +## What it was not |
| 49 | + |
| 50 | +Ruled out by measurement, in this order: |
| 51 | + |
| 52 | +| Suspected | Verdict | |
| 53 | +|---|---| |
| 54 | +| reach-edu's data missing | **No.** All 9 domains present in SurrealDB | |
| 55 | +| Client-specific | **No.** `{}`, `reach-edu` and `humain-vc` all timed out | |
| 56 | +| The `registerHandlers` rename shipped the same week | **No.** `domain.list.requested` is registered by `registerDomainHandlers` in `domains.ts`, untouched by that commit | |
| 57 | +| Service not running / crashed | **No.** Container up, `RestartCount=0`, booted clean | |
| 58 | +| SurrealDB unreachable from the container | **No.** DNS + TLS OK; full connect → signin → use → query in **1,107ms** | |
| 59 | +| The full-table `UPDATE` in `ensureDomainSchema` | **No.** Measured **538ms** across 210 `sources` and 254 `source_usages` | |
| 60 | +| Nothing subscribed to the subject | **No.** A misread of the NATS monitoring payload — `subs_detail` is empty, the real key is `subscriptions_list_detail`, and the subject *was* registered | |
| 61 | + |
| 62 | +## The evidence that located it |
| 63 | + |
| 64 | +NATS monitoring, before and after a single probe request: |
| 65 | + |
| 66 | +``` |
| 67 | +BEFORE: in_msgs=4 out_msgs=15 |
| 68 | +PROBE: timeout |
| 69 | +AFTER: in_msgs=4 out_msgs=16 |
| 70 | +``` |
| 71 | + |
| 72 | +`out_msgs` incremented — the server **delivered** the message to the resolver |
| 73 | +connection. `in_msgs` did not — the service **replied with nothing**. The message |
| 74 | +arrived, was consumed, and produced no response and no log line. |
| 75 | + |
| 76 | +A `docker restart` of the service restored it immediately: first call 1,952ms |
| 77 | +cold, second 118ms, all 9 domains returned. |
| 78 | + |
| 79 | +## Root cause |
| 80 | + |
| 81 | +Every handler in `services/record-surrealdb-resolver/src/domains.ts` is |
| 82 | +registered through this shape: |
| 83 | + |
| 84 | +```ts |
| 85 | +void (async () => { |
| 86 | + const sub = nc.subscribe(subject); |
| 87 | + for await (const msg of sub) { |
| 88 | + const args = msg.json() as T; // ← OUTSIDE the try |
| 89 | + try { |
| 90 | + const db = await getDb(); // ← no timeout |
| 91 | + await ensureDomainSchema(db); |
| 92 | + const result = await fn(db, args); |
| 93 | + if (msg.reply) msg.respond(JSON.stringify({ ok: true, ...(result as object) })); |
| 94 | + } catch (err: unknown) { |
| 95 | + if (msg.reply) msg.respond(JSON.stringify({ ok: false, error: String(err) })); |
| 96 | + } |
| 97 | + } |
| 98 | +})(); |
| 99 | +``` |
| 100 | + |
| 101 | +Three defects compound into the observed behaviour. |
| 102 | + |
| 103 | +### 1. `for await` is strictly sequential — one stuck message blocks the subject |
| 104 | + |
| 105 | +The loop awaits each message's full processing before pulling the next. A single |
| 106 | +request that never settles halts the queue **permanently**. Later requests are |
| 107 | +delivered by NATS and then dropped on the floor. Nothing times the loop out, |
| 108 | +nothing retries it, nothing reports it. |
| 109 | + |
| 110 | +### 2. `getDb()` has no timeout and caches only on success |
| 111 | + |
| 112 | +```ts |
| 113 | +export async function getDb(): Promise<Surreal> { |
| 114 | + if (db) return db; |
| 115 | + const instance = new Surreal(); |
| 116 | + await instance.connect(URL); // ← can hang indefinitely |
| 117 | + await signinAndUse(instance); |
| 118 | + db = instance; // ← only reached on success |
| 119 | + return db; |
| 120 | +} |
| 121 | +``` |
| 122 | + |
| 123 | +`connect()` against a WSS endpoint (Surreal Cloud) has no deadline. If the |
| 124 | +handshake stalls — a transient network blip at container start is enough — the |
| 125 | +promise never settles, `db` is never assigned, and combined with defect 1 the |
| 126 | +subject is dead for the lifetime of the process. |
| 127 | + |
| 128 | +### 3. `msg.json()` sits outside the try block |
| 129 | + |
| 130 | +A malformed payload throws out of the `for await` loop entirely. Because the |
| 131 | +loop lives in a bare `void (async () => {})()` with no `.catch()`, that becomes |
| 132 | +an unhandled rejection and the subscription's consumer is gone — silently. The |
| 133 | +NATS subscription stays registered server-side, so the subject *looks* healthy |
| 134 | +from monitoring while nothing consumes it. |
| 135 | + |
| 136 | +## Blast radius |
| 137 | + |
| 138 | +`domains.ts`'s `handle()` covers `domain.list.requested`, |
| 139 | +`domain.assemble.requested` and `tag.suggest.requested`, plus the hand-written |
| 140 | +loops for `domain.create.requested` and `domain.retype.requested`. The same |
| 141 | +`void (async () => { for await ... })()` idiom appears across the other NATS |
| 142 | +services, so this is a **pattern-level** defect rather than a single-file one — |
| 143 | +`domains.ts` is simply where it fired first, being the busiest cold-start path. |
| 144 | + |
| 145 | +## Fix |
| 146 | + |
| 147 | +1. **Bound `getDb()`.** A connect/signin deadline that rejects rather than hangs, |
| 148 | + so the `catch` can answer `{ok:false}` and the loop moves on. |
| 149 | +2. **Move `msg.json()` inside the try**, so a malformed payload answers with an |
| 150 | + error instead of destroying the subscription. |
| 151 | +3. **Stop one message blocking the queue.** Process each message without awaiting |
| 152 | + it in the loop body, so a slow or stuck request cannot starve the others. |
| 153 | +4. **Never let the consumer die silently.** Attach a `.catch()` to the loop that |
| 154 | + logs, so if it ever does exit there is a line in the logs instead of silence. |
| 155 | + |
| 156 | +## Verification |
| 157 | + |
| 158 | +- Unit coverage for the three defects: a payload that is not valid JSON, a |
| 159 | + `getDb()` that never settles, and a slow request that must not block a fast one |
| 160 | + behind it. |
| 161 | +- `domain.list` answers for `reach-edu` (9 domains), `humain-vc`, and an empty |
| 162 | + filter. |
| 163 | +- Full suite green. |
| 164 | + |
| 165 | +## Related |
| 166 | + |
| 167 | +- [[Structural-Refactors-Surfaced-by-the-Codebase-Graph]] — the same service's |
| 168 | + `registerHandlers` rename, ruled out here |
| 169 | +- `services/record-surrealdb-resolver/src/domains.ts` |
| 170 | +- `services/record-surrealdb-resolver/src/surreal.ts` |
0 commit comments