From 01c470a48742d5ee51b09d3b2698996c6e74e0ab Mon Sep 17 00:00:00 2001 From: Anthony Ettinger Date: Tue, 22 Sep 2026 15:49:38 +0000 Subject: [PATCH] A hung dependency restarts the container instead of hanging the site Twice now Redis has gone away and tipoffwatch has stayed down until a person noticed: 2026-09-13, and again on 2026-09-22 while the volume was being cleared. Both times the shape was identical. `/healthz` answered 200 in 50ms, `/` returned nothing at all, Railway reported the service Online, and restarting Redis did not fix it -- the wedge is on this side of the socket, so only redeploying the web service brought the site back. The reason it cannot recover on its own is one line in the shared client. BullMQ requires `maxRetriesPerRequest: null`, and that turns a disconnect into a hang: a command issued while the socket is down is queued until it returns rather than rejected. Verified rather than assumed -- a bare `ping()` against a dead port with the app's own options never settles. The page render catches Redis errors and falls through to Postgres, but there is no error to catch, so the request simply stops. `/healthz` touches neither dependency, which is why every liveness signal Railway has stayed green through both outages. genrewatch already solved this for Postgres in its PR #23, after the same failure on its pool: probe through the client the requests actually use, and exit when it stops answering. A separate connection is the one thing guaranteed to look healthy during this failure, which is why the probe has to share the client. So the watchdog is ported here and given a subject, and both dependencies get one: `select 1` on the shared `sql` handle, `PING` on the shared ioredis connection. Exiting reads as drastic for a web server and is the cheapest correct move -- the failure is process-local state no request can repair, a restart demonstrably clears it, and Railway replaces the container in about a minute. Hanging forever is not the safer option, it is the outage. Redis gets one more failure than the pool, four probes rather than three. A healthy Redis here is routinely unreachable for a while, because it restarts by reading an RDB off the volume before accepting anything: 26 seconds now, 124 before the event streams were trimmed. Boot already throws if Redis is absent, so an impatient watchdog would turn one Redis deploy into a deploy loop on this service. Co-Authored-By: Claude Opus 5 (1M context) --- apps/web/src/lib/db-watchdog.js | 147 ++++++++++++++++++++++ apps/web/src/main.js | 54 +++++++- test/db-watchdog.test.js | 217 ++++++++++++++++++++++++++++++++ 3 files changed, 417 insertions(+), 1 deletion(-) create mode 100644 apps/web/src/lib/db-watchdog.js create mode 100644 test/db-watchdog.test.js diff --git a/apps/web/src/lib/db-watchdog.js b/apps/web/src/lib/db-watchdog.js new file mode 100644 index 0000000..57afa27 --- /dev/null +++ b/apps/web/src/lib/db-watchdog.js @@ -0,0 +1,147 @@ +/** + * Notice when a dependency has stopped answering the client this process uses. + * + * Ported from genrewatch (PR #23), which added it after 2026-09-07: every page on + * that site hung forever while the container stayed up, Postgres stayed healthy + * and Railway reported the service Online. The web process had run for about 29 + * hours; in that time its Bun `SQL` pool lost every slot it had. A query issued + * from a request queued for a connection that was never going to arrive, and + * Bun's pool has no queue deadline -- `connectionTimeout` bounds opening a socket, + * not waiting for a free one -- so the request never failed and never answered. + * `/healthz`, robots.txt and the 402 the crawler wall serves all answered in + * milliseconds, because none of them touch the database. + * + * That combination is the dangerous part. Every liveness signal a Railway + * deployment has was green: the process was alive and sleeping, the accept queue + * was empty, Postgres held four connections and no locks. Only requests through + * the app's own pool hung. Railway's `healthcheckPath` gates a new deploy and is + * never re-run, so nothing was ever going to restart it. It took a person + * noticing the site was down. + * + * So the probe MUST go through the same client the requests use. A separate + * connection is exactly the thing that stayed healthy for 29 hours while readers + * got nothing, and a watchdog built on one would have reported everything fine. + * + * **This site has now lost the same bet twice, on the other dependency.** On + * 2026-09-13 and again on 2026-09-22, Redis went away and the web process never + * came back: `/healthz` answered 200 in 50ms while `/` returned nothing for + * minutes, and only redeploying the service recovered it -- restarting Redis + * alone did not, because the wedge is on this side of the socket. Both times a + * person had to notice. That is why `startWorkers`/the page cache get a watchdog + * here too, not just the pool. + * + * What it does when it decides the client is gone is exit. That reads as drastic + * for a web server, and it is the cheapest correct move here: the failure is + * process-local state that no request can repair, a restart demonstrably clears + * it (both outages ended with one), and Railway replaces the container in about a + * minute. Hanging forever is not the safer option -- it is the outage. + */ + +/** Enough consecutive failures that a blip cannot trigger a restart. */ +const DEFAULT_FAILURES = 3; + +/** + * @param {object} o + * @param {(signal: AbortSignal) => Promise} o.probe + * Runs a trivial command on the shared client. Given a signal, but a client that + * has stopped issuing connections will not observe it -- the timeout below is + * what actually bounds the wait. + * @param {string} [o.subject] what is being watched, for the log and the give-up + * reason: "the database pool", "redis". Defaults to the pool, which is what + * genrewatch's copy watches, so the two stay diffable. + * @param {number} [o.intervalMs] gap between probes + * @param {number} [o.timeoutMs] how long one probe may take before it counts as a failure + * @param {number} [o.failures] consecutive failures before giving up + * @param {(reason: string) => void} [o.onGiveUp] what to do when the client is declared gone + * @param {Console} [o.log] + * @returns {{ stop: () => void, check: () => Promise }} + */ +export function startDbWatchdog({ + probe, + subject = 'the database pool', + intervalMs = 30_000, + timeoutMs = 10_000, + failures = DEFAULT_FAILURES, + // Non-zero: this is a crash, not a drain. Railway restarts it either way, but a + // clean exit in the deploy log would read as the app choosing to stop. + onGiveUp = () => process.exit(1), + log = console, +} = {}) { + if (typeof probe !== 'function') throw new TypeError('the watchdog needs a probe'); + + let consecutive = 0; + let stopped = false; + let timer = null; + + /** + * One probe. Resolves true if the client answered inside the timeout. + * + * The timeout is a race rather than a rejection from the driver, because the + * symptom being watched for is a promise that never settles at all. Waiting on + * the command alone would hang the watchdog in precisely the case it exists + * for -- and for Redis that is not a hypothetical: the shared ioredis client is + * built with `maxRetriesPerRequest: null` (BullMQ requires it), which means a + * command issued while disconnected is queued forever rather than rejected. + */ + async function check() { + const controller = new AbortController(); + let timeoutId; + const expired = Symbol('timeout'); + try { + const outcome = await Promise.race([ + probe(controller.signal).then(() => true), + new Promise((resolve) => { + timeoutId = setTimeout(() => resolve(expired), timeoutMs); + }), + ]); + if (outcome === expired) { + controller.abort(); + consecutive += 1; + log.error( + `[db-watchdog] ${subject} did not answer in ${timeoutMs}ms (${consecutive}/${failures})`, + ); + } else { + // A success clears the count: the bar is CONSECUTIVE failures, so a slow + // minute or a single dropped connection never costs a restart. The wedge + // this watches for does not recover on its own, so it never clears. + if (consecutive > 0) + log.warn(`[db-watchdog] ${subject} answered again after ${consecutive}`); + consecutive = 0; + return true; + } + } catch (err) { + // A rejection is a healthier signal than a hang: the client is still + // refusing work, but it is refusing rather than swallowing. Counted the same. + consecutive += 1; + log.error( + `[db-watchdog] ${subject} probe failed (${consecutive}/${failures}): ${err?.message ?? err}`, + ); + } finally { + clearTimeout(timeoutId); + } + + if (consecutive >= failures && !stopped) { + stopped = true; + clearInterval(timer); + const reason = + `[db-watchdog] ${subject} has stopped issuing connections ` + + `(${consecutive} probes in a row). The server itself may be fine -- this is the ` + + `in-process client. Exiting so the platform starts a container that can serve.`; + log.error(reason); + onGiveUp(reason); + } + return false; + } + + timer = setInterval(check, intervalMs); + // A watchdog is not a reason to hold the process open on its own. + timer.unref?.(); + + return { + check, + stop() { + stopped = true; + clearInterval(timer); + }, + }; +} diff --git a/apps/web/src/main.js b/apps/web/src/main.js index 6b75fad..1720e9c 100644 --- a/apps/web/src/main.js +++ b/apps/web/src/main.js @@ -2,9 +2,10 @@ import { assertCoinpayMerchantKey, config } from '@tipoff/config'; import { close as closeDb, healthcheck, sql } from '@tipoff/db'; import { migrate } from '@tipoff/db/migrate'; import { configurePayments } from '@tipoff/payments'; -import { closeQueues, installSchedules } from '@tipoff/queue'; +import { closeQueues, connection, installSchedules } from '@tipoff/queue'; import { startWorkers } from '@tipoff/queue/workers'; import { app } from './app.js'; +import { startDbWatchdog } from './lib/db-watchdog.js'; /* * Hand the payments package its database handle and settings. @@ -77,8 +78,59 @@ if (config.roles.includes('web')) { console.log(`[web] listening on :${server.port} as ${config.roles.join('+')}`); } +/* + * Watch the two clients the requests actually use. + * + * Both are started for either role, because both roles depend on both: the web + * side reads the page cache and writes passkey challenges through the same Redis + * client the workers queue on, and a wedged worker stops every score updating + * without anything going red. + * + * The probes deliberately go through the shared `sql` handle and the shared + * `connection`, not a fresh one -- see db-watchdog.js for why a second connection + * is the one thing guaranteed to look healthy during this failure. `healthcheck()` + * runs `select 1`; `connection.ping()` is the Redis equivalent and is what hung on + * 2026-09-13 and 2026-09-22 while `/healthz` went on answering 200. + * + * Read from the environment directly, the way DB_POOL_MAX already is, and every + * knob has a working default so a service needs no new variables. + */ +const watchdogs = [ + startDbWatchdog({ + subject: 'the database pool', + probe: async () => { + if (!(await healthcheck())) throw new Error('select 1 did not come back'); + }, + intervalMs: Number(process.env.DB_WATCHDOG_INTERVAL_MS ?? 30_000), + timeoutMs: Number(process.env.DB_WATCHDOG_TIMEOUT_MS ?? 10_000), + failures: Number(process.env.DB_WATCHDOG_FAILURES ?? 3), + }), + startDbWatchdog({ + subject: 'redis', + probe: async () => { + if ((await connection.ping()) !== 'PONG') throw new Error('PING did not come back'); + }, + /* + * One more failure than the pool gets, because a healthy Redis here is + * routinely unreachable for a while: it restarts by reading an RDB off the + * volume before it accepts anything, 26 seconds at the last measurement and + * 124 before the event streams were trimmed. Four 30-second probes puts the + * floor around two minutes, which a normal restart stays well under. Tripping + * early would be worse than useless -- boot does `preflight('redis')` and + * throws if Redis is absent, so an impatient watchdog turns one Redis deploy + * into a deploy loop on this service. + */ + intervalMs: Number(process.env.REDIS_WATCHDOG_INTERVAL_MS ?? 30_000), + timeoutMs: Number(process.env.REDIS_WATCHDOG_TIMEOUT_MS ?? 10_000), + failures: Number(process.env.REDIS_WATCHDOG_FAILURES ?? 4), + }), +]; + async function shutdown(signal) { console.log(`[main] ${signal}, draining`); + // Before anything else: a shutdown closes these clients, and a watchdog probing + // a closing pool would call a clean drain a wedge and exit(1) over the top of it. + for (const w of watchdogs) w.stop(); // Stop taking new work before closing the pool, so an in-flight fan-out finishes // its claim rather than half-sending a batch. await Promise.allSettled([server?.stop(true), ...workers.map((w) => w.close())]); diff --git a/test/db-watchdog.test.js b/test/db-watchdog.test.js new file mode 100644 index 0000000..748f6f1 --- /dev/null +++ b/test/db-watchdog.test.js @@ -0,0 +1,217 @@ +import { describe, expect, it } from 'bun:test'; +import { startDbWatchdog } from '../apps/web/src/lib/db-watchdog.js'; + +/** Swallow the watchdog's own logging so a passing run stays readable. */ +const quiet = { error() {}, warn() {}, log() {} }; + +/** The 2026-09-07 symptom exactly: a query that never settles, in either direction. */ +const neverSettles = () => new Promise(() => {}); + +describe('the database watchdog', () => { + it('gives up after the pool stops answering, and says so once', async () => { + const reasons = []; + const w = startDbWatchdog({ + probe: neverSettles, + // Long enough that only an explicit check() drives this test. + intervalMs: 60_000, + timeoutMs: 5, + failures: 3, + onGiveUp: (reason) => reasons.push(reason), + log: quiet, + }); + + expect(await w.check()).toBe(false); + expect(await w.check()).toBe(false); + expect(reasons).toEqual([]); + + // The third consecutive failure is the one that restarts the container. + expect(await w.check()).toBe(false); + expect(reasons).toHaveLength(1); + expect(reasons[0]).toContain('stopped issuing connections'); + + // And it does not keep firing after it has given up, which would turn one + // restart into a loop of them. + await w.check(); + expect(reasons).toHaveLength(1); + w.stop(); + }); + + it('never gives up while the pool is answering', async () => { + const reasons = []; + const w = startDbWatchdog({ + probe: async () => true, + intervalMs: 60_000, + timeoutMs: 50, + failures: 2, + onGiveUp: (reason) => reasons.push(reason), + log: quiet, + }); + + for (let i = 0; i < 5; i += 1) expect(await w.check()).toBe(true); + expect(reasons).toEqual([]); + w.stop(); + }); + + it('counts a rejection the same as a hang', async () => { + const reasons = []; + const w = startDbWatchdog({ + probe: async () => { + throw new Error('ERR_POSTGRES_CONNECTION_CLOSED'); + }, + intervalMs: 60_000, + timeoutMs: 50, + failures: 2, + onGiveUp: (reason) => reasons.push(reason), + log: quiet, + }); + + await w.check(); + await w.check(); + expect(reasons).toHaveLength(1); + w.stop(); + }); + + it('treats a healthcheck that answers "no" as a failure', async () => { + // main.js turns a falsy healthcheck() into a throw; this pins that a probe + // which resolves falsy is NOT read as the pool being fine. + const reasons = []; + const w = startDbWatchdog({ + probe: async () => { + throw new Error('select 1 did not come back'); + }, + intervalMs: 60_000, + timeoutMs: 50, + failures: 1, + onGiveUp: (reason) => reasons.push(reason), + log: quiet, + }); + await w.check(); + expect(reasons).toHaveLength(1); + w.stop(); + }); + + it('forgives a blip: one success clears the count', async () => { + // The bar is CONSECUTIVE failures. A pool that answers again has recovered, + // and restarting it would be the watchdog causing the outage. + const reasons = []; + let healthy = false; + const w = startDbWatchdog({ + probe: async () => { + healthy = !healthy; + if (!healthy) throw new Error('down'); + return true; + }, + intervalMs: 60_000, + timeoutMs: 50, + failures: 2, + onGiveUp: (reason) => reasons.push(reason), + log: quiet, + }); + + await w.check(); // healthy -> true, resets + expect(reasons).toEqual([]); + await w.check(); // fails, 1 + await w.check(); // healthy again, resets to 0 + expect(reasons).toEqual([]); + w.stop(); + }); + + it('refuses to start without a probe', () => { + expect(() => startDbWatchdog({})).toThrow(/probe/); + }); + + it('does not hold the process open on its own', () => { + // An interval that keeps the event loop alive would stop a CLI or a test run + // from exiting; the watchdog is a passenger on a server that is already up. + const w = startDbWatchdog({ probe: async () => true, log: quiet }); + expect(typeof w.stop).toBe('function'); + w.stop(); + }); +}); + +/** + * The Redis half, which is why this file is in tipoffwatch and not only in + * genrewatch. Redis went away on 2026-09-13 and again on 2026-09-22; both times + * `/healthz` answered 200 while `/` returned nothing, and only redeploying the + * web service recovered it. + */ +describe('the redis watchdog', () => { + it('names redis in the reason, so the deploy log says which one went', async () => { + const reasons = []; + const w = startDbWatchdog({ + subject: 'redis', + probe: async () => { + throw new Error('Connection is closed.'); + }, + intervalMs: 60_000, + timeoutMs: 50, + failures: 1, + onGiveUp: (reason) => reasons.push(reason), + log: quiet, + }); + + await w.check(); + expect(reasons).toHaveLength(1); + expect(reasons[0]).toContain('redis'); + // Restarting the app for a wedged pool and for a wedged Redis are the same + // move, so the sentence that explains it stays the same too. + expect(reasons[0]).toContain('stopped issuing connections'); + w.stop(); + }); + + it('catches a PING that is queued forever rather than rejected', async () => { + /* + * The shared client is built with `maxRetriesPerRequest: null` because BullMQ + * requires it, and that is exactly what turns a disconnect into a hang: the + * command is queued until the socket comes back instead of failing. A probe + * that only caught rejections would have sat here for the whole outage, which + * is what the app itself did. + */ + const reasons = []; + const w = startDbWatchdog({ + subject: 'redis', + probe: () => new Promise(() => {}), + intervalMs: 60_000, + timeoutMs: 5, + failures: 2, + onGiveUp: (reason) => reasons.push(reason), + log: quiet, + }); + + expect(await w.check()).toBe(false); + expect(await w.check()).toBe(false); + expect(reasons).toHaveLength(1); + w.stop(); + }); + + it('does not restart the app while Redis is merely slow to load its RDB', async () => { + // Redis reads a 1.8GB RDB off the volume before it answers, ~26 seconds at the + // last measurement. A restart must not be read as a wedge, so the count has to + // clear the moment PING comes back. + const reasons = []; + let loaded = false; + const w = startDbWatchdog({ + subject: 'redis', + probe: async () => { + if (!loaded) throw new Error('LOADING Redis is loading the dataset in memory'); + return 'PONG'; + }, + intervalMs: 60_000, + timeoutMs: 50, + failures: 3, + onGiveUp: (reason) => reasons.push(reason), + log: quiet, + }); + + await w.check(); + await w.check(); + loaded = true; + expect(await w.check()).toBe(true); + // Two more failures after recovery must not reach the ceiling on their own. + loaded = false; + await w.check(); + await w.check(); + expect(reasons).toEqual([]); + w.stop(); + }); +});