Skip to content

Commit 132d57f

Browse files
ralyodioclaude
andauthored
A write that lands is not a write that failed, and a silent consumer stops everything (#152)
* A write that lands is not a write that failed, and a silent consumer stops everything The crawler stopped at 20:48 on 2026-08-27 and did not start again for seventeen hours. Nothing was broken in the places worth suspecting: the worker was healthy and picked jobs up 66ms after they were added, an empty write transaction against Turso answered in 0.34s, Redis was 1MB with no restarts and no evictions, and the jobs themselves ran and committed with their full return values written to the events stream. Nobody was reading that stream. `CLIENT LIST` on the production Redis showed fourteen clients and not one of them running `xread` — the poller's `QueueEvents` connection had gone away without the socket ever erroring, so the server had no such client left while the process sat in a read that would never return. `checkConnectionError` only retries a read that *errors*, and there was no error, so the loop never came round again and never said so. That is a hard stall rather than a slowdown, because `createWriteFolder` keeps one job in flight per process: every caller waited out the full `WAIT_MS` and the whole cluster fell to one write attempt per two minutes. The signature is in the log, where every failure is exactly 120000ms or 240000ms and every success is under a second, with nothing in between — a slow database gives a continuum, a lost notification gives two spikes. Three changes, in the order they matter: - `recoverFinished` asks the job what became of it when the wait expires, using `isFinished` — the same primitive `waitUntilFinished` polls with before it starts listening, and the one answer that does not depend on the stream that just failed. A committed write is handed back to its caller instead of being reported as a failure, which is the half of this that was quietly corrupting state: the crawler recorded an error against healthy feeds and re-crawled rows it had already stored. - `removeOnComplete` keeps the last 200 jobs rather than deleting each one the instant it succeeds. Tidy, and it was what made a lost notification unrecoverable — the waiter went looking for the job and found nothing. - `reviveEvents` replaces a consumer that has stopped consuming, guarded on a pulse so a genuinely slow job does not cost a reconnect. `entry.events` is read through the entry at every wait, because a destructured copy would pin every future caller to the corpse. An `error` listener goes on both objects so the next connection failure is a log line rather than nothing at all. Production was recovered by restarting the poller before this landed; write throughput went from ~30 statements per ten minutes to 943, and the OPML import that had been frozen at 30,000 rows since 20:45 resumed. Tested against stubs rather than a broker, for the reason `runWriteJob` is: the judgement is in what to believe when the notification never came, and the BullMQ plumbing is not the part that was wrong. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01PLtMz1jBZVziV2xn8iTh2j * Say only what was measured about why the consumer went quiet The first version of these comments asserted a mechanism — the consumer hung forever in a blocking read that never errored — on the strength of there being no `xread` client in Redis during the outage. That inference does not hold. Sampled thirty times over thirty seconds against a fully healthy crawler, none of the samples showed an `xread` client either, so its absence says nothing about whether the consumer is alive. BullMQ 6.1.2 also already carries a watchdog for precisely the hang that was being claimed, which the story did not account for. What was actually measured is unchanged and is enough: for seventeen hours every wait expired while the jobs ran and committed, their completion events and return values were written to the stream, nothing acted on them, and restarting the process fixed it. The fix does not depend on knowing why. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01PLtMz1jBZVziV2xn8iTh2j * Poll the job beside the wait, because the stall outlived the restart Restarting the poller at 14:11 restored the crawler — 943 statements in a ten-minute tally against the ~30 it had been managing — and by 14:41 it had stalled again, with the same 120000ms waits on feeds that were being written successfully. So the condition recurs on its own, and a fix that only takes effect after the deadline is not a fix: recovering the result once the wait expires tells the caller the truth and still leaves `createWriteFolder` with one job in flight per two minutes, which is a stopped crawler with accurate error messages. `settleJob` runs the poll *beside* the notification instead of after it. `waitUntilFinished` stays the fast path, so a working stream still settles a write on one Redis round trip. Alongside it, `isFinished` — the job's own state, which owes nothing to any consumer — is asked every 500ms, and whichever answer comes first wins. There is only ever one job in flight per process, so the cost is two small reads a second against a failure mode that costs everything. The deadline still exists and still means what it meant: if neither the stream nor two minutes of polling can find a finished job, the job really is unfinished and the caller fails. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01PLtMz1jBZVziV2xn8iTh2j --------- Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
1 parent 30f3766 commit 132d57f

2 files changed

Lines changed: 442 additions & 7 deletions

File tree

‎packages/db/src/writeQueue.js‎

Lines changed: 261 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -55,6 +55,24 @@ export const WRITE_QUEUE = 'turso-writes';
5555
*/
5656
const WAIT_MS = 120_000;
5757

58+
/**
59+
* How often a caller asks the job directly whether it has finished.
60+
*
61+
* The event stream is an optimisation, not the mechanism. It was treated as
62+
* the mechanism, and when it went quiet every caller sat out the full
63+
* `WAIT_MS` — which, because `createWriteFolder` keeps one job in flight per
64+
* process, is not a slow write but a stopped crawler. Recovering *after* the
65+
* timeout fixes the lie told to the caller and leaves the two-minute ceiling
66+
* exactly where it was, so the poll has to run alongside the wait rather than
67+
* after it.
68+
*
69+
* Half a second against a write that takes a few hundred milliseconds costs at
70+
* most one extra round trip per write, and there is only ever one job in flight
71+
* per process to poll for — two small reads a second, against a stall that
72+
* costs everything.
73+
*/
74+
const SETTLE_POLL_MS = 500;
75+
5876
/**
5977
* Encode one libSQL value for JSON.
6078
*
@@ -209,15 +227,18 @@ export function queueWrites(client, opts) {
209227
// so the keyspace is claimed explicitly rather than left on BullMQ's default.
210228
const prefix = opts.prefix ?? '{rssamplifier}';
211229

212-
const { queue, events } = sharedQueue(opts.url, prefix);
230+
// The entry rather than its fields: `entry.events` is replaced in place when
231+
// a dead consumer is rebuilt, and a destructured copy would pin every future
232+
// wait to the corpse. See `reviveEvents`.
233+
const entry = sharedQueue(opts.url, prefix);
213234
const original = client.batch.bind(client);
214235

215236
/**
216237
* @param {unknown[]} statements
217238
* @returns {Promise<unknown>}
218239
*/
219240
const enqueue = async (statements) => {
220-
const job = await queue.add(
241+
const job = await entry.queue.add(
221242
'batch',
222243
{ statements: Array.from(statements ?? []).map(encodeStatement) },
223244
{
@@ -241,15 +262,37 @@ export function queueWrites(client, opts) {
241262
// gives a contended primary a chance to drain first, which is the
242263
// only thing that makes the next attempt differ from the last.
243264
backoff: { type: 'exponential', delay: opts.backoffMs ?? 5_000 },
244-
removeOnComplete: true,
265+
// Was `true`, which deletes the job the instant it succeeds. That is
266+
// the tidy answer and it made a lost notification unrecoverable: the
267+
// waiter times out, goes looking for the job to ask whether its write
268+
// actually landed, and finds nothing — so a write that *committed* is
269+
// reported to the crawler as a failure, and a healthy feed collects an
270+
// error and a re-crawl for a row it already stored.
271+
//
272+
// A short retention gives `recoverFinished` something to read. Two
273+
// hundred is a couple of minutes of queue at full rate, which is far
274+
// longer than the window between a completion and the waiter noticing
275+
// it, and small enough to stay invisible next to a 1MB Redis.
276+
removeOnComplete: { count: 200 },
245277
// Kept, because a write that failed every attempt is the thing you go
246278
// looking for afterwards. Bounded so the list cannot become the leak.
247279
removeOnFail: 1000,
248280
},
249281
);
250282

251-
const encoded = await job.waitUntilFinished(events, WAIT_MS);
252-
return /** @type {object[]} */ (encoded).map(decodeResult);
283+
try {
284+
const encoded = await settleJob(entry, job);
285+
return /** @type {object[]} */ (encoded).map(decodeResult);
286+
} catch (err) {
287+
if (!isWaitTimeout(err)) throw err;
288+
289+
// Both the notification and every poll for two minutes failed to find a
290+
// finished job, so the consumer is rebuilt before the next caller
291+
// inherits the same silence. The job itself is genuinely unfinished --
292+
// `settleJob` would have returned it otherwise -- so this caller fails.
293+
await reviveEvents(entry);
294+
throw err;
295+
}
253296
};
254297

255298
// Callers waiting at the same moment are folded into one job, which is one
@@ -305,10 +348,21 @@ function groupStatements(opts) {
305348
* minutes and kept climbing. Refcounted rather than cached outright so that
306349
* `closeWriteQueue` still means something to a caller that owns the last one.
307350
*
308-
* @type {Map<string, { queue: import('bullmq').Queue, events: import('bullmq').QueueEvents, refs: number }>}
351+
* @type {Map<string, Entry>}
309352
*/
310353
const shared = new Map();
311354

355+
/**
356+
* @typedef {{
357+
* queue: import('bullmq').Queue,
358+
* events: import('bullmq').QueueEvents,
359+
* url: string,
360+
* prefix: string,
361+
* refs: number,
362+
* lastEventAt: number,
363+
* }} Entry
364+
*/
365+
312366
/**
313367
* @param {string} url
314368
* @param {string} prefix
@@ -325,14 +379,214 @@ function sharedQueue(url, prefix) {
325379
const connection = connectionFor(url);
326380
const entry = {
327381
queue: new Queue(WRITE_QUEUE, { connection, prefix }),
328-
events: new QueueEvents(WRITE_QUEUE, { connection, prefix }),
382+
events: newEvents(url, prefix),
383+
url,
384+
prefix,
329385
refs: 1,
386+
lastEventAt: Date.now(),
330387
};
331388

389+
// Once, at construction rather than in `watchEvents`, which runs again on
390+
// every revive. An `error` with no listener is a throw, and BullMQ reports
391+
// connection trouble on the object it happened to.
392+
entry.queue.on('error', () => {});
393+
394+
watchEvents(entry);
332395
shared.set(key, entry);
333396
return entry;
334397
}
335398

399+
/**
400+
* @param {string} url
401+
* @param {string} prefix
402+
* @returns {import('bullmq').QueueEvents}
403+
*/
404+
function newEvents(url, prefix) {
405+
return new QueueEvents(WRITE_QUEUE, { connection: connectionFor(url), prefix });
406+
}
407+
408+
/**
409+
* Keep a pulse on the event consumer, and stop its failures being silent.
410+
*
411+
* Both halves of this were missing and the outage needed both. BullMQ's
412+
* `QueueEvents` swallows connection errors inside its own read loop and
413+
* re-emits them on itself; with no `error` listener attached, node's
414+
* EventEmitter turns that into a throw which BullMQ then catches and discards.
415+
* So the consumer can stop being a consumer without a single line in the log.
416+
*
417+
* `lastEventAt` is the pulse. The queue emits `added` and `active` for every
418+
* job and `completed` or `failed` for every outcome, so a consumer that is
419+
* reading at all cannot be quiet for long while work is going through. That is
420+
* what lets a wait timeout tell "the job is slow" from "nobody is listening" —
421+
* see `reviveEvents`.
422+
*
423+
* @param {Entry} entry
424+
*/
425+
function watchEvents(entry) {
426+
const beat = () => {
427+
entry.lastEventAt = Date.now();
428+
};
429+
430+
for (const name of ['added', 'active', 'completed', 'failed', 'drained']) {
431+
entry.events.on(name, beat);
432+
}
433+
434+
entry.events.on('error', beat);
435+
}
436+
437+
/**
438+
* Replace an event consumer that has stopped consuming.
439+
*
440+
* The failure this exists for, stated only as far as it was actually observed:
441+
* for seventeen hours every wait expired while the jobs themselves ran and
442+
* committed, with their `completed` events and full return values written to
443+
* the stream and nothing acting on them. The database was healthy, the worker
444+
* was healthy, and restarting the process fixed it — so whatever had happened
445+
* had happened to this object, and only a new one would do.
446+
*
447+
* The mechanism underneath is *not* settled, and this comment deliberately does
448+
* not claim it is. The obvious story — the consumer hung forever in a blocking
449+
* read — is undermined by BullMQ 6.1.2 already carrying a watchdog for exactly
450+
* that (`readEvents` races the read and reconnects). What can be said is that
451+
* the recovery is cheap, bounded, and only ever runs on a wait that has already
452+
* failed.
453+
*
454+
* Guarded on the pulse so a genuinely slow job does not cost a reconnect: if
455+
* the consumer has reported anything at all within the last `WAIT_MS`, it is
456+
* alive and the wait was simply too short.
457+
*
458+
* The old object is closed for its connection's sake, but not waited on: if it
459+
* is wedged, awaiting its close is the one thing guaranteed to hang.
460+
*
461+
* @param {Entry} entry
462+
* @returns {Promise<void>}
463+
*/
464+
async function reviveEvents(entry) {
465+
if (Date.now() - entry.lastEventAt < WAIT_MS) return;
466+
467+
const dead = entry.events;
468+
entry.events = newEvents(entry.url, entry.prefix);
469+
entry.lastEventAt = Date.now();
470+
watchEvents(entry);
471+
472+
void Promise.resolve()
473+
.then(() => dead.close())
474+
.catch(() => {});
475+
}
476+
477+
/**
478+
* Wait for one job, believing the event stream *or* the job itself.
479+
*
480+
* `waitUntilFinished` is kept as the fast path: when the stream is working it
481+
* settles a write the instant the worker finishes it, which is what makes the
482+
* queue cost one Redis round trip rather than a poll interval.
483+
*
484+
* The poll runs beside it because the stream is the part that failed. It asks
485+
* `isFinished` — the job's own state, which owes nothing to any consumer — and
486+
* whichever answer arrives first wins. That is the difference between a write
487+
* that is merely reported honestly and a crawler that keeps running: recovering
488+
* after the timeout still leaves one job in flight per `WAIT_MS`, which is a
489+
* stopped crawler with accurate error messages.
490+
*
491+
* The losing promise is left with a `catch` attached rather than cancelled;
492+
* `waitUntilFinished` has no cancel, and its later rejection must not surface
493+
* as an unhandled one.
494+
*
495+
* @param {Entry} entry
496+
* @param {import('bullmq').Job} job
497+
* @returns {Promise<unknown[]>}
498+
*/
499+
export async function settleJob(entry, job) {
500+
let settled = false;
501+
502+
const notified = job.waitUntilFinished(entry.events, WAIT_MS);
503+
notified.catch(() => null);
504+
505+
const polled = (async () => {
506+
// Loops until the notification path resolves or rejects. It never resolves
507+
// "not finished" of its own accord, because that would win the race with a
508+
// non-answer and rob the caller of the real one.
509+
for (;;) {
510+
await new Promise((resolve) => {
511+
setTimeout(resolve, SETTLE_POLL_MS);
512+
});
513+
514+
// The race is already decided, so this value is discarded. Returning
515+
// rather than looping is what lets the timer stop.
516+
if (settled) return null;
517+
518+
// A job that failed every attempt throws here, which is the right answer
519+
// and beats waiting out the rest of the deadline for the same news.
520+
const recovered = await recoverFinished(job);
521+
if (recovered) return recovered;
522+
}
523+
})();
524+
525+
polled.catch(() => null);
526+
527+
try {
528+
return /** @type {unknown[]} */ (await Promise.race([notified, polled]));
529+
} finally {
530+
settled = true;
531+
}
532+
}
533+
534+
/**
535+
* Whether an error is `waitUntilFinished` giving up, rather than a real failure.
536+
*
537+
* Matched on the message because BullMQ throws a plain `Error` for it — there
538+
* is no class to test and no code on it.
539+
*
540+
* @param {unknown} err
541+
* @returns {boolean}
542+
*/
543+
export function isWaitTimeout(err) {
544+
return /timed out before finishing, no finish notification/.test(
545+
String(/** @type {{ message?: string }} */ (err)?.message ?? err),
546+
);
547+
}
548+
549+
/**
550+
* Ask the queue what became of a job whose notification never arrived.
551+
*
552+
* Deliberately the same primitive `waitUntilFinished` polls with before it
553+
* starts listening — `isFinished`, which reads the job's own state rather than
554+
* anything on the event stream. That is the whole point: the stream is the part
555+
* that just failed, so the recovery must not consult it.
556+
*
557+
* Returns the encoded results if the job had in fact completed, and null if it
558+
* is genuinely still running or its state cannot be read. A job that failed
559+
* every attempt throws its own reason, because "UNIQUE constraint failed" is a
560+
* far better thing to hand a caller than "we waited two minutes".
561+
*
562+
* @param {{ id?: string|number, backend: { isFinished: (id: string, returnValue: boolean) => Promise<[number, string]> } }} job
563+
* @returns {Promise<unknown[]|null>}
564+
*/
565+
export async function recoverFinished(job) {
566+
let status;
567+
let result;
568+
569+
try {
570+
[status, result] = await job.backend.isFinished(String(job.id), true);
571+
} catch {
572+
return null;
573+
}
574+
575+
// Still waiting, still running, or gone. Nothing to hand back.
576+
if (!status) return null;
577+
578+
// The two codes `waitUntilFinished` treats as failure. `result` is the
579+
// failedReason rather than a return value.
580+
if (status === -1 || status === 2) throw new Error(String(result) || 'write job failed');
581+
582+
try {
583+
const value = JSON.parse(String(result));
584+
return Array.isArray(value) ? value : null;
585+
} catch {
586+
return null;
587+
}
588+
}
589+
336590
/**
337591
* @param {string} url
338592
* @param {string} prefix

0 commit comments

Comments
 (0)