From 681aa9bc5f13079b5fcb0a55a4d09445f3890355 Mon Sep 17 00:00:00 2001 From: Anthony Ettinger Date: Tue, 22 Sep 2026 16:15:35 +0000 Subject: [PATCH] The watchdog is a package now, not a file in this repo Shipped here yesterday as apps/web/src/lib/db-watchdog.js, and genrewatch and watchnews both need the same thing for the same reason, so it is @profullstack/watchdog 0.2.0 instead of three copies. What moved is not really the code, it is the reasoning. Why the probe has to go through the SAME client the requests use, why the timeout has to be a race rather than a driver option, and why Redis is allowed one more failure than the pool because a healthy Redis is routinely unreachable while it reloads its snapshot. A comment explaining that is worth nothing if it only exists in one of three copies, and the numbers drift apart the moment they are duplicated. `watchDependencies` takes probes rather than clients, so the package stays zero-dependency and does not care that this repo is on bun:sql and ioredis. The DB_WATCHDOG and REDIS_WATCHDOG knobs and their defaults live there too, so this file no longer names any of them. Net 38 lines lighter here, and the module's own tests moved to the package. Co-Authored-By: Claude Opus 5 (1M context) --- apps/web/package.json | 3 +- apps/web/src/lib/db-watchdog.js | 147 ---------------------- apps/web/src/main.js | 50 ++------ test/db-watchdog.test.js | 217 -------------------------------- 4 files changed, 15 insertions(+), 402 deletions(-) delete mode 100644 apps/web/src/lib/db-watchdog.js delete mode 100644 test/db-watchdog.test.js 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(); - }); -});