diff --git a/apps/web/package.json b/apps/web/package.json index 83a4c40..113cfdf 100644 --- a/apps/web/package.json +++ b/apps/web/package.json @@ -24,6 +24,7 @@ "@tipoff/sports": "workspace:*", "hono": "^4.10.3", "mpegts.js": "1.8.2", - "@profullstack/leaderboard": "^0.3.0" + "@profullstack/leaderboard": "^0.3.0", + "@profullstack/watchdog": "^0.2.0" } } diff --git a/apps/web/src/lib/db-watchdog.js b/apps/web/src/lib/db-watchdog.js deleted file mode 100644 index 57afa27..0000000 --- a/apps/web/src/lib/db-watchdog.js +++ /dev/null @@ -1,147 +0,0 @@ -/** - * 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 1720e9c..2117787 100644 --- a/apps/web/src/main.js +++ b/apps/web/src/main.js @@ -1,3 +1,4 @@ +import { watchDependencies } from '@profullstack/watchdog'; import { assertCoinpayMerchantKey, config } from '@tipoff/config'; import { close as closeDb, healthcheck, sql } from '@tipoff/db'; import { migrate } from '@tipoff/db/migrate'; @@ -5,7 +6,6 @@ import { configurePayments } from '@tipoff/payments'; 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. @@ -87,50 +87,26 @@ if (config.roles.includes('web')) { * 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 + * `connection` rather than a fresh one. That is the whole trick, and the package + * explains why: a second connection is the one thing guaranteed to look healthy + * while every reader gets nothing. `connection.ping()` 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. + * Timings, the DB_WATCHDOG and REDIS_WATCHDOG knobs, and the reason Redis is + * allowed one more failure than the pool all live in the package now, so the + * three sibling sites cannot drift apart on the part that took an outage to work + * out. */ -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), - }), -]; +const watchdogs = watchDependencies({ + postgres: () => healthcheck(), + redis: () => connection.ping(), +}); 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(); + watchdogs.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 deleted file mode 100644 index 748f6f1..0000000 --- a/test/db-watchdog.test.js +++ /dev/null @@ -1,217 +0,0 @@ -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(); - }); -});