diff --git a/.env.example b/.env.example index f4d6fa1..2b735a0 100644 --- a/.env.example +++ b/.env.example @@ -96,6 +96,19 @@ SEO_PRODUCT_JSONLD=1 # so reviews the old site published to snort/primal were invisible to it. RELAYS=wss://relay.cashumints.space,wss://nos.lol,wss://relay.azzamo.net,wss://relay.snort.social,wss://relay.primal.net +# How many events a backfill has to read before it counts as having read anything. +# +# A backfill asks every relay above for the whole history of four kinds; on a working +# relay list that is thousands of events. Under this floor, discovery logs +# `ERROR discovery starvation suspected` and /api/health answers 503 with +# `discovery_starved: true` until the next backfill clears it. +# +# This exists because a RELAYS list missing the relay that carries the announcement +# archive returned about thirty events per backfill for a year, reported ok=true every +# time, and left the index at eight mints with every health signal green. Lower it only +# for a private or test relay that genuinely holds less; 1 disables the check. +#BACKFILL_MIN_EVENTS=200 + # Profile relays for the BUILD (kind 0, prerendered reviewer names on the home # page). A wider pool than RELAYS on purpose: relay.cashumints.space holds no kind # 0 at all and snort/primal hold almost none, so the two aggregators below are what diff --git a/README.md b/README.md index 8bd258b..0b66e34 100644 --- a/README.md +++ b/README.md @@ -585,6 +585,7 @@ so a systemd `Environment=` line or a one-off `PORT=9000 pnpm dev:api` still ove | `DB_POOL_MAX` | `10` | Postgres connections held open. Unused by SQLite. | | `ICON_DIR` | `api/data/icons` | Cached mint icons, served at `/icons/*` | | `RELAYS` | see `shared/src/nostr.ts` | Comma separated relay list | +| `BACKFILL_MIN_EVENTS` | `200` | Events a backfill has to read before it counts as one. Under it, discovery logs `ERROR discovery starvation suspected` and health goes 503. See [Starvation](#discovery-starvation). | | `PROBE_INTERVAL_MIN` | `10` | Minutes between probe cycles | | `DISCOVERY_INTERVAL_MIN` | `60` | Minutes between discovery cycles | | `PROBE_CONCURRENCY` | `8` | Mints probed in parallel | @@ -717,7 +718,7 @@ Five endpoints, CORS open, no auth. Four read; the fifth writes. | Endpoint | Notes | | -------------------- | ------------------------------------------------------------------ | -| `GET /api/health` | Never cached. 503 when probes are stale or discovery failed. | +| `GET /api/health` | Never cached. 503 when probes are stale, discovery failed, or discovery is starved. Carries the last cycle's per-relay outcome. | | `GET /api/stats` | Network counters, memoized 60s in process. | | `GET /api/mints` | Everything listed, online first then score descending. `?limit=`, `?type=`. | | `GET /api/mints/:host` | One listing plus its ecosystem's own fields, distribution, uptime and probe history. | @@ -725,6 +726,82 @@ Five endpoints, CORS open, no auth. Four read; the fifth writes. `/icons/*` serves the cached mint icons. +### Discovery starvation + +For about a year, `GET /api/health` said `ok`, every discovery cycle reported +`ok=true`, and the index sat at eight mints. The production `RELAYS` list did not +include the relay carrying the kind 38000/38172 archive, so each backfill read about +thirty events, wrote them faithfully, and the nightly build republished the result. +Nothing was broken in a way anything measured. + +What was missing is that "the cycle completed" and "the cycle read anything" are +different claims, and only the first one was being made. Three things now make the +second one: + +**Per-relay attribution.** A cycle records, for every relay in `RELAYS`, whether a +socket opened, how many events it sent, and whether it ended in a real EOSE. Counts are +taken before cross-relay deduplication, so they say what each relay contributed rather +than what happened to be new because of it. The one-line cycle log carries the lot: + +``` +INFO discovery cycle mode=backfill events=1528 … starved=false \ + relays=wss://relay.cashumints.space=12 wss://nos.lol=1566 wss://relay.azzamo.net=10 \ + wss://relay.snort.social=18 wss://relay.primal.net=1 +``` + +Read that line before changing `RELAYS`. It is also how you find out that most of this +network's archive currently sits behind one relay. + +**A WARN per relay, naming it.** A relay that would not connect is warned about on every +cycle. A relay that connected and sent nothing is warned about on backfills only — an +incremental cycle asking for one interval is *supposed* to come back empty, and an +hourly warning about that would train everyone to skip the line that eventually matters. + +``` +WARN discovery relay unreachable relay=wss://relay.example.invalid mode=backfill +WARN discovery relay returned no events relay=wss://relay.azzamo.net mode=backfill +``` + +**A floor.** `BACKFILL_MIN_EVENTS`, 200 by default. A backfill asks five relays for the +entire history of four kinds; on a working relay set that is thousands of events. Under +the floor: + +``` +ERROR discovery starvation suspected events=31 floor=200 relays=5 silent=4 unreachable=0 +``` + +and a flag is set that `GET /api/health` reports as `discovery_starved`, which forces +`status` to `degraded` and the response to **503**. The flag is sticky across +incremental cycles: an hourly cycle finding four events must not clear a starvation a +backfill diagnosed. Only the next backfill clears it. + +`GET /api/health` grew four fields for this: + +```json +{ + "status": "degraded", + "discovery_relays": [ + { "url": "wss://relay.cashumints.space", "connected": true, "events": 12, "eose": true }, + { "url": "wss://relay.example.invalid", "connected": false, "events": 0, "eose": false } + ], + "last_discovery_events": 31, + "last_discovery_mode": "backfill", + "discovery_starved": true, + "backfill_min_events": 200 +} +``` + +**A fresh database reports 503 until its first backfill finishes, and that is correct.** +Before any backfill has run, nothing has confirmed that this deployment's relay list +reads anything at all, and answering `ok` would be the original bug in miniature. In +practice it holds `cashumints-web.service` at its health gate — which is the point: a +first deploy should not publish a site built from an empty index. The state is stored in +the database rather than in memory for the same reason, so a restart cannot launder a +starvation into "no cycle yet". + +To silence it deliberately on a deployment that genuinely has less history than this — +a private relay, a test rig — set `BACKFILL_MIN_EVENTS=1`. + ### Indexing on demand ```bash diff --git a/api/src/config.ts b/api/src/config.ts index f242b17..e573ce3 100644 --- a/api/src/config.ts +++ b/api/src/config.ts @@ -112,6 +112,20 @@ export const config = { iconDir: process.env['ICON_DIR'] ?? path.join(apiRoot, 'data', 'icons'), relays: (process.env['RELAYS']?.split(',').map((r) => r.trim()).filter(Boolean) ?? [...DEFAULT_RELAYS]) as string[], + /** + * The floor a backfill cycle has to clear before it counts as a real read. + * + * For about a year this deployment's RELAYS list did not include the relay carrying + * the kind 38000/38172 archive. Every backfill returned about thirty events, wrote + * them, reported ok=true, and the index sat at eight mints while every health signal + * stayed green. A backfill asks five relays for the whole history of four kinds; on a + * working relay set it comes back with thousands. Anything under this is not a quiet + * network, it is a misconfigured one, and it says so in the log and on /api/health. + * + * Raise it on a deployment that genuinely has more history, lower it for a local + * test relay. It is deliberately not zero-able: set it to 1 if you mean "off". + */ + backfillMinEvents: int('BACKFILL_MIN_EVENTS', 200), probeIntervalMin: int('PROBE_INTERVAL_MIN', 10), discoveryIntervalMin: int('DISCOVERY_INTERVAL_MIN', 60), probeConcurrency: int('PROBE_CONCURRENCY', 8), diff --git a/api/src/discovery.ts b/api/src/discovery.ts index d39000a..e3a1531 100644 --- a/api/src/discovery.ts +++ b/api/src/discovery.ts @@ -19,9 +19,10 @@ import { type FedimintAnnouncement, type LnurlAnnouncement, type LnurlFields, + type RelayHealth, } from '@cashumints/shared'; import { config } from './config.ts'; -import { getDb, setState, getStateNumber } from './db.ts'; +import { getDb, setState, getState, getStateNumber } from './db.ts'; import type { Sql } from './db-driver.ts'; import { log } from './log.ts'; import { insertMintIfNew, upsertFedimint, upsertLnurl } from './mints.ts'; @@ -39,8 +40,118 @@ export interface DiscoveryResult { newMints: string[]; newReviews: number; ok: boolean; + /** What each configured relay actually did, in `config.relays` order. */ + relays: RelayHealth[]; + /** A backfill that came in under `config.backfillMinEvents`. */ + starved: boolean; } +/** + * What the last cycle did, kept so /api/health can answer for it. + * + * Written to the `state` table rather than held in memory, because the question it + * answers — "is discovery actually reading anything?" — has to survive the restart that + * would otherwise reset it to "no cycle yet, nothing to report". A process that crash + * loops would clear an in-memory flag on every attempt. + */ +export interface DiscoveryReport { + at: number; + mode: 'backfill' | 'incremental'; + events: number; + ok: boolean; + relays: RelayHealth[]; + starved: boolean; +} + +/** `state` key holding the JSON of the above. */ +const REPORT_KEY = 'last_discovery_report'; + +/** + * The last cycle's report, or null before any cycle has run. + * + * A row that will not parse reads as null — the same as no cycle — because the caller + * is a health endpoint and "I cannot tell you" must not be dressed up as "fine". + */ +export async function lastDiscoveryReport(): Promise { + const raw = await getState(REPORT_KEY); + if (!raw) return null; + try { + const parsed = JSON.parse(raw) as DiscoveryReport; + return Array.isArray(parsed.relays) ? parsed : null; + } catch { + return null; + } +} + +/** + * Per-relay bookkeeping for one cycle. + * + * Every relay in `config.relays` gets a row up front, including the ones that are never + * reached, because a relay that produced no row at all is exactly the one worth naming: + * the year-long starvation was a relay list that connected cleanly and simply did not + * hold the archive, and the only field that would have shown it is a zero here. + * + * `events` counts what a relay sent *before* cross-relay deduplication, so five relays + * carrying the same 400 events report 400 each rather than 400 once and 0 four times. + * Attribution is the whole point; the deduplicated total is reported separately. + */ +class RelayTally { + private readonly rows = new Map(); + + constructor(urls: readonly string[]) { + for (const url of urls) { + this.rows.set(url, { events: 0, subs: 0, eoses: 0, connected: false }); + } + } + + private row(url: string) { + let found = this.rows.get(url); + if (!found) { + found = { events: 0, subs: 0, eoses: 0, connected: false }; + this.rows.set(url, found); + } + return found; + } + + connected(url: string): void { + this.row(url).connected = true; + } + + subscribed(url: string): void { + this.row(url).subs++; + } + + event(url: string): void { + this.row(url).events++; + } + + eose(url: string): void { + this.row(url).eoses++; + } + + /** One row per configured relay, in configuration order. */ + list(): RelayHealth[] { + return [...this.rows.entries()].map(([url, row]) => ({ + url, + connected: row.connected, + events: row.events, + // A cycle asks a relay many questions. It only counts as having reached the end + // of the stream if it reached the end of every one of them. + eose: row.subs > 0 && row.eoses === row.subs, + })); + } +} + +/** + * Long enough that the relay's own EOSE timer never wins. + * + * `Subscription` fires `oneose` both when an EOSE frame arrives and when its internal + * timer expires, so the two are indistinguishable from the callback. Pushing that timer + * out of reach and running the deadline here instead is what makes `eose` in the report + * mean "the relay said it was done" rather than "something gave up". + */ +const NEVER_EOSE_MS = 24 * 60 * 60 * 1000; + let pool: SimplePool | null = null; /** @@ -66,12 +177,100 @@ export function closePool(): void { pool = null; } +/** + * Ask every configured relay one filter, and record what each of them did. + * + * This replaces `pool.querySync(config.relays, …)`, which answers the same question and + * throws the attribution away: it merges five relays into one deduplicated array, so a + * relay list where four relays are empty and one carries everything is indistinguishable + * from five healthy ones. That indistinguishability is the bug this whole file is being + * changed for — a year of ~31-event backfills, `ok=true` every time. + * + * What it keeps from `querySync`, deliberately: + * + * - One subscription per relay over the pool's existing sockets, so this is the same + * number of connections as before. + * - A single `alreadyHaveEvent` shared across all five. `AbstractRelay._onmessage` + * consults it *before* `JSON.parse` and signature verification, so an event five + * relays all carry is still verified once. Per-relay `querySync` calls would have + * verified it five times, which at 500 events a page is real CPU. + * - `receivedEvent`, which fires on the way past that check, so the per-relay count is + * what the relay sent rather than what was new because of it. + * + * What it changes: the deadline is run here rather than by each `Subscription`'s own + * EOSE timer, so `oneose` firing means an EOSE frame actually arrived. See NEVER_EOSE_MS. + * + * Never throws. A relay that will not connect is a fact to record, not a reason to + * abandon the four that did. + */ +async function queryRelays(filter: Filter, tally: RelayTally | null): Promise { + const events: NostrEvent[] = []; + const known = new Set(); + const alreadyHaveEvent = (id: string): boolean => { + if (known.has(id)) return true; + known.add(id); + return false; + }; + + await Promise.all( + config.relays.map(async (url) => { + let relay; + try { + // The same connection budget subscribeMap would have used for this maxWait. + relay = await getPool().ensureRelay(url, { + connectionTimeout: Math.max(MAX_WAIT_MS * 0.8, MAX_WAIT_MS - 1000), + }); + } catch { + // Left as connected=false in the tally, which is the whole report this needs. + return; + } + tally?.connected(url); + + await new Promise((resolve) => { + let settled = false; + let deadline: ReturnType | undefined; + const finish = (): void => { + if (settled) return; + settled = true; + if (deadline !== undefined) clearTimeout(deadline); + resolve(); + }; + + try { + const sub = relay.subscribe([filter], { + onevent: (event) => events.push(event), + alreadyHaveEvent, + receivedEvent: () => tally?.event(url), + oneose: () => { + tally?.eose(url); + sub.close('closed automatically on eose'); + }, + onclose: finish, + eoseTimeout: NEVER_EOSE_MS, + }); + tally?.subscribed(url); + deadline = setTimeout(() => sub.close('closed on maxWait'), MAX_WAIT_MS); + } catch { + // The socket went away between ensureRelay and the REQ. + finish(); + } + }); + }), + ); + + return events; +} + /** * Query one kind, paging backwards with `until` until a page yields nothing new. * Relays cap `limit` independently, so paging is the only way a fresh database * converges to the complete history. */ -async function fetchKind(kind: number, since: number | null): Promise { +async function fetchKind( + kind: number, + since: number | null, + tally: RelayTally | null, +): Promise { const seen = new Map(); let until: number | undefined; @@ -82,7 +281,7 @@ async function fetchKind(kind: number, since: number | null): Promise { const filters: Filter[] = []; const base: Filter = { kinds: [KIND_REVIEW], limit: QUERY_LIMIT }; @@ -178,11 +378,7 @@ async function fetchReviewsForMint( } const batches = await Promise.all( - filters.map((filter) => - getPool() - .querySync(config.relays, filter, { maxWait: MAX_WAIT_MS }) - .catch(() => [] as NostrEvent[]), - ), + filters.map((filter) => queryRelays(filter, tally).catch(() => [] as NostrEvent[])), ); return batches.flat(); @@ -596,6 +792,7 @@ export async function runDiscovery(backfill: boolean): Promise const since = lastRun === null ? null : Math.max(0, lastRun - 3600); const newMints = new Set(); + const tally = new RelayTally(config.relays); let newReviews = 0; let events = 0; let ok = true; @@ -610,7 +807,7 @@ export async function runDiscovery(backfill: boolean): Promise const announcementsByType = new Map(); await Promise.all( Object.entries(ANNOUNCEMENT_KINDS).map(async ([type, kind]) => { - announcementsByType.set(type, await fetchKind(kind, since)); + announcementsByType.set(type, await fetchKind(kind, since, tally)); }), ); @@ -625,10 +822,10 @@ export async function runDiscovery(backfill: boolean): Promise // Announcements alone miss mints that only ever appear in a review's `u` tag, // so reviews feed discovery too. - const reviews = await fetchKind(KIND_REVIEW, since); + const reviews = await fetchKind(KIND_REVIEW, since, tally); // The recent window catches anything a relay dropped from the unbounded query. const recent = - since === null ? await fetchKind(KIND_REVIEW, now - RECENT_WINDOW_S) : []; + since === null ? await fetchKind(KIND_REVIEW, now - RECENT_WINDOW_S, tally) : []; const byId = new Map(); for (const e of [...reviews, ...recent]) byId.set(e.id, e); @@ -689,7 +886,7 @@ export async function runDiscovery(backfill: boolean): Promise while (cursor < targets.length) { const target = targets[cursor++]; if (!target) continue; - const found = await fetchReviewsForMint(target, since); + const found = await fetchReviewsForMint(target, since, tally); if (found.length > 0) { events += found.length; newReviews += await ingestReviews(found, index); @@ -707,14 +904,79 @@ export async function runDiscovery(backfill: boolean): Promise log.error('discovery failed', { reason: err instanceof Error ? err.message : String(err) }); } + const mode = backfill ? 'backfill' : 'incremental'; + const relays = tally.list(); + + /* + * Name the relay, every time, one line each. + * + * A relay that would not connect is worth saying on any cycle: the address is wrong, + * or it is down, and neither gets better by itself. A relay that connected and sent + * nothing is only news on a backfill — an incremental cycle asking for the last hour + * of four kinds legitimately comes back empty, and warning about that hourly would + * train everyone to skip the line that eventually matters. + */ + for (const relay of relays) { + if (!relay.connected) { + log.warn('discovery relay unreachable', { relay: relay.url, mode }); + continue; + } + if (backfill && relay.events === 0) { + log.warn('discovery relay returned no events', { relay: relay.url, mode }); + } else if (!relay.eose) { + log.warn('discovery relay never reached EOSE', { + relay: relay.url, + mode, + events: relay.events, + }); + } + } + + /* + * The floor, and the flag the health endpoint reads. + * + * Only a backfill is measured against it. A backfill asks for the entire history of + * every announcement kind and every review, so on a working relay set it is thousands + * of events; an incremental cycle asks for one interval and is supposed to be small. + * + * The flag is sticky across incremental cycles: an hourly cycle that finds four + * events must not clear a starvation a backfill diagnosed, so a non-backfill carries + * forward whatever the last backfill concluded. + */ + let starved: boolean; + if (backfill) { + starved = events < config.backfillMinEvents; + if (starved) { + log.error('discovery starvation suspected', { + events, + floor: config.backfillMinEvents, + relays: relays.length, + silent: relays.filter((r) => r.events === 0).length, + unreachable: relays.filter((r) => !r.connected).length, + hint: 'check RELAYS: a relay list missing the announcement archive looks exactly like this', + }); + } + } else { + // No backfill has ever run in this deployment: nothing has confirmed the relay set + // reads anything, and saying "fine" would be the whole original bug. + starved = (await lastDiscoveryReport())?.starved ?? true; + } + + const report: DiscoveryReport = { at: now, mode, events, ok, relays, starved }; + // A report that cannot be written is not worth failing a cycle over; the cycle's own + // work is already committed, and health degrades on the stale timestamp instead. + await setState(REPORT_KEY, JSON.stringify(report)).catch(() => undefined); + log.info('discovery cycle', { - mode: backfill ? 'backfill' : 'incremental', + mode, events, new_mints: newMints.size, new_reviews: newReviews, ok, + starved, + relays: relays.map((r) => `${r.url}=${r.connected ? r.events : 'down'}`).join(' '), ms: Date.now() - started, }); - return { events, newMints: [...newMints], newReviews, ok }; + return { events, newMints: [...newMints], newReviews, ok, relays, starved }; } diff --git a/api/src/queries.ts b/api/src/queries.ts index 59df339..0d59b46 100644 --- a/api/src/queries.ts +++ b/api/src/queries.ts @@ -16,6 +16,7 @@ import { } from '@cashumints/shared'; import { config, startedAt } from './config.ts'; import { getDb, getStateNumber, getState } from './db.ts'; +import { lastDiscoveryReport } from './discovery.ts'; import { mintByHost, parseEcosystem, type MintRow } from './mints.ts'; /** @@ -379,28 +380,55 @@ export function resetStatsCache(): void { statsCache = null; } -/** Health bypasses the stats cache: it is the endpoint you page on. */ +/** + * Health bypasses the stats cache: it is the endpoint you page on. + * + * Three things can degrade it, and they are three different failures: + * + * probeStale nothing has checked a mint in three intervals + * !discoveryOk the last discovery cycle threw + * report.starved the last backfill read less than BACKFILL_MIN_EVENTS + * + * The third is the one added after the postmortem, and it is the only one that would + * have caught a year of the index sitting at eight mints: the cycles were completing, + * `ok` was true, the probes were fresh, and the relay list simply did not contain the + * relay holding the archive. "Ran without throwing" is not the same claim as "read + * anything", and only the second one is worth a green light. + * + * A deployment with an empty database reports degraded until its first backfill lands, + * because until then nothing has confirmed the relay set reads anything at all. That is + * intended: it holds `cashumints-web.service` at its health gate rather than letting it + * publish a site built from nothing. + */ export async function getHealth(): Promise { const now = Math.floor(Date.now() / 1000); const db = await getDb(); - const [lastProbe, lastDiscovery, discoveryOkRaw, tracked] = await Promise.all([ + const [lastProbe, lastDiscovery, discoveryOkRaw, tracked, report] = await Promise.all([ getStateNumber('last_probe_at'), getStateNumber('last_discovery_at'), getState('last_discovery_ok'), db.get<{ n: number }>('SELECT COUNT(*) AS n FROM mints'), + lastDiscoveryReport(), ]); const discoveryOk = discoveryOkRaw !== '0'; const staleAfter = config.probeIntervalMin * 60 * 3; const probeStale = lastProbe === null || now - lastProbe > staleAfter; + // No report at all is starvation by default: see the note above. + const starved = report?.starved ?? true; return { - status: probeStale || !discoveryOk ? 'degraded' : 'ok', + status: probeStale || !discoveryOk || starved ? 'degraded' : 'ok', uptime_s: now - startedAt, last_probe_at: lastProbe, last_discovery_at: lastDiscovery, mints_tracked: tracked?.n ?? 0, updated_at: now, + discovery_relays: report?.relays ?? [], + last_discovery_events: report?.events ?? null, + last_discovery_mode: report?.mode ?? null, + discovery_starved: starved, + backfill_min_events: config.backfillMinEvents, }; } diff --git a/shared/src/types.ts b/shared/src/types.ts index 4177c24..d8691f1 100644 --- a/shared/src/types.ts +++ b/shared/src/types.ts @@ -236,6 +236,29 @@ export interface Stats { lnurl_reviews: number; } +/** + * How one configured relay answered during the last discovery cycle. + * + * The three facts are deliberately separate, because the failure this exists to catch + * had all three looking different from each other: the relays in `RELAYS` connected + * fine, reached EOSE fine, and simply did not carry the archive, so `events` was the + * only field that would have said anything. A relay that is down and a relay that is + * up and empty are different problems with different fixes. + */ +export interface RelayHealth { + url: string; + /** A socket was opened to it. false means the address is wrong or the relay is down. */ + connected: boolean; + /** + * Events it sent, counted before cross-relay deduplication — so this is what *this* + * relay contributed, not what was new because of it. Zero on a connected relay is + * the interesting number. + */ + events: number; + /** Every query it was asked ended in a real EOSE rather than in a timeout. */ + eose: boolean; +} + /** `GET /api/health`. */ export interface Health { status: 'ok' | 'degraded'; @@ -244,6 +267,26 @@ export interface Health { last_discovery_at: number | null; mints_tracked: number; updated_at: number; + /** + * Per-relay outcome of the last discovery cycle. Empty until one has run — including + * on a fresh database, which is why a brand new deployment reports degraded until its + * first backfill finishes. + */ + discovery_relays: RelayHealth[]; + /** Unique events the last discovery cycle received. null before the first one. */ + last_discovery_events: number | null; + /** Which kind of cycle those numbers describe. */ + last_discovery_mode: 'backfill' | 'incremental' | null; + /** + * The last backfill came back under `backfill_min_events`, or none has run yet. + * + * This is the flag that would have caught a year of ~31-event backfills against a + * relay list missing the archive. It forces `status` to degraded, and /api/health to + * 503, which is what the build gate and the site's own health checks read. + */ + discovery_starved: boolean; + /** `BACKFILL_MIN_EVENTS`, echoed so a reader of this payload can see the threshold. */ + backfill_min_events: number; } /**