diff --git a/.env.example b/.env.example index 8812e3f..3129941 100644 --- a/.env.example +++ b/.env.example @@ -60,6 +60,14 @@ DATABASE_SCHEMA=programmatic_orders # ETH_GET_LOGS_BLOCK_RANGE_100=5000 # gnosis +# How stale a chain's newest synced block may get before /readyz reports 503 and the +# container healthcheck starts failing. Seconds; default 300. Raise it if normal +# indexing latency on a chain regularly exceeds the budget; lower it to detect a +# stalled subscription sooner. Per-chain override takes the numeric chain-id suffix. +# READINESS_MAX_LAG_SECONDS=300 +# READINESS_MAX_LAG_SECONDS_1=300 # mainnet +# READINESS_MAX_LAG_SECONDS_100=300 # gnosis + # Logging (optional) # PINO_LOG_LEVEL=info diff --git a/Dockerfile b/Dockerfile index 25a7b20..335bfcf 100644 --- a/Dockerfile +++ b/Dockerfile @@ -31,11 +31,18 @@ RUN pnpm install --frozen-lockfile \ USER node +# /readyz, not Ponder's /ready: /ready returns 200 forever once historical sync +# finishes, so a stalled realtime subscription still reports healthy. /readyz also +# checks that each chain's newest synced block is keeping up with wall-clock. +# Note: Docker never restarts a container for failing its healthcheck — the +# `autoheal` label on the ponder service is what turns unhealthy into a restart. HEALTHCHECK \ --start-period=24h \ --start-interval=1s \ + --interval=30s \ + --timeout=10s \ --retries=3 \ - CMD curl -f http://localhost:3000/ready || exit 1 + CMD curl -f http://localhost:3000/readyz || exit 1 EXPOSE 3000/tcp diff --git a/docker-compose.yml b/docker-compose.yml index 2070ee0..5ee46bd 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -59,6 +59,14 @@ services: # (after drop) it's a no-op; on an existing schema it allows resuming from the # last checkpoint rather than wiping and starting over. PONDER_EXPERIMENTAL_DB: "platform" + # Docker restarts a container when its process exits, never when its healthcheck + # fails — a wedged-but-alive indexer would sit there unhealthy forever. The host's + # autoheal daemon (willfarrell/autoheal, AUTOHEAL_CONTAINER_LABEL=autoheal) watches + # for this label and restarts the container once HEALTHCHECK marks it unhealthy. + # Without that daemon running on the host, the label is inert and the healthcheck + # only reports; it does not recover. + labels: + autoheal: "true" ports: - "${PONDER_EXPOSED_PORT:-40000}:3000" depends_on: diff --git a/docs/api-reference.md b/docs/api-reference.md index ebe7de9..11bb64e 100644 --- a/docs/api-reference.md +++ b/docs/api-reference.md @@ -14,7 +14,8 @@ The default local URL is `http://localhost:42069` when using `pnpm dev`. The pro | `/docs` | GET | Swagger UI for the REST endpoints. | | `/openapi.json` | GET | OpenAPI 3.0 spec for the REST endpoints. | | `/health` | GET | Ponder built-in. Returns `200` (empty body) when the process is running. | -| `/ready` | GET | Ponder built-in. Returns `200` when initial sync is complete; `503` while still syncing. Suitable for K8s readiness probes. | +| `/ready` | GET | Ponder built-in. Returns `200` when initial sync is complete; `503` while still syncing. Latches at `200` afterwards, so it will not detect a stalled indexer — prefer `/readyz`. | +| `/readyz` | GET | Application-level readiness. Returns `200` only when Ponder is synced, every active chain's newest block is within `READINESS_MAX_LAG_SECONDS` of now, and the owner backfill has drained. `503` with a plain-text reason otherwise. | | `/healthz` | GET | Application-level. Returns `{ "status": "ok" }` when the server is up. Does not reflect indexer sync progress. | | `/status` | GET | Sync progress per chain. Returns current indexed block, latest chain block, and a completion percentage. Useful for monitoring backfill progress. | | `/metrics` | GET | Prometheus metrics. Exposes Ponder internals (block lag, handler latency, RPC call counts). | diff --git a/docs/deployment.md b/docs/deployment.md index adfc6b3..160a428 100644 --- a/docs/deployment.md +++ b/docs/deployment.md @@ -89,7 +89,7 @@ The deploy services (`postgres-deploy` and `ponder`) live in the root `docker-co docker compose --profile deploy up -d ``` -The `Dockerfile` in the project root builds the Ponder image: two-stage Node 22 Alpine, installs dependencies with `--frozen-lockfile`, exposes port 3000, runs `pnpm start`. The health check hits `/ready` with a 24-hour start period (initial sync takes hours). +The `Dockerfile` in the project root builds the Ponder image: two-stage Node 22 Alpine, installs dependencies with `--frozen-lockfile`, exposes port 3000, runs `pnpm start`. The health check hits `/readyz` with a 24-hour start period (initial sync takes hours). ### Kubernetes Probes @@ -99,9 +99,11 @@ The indexer exposes two health endpoints with distinct semantics: |----------|----------|-----------------| | `/health` | **Liveness** — is the process alive? | Always, once the server starts | | `/ready` | Ponder sync — has it reached the chain tip? | Only when historical sync is complete | -| `/readyz` | **Readiness** — synced **and** owner backfill complete | Ponder synced AND no non-deterministic historical generator still pending | +| `/readyz` | **Readiness** — synced, keeping up, **and** owner backfill complete | Ponder synced AND every active chain within its staleness budget AND no non-deterministic historical generator still pending | -Use **`/readyz`** as the readiness/promotion probe. Ponder's built-in `/ready` flips as soon as historical sync reaches the tip, and `OwnerBackfillLive` then drains historical discrete orders across the following live-sync blocks. `/readyz` waits for both: it returns 200 only once Ponder is synced **and** `COUNT(historyBackfilled = false) = 0` (it internally checks `/ready` first, so it also can't false-positive on an empty fresh DB). Expect it to report pending during the drain, which begins after `/ready` flips. Ponder reserves the `/ready` path, so `/readyz` is a distinct endpoint served by the app. +Use **`/readyz`** as the readiness/promotion probe. Ponder's built-in `/ready` flips as soon as historical sync reaches the tip. `/readyz` waits for all three conditions: Ponder synced, no chain lagging the tip, and `COUNT(historyBackfilled = false) = 0`. Expect it to report pending during the drain, which begins after `/ready` flips. Ponder reserves the `/ready` path, so `/readyz` is a distinct endpoint served by the app. + +The staleness check reads each chain's newest indexed block from Ponder's `/status` and compares its timestamp against wall-clock time. Anything older than `READINESS_MAX_LAG_SECONDS` (default 300) makes `/readyz` return 503 naming the chain, its newest block, and the measured lag. It deliberately does not call the RPC for the current head, because it wants to be robust to RPC outages. Map these to different K8s probe types. The specific timing values (`periodSeconds`, `failureThreshold`, `initialDelaySeconds`) depend on your cluster's SLOs; what matters is which path and port to use: @@ -126,7 +128,29 @@ readinessProbe: A pod in `NotReady` state is not killed — it is simply removed from load-balancer rotation. On a cold start (no existing database), the pod will be `NotReady` for the duration of the historical backfill (hours). That is expected: the old pod (if any) keeps serving traffic during this window, and once the new pod catches up, K8s starts routing to it. -The Docker Compose health check uses `/ready` with a 24-hour start period as a pragmatic fallback for single-container deployments, not as a K8s-style probe. +The container health check (declared in the `Dockerfile`) uses `/readyz` with a 24-hour start period as a pragmatic fallback for single-container deployments, not as a K8s-style probe. Two things about it are easy to get wrong: + +Docker never restarts a container because its health check fails — `restart: unless-stopped` only reacts to the process exiting. A wedged-but-alive indexer stays up. The host's `willfarrell/autoheal` daemon (started with `AUTOHEAL_CONTAINER_LABEL=autoheal`) polls for unhealthy labelled containers and restarts them. + +The 24-hour start period exists because a cold start legitimately fails `/readyz` for hours. During the start period a failing check does not mark the container unhealthy; the first success ends it. + +### Splitting the API from the Indexer + +Today one container does both jobs: `pnpm start` runs `ponder start`, which indexes and serves HTTP in a single process. Every indexer restart therefore takes the API down with it. Ponder supports separating the two. This also useful for horizontal scaling the API side of the application. + +`ponder serve` starts the HTTP server without the indexer. Same image, different command: one container keeps running `ponder start`, a second runs `ponder serve` against the same database and schema, and the public route points at the second one. + +Four constraints, read off the installed Ponder 0.16.6: + +| Aspect | Behaviour under `ponder serve` | +|--------|-------------------------------| +| Database | Postgres only | +| Schema | Must already exist. | +| `/ready` | Works normally. | +| `/status` | Works normally. | +| `ponder_sync_*` metrics | Absent. They are in-memory gauges set only by the indexing runtime (`runtime/realtime.js`, `runtime/historical.js`), which serve mode never runs. | + +The RPC diagnostic is skipped in serve mode, but `ponder.config.ts` still executes, so give both containers the same environment rather than trimming the RPC variables from the API one. ### Structured Logging @@ -192,7 +216,9 @@ A reindex that reuses an existing `ponder_sync` cache (same chain, same start bl `GET /ready` (Ponder built-in) returns `200` when Ponder has processed all historical blocks up to the tip and the live indexer is running. It does **not** guarantee historical discrete-order data is complete — `OwnerBackfillLive` drains that across live blocks after the tip. -`GET /readyz` (app) returns `200` only when Ponder is synced **and** the owner backfill has finished (no non-deterministic historical generator with `historyBackfilled = false`). This is the promotion gate: it guarantees a newly-promoted pod has the full historical discrete-order set, so blue-green promotion never drops a complete pod for one that's still filling. It returns `503` (with the pending count) while the drain is in progress. +`GET /readyz` (app) returns `200` only when Ponder is synced, no active chain has fallen behind the tip, **and** the owner backfill has finished (no non-deterministic historical generator with `historyBackfilled = false`). It guarantees a newly-promoted pod has the full historical discrete-order set. It returns `503` (with the pending count) while the drain is in progress. + +The staleness condition also makes `/readyz` useful after startup, which `/ready` has a bug. During our tests, we notice that `/ready` latches at 200 once historical sync completes and doesn't go back in case of RPC websocket connection stopped delivering new blocks. During backfill both return `503`. GraphQL queries are still available but data is incomplete (generators and transactions accumulate; discrete orders fill in as live sync progresses). diff --git a/src/api/freshness.ts b/src/api/freshness.ts new file mode 100644 index 0000000..4d02f57 --- /dev/null +++ b/src/api/freshness.ts @@ -0,0 +1,103 @@ +import { ACTIVE_CHAINS } from "../chains"; +import type { ChainConfig } from "../chains/types"; + +/** + * How far the newest indexed block may fall behind wall-clock before a chain is + * considered stalled. Generous by default: the live block handlers + * (OrderDiscoveryPoller, CandidateConfirmer, …) each add seconds of latency per + * firing, so normal operation already lags tens of seconds behind the tip. + */ +export const DEFAULT_MAX_LAG_SECONDS = 300; + +/** Resolve the staleness budget for a chain: per-chain env, then global env, then default. */ +export function maxLagSecondsFor(chainId: number): number { + for (const raw of [ + process.env[`READINESS_MAX_LAG_SECONDS_${chainId}`], + process.env.READINESS_MAX_LAG_SECONDS, + ]) { + const parsed = Number(raw); + if (Number.isFinite(parsed) && parsed > 0) return parsed; + } + return DEFAULT_MAX_LAG_SECONDS; +} + +/** Ponder's /status payload, keyed by chain name. */ +export type ChainStatus = Record< + string, + { id?: number; block?: { number?: number; timestamp?: number } | null } | null +>; + +/** + * Read the newest indexed block per chain from Ponder's /status. + * + * /status decodes the `_ponder_checkpoint` table, so it reflects committed + * database state rather than the indexing process's memory. That matters for + * two reasons: it stays correct if the API is ever run separately from the + * indexer (`ponder serve`), and it avoids parsing the Prometheus text format. + */ +export async function fetchChainStatus(origin: string): Promise { + try { + const res = await fetch(`${origin}/status`); + if (!res.ok) return {}; + return (await res.json()) as ChainStatus; + } catch { + return {}; + } +} + +export type StaleChain = { + chain: string; + /** Newest indexed block number, or null when the chain reports no block at all. */ + blockNumber: number | null; + /** Seconds between that block's timestamp and now, or null when unknown. */ + lagSeconds: number | null; + maxLagSeconds: number; +}; + +/** + * Compare each active chain's newest indexed block against wall-clock time. + * + * Wall-clock rather than a fresh `eth_blockNumber` call on purpose: a readiness + * probe that depends on the RPC turns an RPC outage into a restart loop, and the + * block timestamp already carries everything needed to spot a stalled sync. + * The trade-off is that a genuine chain halt reads as staleness. + * + * A chain missing from the payload counts as stale — absent data is not evidence + * of freshness. + */ +export function findStaleChains( + status: ChainStatus, + nowSeconds: number, + chains: ChainConfig[] = ACTIVE_CHAINS, +): StaleChain[] { + const stale: StaleChain[] = []; + + for (const chain of chains) { + const maxLagSeconds = maxLagSecondsFor(chain.chainId); + const block = status[chain.name]?.block; + const blockNumber = typeof block?.number === "number" ? block.number : null; + const timestamp = block?.timestamp; + + if (typeof timestamp !== "number" || timestamp <= 0) { + stale.push({ chain: chain.name, blockNumber, lagSeconds: null, maxLagSeconds }); + continue; + } + + const lagSeconds = Math.round(nowSeconds - timestamp); + if (lagSeconds > maxLagSeconds) { + stale.push({ chain: chain.name, blockNumber, lagSeconds, maxLagSeconds }); + } + } + + return stale; +} + +/** One-line, operator-readable summary of why the probe failed. */ +export function describeStaleChains(stale: StaleChain[]): string { + const parts = stale.map((s) => + s.lagSeconds === null + ? `${s.chain}: no indexed block reported` + : `${s.chain}: block ${s.blockNumber ?? "?"} is ${s.lagSeconds}s old (max ${s.maxLagSeconds}s)`, + ); + return `Chain sync is stalled — ${parts.join("; ")}.`; +} diff --git a/src/api/index.ts b/src/api/index.ts index 7c98b5c..b0387cb 100644 --- a/src/api/index.ts +++ b/src/api/index.ts @@ -7,6 +7,11 @@ import { swaggerUI } from "@hono/swagger-ui"; import { apiRouter } from "./router"; import { gqlDocsMiddleware } from "./gql-docs"; import { OWNER_BACKFILL_TYPES } from "../utils/order-types"; +import { + describeStaleChains, + fetchChainStatus, + findStaleChains, +} from "./freshness"; const app = new Hono(); @@ -19,27 +24,39 @@ app.use("/graphql", graphql({ db, schema })); app.get("/healthz", (c) => c.json({ status: "ok" })); -// Readiness for blue-green promotion. Ponder's built-in /ready flips once historical -// sync reaches the tip, but OwnerBackfill drains historical orders across the following -// live blocks — so /ready alone would promote an indexer with history still filling. -// /readyz returns 200 only when BOTH Ponder is synced AND the owner backfill is complete -// (no non-deterministic historical generator still pending). Point the deployment -// readiness probe at this instead of /ready. Ponder reserves /ready, so it can't be -// shadowed — hence a distinct path. +// Readiness for blue-green promotion and for the container healthcheck. Ponder's +// built-in /ready flips once historical sync reaches the tip and then stays 200 +// forever — it says nothing about whether live indexing is still advancing, so a +// stalled indexer keeps reporting itself ready. OwnerBackfill also drains historical +// orders across the following live blocks, so /ready alone would promote an indexer +// with history still filling. /readyz returns 200 only when Ponder is synced, every +// active chain is still keeping up with the tip, and the owner backfill is complete. +// Ponder reserves /ready, so it can't be shadowed — hence a distinct path. app.get("/readyz", async (c) => { + const origin = new URL(c.req.url).origin; + // 1. Ponder historical sync complete? Reuse the built-in /ready on the same origin // (also guards the empty-DB false positive: a fresh pod with zero generators would // otherwise have a pending count of 0 and look ready before indexing anything). let synced = false; try { - const res = await fetch(`${new URL(c.req.url).origin}/ready`); + const res = await fetch(`${origin}/ready`); synced = res.status === 200; } catch { synced = false; } if (!synced) return c.text("Historical indexing is not complete.", 503); - // 2. OwnerBackfill drained? Count matches OwnerBackfill's eligibility set exactly. + // 2. Live indexing still advancing? A dead RPC subscription leaves the process + // healthy and serving while the newest indexed block silently ages. /status + // decodes _ponder_checkpoint, so this reads committed database state. + const stale = findStaleChains( + await fetchChainStatus(origin), + Math.floor(Date.now() / 1000), + ); + if (stale.length > 0) return c.text(describeStaleChains(stale), 503); + + // 3. OwnerBackfill drained? Count matches OwnerBackfill's eligibility set exactly. const rows = await db .select({ pending: count() }) .from(schema.conditionalOrderGenerator) diff --git a/tests/api/freshness.test.ts b/tests/api/freshness.test.ts new file mode 100644 index 0000000..487bc06 --- /dev/null +++ b/tests/api/freshness.test.ts @@ -0,0 +1,204 @@ +import { describe, it, expect, vi, afterEach } from "vitest"; +import { + DEFAULT_MAX_LAG_SECONDS, + describeStaleChains, + fetchChainStatus, + findStaleChains, + maxLagSecondsFor, + type ChainStatus, +} from "../../src/api/freshness"; +import type { ChainConfig } from "../../src/chains/types"; + +const NOW = 1_786_024_484; + +// Only the two fields findStaleChains reads. +const CHAINS = [ + { name: "mainnet", chainId: 1 }, + { name: "gnosis", chainId: 100 }, +] as unknown as ChainConfig[]; + +/** Shape copied from a live /status response. */ +function status( + entries: Record, +): ChainStatus { + return Object.fromEntries( + Object.entries(entries).map(([chain, block]) => [chain, { block }]), + ); +} + +const FRESH = status({ + mainnet: { number: 25_696_339, timestamp: NOW - 21 }, + gnosis: { number: 47_586_912, timestamp: NOW - 14 }, +}); + +afterEach(() => { + delete process.env.READINESS_MAX_LAG_SECONDS; + delete process.env.READINESS_MAX_LAG_SECONDS_1; + delete process.env.READINESS_MAX_LAG_SECONDS_100; + vi.unstubAllGlobals(); +}); + +describe("maxLagSecondsFor", () => { + it("falls back to the default when nothing is configured", () => { + expect(maxLagSecondsFor(1)).toBe(DEFAULT_MAX_LAG_SECONDS); + }); + + it("prefers the per-chain override over the global one", () => { + process.env.READINESS_MAX_LAG_SECONDS = "120"; + process.env.READINESS_MAX_LAG_SECONDS_1 = "600"; + expect(maxLagSecondsFor(1)).toBe(600); + expect(maxLagSecondsFor(100)).toBe(120); + }); + + it("ignores unparseable and non-positive values", () => { + process.env.READINESS_MAX_LAG_SECONDS = "not-a-number"; + expect(maxLagSecondsFor(1)).toBe(DEFAULT_MAX_LAG_SECONDS); + process.env.READINESS_MAX_LAG_SECONDS = "0"; + expect(maxLagSecondsFor(1)).toBe(DEFAULT_MAX_LAG_SECONDS); + }); +}); + +describe("fetchChainStatus", () => { + it("returns the parsed payload", async () => { + const body = { + mainnet: { id: 1, block: { number: 25_696_339, timestamp: NOW - 21 } }, + }; + vi.stubGlobal( + "fetch", + vi.fn(() => + Promise.resolve({ ok: true, json: () => Promise.resolve(body) } as Response), + ), + ); + + await expect(fetchChainStatus("http://localhost:3000")).resolves.toEqual(body); + }); + + it("returns an empty payload on a non-200, so every chain reads as stale", async () => { + vi.stubGlobal( + "fetch", + vi.fn(() => Promise.resolve({ ok: false } as Response)), + ); + + await expect(fetchChainStatus("http://localhost:3000")).resolves.toEqual({}); + }); + + it("returns an empty payload when the request throws", async () => { + vi.stubGlobal( + "fetch", + vi.fn(() => Promise.reject(new Error("ECONNREFUSED"))), + ); + + await expect(fetchChainStatus("http://localhost:3000")).resolves.toEqual({}); + }); +}); + +describe("findStaleChains", () => { + it("reports nothing while every chain is near the tip", () => { + expect(findStaleChains(FRESH, NOW, CHAINS)).toEqual([]); + }); + + it("flags a chain whose newest block has aged past the budget", () => { + // The production failure: sync froze and the checkpoint stopped moving. + const frozen = status({ + mainnet: { number: 25_694_617, timestamp: NOW - 16_670 }, + gnosis: { number: 47_586_912, timestamp: NOW - 10 }, + }); + + expect(findStaleChains(frozen, NOW, CHAINS)).toEqual([ + { + chain: "mainnet", + blockNumber: 25_694_617, + lagSeconds: 16_670, + maxLagSeconds: DEFAULT_MAX_LAG_SECONDS, + }, + ]); + }); + + it("flags every stalled chain, not just the first", () => { + const frozen = status({ + mainnet: { number: 25_694_617, timestamp: NOW - 16_670 }, + gnosis: { number: 47_582_895, timestamp: NOW - 16_671 }, + }); + + expect(findStaleChains(frozen, NOW, CHAINS).map((s) => s.chain)).toEqual([ + "mainnet", + "gnosis", + ]); + }); + + it("treats a chain missing from the payload as stale", () => { + const partial = status({ + mainnet: { number: 25_696_339, timestamp: NOW - 21 }, + }); + + expect(findStaleChains(partial, NOW, CHAINS)).toEqual([ + { + chain: "gnosis", + blockNumber: null, + lagSeconds: null, + maxLagSeconds: DEFAULT_MAX_LAG_SECONDS, + }, + ]); + }); + + it("treats an unreachable /status as stale rather than fresh", () => { + expect(findStaleChains({}, NOW, CHAINS)).toHaveLength(2); + }); + + it("treats a malformed entry as stale", () => { + const malformed = { mainnet: { block: null }, gnosis: null } as ChainStatus; + + expect(findStaleChains(malformed, NOW, CHAINS)).toHaveLength(2); + }); + + it("stays fresh right at the budget and turns stale one second past it", () => { + const atBudget = status({ + mainnet: { number: 1, timestamp: NOW - DEFAULT_MAX_LAG_SECONDS }, + gnosis: { number: 2, timestamp: NOW }, + }); + expect(findStaleChains(atBudget, NOW, CHAINS)).toEqual([]); + + const pastBudget = status({ + mainnet: { number: 1, timestamp: NOW - DEFAULT_MAX_LAG_SECONDS - 1 }, + gnosis: { number: 2, timestamp: NOW }, + }); + expect(findStaleChains(pastBudget, NOW, CHAINS)).toHaveLength(1); + }); + + it("honours a per-chain budget", () => { + process.env.READINESS_MAX_LAG_SECONDS_100 = "30"; + const lagging = status({ + mainnet: { number: 1, timestamp: NOW - 60 }, + gnosis: { number: 2, timestamp: NOW - 60 }, + }); + + expect(findStaleChains(lagging, NOW, CHAINS).map((s) => s.chain)).toEqual([ + "gnosis", + ]); + }); +}); + +describe("describeStaleChains", () => { + it("names the block and its age", () => { + const message = describeStaleChains([ + { + chain: "mainnet", + blockNumber: 25_694_617, + lagSeconds: 16_670, + maxLagSeconds: 300, + }, + ]); + + expect(message).toBe( + "Chain sync is stalled — mainnet: block 25694617 is 16670s old (max 300s).", + ); + }); + + it("distinguishes a chain that reported no block at all", () => { + const message = describeStaleChains([ + { chain: "gnosis", blockNumber: null, lagSeconds: null, maxLagSeconds: 300 }, + ]); + + expect(message).toBe("Chain sync is stalled — gnosis: no indexed block reported."); + }); +});