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(); + }); +});