From d9e04f8855231e9bd6bef762d9110e6e8b3e2524 Mon Sep 17 00:00:00 2001 From: Jorge Rivera Date: Sat, 24 Oct 2026 00:14:22 +0200 Subject: [PATCH 1/6] fix(tools): make each tools card a link to its docs page Only the arrow button navigated, through router.push, while the card's pointer cursor and whole-card hover made the rest look clickable. A Link now fills each card, and the arrow is a second link to the same page, kept out of the tab order and the accessibility tree. Generated with Claude --- .../BuildTools/BuildTools.module.scss | 20 ++++++++-- .../organisms/BuildTools/BuildTools.tsx | 38 +++++++++++-------- 2 files changed, 38 insertions(+), 20 deletions(-) diff --git a/src/components/organisms/BuildTools/BuildTools.module.scss b/src/components/organisms/BuildTools/BuildTools.module.scss index b0e4cef..d978768 100644 --- a/src/components/organisms/BuildTools/BuildTools.module.scss +++ b/src/components/organisms/BuildTools/BuildTools.module.scss @@ -40,15 +40,26 @@ .box { display: flex; flex-direction: column; - cursor: pointer; + + // The button is positioned against the box. + position: relative; width: rem(308); height: rem(300); - padding: rem(20) rem(10) rem(10); color: var(--color-bg); background-color: var(--color-stone); border-radius: rem(4); } +// Fills the box; the bottom padding keeps the text clear of the button. +.boxLink { + display: flex; + flex: 1; + flex-direction: column; + padding: rem(20) rem(10) rem(48); + color: inherit; + text-decoration: none; +} + .boxTitle { @include font-size(26px, 0.95); @@ -67,8 +78,9 @@ } .boxButton { - align-self: flex-end; - margin-top: auto; + position: absolute; + right: rem(10); + bottom: rem(10); } .headingBlock { diff --git a/src/components/organisms/BuildTools/BuildTools.tsx b/src/components/organisms/BuildTools/BuildTools.tsx index 2d3858c..ef6eef1 100644 --- a/src/components/organisms/BuildTools/BuildTools.tsx +++ b/src/components/organisms/BuildTools/BuildTools.tsx @@ -1,6 +1,6 @@ 'use client'; -import { useRouter } from 'next/navigation'; +import Link from 'next/link'; import styles from './BuildTools.module.scss'; @@ -35,24 +35,32 @@ const boxes = [ }, ]; -const renderBox = (index: number, go: (href: string) => void) => { +const renderBox = (index: number) => { const { title, text, href } = boxes[index]!; return ( + // The zone is the box: hovering anywhere on it flies the button's arrow + // (see the Button atom), and the link fills it.
-

- {title} -

-

- {text} -

+ +

+ {title} +

+

+ {text} +

+ + {/* Beside the link, since an anchor cannot hold another one. The box + is the link, so this copy stays out of the tab order and the + accessibility tree. */}
); @@ -60,8 +68,6 @@ const renderBox = (index: number, go: (href: string) => void) => { const BuildTools = () => { const sectionRef = useReveal(); - const router = useRouter(); - const go = (href: string) => router.push(href); return (
{ >
- {renderBox(0, go)} - {renderBox(1, go)} + {renderBox(0)} + {renderBox(1)}
- {renderBox(2, go)} - {renderBox(3, go)} + {renderBox(2)} + {renderBox(3)}
Date: Sat, 24 Oct 2026 11:47:16 +0200 Subject: [PATCH 2/6] fix(tools): show keyboard focus on the tools card links Generated with Claude --- .../organisms/BuildTools/BuildTools.module.scss | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/src/components/organisms/BuildTools/BuildTools.module.scss b/src/components/organisms/BuildTools/BuildTools.module.scss index d978768..2c529ab 100644 --- a/src/components/organisms/BuildTools/BuildTools.module.scss +++ b/src/components/organisms/BuildTools/BuildTools.module.scss @@ -58,6 +58,14 @@ padding: rem(20) rem(10) rem(48); color: inherit; text-decoration: none; + border-radius: inherit; + + // The link is each box's only tab stop, and the global reset drops the + // focus outline. + &:focus-visible { + outline: 2px solid var(--color-step-text); + outline-offset: 2px; + } } .boxTitle { From 86d06a85426f18bb70908a4ccaf88d321dcd975a Mon Sep 17 00:00:00 2001 From: Jorge Rivera Date: Sat, 24 Oct 2026 14:16:58 +0200 Subject: [PATCH 3/6] fix(events): keep three exported accounts behind every named organisation (#60) account_daily counts only accounts created before today (UTC), the accounts the export holds, so a named domain always shows at least 3 of them. The account export fails on an empty user table, replaces the table with no rows when every account is from today, and fails on an empty webmail_domain. Each exported event row carries export_rules, a digest of the export rules, ROW_SHAPE_VERSION and an HMAC under the hashing key, and every day holding an older digest reloads. A day that fails no longer blocks later days, the run stops starting days after a 20-minute budget, and its error names the failed, short, and unreached days. --- db/account-export.ts | 84 +- db/connection.ts | 54 +- db/event-export.ts | 348 +++++- db/export-events.ts | 64 +- .../0021_account_daily_before_today.sql | 44 + db/migrations/meta/0021_snapshot.json | 1092 +++++++++++++++++ db/migrations/meta/_journal.json | 7 + db/test/account-export.test.ts | 106 +- db/test/event-export.test.ts | 359 +++++- deploy/README.md | 109 +- 10 files changed, 1991 insertions(+), 276 deletions(-) create mode 100644 db/migrations/0021_account_daily_before_today.sql create mode 100644 db/migrations/meta/0021_snapshot.json diff --git a/db/account-export.ts b/db/account-export.ts index d48ff79..01bf132 100644 --- a/db/account-export.ts +++ b/db/account-export.ts @@ -6,11 +6,11 @@ import type { Pool } from 'pg'; /** * The account export, which the event export Job (db/export-events.ts) runs * before the event export: copies the Postgres view `account_daily` - * (migration 0020) into the BigQuery table `account_daily`, replacing the - * whole table in one load job, so a failed run leaves the previous table. - * The view counts new accounts per UTC day and organisation, for every day - * from the first account's through yesterday's, and the rows hold no email - * address or user id. + * (migrations 0020 and 0021) into the BigQuery table `account_daily`, + * replacing the whole table in one load job, so a failed run leaves the + * previous table. The view counts new accounts per UTC day and + * organisation, for every day from the first account's through + * yesterday's, and the rows hold no email address or user id. */ /** One `account_daily` row. */ @@ -45,15 +45,48 @@ export const ACCOUNT_SCHEMA: TableField[] = [ }, ]; -/** Every row of the view, oldest day first. */ -export const readAccountDaily = async (pool: Pool): Promise => { - const { rows } = await pool.query( - `SELECT to_char(day, 'YYYY-MM-DD') AS day, organisation, accounts - FROM account_daily - ORDER BY day, organisation`, - ); +/** + * What one read of the view returns. `accounts` and `webmailDomains` come + * from the view `account_daily_source`: whether the user table holds any + * account, and whether `webmail_domain` holds any domain. + */ +export type AccountRead = { + rows: AccountRow[]; + accounts: boolean; + webmailDomains: boolean; +}; - return rows; +/** + * Every row of the view, oldest day first, with the facts that say why it + * holds none. One read-only transaction reads both, so they share one + * `now()` and one snapshot. + */ +export const readAccountDaily = async (pool: Pool): Promise => { + const client = await pool.connect(); + + try { + await client.query('BEGIN ISOLATION LEVEL REPEATABLE READ READ ONLY'); + + const { rows } = await client.query( + `SELECT to_char(day, 'YYYY-MM-DD') AS day, organisation, accounts + FROM account_daily + ORDER BY day, organisation`, + ); + const { rows: source } = await client.query<{ + accounts: boolean; + webmailDomains: boolean; + }>(`SELECT accounts, webmail_domains AS "webmailDomains" FROM account_daily_source`); + + await client.query('COMMIT'); + client.release(); + + return { rows, ...source[0]! }; + } catch (error) { + // A failed query leaves the transaction open, and a release with + // the error discards the connection and the transaction with it. + client.release(error instanceof Error ? error : true); + throw error; + } }; /** Replaces the BigQuery table `account_daily` with the rows in `file`, one JSON object a line. */ @@ -74,10 +107,13 @@ export const bigQueryAccountTable = /** * One account export run. Writes every row to `scratchFile`, then replaces - * the table with it. The view holds a row for every day since the first - * account's, so a read with no rows is a fault (a wrong database, an - * emptied table) unless every account is from today, and rejects with the - * table kept. + * the table with it. The view holds a row for every day from the first + * account's through yesterday's while `webmail_domain` holds any domain, + * so a read with no rows means one of three things. While `webmail_domain` + * is empty, or while the user table holds no account (a wrong database, an + * emptied table), the run rejects with the table kept. When every account + * is from today, the table is replaced with no rows, so an account deleted + * since the last run, and the organisation it named, leave the export. */ export const runAccountExport = async ({ read, @@ -85,15 +121,21 @@ export const runAccountExport = async ({ scratchFile, log, }: { - read: () => Promise; + read: () => Promise; replace: (file: string) => Promise; scratchFile: string; log: (line: string) => void; }): Promise => { - const rows = await read(); + const { rows, accounts, webmailDomains } = await read(); + + if (rows.length === 0 && !webmailDomains) { + throw new Error( + 'account export: account_daily read no rows, webmail_domain is empty, table kept', + ); + } - if (rows.length === 0) { - throw new Error('account export: account_daily read no rows, table kept'); + if (rows.length === 0 && !accounts) { + throw new Error('account export: account_daily read no accounts, table kept'); } try { diff --git a/db/connection.ts b/db/connection.ts index faf336f..43c46c4 100644 --- a/db/connection.ts +++ b/db/connection.ts @@ -97,9 +97,8 @@ type EnvLike = Record; /** * Non-throwing check for which pool kind the runtime should build. Shared * by `resolveRuntimeConnection` below (full validation, safe to throw -- - * called from instrumentation.ts's `register()` at server start) and - * src/lib/db/index.ts (must never throw at import, including during - * `next build` with no env at all). + * called at process start) and src/lib/db/index.ts (must never throw at + * import, including during `next build` with no env at all). */ export function isCloudSqlConfigured(env: EnvLike = process.env): boolean { return !!env.WEBSITE_DB_INSTANCE_CONNECTION_NAME; @@ -107,10 +106,11 @@ export function isCloudSqlConfigured(env: EnvLike = process.env): boolean { /** * Resolves which database the runtime pool should connect to. Cloud SQL - * (deployed services) wins whenever its instance var is set; a local - * Postgres via DATABASE_URL is the fallback. Throws a clear error naming - * the missing variable(s) otherwise -- safe here because this is only - * called from instrumentation.ts's `register()` at server start, never at + * (deployed services and the event export Job) wins whenever its instance + * var is set; a local Postgres via DATABASE_URL is the fallback. Throws a + * clear error naming the missing variable(s) otherwise -- safe here + * because its callers, instrumentation.ts's `register()` at server start + * and db/export-events.ts's `main()`, call it at process start, never at * module import time. */ export function resolveRuntimeConnection(env: EnvLike = process.env): RuntimeConnection { @@ -145,10 +145,11 @@ export function resolveRuntimeConnection(env: EnvLike = process.env): RuntimeCon * Opens one `Connector` for the runtime pool's lifetime and resolves the * stream factory pg's `Pool` uses to dial Cloud SQL over PSC with IAM auth * -- the same path `buildMigratorPool` uses for the migrator role, just - * authenticating as the runtime IAM database user instead. Called once - * from instrumentation.ts's `register()`; the `Connector` is intentionally - * never closed here (SIGTERM exits the process, same as the migrator's - * shutdown note above but there is no request to await first). + * authenticating as the connection's IAM database user instead. Called + * once per process, from instrumentation.ts's `register()` and from + * db/export-events.ts's `main()`. The caller owns the `Connector`: the + * server leaves it open until SIGTERM exits the process, and the export + * Job closes it after ending its pool. */ export async function connectCloudSqlRuntime( connection: CloudSqlRuntimeConnection, @@ -170,18 +171,19 @@ interface CloudSqlRuntimeGlobal { const globalForCloudSqlRuntime = globalThis as unknown as CloudSqlRuntimeGlobal; /** - * Stores the stream factory `instrumentation.ts`'s `register()` resolved, - * so src/lib/db/index.ts's pool can read it lazily at connect time without - * importing the connector itself (index.ts must stay import-safe during - * `next build`, and the connector is only ever constructed once, in - * `register()`). + * Stores the stream factory `connectCloudSqlRuntime` resolved, so a pool + * from `buildRuntimePool` (src/lib/db/index.ts's, the export Job's) can + * read it lazily at connect time without importing the connector itself + * (index.ts must stay import-safe during `next build`, and the connector + * is constructed once per process, in `register()` or the export Job's + * `main()`). */ export function setCloudSqlRuntimeStream(stream: DriverOptions['stream']): void { globalForCloudSqlRuntime.cloudSqlRuntimeStream = stream; } /** - * Reads the stream factory `register()` stored. Throws only when actually + * Reads the stored stream factory. Throws only when actually * called -- i.e. when pg attempts a connection -- never at import, so a * misconfigured deploy still builds and starts; it just fails the first * request that touches the database. @@ -200,23 +202,23 @@ export function getCloudSqlRuntimeStream(): DriverOptions['stream'] { } /** - * Builds the one runtime `pg.Pool`, shared by src/lib/db/index.ts and - * db/test/runtime-pool.test.ts so both exercise the same construction - * path. Picks the pool kind from `isCloudSqlConfigured` alone -- a + * Builds a runtime `pg.Pool`, shared by src/lib/db/index.ts, the export + * Job (db/export-events.ts) and db/test/runtime-pool.test.ts so all + * exercise the same construction path. Picks the pool kind from `isCloudSqlConfigured` alone -- a * non-throwing check -- rather than the full, throwing * `resolveRuntimeConnection`, because this must never throw when called at * module import time (`next build` runs with no DB env at all): * * - Cloud SQL: `stream` is a function pg only calls when it actually opens - * a connection. It reads the factory `instrumentation.ts`'s `register()` - * stored on globalThis at that point, not now -- a clear error surfaces - * on the first connection attempt if `register()` never ran, not at - * import or build. + * a connection. It reads the factory `setCloudSqlRuntimeStream` stored + * on globalThis at that point, not now -- a clear error surfaces on the + * first connection attempt if none was stored, not at import or build. * - URL: `connectionString` may be `undefined` here (no env at build); pg * only fails to connect with it later. * - * `sizing` overrides the pool size and adds timeouts, for a pool that must - * give up fast (src/lib/db/index.ts's counter pool). + * `sizing` overrides the pool size and adds timeouts: src/lib/db/index.ts's + * counter pool gives up fast, and the export Job's pool holds one + * connection with a 5-minute `statement_timeout`. * * Every pool gets an `'error'` listener. pg-pool emits `'error'` when an * idle client fails (Cloud SQL or a proxy dropping the connection), and an diff --git a/db/event-export.ts b/db/event-export.ts index 756e809..7b49a38 100644 --- a/db/event-export.ts +++ b/db/event-export.ts @@ -1,10 +1,12 @@ -import { createHmac } from 'node:crypto'; +import { createHash, createHmac } from 'node:crypto'; import fs from 'node:fs/promises'; import { BigQuery, type TableField } from '@google-cloud/bigquery'; import type { Pool } from 'pg'; import type { GalleryKind } from '../src/components/organisms/Gallery/galleryData.ts'; +import type { CardTarget } from '../src/components/organisms/Studio/hooks/useChat.ts'; +import type { ShareMode } from '../src/lib/chat/shareMode.ts'; import type { ShareKind } from '../src/lib/chat/sharePrune.ts'; import type { Widget } from '../src/lib/chat/widgets.ts'; import type { EventName } from '../src/lib/events/track.ts'; @@ -25,9 +27,10 @@ import { requiredEnv } from './connection.ts'; * BigQuery table `event`, one day partition per UTC day of `created_at`. * Each run replaces every day from the latest day in BigQuery minus one * through today, every day from the first event on when the table is - * empty, and every earlier day whose event count differs from its - * partition's row count. A day is read whole before its partition is - * replaced, so a failed read leaves BigQuery as it was. + * empty, every earlier day whose event count differs from its partition's + * row count, and every day holding a row exported under other rules + * (exportRules). A day is read whole before its partition is replaced, so + * a failed read leaves BigQuery as it was. * * Rows keep no raw ids and no free text. `visitor_id` and `user_id` become * HMAC-SHA256 digests under EXPORT_ID_HMAC_KEY, as does the `shareId` prop, @@ -96,7 +99,10 @@ const ANSWER_KINDS = every()(['resolution', 'catalogue' const DECLINED_REASONS = every>()(['out_of_scope', 'requires_analysis']); const ABANDON_REASONS = every()(['hidden', 'superseded', 'reset', 'left']); const SHARE_KINDS = every()(['conversation', 'canvas', 'card', 'search']); -const SHARE_MODES = every()(['live', 'snapshot']); +// share.create and share.open send Studio's ShareMode, search.action the search's. +const SHARE_MODES = every()(['live', 'snapshot']); +// A prompt with no card target is `new` on the first turn. +const PROMPT_INTENTS = every<'new' | CardTarget['intent']>()(['new', 'follow_up', 'edit']); const CARD_KINDS = every()(['key_number', 'chart', 'table', 'text']); const GALLERY_KINDS = every()(['conversation', 'canvas', 'card', 'dataset']); const DATASET_FORMATS = every()(['csv', 'xlsx', 'parquet']); @@ -144,6 +150,7 @@ export const PROP_RULES = { 'search.action': { searchId: 'token', traceId: 'token', + // DataSearch.tsx's SearchAction, which src/ does not export. action: ['pick_reading', 'download', 'share'], partIndex: 'count', specId: 'token', @@ -154,7 +161,7 @@ export const PROP_RULES = { }, 'studio.prompt': { turn: 'count', - intent: ['new', 'follow_up', 'edit'], + intent: PROMPT_INTENTS, length: 'count', guest: 'boolean', }, @@ -163,6 +170,7 @@ export const PROP_RULES = { 'studio.session_end': { turns: 'count', cards: 'count', pins: 'count', guest: 'boolean' }, 'auth.signin': { provider: 'token' }, 'guest.wall_hit': { prompts: 'count' }, + // Literals in src/app/api/feedback/route.ts, without a named type. 'feedback.submit': { kind: ['chat', 'widget'] }, 'embed.view': { shareId: 'digest', kind: SHARE_KINDS, host: 'token' }, 'share.create': { shareId: 'digest', kind: SHARE_KINDS, mode: SHARE_MODES }, @@ -170,6 +178,8 @@ export const PROP_RULES = { 'gallery.open': { slug: 'token', kind: GALLERY_KINDS }, } satisfies Record>; +// A change to digest, passes, exportProps, exportPage or exportRow bumps +// ROW_SHAPE_VERSION. const digest = (key: string, id: string | null): string | null => id === null ? null : createHmac('sha256', key).update(id).digest('hex'); @@ -187,7 +197,10 @@ const passes = (rule: PropRule, value: unknown): boolean => { } }; -/** The props an event keeps. A name the site does not emit keeps none. */ +/** + * The props an event keeps. A name the site does not emit keeps none. A + * change here bumps ROW_SHAPE_VERSION. + */ export const exportProps = ( name: string, props: Record, @@ -229,9 +242,18 @@ export type ExportRow = { visitor_hash: string | null; user_hash: string | null; props: Record; + export_rules: string; }; -export const EXPORT_SCHEMA: TableField[] = [ +// The columns the table was created with that are REQUIRED. A load's +// ALLOW_FIELD_ADDITION adds NULLABLE columns only, and a load whose schema +// adds a REQUIRED one fails, so a column added later must be NULLABLE and +// tsc refuses a REQUIRED one with another name. +type CreatedRequired = 'id' | 'created_at' | 'name' | 'signed_in' | 'props'; + +export type ExportField = TableField & ({ name: CreatedRequired } | { mode?: 'NULLABLE' }); + +export const EXPORT_SCHEMA: ExportField[] = [ { name: 'id', type: 'INT64', mode: 'REQUIRED' }, { name: 'created_at', type: 'TIMESTAMP', mode: 'REQUIRED' }, { name: 'name', type: 'STRING', mode: 'REQUIRED' }, @@ -240,6 +262,7 @@ export const EXPORT_SCHEMA: TableField[] = [ { name: 'visitor_hash', type: 'STRING' }, { name: 'user_hash', type: 'STRING' }, { name: 'props', type: 'JSON', mode: 'REQUIRED' }, + { name: 'export_rules', type: 'STRING' }, ]; // A path on the site: a slash, then letters, digits and `_ - . : /`, up to @@ -256,15 +279,51 @@ const SHARE_PATH = /^\/(s|embed)\/[^/]+/; /** * The page's path without its query string or fragment and with any share - * id written `:id`, null unless it is a site path. + * id written `:id`, null unless it is a site path. A change here bumps + * ROW_SHAPE_VERSION. */ +// The query-string strip repeats eventLogEntry's in src/lib/events/eventLog.ts, +// which keeps it inline and exports no function for it. const exportPage = (page: string | null): string | null => { const path = page?.split(/[?#]/, 1)[0]; return path !== undefined && PAGE_PATH.test(path) ? path.replace(SHARE_PATH, '/$1/:id') : null; }; -export const exportRow = (row: SourceEvent, hmacKey: string): ExportRow => ({ +// The version of the code that shapes a row: digest, passes, exportProps, +// exportPage and exportRow. Bumped by hand with any change to them, so the +// change reaches every day (exportRules). +const ROW_SHAPE_VERSION = 1; + +/** + * The digest every row carries in `export_rules`: SHA-256 over PROP_RULES, + * TOKEN, PAGE_PATH, SHARE_PATH, EXPORT_SCHEMA, ROW_SHAPE_VERSION and an + * HMAC of a fixed string under `hmacKey`, so a new key changes it too. A + * day holding a row with another digest, or none, reloads (exportDays). + */ +export const exportRules = (hmacKey: string): string => + createHash('sha256') + .update( + JSON.stringify({ + PROP_RULES, + TOKEN: TOKEN.source, + PAGE_PATH: PAGE_PATH.source, + SHARE_PATH: SHARE_PATH.source, + EXPORT_SCHEMA, + ROW_SHAPE_VERSION, + key: createHmac('sha256', hmacKey).update('export_rules').digest('hex'), + }), + ) + .digest('hex'); + +// Every prop key some event keeps, the only keys readDay fetches. +const KEPT_PROPS = [...new Set(Object.values(PROP_RULES).flatMap((rules) => Object.keys(rules)))]; + +/** + * The row BigQuery holds for an event, under `rules` from exportRules. A + * change here bumps ROW_SHAPE_VERSION. + */ +export const exportRow = (row: SourceEvent, hmacKey: string, rules: string): ExportRow => ({ id: row.id, created_at: row.createdAt, name: row.name, @@ -274,10 +333,24 @@ export const exportRow = (row: SourceEvent, hmacKey: string): ExportRow => ({ visitor_hash: digest(hmacKey, row.visitorId), user_hash: digest(hmacKey, row.userId), props: exportProps(row.name, row.props, hmacKey), + export_rules: rules, }); const DAY_MS = 86_400_000; +/** + * How long a run starts new days for, 20 minutes, well inside the Job's + * 1800 s task timeout, so a run that has many days each waiting out a + * statement timeout ends and reports before the platform kills it. + */ +export const EXPORT_BUDGET_MS = 20 * 60_000; + +/** The most one BigQuery query may bill (`maximumBytesBilled`). */ +const MAX_BYTES_BILLED = 1e9; + +/** What the staleDays scan bills per event row, from its two columns. */ +const STALE_BYTES_PER_ROW = 74; + const dayOf = (ms: number): string => new Date(ms).toISOString().slice(0, 10); /** Rows per UTC day (`YYYY-MM-DD`). A day without rows is absent. */ @@ -287,23 +360,26 @@ export type DayCounts = ReadonlyMap; * The UTC days a run replaces, oldest first. They run from the day before * the latest day BigQuery holds through `today`, or from the first event's * day when BigQuery holds nothing, and add every day whose `events` count - * differs from its `partitions` count. A day that loaded short thus stays - * in every run until it matches, however many later days load. None when - * there is no event and BigQuery holds nothing. + * differs from its `partitions` count and every `stale` day. A day that + * loaded short, or failed to load under new rules, thus stays in every run + * until it matches, however many later days load. None when there is no + * event and BigQuery holds nothing. */ export const exportDays = ({ today, events, partitions, + stale = new Set(), }: { today: string; events: DayCounts; partitions: DayCounts; + stale?: ReadonlySet; }): string[] => { const latest = [...partitions.keys()].sort().at(-1); const start = latest !== undefined ? dayOf(Date.parse(latest) - DAY_MS) : [...events.keys()].sort()[0]; - const days = new Set(); + const days = new Set(stale); if (start !== undefined) { for (let ms = Date.parse(start); ms <= Date.parse(today); ms += DAY_MS) { @@ -324,7 +400,7 @@ export const exportDays = ({ export type EventSource = { /** The events per UTC day of `created_at`, over the whole table. */ dayCounts(): Promise; - /** One UTC day's events in id order, a page at a time. */ + /** One UTC day's events in `created_at`, then id, order, a page at a time. */ readDay(day: string): AsyncIterable; }; @@ -334,6 +410,8 @@ export type Warehouse = { ensureTable(): Promise; /** The rows each day's partition holds. */ dayCounts(): Promise; + /** The days holding a row whose `export_rules` is not `rules`, NULL included. */ + staleDays(rules: string): Promise>; /** Replaces the day's partition with the rows in `file`, one JSON object a line. */ replaceDay(day: string, file: string): Promise; }; @@ -344,30 +422,36 @@ export const pgEventSource = (pool: Pool, pageSize = PAGE_SIZE): EventSource => async dayCounts() { // The UTC date of created_at, the same day readDay's range bounds. const { rows } = await pool.query<{ day: string; n: number }>( - `SELECT to_char(created_at AT TIME ZONE 'UTC', 'YYYY-MM-DD') AS day, - count(*)::int AS n - FROM event - GROUP BY 1`, + `SELECT to_char(day, 'YYYY-MM-DD') AS day, n + FROM (SELECT (created_at AT TIME ZONE 'UTC')::date AS day, count(*)::int AS n + FROM event + GROUP BY 1) AS days`, ); return new Map(rows.map(({ day, n }) => [day, n])); }, async *readDay(day) { - const from = `${day}T00:00:00Z`; const to = `${dayOf(Date.parse(day) + DAY_MS)}T00:00:00Z`; - let after = 0; + // Keyset paging: each page starts after the last row of the one + // before, so no page reads the rows before it. Ids start at 1, so + // (midnight, 0) precedes the day's first row. `props` keeps only the keys some + // event keeps; exportProps picks each event's own. + let after = { createdAt: `${day}T00:00:00Z`, id: 0 }; for (;;) { const { rows } = await pool.query( `SELECT id::float8 AS id, to_char(created_at AT TIME ZONE 'UTC', 'YYYY-MM-DD"T"HH24:MI:SS.US"Z"') AS "createdAt", - name, user_id AS "userId", visitor_id AS "visitorId", page, props + name, user_id AS "userId", visitor_id AS "visitorId", page, + coalesce((SELECT jsonb_object_agg(key, value) + FROM jsonb_each(props) + WHERE key = ANY($4::text[])), '{}') AS props FROM event - WHERE created_at >= $1 AND created_at < $2 AND id > $3 - ORDER BY id - LIMIT $4`, - [from, to, after, pageSize], + WHERE created_at >= $1 AND created_at < $2 AND (created_at, id) > ($1, $3) + ORDER BY created_at, id + LIMIT $5`, + [after.createdAt, to, after.id, KEPT_PROPS, pageSize], ); if (rows.length === 0) { @@ -375,7 +459,7 @@ export const pgEventSource = (pool: Pool, pageSize = PAGE_SIZE): EventSource => } yield rows; - after = rows[rows.length - 1]!.id; + after = rows[rows.length - 1]!; } }, }); @@ -392,6 +476,51 @@ export const bigQueryWarehouse = ({ const dataset = bigquery.dataset(datasetId); const table = dataset.table('event'); + // A query job fails past 1 GB billed or past 2 minutes, well inside the + // Job's 1800 s task timeout, and the run fails with it. + const query = async (sql: string, params?: Record): Promise => { + try { + const [rows] = await bigquery.query({ + query: sql, + params, + maximumBytesBilled: String(MAX_BYTES_BILLED), + jobTimeoutMs: 120_000, + }); + + return rows; + } catch (error) { + if (/bytes billed/i.test(messageOf(error))) { + throw new Error( + `a query exceeded the ${MAX_BYTES_BILLED / 1e9} GB maximumBytesBilled cap, ` + + `which staleDays reaches at about ${(MAX_BYTES_BILLED / STALE_BYTES_PER_ROW / 1e6).toFixed(1)} million event rows`, + { cause: error }, + ); + } + + throw error; + } + }; + + const dayCounts = async (): Promise => { + // Each partition's row count from the table's metadata, which a + // finished load updates, so the query scans no table data. + // partition_id is the UTC day as YYYYMMDD, and the pattern leaves + // out the special partitions such as __NULL__. + const rows = await query<{ partition_id: string; total_rows: unknown }>( + `SELECT partition_id, total_rows + FROM \`${projectId}.${datasetId}.INFORMATION_SCHEMA.PARTITIONS\` + WHERE table_name = 'event' AND total_rows > 0 + AND REGEXP_CONTAINS(partition_id, r'^\\d{8}$')`, + ); + + return new Map( + rows.map((row) => [ + row.partition_id.replace(/^(\d{4})(\d{2})(\d{2})$/, '$1-$2-$3'), + Number(row.total_rows), + ]), + ); + }; + return { async ensureTable() { const [exists] = await table.exists(); @@ -403,23 +532,28 @@ export const bigQueryWarehouse = ({ }); } }, - async dayCounts() { - // An exact count that sees every finished load. It scans the - // created_at column alone, 8 bytes a row. DATE() takes the UTC - // date, the day the table partitions on. The job fails past - // 1 GB billed, 125 million rows, or past 2 minutes, well inside - // the Job's 1800 s task timeout, and the run fails with it. - const [rows] = await bigquery.query({ - query: `SELECT FORMAT_DATE('%F', DATE(created_at)) AS day, COUNT(*) AS n - FROM \`${projectId}.${datasetId}.event\` - GROUP BY day`, - maximumBytesBilled: String(1e9), - jobTimeoutMs: 120_000, - }); + dayCounts, + async staleDays(rules) { + const [metadata] = await table.getMetadata(); + const fields: TableField[] = metadata.schema?.fields ?? []; + + // A table created without the column holds no digest, so every + // day with rows is stale. The next load adds the column. + if (!fields.some((field) => field.name === 'export_rules')) { + return new Set((await dayCounts()).keys()); + } - return new Map( - rows.map((row: { day: string; n: unknown }) => [row.day, Number(row.n)]), + // Scans the created_at and export_rules columns, about + // STALE_BYTES_PER_ROW bytes a row. + const rows = await query<{ day: string }>( + `SELECT FORMAT_DATE('%F', DATE(created_at)) AS day + FROM \`${projectId}.${datasetId}.event\` + WHERE export_rules IS DISTINCT FROM @rules + GROUP BY day`, + { rules }, ); + + return new Set(rows.map(({ day }) => day)); }, async replaceDay(day, file) { // Resolves once the load job is done, and throws if it failed. @@ -427,30 +561,43 @@ export const bigQueryWarehouse = ({ sourceFormat: 'NEWLINE_DELIMITED_JSON', writeDisposition: 'WRITE_TRUNCATE', schema: { fields: EXPORT_SCHEMA }, - // A column added to EXPORT_SCHEMA reaches the table on the next load. + // A NULLABLE column added to EXPORT_SCHEMA reaches the table + // on the next load (ExportField). schemaUpdateOptions: ['ALLOW_FIELD_ADDITION'], }); }, }; }; +const messageOf = (error: unknown): string => + error instanceof Error ? error.message : String(error); + /** * One export run over the days exportDays picks. Each day is written to - * `scratchFile` page by page, so memory holds one page. The partition is - * replaced only once the day has been read to its end, and only when the - * read holds at least as many rows as the partition. Nothing deletes - * `event` rows, and they carry no foreign key to `user`, so deleting an - * account leaves them. A shorter read is therefore a fault (a wrong - * database, an emptied table, a lagging replica). Such a day keeps its - * partition, the other days still load, and the run then rejects naming - * each short day with both counts. Its counts still differ, so the day - * stays in every later run and fails it until it matches. A read below - * the day's source count from `source.dayCounts()` is a fault too, - * whatever the partition holds: the day loads by the rule above, and the - * run then rejects naming it with both counts. Today's count is taken - * before its read, so a read above the count is normal. A day that reads - * no rows and holds none loads nothing. Logs each day as it is done, - * names the day in a failure, and returns the rows read per day. + * `scratchFile` page by page before its load, so memory holds one page of + * rows plus the day's file, since Cloud Run's disk is in memory too. A + * day's NDJSON runs to about 360 bytes an event. The partition is replaced + * only once the day has been read to its end, and only when the read holds + * at least as many rows as the partition. Nothing deletes `event` rows, + * and they carry no foreign key to `user`, so deleting an account leaves + * them. A shorter read is therefore a fault (a wrong database, an emptied + * table, a lagging replica). Such a day keeps its partition, the other + * days still load, and the run then rejects naming each short day with + * both counts. Its counts still differ, so the day stays in every later + * run and fails it until it matches. A read below the day's source count + * from `source.dayCounts()` is a fault too, whatever the partition holds: + * the day loads by the rule above, and the run then rejects naming it with + * both counts. Today's count is taken before its read, so a read above the + * count is normal. A day that reads no rows and holds none loads nothing. + * A day whose read or load fails keeps its partition as it was, the later + * days still load, and the run then rejects naming every such day with its + * error. Each row carries the run's exportRules digest, so a day that + * fails under new rules still holds the old digest and is the one day the + * next run reloads for them. A run starts no new day once `budgetMs` has + * passed since it began (`now` is its clock); it ends the day in hand, then + * rejects naming the days it did not reach as well as the failed and short + * ones, and the next run picks those days up. Logs each day as it is done + * and returns the rows read per day. */ export const runExport = async ({ source, @@ -459,6 +606,8 @@ export const runExport = async ({ today, scratchFile, log, + budgetMs = EXPORT_BUDGET_MS, + now = Date.now, }: { source: EventSource; warehouse: Warehouse; @@ -466,17 +615,32 @@ export const runExport = async ({ today: string; scratchFile: string; log: (line: string) => void; + budgetMs?: number; + now?: () => number; }): Promise<{ day: string; rows: number }[]> => { + const startedAt = now(); + const rules = exportRules(hmacKey); + await warehouse.ensureTable(); - const [events, partitions] = await Promise.all([source.dayCounts(), warehouse.dayCounts()]); - const days = exportDays({ today, events, partitions }); + const [events, partitions, stale] = await Promise.all([ + source.dayCounts(), + warehouse.dayCounts(), + warehouse.staleDays(rules), + ]); + const days = exportDays({ today, events, partitions, stale }); const read: { day: string; rows: number }[] = []; + const failed: { day: string; error: unknown }[] = []; const short: string[] = []; - const shortDays = () => `short days: ${short.join(', ')}`; + const unreached: string[] = []; try { for (const day of days) { + if (now() - startedAt >= budgetMs) { + unreached.push(day); + continue; + } + let rows = 0; const held = partitions.get(day) ?? 0; const counted = events.get(day) ?? 0; @@ -485,7 +649,9 @@ export const runExport = async ({ await fs.writeFile(scratchFile, ''); for await (const page of source.readDay(day)) { - const lines = page.map((row) => `${JSON.stringify(exportRow(row, hmacKey))}\n`); + const lines = page.map( + (row) => `${JSON.stringify(exportRow(row, hmacKey, rules))}\n`, + ); await fs.appendFile(scratchFile, lines.join('')); rows += page.length; @@ -495,10 +661,9 @@ export const runExport = async ({ await warehouse.replaceDay(day, scratchFile); } } catch (error) { - const message = error instanceof Error ? error.message : String(error); - const earlier = short.length > 0 ? `; earlier days ${shortDays()}` : ''; - - throw new Error(`event export ${day}: ${message}${earlier}`, { cause: error }); + log(`${day}: failed, partition kept: ${messageOf(error)}`); + failed.push({ day, error }); + continue; } const belowSource = rows < counted ? `, source counts ${counted}` : ''; @@ -523,13 +688,60 @@ export const runExport = async ({ await fs.rm(scratchFile, { force: true }); } - if (short.length > 0) { - throw new Error(`event export ${shortDays()}`); + const faults = [ + ...failed.map(({ day, error }) => `${day}: ${messageOf(error)}`), + ...(short.length > 0 ? [`short days: ${short.join(', ')}`] : []), + ...(unreached.length > 0 + ? [ + `days not reached in the ${budgetMs / 60_000} minute budget: ${unreached.join(', ')}`, + ] + : []), + ]; + + if (faults.length > 0) { + throw new Error(`event export ${faults.join('; ')}`, { + cause: + failed.length > 0 + ? new AggregateError(failed.map(({ error }) => error)) + : undefined, + }); } return read; }; +/** + * The export Job's run (db/export-events.ts): the account export, then the + * event export, which runs whether or not the account export failed. Logs + * an account export failure as it happens and rejects with it once the + * event export is done, so a failing one leaves the other's tables + * current. An event export failure rejects as it is. + */ +export const runExportJob = async ({ + exportAccounts, + exportEvents, + logError, +}: { + exportAccounts: () => Promise; + exportEvents: () => Promise; + logError: (error: unknown) => void; +}): Promise => { + let accountFailure: Error | null = null; + + try { + await exportAccounts(); + } catch (error) { + accountFailure = new Error('account export failed', { cause: error }); + logError(error); + } + + await exportEvents(); + + if (accountFailure !== null) { + throw accountFailure; + } +}; + /** The export's own settings. The database settings are the runtime's (db/connection.ts). */ export const readExportEnv = () => ({ projectId: requiredEnv('EXPORT_BQ_PROJECT'), diff --git a/db/export-events.ts b/db/export-events.ts index b9950e3..aaabd3e 100644 --- a/db/export-events.ts +++ b/db/export-events.ts @@ -8,13 +8,18 @@ import { resolveRuntimeConnection, setCloudSqlRuntimeStream, } from './connection'; -import { bigQueryWarehouse, pgEventSource, readExportEnv, runExport } from './event-export'; +import { + bigQueryWarehouse, + pgEventSource, + readExportEnv, + runExport, + runExportJob, +} from './event-export'; // The event export Job's command (`node dist/export-events.cjs`, see // deploy/Dockerfile). It reads the database as the runtime does, through -// WEBSITE_DB_* over the Cloud SQL connector, or DATABASE_URL locally. It -// runs the account export, then the event export, and fails when either -// fails, so a failing one leaves the other's tables current. +// WEBSITE_DB_* over the Cloud SQL connector, or DATABASE_URL locally, and +// runs the account export, then the event export (runExportJob). async function main(): Promise { const settings = readExportEnv(); const connection = resolveRuntimeConnection(); @@ -27,40 +32,37 @@ async function main(): Promise { // One connection suffices, since the run sends one query at a time. A // query that runs past 5 minutes, the per-day count over the whole - // table or a page read, fails the run, well inside the Job's 1800 s - // task timeout, so a hung read ends before the next hourly run starts. + // table, a page read or an account read, fails that read. The event + // export starts no new day after 20 minutes (EXPORT_BUDGET_MS), so + // days that each wait out the timeout still end the run, with a + // report naming the days it did not reach, inside the Job's 1800 s + // task timeout and before the next hourly run starts. const pool = buildRuntimePool(process.env, { max: 1, statement_timeout: 300_000 }); const bigquery = new BigQuery({ projectId: settings.projectId }); const log = (line: string) => console.log(line); try { - let accountFailure: Error | null = null; - - try { - await runAccountExport({ - read: () => readAccountDaily(pool), - replace: bigQueryAccountTable({ datasetId: settings.datasetId, bigquery }), - scratchFile: path.join(os.tmpdir(), `account-export-${process.pid}.ndjson`), - log, - }); - } catch (error) { - accountFailure = new Error('account export failed', { cause: error }); - console.error('ERROR:', error instanceof Error ? error.stack : error); - } - - await runExport({ - source: pgEventSource(pool), - warehouse: bigQueryWarehouse({ ...settings, bigquery }), - hmacKey: settings.hmacKey, - today: new Date().toISOString().slice(0, 10), - scratchFile: path.join(os.tmpdir(), `event-export-${process.pid}.ndjson`), - log, + await runExportJob({ + exportAccounts: () => + runAccountExport({ + read: () => readAccountDaily(pool), + replace: bigQueryAccountTable({ datasetId: settings.datasetId, bigquery }), + scratchFile: path.join(os.tmpdir(), `account-export-${process.pid}.ndjson`), + log, + }), + exportEvents: () => + runExport({ + source: pgEventSource(pool), + warehouse: bigQueryWarehouse({ ...settings, bigquery }), + hmacKey: settings.hmacKey, + today: new Date().toISOString().slice(0, 10), + scratchFile: path.join(os.tmpdir(), `event-export-${process.pid}.ndjson`), + log, + }), + logError: (error) => + console.error('ERROR:', error instanceof Error ? error.stack : error), }); - - if (accountFailure !== null) { - throw accountFailure; - } } finally { // The pool first, so its connections close over the connector's tunnel. await pool.end(); diff --git a/db/migrations/0021_account_daily_before_today.sql b/db/migrations/0021_account_daily_before_today.sql new file mode 100644 index 0000000..01677f5 --- /dev/null +++ b/db/migrations/0021_account_daily_before_today.sql @@ -0,0 +1,44 @@ +-- `account_daily` holds the UTC days through yesterday's and counts only +-- the accounts created before today, UTC, so a domain it names holds at +-- least 3 of the accounts the export carries. +-- CREATE OR REPLACE keeps the view's grant to `website_export_reader`. +CREATE OR REPLACE VIEW "account_daily" AS +WITH account AS ( + SELECT "created_at"::date AS day, lower(substring("email" FROM '[^@]*$')) AS domain + FROM "user" + WHERE "created_at" < (now() AT TIME ZONE 'UTC')::date +), +labelled AS ( + SELECT day, + CASE + WHEN domain IN (SELECT "domain" FROM "webmail_domain") THEN 'Personal email' + WHEN count(*) OVER (PARTITION BY domain) >= 3 THEN domain + ELSE 'Other organisations' + END AS organisation + FROM account +), +counted AS ( + SELECT day, organisation, count(*)::int AS accounts + FROM labelled + GROUP BY day, organisation +), +days AS ( + SELECT generate_series(min(day), (now() AT TIME ZONE 'UTC')::date - 1, interval '1 day')::date AS day + FROM account + WHERE EXISTS (SELECT 1 FROM "webmail_domain") +) +SELECT days.day, counted.organisation, coalesce(counted.accounts, 0) AS accounts +FROM days +LEFT JOIN counted USING (day); +--> statement-breakpoint +-- Why `account_daily` holds no rows: whether the user table holds any +-- account, and whether `webmail_domain` holds any domain. The account +-- export reads it in the same transaction as the view, and fails on no rows +-- when either is empty. It runs with the migrator's rights, like the view, +-- and leaves no email address or user id with the reader. +CREATE VIEW "account_daily_source" AS +SELECT + EXISTS (SELECT 1 FROM "user") AS accounts, + EXISTS (SELECT 1 FROM "webmail_domain") AS webmail_domains; +--> statement-breakpoint +GRANT SELECT ON "account_daily_source" TO website_export_reader; diff --git a/db/migrations/meta/0021_snapshot.json b/db/migrations/meta/0021_snapshot.json new file mode 100644 index 0000000..ad02bdc --- /dev/null +++ b/db/migrations/meta/0021_snapshot.json @@ -0,0 +1,1092 @@ +{ + "id": "3a669c64-ea49-434a-9f75-2f090520da67", + "prevId": "0327543c-60f8-4b9d-b94f-1bff81ca8bbf", + "version": "7", + "dialect": "postgresql", + "tables": { + "public.conversation": { + "name": "conversation", + "schema": "", + "columns": { + "id": { + "name": "id", + "type": "text", + "primaryKey": true, + "notNull": true + }, + "user_id": { + "name": "user_id", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "title": { + "name": "title", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "agent_session_id": { + "name": "agent_session_id", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "turn_count": { + "name": "turn_count", + "type": "integer", + "primaryKey": false, + "notNull": true, + "default": 0 + }, + "data": { + "name": "data", + "type": "jsonb", + "primaryKey": false, + "notNull": true + }, + "created_at": { + "name": "created_at", + "type": "timestamp with time zone", + "primaryKey": false, + "notNull": true, + "default": "now()" + }, + "updated_at": { + "name": "updated_at", + "type": "timestamp with time zone", + "primaryKey": false, + "notNull": true, + "default": "now()" + } + }, + "indexes": { + "conversation_user_updated_idx": { + "name": "conversation_user_updated_idx", + "columns": [ + { + "expression": "user_id", + "isExpression": false, + "asc": true, + "nulls": "last" + }, + { + "expression": "updated_at", + "isExpression": false, + "asc": true, + "nulls": "last" + } + ], + "isUnique": false, + "concurrently": false, + "method": "btree", + "with": {} + } + }, + "foreignKeys": { + "conversation_user_id_user_id_fk": { + "name": "conversation_user_id_user_id_fk", + "tableFrom": "conversation", + "tableTo": "user", + "columnsFrom": [ + "user_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "policies": {}, + "checkConstraints": {}, + "isRLSEnabled": false + }, + "public.event": { + "name": "event", + "schema": "", + "columns": { + "id": { + "name": "id", + "type": "bigint", + "primaryKey": true, + "notNull": true, + "identity": { + "type": "always", + "name": "event_id_seq", + "schema": "public", + "increment": "1", + "startWith": "1", + "minValue": "1", + "maxValue": "9223372036854775807", + "cache": "1", + "cycle": false + } + }, + "created_at": { + "name": "created_at", + "type": "timestamp with time zone", + "primaryKey": false, + "notNull": true, + "default": "now()" + }, + "name": { + "name": "name", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "user_id": { + "name": "user_id", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "visitor_id": { + "name": "visitor_id", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "page": { + "name": "page", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "props": { + "name": "props", + "type": "jsonb", + "primaryKey": false, + "notNull": true, + "default": "'{}'::jsonb" + } + }, + "indexes": { + "event_created_at_idx": { + "name": "event_created_at_idx", + "columns": [ + { + "expression": "created_at", + "isExpression": false, + "asc": false, + "nulls": "last" + } + ], + "isUnique": false, + "concurrently": false, + "method": "btree", + "with": {} + }, + "event_name_created_at_idx": { + "name": "event_name_created_at_idx", + "columns": [ + { + "expression": "name", + "isExpression": false, + "asc": true, + "nulls": "last" + }, + { + "expression": "created_at", + "isExpression": false, + "asc": false, + "nulls": "last" + } + ], + "isUnique": false, + "concurrently": false, + "method": "btree", + "with": {} + } + }, + "foreignKeys": {}, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "policies": {}, + "checkConstraints": {}, + "isRLSEnabled": false + }, + "public.feedback": { + "name": "feedback", + "schema": "", + "columns": { + "id": { + "name": "id", + "type": "bigint", + "primaryKey": true, + "notNull": true, + "identity": { + "type": "always", + "name": "feedback_id_seq", + "schema": "public", + "increment": "1", + "startWith": "1", + "minValue": "1", + "maxValue": "9223372036854775807", + "cache": "1", + "cycle": false + } + }, + "created_at": { + "name": "created_at", + "type": "timestamp with time zone", + "primaryKey": false, + "notNull": true, + "default": "now()" + }, + "message": { + "name": "message", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "email": { + "name": "email", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "page": { + "name": "page", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "user_agent": { + "name": "user_agent", + "type": "text", + "primaryKey": false, + "notNull": false + } + }, + "indexes": { + "feedback_created_at_idx": { + "name": "feedback_created_at_idx", + "columns": [ + { + "expression": "created_at", + "isExpression": false, + "asc": false, + "nulls": "last" + } + ], + "isUnique": false, + "concurrently": false, + "method": "btree", + "with": {} + } + }, + "foreignKeys": {}, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "policies": {}, + "checkConstraints": { + "feedback_message_length": { + "name": "feedback_message_length", + "value": "char_length(\"feedback\".\"message\") BETWEEN 1 AND 5000" + } + }, + "isRLSEnabled": false + }, + "public.limit_counter": { + "name": "limit_counter", + "schema": "", + "columns": { + "key": { + "name": "key", + "type": "text", + "primaryKey": true, + "notNull": true + }, + "window_start": { + "name": "window_start", + "type": "timestamp with time zone", + "primaryKey": false, + "notNull": true + }, + "count": { + "name": "count", + "type": "integer", + "primaryKey": false, + "notNull": true + } + }, + "indexes": { + "limit_counter_window_start_idx": { + "name": "limit_counter_window_start_idx", + "columns": [ + { + "expression": "window_start", + "isExpression": false, + "asc": true, + "nulls": "last" + } + ], + "isUnique": false, + "concurrently": false, + "method": "btree", + "with": {} + } + }, + "foreignKeys": {}, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "policies": {}, + "checkConstraints": {}, + "isRLSEnabled": false + }, + "public.roadmap_vote": { + "name": "roadmap_vote", + "schema": "", + "columns": { + "user_id": { + "name": "user_id", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "entry_id": { + "name": "entry_id", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "created_at": { + "name": "created_at", + "type": "timestamp with time zone", + "primaryKey": false, + "notNull": true, + "default": "now()" + } + }, + "indexes": { + "roadmap_vote_entry_idx": { + "name": "roadmap_vote_entry_idx", + "columns": [ + { + "expression": "entry_id", + "isExpression": false, + "asc": true, + "nulls": "last" + } + ], + "isUnique": false, + "concurrently": false, + "method": "btree", + "with": {} + } + }, + "foreignKeys": { + "roadmap_vote_user_id_user_id_fk": { + "name": "roadmap_vote_user_id_user_id_fk", + "tableFrom": "roadmap_vote", + "tableTo": "user", + "columnsFrom": [ + "user_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": { + "roadmap_vote_user_id_entry_id_pk": { + "name": "roadmap_vote_user_id_entry_id_pk", + "columns": [ + "user_id", + "entry_id" + ] + } + }, + "uniqueConstraints": {}, + "policies": {}, + "checkConstraints": {}, + "isRLSEnabled": false + }, + "public.share": { + "name": "share", + "schema": "", + "columns": { + "id": { + "name": "id", + "type": "text", + "primaryKey": true, + "notNull": true + }, + "user_id": { + "name": "user_id", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "kind": { + "name": "kind", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "mode": { + "name": "mode", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "conversation_id": { + "name": "conversation_id", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "card_id": { + "name": "card_id", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "title": { + "name": "title", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "data": { + "name": "data", + "type": "jsonb", + "primaryKey": false, + "notNull": true + }, + "created_at": { + "name": "created_at", + "type": "timestamp with time zone", + "primaryKey": false, + "notNull": true, + "default": "now()" + } + }, + "indexes": { + "share_user_idx": { + "name": "share_user_idx", + "columns": [ + { + "expression": "user_id", + "isExpression": false, + "asc": true, + "nulls": "last" + } + ], + "isUnique": false, + "concurrently": false, + "method": "btree", + "with": {} + } + }, + "foreignKeys": { + "share_user_id_user_id_fk": { + "name": "share_user_id_user_id_fk", + "tableFrom": "share", + "tableTo": "user", + "columnsFrom": [ + "user_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "policies": {}, + "checkConstraints": {}, + "isRLSEnabled": false + }, + "public.share_card_result": { + "name": "share_card_result", + "schema": "", + "columns": { + "share_id": { + "name": "share_id", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "card_id": { + "name": "card_id", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "status": { + "name": "status", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "card": { + "name": "card", + "type": "jsonb", + "primaryKey": false, + "notNull": false + }, + "frame": { + "name": "frame", + "type": "jsonb", + "primaryKey": false, + "notNull": false + }, + "code": { + "name": "code", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "retryable": { + "name": "retryable", + "type": "boolean", + "primaryKey": false, + "notNull": false + }, + "retry_after_s": { + "name": "retry_after_s", + "type": "integer", + "primaryKey": false, + "notNull": false + }, + "checked_at": { + "name": "checked_at", + "type": "timestamp with time zone", + "primaryKey": false, + "notNull": false + }, + "fresh_until": { + "name": "fresh_until", + "type": "timestamp with time zone", + "primaryKey": false, + "notNull": false + }, + "lease_until": { + "name": "lease_until", + "type": "timestamp with time zone", + "primaryKey": false, + "notNull": false + } + }, + "indexes": {}, + "foreignKeys": { + "share_card_result_share_id_share_id_fk": { + "name": "share_card_result_share_id_share_id_fk", + "tableFrom": "share_card_result", + "tableTo": "share", + "columnsFrom": [ + "share_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": { + "share_card_result_share_id_card_id_pk": { + "name": "share_card_result_share_id_card_id_pk", + "columns": [ + "share_id", + "card_id" + ] + } + }, + "uniqueConstraints": {}, + "policies": {}, + "checkConstraints": {}, + "isRLSEnabled": false + }, + "public.share_ref": { + "name": "share_ref", + "schema": "", + "columns": { + "share_id": { + "name": "share_id", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "part_index": { + "name": "part_index", + "type": "integer", + "primaryKey": false, + "notNull": true + }, + "spec_id": { + "name": "spec_id", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "identity": { + "name": "identity", + "type": "jsonb", + "primaryKey": false, + "notNull": true + }, + "entity_groups": { + "name": "entity_groups", + "type": "jsonb", + "primaryKey": false, + "notNull": false + }, + "variable_text": { + "name": "variable_text", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "content_version": { + "name": "content_version", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "artifact_digest": { + "name": "artifact_digest", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "operations": { + "name": "operations", + "type": "jsonb", + "primaryKey": false, + "notNull": true, + "default": "'[]'::jsonb" + }, + "assumptions": { + "name": "assumptions", + "type": "jsonb", + "primaryKey": false, + "notNull": false + } + }, + "indexes": {}, + "foreignKeys": { + "share_ref_share_id_share_id_fk": { + "name": "share_ref_share_id_share_id_fk", + "tableFrom": "share_ref", + "tableTo": "share", + "columnsFrom": [ + "share_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": { + "share_ref_share_id_part_index_pk": { + "name": "share_ref_share_id_part_index_pk", + "columns": [ + "share_id", + "part_index" + ] + } + }, + "uniqueConstraints": {}, + "policies": {}, + "checkConstraints": {}, + "isRLSEnabled": false + }, + "public.webmail_domain": { + "name": "webmail_domain", + "schema": "", + "columns": { + "domain": { + "name": "domain", + "type": "text", + "primaryKey": true, + "notNull": true + } + }, + "indexes": {}, + "foreignKeys": {}, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "policies": {}, + "checkConstraints": {}, + "isRLSEnabled": false + }, + "public.account": { + "name": "account", + "schema": "", + "columns": { + "id": { + "name": "id", + "type": "text", + "primaryKey": true, + "notNull": true + }, + "account_id": { + "name": "account_id", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "provider_id": { + "name": "provider_id", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "user_id": { + "name": "user_id", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "access_token": { + "name": "access_token", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "refresh_token": { + "name": "refresh_token", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "id_token": { + "name": "id_token", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "access_token_expires_at": { + "name": "access_token_expires_at", + "type": "timestamp", + "primaryKey": false, + "notNull": false + }, + "refresh_token_expires_at": { + "name": "refresh_token_expires_at", + "type": "timestamp", + "primaryKey": false, + "notNull": false + }, + "scope": { + "name": "scope", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "password": { + "name": "password", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "created_at": { + "name": "created_at", + "type": "timestamp", + "primaryKey": false, + "notNull": true, + "default": "now()" + }, + "updated_at": { + "name": "updated_at", + "type": "timestamp", + "primaryKey": false, + "notNull": true + } + }, + "indexes": { + "account_userId_idx": { + "name": "account_userId_idx", + "columns": [ + { + "expression": "user_id", + "isExpression": false, + "asc": true, + "nulls": "last" + } + ], + "isUnique": false, + "concurrently": false, + "method": "btree", + "with": {} + } + }, + "foreignKeys": { + "account_user_id_user_id_fk": { + "name": "account_user_id_user_id_fk", + "tableFrom": "account", + "tableTo": "user", + "columnsFrom": [ + "user_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "policies": {}, + "checkConstraints": {}, + "isRLSEnabled": false + }, + "public.session": { + "name": "session", + "schema": "", + "columns": { + "id": { + "name": "id", + "type": "text", + "primaryKey": true, + "notNull": true + }, + "expires_at": { + "name": "expires_at", + "type": "timestamp", + "primaryKey": false, + "notNull": true + }, + "token": { + "name": "token", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "created_at": { + "name": "created_at", + "type": "timestamp", + "primaryKey": false, + "notNull": true, + "default": "now()" + }, + "updated_at": { + "name": "updated_at", + "type": "timestamp", + "primaryKey": false, + "notNull": true + }, + "ip_address": { + "name": "ip_address", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "user_agent": { + "name": "user_agent", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "user_id": { + "name": "user_id", + "type": "text", + "primaryKey": false, + "notNull": true + } + }, + "indexes": { + "session_userId_idx": { + "name": "session_userId_idx", + "columns": [ + { + "expression": "user_id", + "isExpression": false, + "asc": true, + "nulls": "last" + } + ], + "isUnique": false, + "concurrently": false, + "method": "btree", + "with": {} + } + }, + "foreignKeys": { + "session_user_id_user_id_fk": { + "name": "session_user_id_user_id_fk", + "tableFrom": "session", + "tableTo": "user", + "columnsFrom": [ + "user_id" + ], + "columnsTo": [ + "id" + ], + "onDelete": "cascade", + "onUpdate": "no action" + } + }, + "compositePrimaryKeys": {}, + "uniqueConstraints": { + "session_token_unique": { + "name": "session_token_unique", + "nullsNotDistinct": false, + "columns": [ + "token" + ] + } + }, + "policies": {}, + "checkConstraints": {}, + "isRLSEnabled": false + }, + "public.user": { + "name": "user", + "schema": "", + "columns": { + "id": { + "name": "id", + "type": "text", + "primaryKey": true, + "notNull": true + }, + "name": { + "name": "name", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "email": { + "name": "email", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "email_verified": { + "name": "email_verified", + "type": "boolean", + "primaryKey": false, + "notNull": true, + "default": false + }, + "image": { + "name": "image", + "type": "text", + "primaryKey": false, + "notNull": false + }, + "created_at": { + "name": "created_at", + "type": "timestamp", + "primaryKey": false, + "notNull": true, + "default": "now()" + }, + "updated_at": { + "name": "updated_at", + "type": "timestamp", + "primaryKey": false, + "notNull": true, + "default": "now()" + } + }, + "indexes": {}, + "foreignKeys": {}, + "compositePrimaryKeys": {}, + "uniqueConstraints": { + "user_email_unique": { + "name": "user_email_unique", + "nullsNotDistinct": false, + "columns": [ + "email" + ] + } + }, + "policies": {}, + "checkConstraints": {}, + "isRLSEnabled": false + }, + "public.verification": { + "name": "verification", + "schema": "", + "columns": { + "id": { + "name": "id", + "type": "text", + "primaryKey": true, + "notNull": true + }, + "identifier": { + "name": "identifier", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "value": { + "name": "value", + "type": "text", + "primaryKey": false, + "notNull": true + }, + "expires_at": { + "name": "expires_at", + "type": "timestamp", + "primaryKey": false, + "notNull": true + }, + "created_at": { + "name": "created_at", + "type": "timestamp", + "primaryKey": false, + "notNull": true, + "default": "now()" + }, + "updated_at": { + "name": "updated_at", + "type": "timestamp", + "primaryKey": false, + "notNull": true, + "default": "now()" + } + }, + "indexes": { + "verification_identifier_idx": { + "name": "verification_identifier_idx", + "columns": [ + { + "expression": "identifier", + "isExpression": false, + "asc": true, + "nulls": "last" + } + ], + "isUnique": false, + "concurrently": false, + "method": "btree", + "with": {} + } + }, + "foreignKeys": {}, + "compositePrimaryKeys": {}, + "uniqueConstraints": {}, + "policies": {}, + "checkConstraints": {}, + "isRLSEnabled": false + } + }, + "enums": {}, + "schemas": {}, + "sequences": {}, + "roles": {}, + "policies": {}, + "views": {}, + "_meta": { + "columns": {}, + "schemas": {}, + "tables": {} + } +} \ No newline at end of file diff --git a/db/migrations/meta/_journal.json b/db/migrations/meta/_journal.json index 4121e67..31bc3a0 100644 --- a/db/migrations/meta/_journal.json +++ b/db/migrations/meta/_journal.json @@ -141,6 +141,13 @@ "when": 1792794247981, "tag": "0020_account_daily", "breakpoints": true + }, + { + "idx": 21, + "version": "7", + "when": 1792794347981, + "tag": "0021_account_daily_before_today", + "breakpoints": true } ] } \ No newline at end of file diff --git a/db/test/account-export.test.ts b/db/test/account-export.test.ts index bfeed53..7c010f7 100644 --- a/db/test/account-export.test.ts +++ b/db/test/account-export.test.ts @@ -9,6 +9,7 @@ import freeEmailDomains from 'free-email-domains'; import { Pool } from 'pg'; import { ACCOUNT_SCHEMA, + type AccountRead, type AccountRow, bigQueryAccountTable, readAccountDaily, @@ -120,8 +121,11 @@ test('the export reader reads accounts per UTC day and organisation, and not "us options: `-c TimeZone=${hour >= 12 ? 'Etc/GMT-14' : 'Etc/GMT+12'}`, }); + const { rows, accounts, webmailDomains } = await readAccountDaily(readerPool); + + assert.deepEqual({ accounts, webmailDomains }, { accounts: true, webmailDomains: true }); assert.deepEqual( - sorted(await readAccountDaily(readerPool)), + sorted(rows), sorted([ { day: day(4), organisation: 'Personal email', accounts: 1 }, { day: day(3), organisation: 'Other organisations', accounts: 2 }, @@ -138,6 +142,29 @@ test('the export reader reads accounts per UTC day and organisation, and not "us await assert.rejects(readerPool.query('select 1 from webmail_domain'), /permission denied/); }); +test('account_daily names a domain only once it holds 3 accounts before today', async (t) => { + const database = await createTestDatabase(); + t.after(() => database.teardown()); + + await migrate(database); + await database.runtimePool().query( + `insert into "user" (id, name, email, created_at) + select email, 'Name', email, (now() at time zone 'UTC')::date - back + from unnest(array['a@three.org', 'b@three.org', 'c@three.org'], array[2, 1, 0]) + as seed (email, back)`, + ); + + const { rows } = await readAccountDaily(database.adminPool()); + + assert.deepEqual( + rows.map(({ organisation, accounts }) => [organisation, accounts]), + [ + ['Other organisations', 1], + ['Other organisations', 1], + ], + ); +}); + test('account_daily holds no rows while webmail_domain is empty, and the export fails', async (t) => { const database = await createTestDatabase(); t.after(() => database.teardown()); @@ -165,11 +192,39 @@ test('account_daily holds no rows while webmail_domain is empty, and the export scratchFile: path.join(os.tmpdir(), `account-export-test-${process.pid}.ndjson`), log: () => {}, }), - /read no rows/, + /webmail_domain is empty/, ); assert.equal(replaced, false); }); +test('account_daily_source tells accounts only from today from an empty user table', async (t) => { + const cases: [string, string[], boolean][] = [ + ['an account today', ['a@one.org'], true], + ['no account', [], false], + ]; + + for (const [label, emails, accounts] of cases) { + await t.test(label, async (t) => { + const database = await createTestDatabase(); + t.after(() => database.teardown()); + + await migrate(database); + await database.runtimePool().query( + `insert into "user" (id, name, email, created_at) + select email, 'Name', email, now() at time zone 'UTC' + from unnest($1::text[]) as email`, + [emails], + ); + + assert.deepEqual(await readAccountDaily(database.adminPool()), { + rows: [], + accounts, + webmailDomains: true, + }); + }); + } +}); + test('syncWebmailDomains rewrites webmail_domain to the package list', async (t) => { const database = await createTestDatabase(); const admin = database.adminPool(); @@ -233,7 +288,7 @@ test('runAccountExport loads every row in one file and removes it', async () => const loaded: string[] = []; await runAccountExport({ - read: async () => ROWS, + read: async () => ({ rows: ROWS, accounts: true, webmailDomains: true }), replace: async (file) => { loaded.push(await fs.readFile(file, 'utf8')); }, @@ -253,19 +308,36 @@ test('runAccountExport loads every row in one file and removes it', async () => await assert.rejects(fs.access(scratchFile)); }); -test('runAccountExport rejects a read with no rows and keeps the table', async () => { - let replaced = false; +test('runAccountExport empties the table when every account is from today, and rejects other empty reads', async (t) => { + const cases: [string, Omit, RegExp | null][] = [ + ['every account from today', { accounts: true, webmailDomains: true }, null], + ['no account', { accounts: false, webmailDomains: true }, /read no accounts/], + [ + 'an empty webmail_domain', + { accounts: true, webmailDomains: false }, + /webmail_domain is empty/, + ], + ]; - await assert.rejects( - runAccountExport({ - read: async () => [], - replace: async () => { - replaced = true; - }, - scratchFile: path.join(os.tmpdir(), `account-export-test-${process.pid}.ndjson`), - log: () => {}, - }), - /read no rows/, - ); - assert.equal(replaced, false); + for (const [label, source, rejects] of cases) { + await t.test(label, async () => { + const loaded: string[] = []; + const run = runAccountExport({ + read: async () => ({ rows: [], ...source }), + replace: async (file) => { + loaded.push(await fs.readFile(file, 'utf8')); + }, + scratchFile: path.join(os.tmpdir(), `account-export-test-${process.pid}.ndjson`), + log: () => {}, + }); + + if (rejects === null) { + await run; + assert.deepEqual(loaded, ['']); + } else { + await assert.rejects(run, rejects); + assert.deepEqual(loaded, []); + } + }); + } }); diff --git a/db/test/event-export.test.ts b/db/test/event-export.test.ts index cc3616a..cd3abf2 100644 --- a/db/test/event-export.test.ts +++ b/db/test/event-export.test.ts @@ -9,11 +9,15 @@ import { Pool } from 'pg'; import { applyMigrations } from '../apply-migrations.ts'; import { bigQueryWarehouse, + EXPORT_SCHEMA, type EventSource, exportDays, + type ExportField, exportRow, + exportRules, pgEventSource, runExport, + runExportJob, type SourceEvent, type Warehouse, } from '../event-export.ts'; @@ -22,6 +26,7 @@ import { createTestDatabase } from './harness.ts'; const MIGRATIONS_FOLDER = path.resolve(import.meta.dirname, '../migrations'); const KEY = 'test-key'; +const RULES = exportRules(KEY); const sourceEvent = (overrides: Partial): SourceEvent => ({ id: 1, @@ -61,6 +66,7 @@ test('exportRow keeps allow-listed props that pass their rule and drops the rest }, }), KEY, + RULES, ); assert.deepEqual(row, { @@ -83,9 +89,15 @@ test('exportRow keeps allow-listed props that pass their rule and drops the rest timedOut: false, kind: 'resolution', }, + export_rules: RULES, }); }); +test('exportRules changes with the HMAC key', () => { + assert.equal(exportRules(KEY), RULES); + assert.notEqual(exportRules('rotated-key'), RULES); +}); + test('exportRow drops a value its rule refuses', async (t) => { const cases: [string, Record][] = [ [ @@ -102,13 +114,13 @@ test('exportRow drops a value its rule refuses', async (t) => { for (const [label, overrides] of cases) { await t.test(label, () => { - assert.deepEqual(exportRow(sourceEvent(overrides), KEY).props, {}); + assert.deepEqual(exportRow(sourceEvent(overrides), KEY, RULES).props, {}); }); } }); test('exportRow leaves the hashes null for a guest without consent', () => { - const row = exportRow(sourceEvent({ page: '/topics/health' }), KEY); + const row = exportRow(sourceEvent({ page: '/topics/health' }), KEY, RULES); assert.equal(row.signed_in, false); assert.equal(row.visitor_hash, null); @@ -140,7 +152,7 @@ test('exportRow keeps a site path as the page and refuses other text', async (t) for (const [label, page, kept] of cases) { await t.test(label, () => { - assert.equal(exportRow(sourceEvent({ page }), KEY).page, kept); + assert.equal(exportRow(sourceEvent({ page }), KEY, RULES).page, kept); }); } }); @@ -156,12 +168,17 @@ test('exportRow exports a share id as its digest, so share events still join', ( ]; for (const [name, props] of events) { - assert.equal(exportRow(sourceEvent({ name, props }), KEY).props.shareId, hashed, name); + assert.equal( + exportRow(sourceEvent({ name, props }), KEY, RULES).props.shareId, + hashed, + name, + ); } const refused = exportRow( sourceEvent({ name: 'share.open', props: { shareId: 'not a share id' } }), KEY, + RULES, ); assert.deepEqual(refused.props, {}); @@ -203,6 +220,16 @@ test('exportDays replaces from the day before the latest loaded day through toda }, ['2026-10-22', '2026-10-23'], ], + [ + 'days holding rows under other export rules', + { + today: '2026-10-23', + events: counts({ '2026-10-17': 1, '2026-10-20': 2, '2026-10-23': 1 }), + partitions: counts({ '2026-10-17': 1, '2026-10-20': 2, '2026-10-23': 1 }), + stale: new Set(['2026-10-17', '2026-10-20']), + }, + ['2026-10-17', '2026-10-20', '2026-10-22', '2026-10-23'], + ], [ 'a month boundary', { @@ -265,8 +292,15 @@ test('exportDays adds every earlier day whose counts differ', async (t) => { } }); -/** An in-memory warehouse. Each partition is the parsed lines of its last load. */ -const fakeWarehouse = (partitions: Map) => { +/** + * An in-memory warehouse. Each partition is the parsed lines of its last + * load, and a day is stale while any of its rows carries an `export_rules` + * other than the run's. A load of a day in `failLoad` throws. + */ +const fakeWarehouse = ( + partitions: Map, + { failLoad = [] }: { failLoad?: string[] } = {}, +) => { const calls: string[] = []; const warehouse: Warehouse = { async ensureTable() { @@ -275,7 +309,22 @@ const fakeWarehouse = (partitions: Map) => { async dayCounts() { return new Map([...partitions].map(([day, rows]) => [day, rows.length])); }, + async staleDays(rules) { + return new Set( + [...partitions] + .filter(([, rows]) => + rows.some( + (row) => (row as { export_rules?: string }).export_rules !== rules, + ), + ) + .map(([day]) => day), + ); + }, async replaceDay(day, file) { + if (failLoad.includes(day)) { + throw new Error('load job failed'); + } + calls.push(`replace ${day}`); const text = await fs.readFile(file, 'utf8'); partitions.set( @@ -293,7 +342,7 @@ const fakeWarehouse = (partitions: Map) => { const fakeSource = ( pages: Record, - failOn: string | null = null, + failOn: readonly string[] = [], // Source counts that differ from the rows a day reads. counted: Record = {}, ): EventSource => ({ @@ -310,7 +359,7 @@ const fakeSource = ( yield page; } - if (day === failOn) { + if (failOn.includes(day)) { throw new Error('connection lost'); } }, @@ -346,8 +395,11 @@ test('runExport backfills an empty table day by day and logs each day', async () logged.map((line) => line.slice(0, 10)), ['2026-10-20', '2026-10-21', '2026-10-22'], ); - assert.deepEqual(partitions.get('2026-10-20'), [exportRow(first, KEY), exportRow(second, KEY)]); - assert.deepEqual(partitions.get('2026-10-22'), [exportRow(third, KEY)]); + assert.deepEqual(partitions.get('2026-10-20'), [ + exportRow(first, KEY, RULES), + exportRow(second, KEY, RULES), + ]); + assert.deepEqual(partitions.get('2026-10-22'), [exportRow(third, KEY, RULES)]); await assert.rejects(fs.access(scratchFile)); }); @@ -411,7 +463,7 @@ test('runExport keeps a partition that holds more rows than the day reads', asyn assert.deepEqual(calls, ['ensureTable', 'replace 2026-10-23']); assert.equal(partitions.get('2026-10-22'), held); - assert.deepEqual(partitions.get('2026-10-23'), [exportRow(fresh, KEY)]); + assert.deepEqual(partitions.get('2026-10-23'), [exportRow(fresh, KEY, RULES)]); assert.deepEqual( logged.map((line) => line.slice(0, 10)), ['2026-10-21', '2026-10-22', '2026-10-23'], @@ -492,7 +544,7 @@ test('runExport rechecks an earlier day whose counts differ until they match', a const partitions = new Map( Object.entries(later).map(([day, dayPages]) => [ day, - dayPages.flat().map((row) => exportRow(row, KEY)), + dayPages.flat().map((row) => exportRow(row, KEY, RULES)), ]), ); @@ -502,7 +554,7 @@ test('runExport rechecks an earlier day whose counts differ until they match', a const { warehouse, calls } = fakeWarehouse(partitions); const run = runExport({ - source: fakeSource({ '2026-10-19': [read], ...later }, null, counted), + source: fakeSource({ '2026-10-19': [read], ...later }, [], counted), warehouse, hmacKey: KEY, today: '2026-10-23', @@ -519,61 +571,131 @@ test('runExport rechecks an earlier day whose counts differ until they match', a assert.deepEqual(calls, expectedCalls); assert.deepEqual( partitions.get('2026-10-23'), - later['2026-10-23']!.flat().map((row) => exportRow(row, KEY)), + later['2026-10-23']!.flat().map((row) => exportRow(row, KEY, RULES)), ); assert.deepEqual( partitions.get('2026-10-19'), calls.includes('replace 2026-10-19') - ? read.map((row) => exportRow(row, KEY)) + ? read.map((row) => exportRow(row, KEY, RULES)) : (held ?? undefined), ); }); } }); -test('runExport names the day it failed on and leaves that day as it was', async () => { +test('runExport loads the days after a failed one, then names every failed day', async () => { const kept = [{ id: 7 }]; const partitions = new Map([ ['2026-10-21', [{ id: 6 }]], ['2026-10-22', kept], ]); - const { warehouse, calls } = fakeWarehouse(partitions); - const fresh = sourceEvent({ id: 8, createdAt: '2026-10-21T10:00:00.000000Z' }); + const before = structuredClone(partitions); + const { warehouse, calls } = fakeWarehouse(partitions, { failLoad: ['2026-10-22'] }); + const fresh = sourceEvent({ id: 9, createdAt: '2026-10-23T10:00:00.000000Z' }); const scratchFile = scratch(); const logged: string[] = []; await assert.rejects( runExport({ source: fakeSource( - { '2026-10-21': [[fresh]], '2026-10-22': [[sourceEvent({ id: 9 })]] }, - '2026-10-22', + { + '2026-10-21': [[sourceEvent({ id: 6 })]], + '2026-10-22': [[sourceEvent({ id: 7 })]], + '2026-10-23': [[fresh]], + }, + ['2026-10-21'], ), warehouse, hmacKey: KEY, - today: '2026-10-22', + today: '2026-10-23', scratchFile, log: (line) => logged.push(line), }), (error: unknown) => { assert.ok(error instanceof Error); - assert.match(error.message, /^event export 2026-10-22: /); - assert.ok(error.cause instanceof Error); - assert.equal(error.cause.message, 'connection lost'); + assert.equal( + error.message, + 'event export 2026-10-21: connection lost; 2026-10-22: load job failed', + ); + assert.ok(error.cause instanceof AggregateError); + assert.deepEqual( + error.cause.errors.map((cause: Error) => cause.message), + ['connection lost', 'load job failed'], + ); return true; }, ); - assert.deepEqual(calls, ['ensureTable', 'replace 2026-10-21']); + assert.deepEqual(calls, ['ensureTable', 'replace 2026-10-23']); assert.deepEqual( logged.map((line) => line.slice(0, 10)), - ['2026-10-21'], + ['2026-10-21', '2026-10-22', '2026-10-23'], ); - assert.deepEqual(partitions.get('2026-10-21'), [exportRow(fresh, KEY)]); + assert.deepEqual(partitions.get('2026-10-21'), before.get('2026-10-21')); assert.equal(partitions.get('2026-10-22'), kept); + assert.deepEqual(partitions.get('2026-10-23'), [exportRow(fresh, KEY, RULES)]); await assert.rejects(fs.access(scratchFile)); }); -test('runExport names the short days read before the day it failed on', async () => { +test('runExport reloads the days holding rows under other rules, and retries a failed one alone', async () => { + const at = (id: number, day: string) => + sourceEvent({ id, createdAt: `${day}T10:00:00.000000Z` }); + const pages = Object.fromEntries( + ['2026-10-18', '2026-10-19', '2026-10-20', '2026-10-21', '2026-10-22'].map((day, i) => [ + day, + [[at(i + 1, day)]], + ]), + ); + // 18 and 20 October hold rows under old rules, 19 October under these. + const partitions = new Map( + Object.entries(pages).map(([day, dayPages]) => [ + day, + dayPages.flat().map((row) => ({ + ...exportRow(row, KEY, RULES), + ...(day === '2026-10-19' ? {} : { export_rules: 'old-rules' }), + })), + ]), + ); + const first = fakeWarehouse(partitions); + + await assert.rejects( + runExport({ + source: fakeSource(pages, ['2026-10-18']), + warehouse: first.warehouse, + hmacKey: KEY, + today: '2026-10-22', + scratchFile: scratch(), + log: () => undefined, + }), + /event export 2026-10-18: connection lost$/, + ); + assert.deepEqual(first.calls, [ + 'ensureTable', + 'replace 2026-10-20', + 'replace 2026-10-21', + 'replace 2026-10-22', + ]); + assert.deepEqual(partitions.get('2026-10-20'), [exportRow(at(3, '2026-10-20'), KEY, RULES)]); + + const second = fakeWarehouse(partitions); + + await runExport({ + source: fakeSource(pages), + warehouse: second.warehouse, + hmacKey: KEY, + today: '2026-10-22', + scratchFile: scratch(), + log: () => undefined, + }); + assert.deepEqual(second.calls, [ + 'ensureTable', + 'replace 2026-10-18', + 'replace 2026-10-21', + 'replace 2026-10-22', + ]); +}); + +test('runExport names the short days beside a failed day', async () => { const partitions = new Map([['2026-10-21', [{ id: 5 }, { id: 6 }]]]); const { warehouse, calls } = fakeWarehouse(partitions); @@ -584,7 +706,7 @@ test('runExport names the short days read before the day it failed on', async () '2026-10-21': [[sourceEvent({ id: 6 })]], '2026-10-22': [[sourceEvent({ id: 9 })]], }, - '2026-10-22', + ['2026-10-22'], ), warehouse, hmacKey: KEY, @@ -604,6 +726,46 @@ test('runExport names the short days read before the day it failed on', async () assert.equal(partitions.get('2026-10-21')?.length, 2); }); +test('runExport starts no new day past its budget and fails naming the days it did not reach', async () => { + const partitions = new Map(); + const { warehouse, calls } = fakeWarehouse(partitions, { failLoad: ['2026-10-21'] }); + const clock = { ms: 0 }; + const source = fakeSource({ + '2026-10-20': [[sourceEvent({ id: 1, createdAt: '2026-10-20T08:00:00.000000Z' })]], + '2026-10-21': [[sourceEvent({ id: 2, createdAt: '2026-10-21T08:00:00.000000Z' })]], + '2026-10-22': [[sourceEvent({ id: 3, createdAt: '2026-10-22T08:00:00.000000Z' })]], + '2026-10-23': [[sourceEvent({ id: 4, createdAt: '2026-10-23T08:00:00.000000Z' })]], + }); + + await assert.rejects( + runExport({ + source: { + ...source, + // Each day read costs 4 minutes of the injected clock. + readDay: (day) => { + clock.ms += 240_000; + return source.readDay(day); + }, + }, + warehouse, + hmacKey: KEY, + today: '2026-10-23', + scratchFile: scratch(), + log: () => undefined, + budgetMs: 600_000, + now: () => clock.ms, + }), + (error: unknown) => { + assert.ok(error instanceof Error); + assert.match(error.message, /2026-10-21: load job failed/); + assert.match(error.message, /not reached\D+10 minute budget: 2026-10-23$/); + return true; + }, + ); + + assert.deepEqual(calls, ['ensureTable', 'replace 2026-10-20', 'replace 2026-10-22']); +}); + test('bigQueryWarehouse loads a day into its partition and lets the schema gain columns', async () => { const loads: { table: string; file: string; metadata: Record }[] = []; const fake = { @@ -631,11 +793,136 @@ test('bigQueryWarehouse loads a day into its partition and lets the schema gain assert.deepEqual(loads[0]?.metadata.schemaUpdateOptions, ['ALLOW_FIELD_ADDITION']); }); +test('EXPORT_SCHEMA admits a REQUIRED column only among those the table was created with', () => { + // @ts-expect-error ALLOW_FIELD_ADDITION adds NULLABLE columns only. + const required: ExportField = { name: 'added', type: 'STRING', mode: 'REQUIRED' }; + const nullable: ExportField = { name: 'added', type: 'STRING' }; + + assert.ok(required && nullable); +}); + +test('bigQueryWarehouse creates the table, finds stale days and counts from partition metadata', async (t) => { + const fakeTable = ({ exists, fields = [] }: { exists: boolean; fields?: string[] }) => { + const calls: unknown[] = []; + const table = { + exists: async () => [exists], + getMetadata: async () => [{ schema: { fields: fields.map((name) => ({ name })) } }], + }; + const bigquery = { + dataset: () => ({ + table: () => table, + createTable: async (name: string, options: { schema: unknown }) => { + calls.push(['createTable', name, options.schema]); + return [table]; + }, + }), + query: async ({ query, params }: { query: string; params?: unknown }) => { + calls.push(['query', params]); + return query.includes('PARTITIONS') + ? [ + [ + { partition_id: '20261021', total_rows: 3 }, + { partition_id: '20261022', total_rows: '1434' }, + ], + ] + : [[{ day: '2026-10-21' }]]; + }, + }; + const warehouse = bigQueryWarehouse({ + projectId: 'p', + datasetId: 'd', + bigquery: bigquery as unknown as BigQuery, + }); + + return { warehouse, calls }; + }; + + await t.test('a missing table is created with the schema', async () => { + const { warehouse, calls } = fakeTable({ exists: false }); + + await warehouse.ensureTable(); + assert.deepEqual(calls, [['createTable', 'event', { fields: EXPORT_SCHEMA }]]); + }); + + await t.test('staleDays queries the days whose rows carry other rules', async () => { + const { warehouse, calls } = fakeTable({ exists: true, fields: ['id', 'export_rules'] }); + + assert.deepEqual(await warehouse.staleDays('r1'), new Set(['2026-10-21'])); + assert.deepEqual(calls, [['query', { rules: 'r1' }]]); + }); + + await t.test('a table without export_rules is stale on every day', async () => { + assert.deepEqual( + await fakeTable({ exists: true, fields: ['id'] }).warehouse.staleDays('r1'), + new Set(['2026-10-21', '2026-10-22']), + ); + }); + + await t.test('a query over the bytes-billed cap fails naming the cap', async () => { + const bigquery = { + dataset: () => ({ + table: () => ({ + getMetadata: async () => [{ schema: { fields: [{ name: 'export_rules' }] } }], + }), + }), + query: async () => { + throw new Error('Query exceeded limit for bytes billed: 1000000000.'); + }, + }; + const warehouse = bigQueryWarehouse({ + projectId: 'p', + datasetId: 'd', + bigquery: bigquery as unknown as BigQuery, + }); + + await assert.rejects(warehouse.staleDays('r1'), /maximumBytesBilled cap/); + }); + + await t.test('dayCounts reads each partition_id as its day', async () => { + assert.deepEqual( + await fakeTable({ exists: true }).warehouse.dayCounts(), + new Map([ + ['2026-10-21', 3], + ['2026-10-22', 1434], + ]), + ); + }); +}); + +test('runExportJob runs the event export after a failed account export, then fails', async () => { + const ran: string[] = []; + const logged: unknown[] = []; + const accountError = new Error('bigquery down'); + + await assert.rejects( + runExportJob({ + exportAccounts: async () => { + ran.push('accounts'); + throw accountError; + }, + exportEvents: async () => { + ran.push('events'); + }, + logError: (error) => logged.push(error), + }), + (error: unknown) => { + assert.ok(error instanceof Error); + assert.equal(error.cause, accountError); + return true; + }, + ); + + assert.deepEqual(ran, ['accounts', 'events']); + assert.deepEqual(logged, [accountError]); +}); + /** * Reads a migrated database as a login member of `website_export_reader`, * the way the Job's IAM user reads it, and checks each UTC day's rows * against Postgres's own per-day count. The page size is 2, so every day - * spans pages, and rows sit either side of a midnight. + * spans pages, rows sit either side of a midnight, three rows share one + * time across a page boundary, and each row's props hold a key no event + * keeps. */ test('the export reader reads every row of each UTC day and no other table', async (t) => { const database = await createTestDatabase(); @@ -661,7 +948,8 @@ test('the export reader reads every row of each UTC day and no other table', asy ); await database.runtimePool().query( `insert into event (name, created_at, user_id, visitor_id, page, props) - select 'search.query', ts::timestamptz, null, 'v', '/data', '{"post": 0}' + select 'search.query', ts::timestamptz, null, 'v', '/data', + '{"post": 0, "query": "aid to kenya"}' from unnest($1::text[]) ts`, [ [ @@ -671,8 +959,8 @@ test('the export reader reads every row of each UTC day and no other table', asy '2026-10-20T23:59:59.999999Z', '2026-10-21T00:00:00.000001Z', '2026-10-22T05:00:00Z', - '2026-10-22T06:00:00Z', - '2026-10-22T07:00:00Z', + '2026-10-22T05:00:00Z', + '2026-10-22T05:00:00Z', ], ], ); @@ -693,19 +981,24 @@ test('the export reader reads every row of each UTC day and no other table', asy from event group by 1 order by 1`, ); const read: { day: string; count: number }[] = []; + const ids: number[] = []; for (const { day } of expected) { let count = 0; for await (const page of source.readDay(day)) { assert.ok(page.every((row) => row.createdAt.startsWith(day))); + assert.ok(page.every((row) => Object.keys(row.props).join() === 'post')); count += page.length; + ids.push(...page.map((row) => row.id)); } read.push({ day, count }); } assert.deepEqual(read, expected); + // The three rows that share 05:00 on 22 October span two pages. + assert.deepEqual(ids, [1, 2, 3, 4, 5, 6, 7, 8]); assert.deepEqual( expected.map(({ count }) => count), [1, 3, 1, 3], diff --git a/deploy/README.md b/deploy/README.md index 937cfaa..36ebeb3 100644 --- a/deploy/README.md +++ b/deploy/README.md @@ -71,54 +71,27 @@ migration. ## Event export -In production a Cloud Run Job, `dfo-prod-website-export`, copies the -`event` table into the BigQuery table `event` in `EXPORT_BQ_DATASET` -(`website_export`) every hour. It runs the website image with the command -`node dist/export-events.cjs` (`db/export-events.ts`, bundled by -`pnpm build:export-events`). `build-migrate-deploy.yml` points it at each -new image after the service update, only where `EXPORT_JOB_WEBSITE` is -set. infra defines the Job, its identity, the dataset and the schedule. - -The Job reads the database as its own IAM user, a member of the NOLOGIN -role `website_export_reader`, which migration `0019_event_export_grant` -grants `SELECT` on `event` and migration `0020_account_daily` on the view -`account_daily`, and on nothing else. infra creates the role in every tier, -so its apply must land before the deploy that first carries the migration. - -| Env var | What it is | -| --------------------------------------------------------------------------- | ------------------------------------------------------------ | -| `WEBSITE_DB_INSTANCE_CONNECTION_NAME`, `WEBSITE_DB_NAME`, `WEBSITE_DB_USER` | The database as the service reads it, `DATABASE_URL` locally | -| `EXPORT_BQ_PROJECT` | The BigQuery project | -| `EXPORT_BQ_DATASET` | The BigQuery dataset | -| `EXPORT_ID_HMAC_KEY` | Key for the visitor and user id digests | - -Each run replaces every UTC day from the latest day in the table minus one -through today, so a missed run is made up by the next one. When the table -is empty or missing, the Job creates it and loads every day from the first -event. The run also replaces every earlier day whose count of `event` rows -differs from its partition's row count. It takes both counts per day up -front, one `GROUP BY` over the whole `event` table and one over the -BigQuery table's `created_at` column. Each day is read in pages into a -scratch file, then loaded into its partition (`event$YYYYMMDD`, -`WRITE_TRUNCATE`, `ALLOW_FIELD_ADDITION`, so a column added to the schema -reaches the table on the next load). A replace never shrinks a partition. -Nothing deletes `event` rows, and they carry no foreign key to `user`, so -deleting an account leaves them in place. A day that reads fewer rows than -its partition holds is therefore a fault, such as a wrong database, an -emptied table or a lagging replica. That day keeps its partition, the -other days still load, and the run then fails naming each short day with -both counts, as it does for a day that reads fewer rows than its source -count from the start of the run, whatever its partition holds. Its counts -still differ, so the day stays in every later run, however many later days -load, and fails each one until it matches. The Job's failure alert -therefore fires on every run until the export is complete. A day that -reads no rows and holds none loads nothing. The Job logs each day as it -finishes. A failure names the day it failed on and any short day before -it, and that day keeps its partition as it was. A database query that runs -past 5 minutes fails the run (`statement_timeout` on the Job's pool), and -so does a BigQuery count job that bills more than 1 GB, about 125 million -rows, or runs past 2 minutes (`maximumBytesBilled` and `jobTimeoutMs`), -all well inside the Job's 1800 s task timeout. +In production a Cloud Run Job, `dfo-prod-website-export`, copies the `event` table into the BigQuery table `event` in `EXPORT_BQ_DATASET` (`website_export`) every hour. It runs the website image with the command `node dist/export-events.cjs` (`db/export-events.ts`, bundled by `pnpm build:export-events`). `build-migrate-deploy.yml` points it at each new image after the service update, only where `EXPORT_JOB_WEBSITE` is set. infra defines the Job, its identity, the dataset and the schedule. + +The Job reads the database as its own IAM user, a member of the NOLOGIN role `website_export_reader`, which migration `0019_event_export_grant` grants `SELECT` on `event`, migration `0020_account_daily` on the view `account_daily`, and migration `0021_account_daily_before_today` on the view `account_daily_source`, and on nothing else. infra creates the role in every tier, so its apply must land before the deploy that first carries the migration. + +| Env var | What it is | +| -------------------------------------------------------- | ------------------------------------------------------------------------- | +| `WEBSITE_DB_INSTANCE_CONNECTION_NAME`, `WEBSITE_DB_NAME` | The database the Job reads, `DATABASE_URL` locally | +| `WEBSITE_DB_USER` | The exporter's own IAM database user, a member of `website_export_reader` | +| `EXPORT_BQ_PROJECT` | The BigQuery project | +| `EXPORT_BQ_DATASET` | The BigQuery dataset | +| `EXPORT_ID_HMAC_KEY` | Key for the visitor and user id digests | + +Each run replaces every UTC day from the latest day in the table minus one through today, so a missed run is made up by the next one. When the table is empty or missing, the Job creates it and loads every day from the first event. The run also replaces every earlier day whose count of `event` rows differs from its partition's row count. It takes both counts per day up front, one `GROUP BY` over the whole `event` table and the partitions' row counts from the dataset's `INFORMATION_SCHEMA.PARTITIONS`, which reads table metadata and scans no rows. Each day is read in pages, in `created_at` and id order with each page starting after the last row of the one before, and only with the prop keys `PROP_RULES` keeps. The pages go to a scratch file, then load into the day's partition (`event$YYYYMMDD`, `WRITE_TRUNCATE`, `ALLOW_FIELD_ADDITION`). A load adds a new NULLABLE column to the table, and fails on a new REQUIRED one, so `ExportField` in `db/event-export.ts` lets a column be REQUIRED only if the table was created with it. + +The scratch file sits in `os.tmpdir()`, which on Cloud Run is in memory, so a run holds one page of rows plus one day's file, about 360 bytes an event. The busiest day so far holds 1,434 events, about 0.5 MB, against the Job's 512 MiB. The file is written in full before its load starts, so a day loads only once it has been read to its end. + +A replace never shrinks a partition. Nothing deletes `event` rows, and they carry no foreign key to `user`, so deleting an account leaves them in place. A day that reads fewer rows than its partition holds is therefore a fault, such as a wrong database, an emptied table or a lagging replica. That day keeps its partition, the other days still load, and the run then fails naming each short day with both counts, as it does for a day that reads fewer rows than its source count from the start of the run, whatever its partition holds. Its counts still differ, so the day stays in every later run, however many later days load, and fails each one until it matches. The Job's failure alert therefore fires on every run until the export is complete. A day that reads no rows and holds none loads nothing. + +A day whose read or load fails keeps its partition as it was, and the later days still load. The run then fails naming every such day with its error, and any short day. The Job logs each day as it finishes. A database query that runs past 5 minutes fails its day (`statement_timeout` on the Job's pool); a query that fails outside a day's read, such as the per-day count, fails the run. A BigQuery query that bills more than 1 GB or runs past 2 minutes fails the run (`maximumBytesBilled` and `jobTimeoutMs`). The stale-day query scans about 74 bytes an event row, so it reaches the 1 GB cap at about 13.5 million rows, and the run then fails with an error naming the cap. Days that each wait out a 5 minute timeout could outlast the Job's 1800 s task timeout, so a run starts no new day once 20 minutes have passed since it began (`EXPORT_BUDGET_MS` in `db/event-export.ts`). It finishes the day in hand, then fails naming every day it did not reach, with any failed or short day, and the next run picks those days up. + +Every row carries in `export_rules` a digest of what shapes it (`exportRules` in `db/event-export.ts`): `PROP_RULES`, `PAGE_PATH`, `SHARE_PATH`, the token rule, the schema, `ROW_SHAPE_VERSION` and an HMAC of a fixed string under `EXPORT_ID_HMAC_KEY`. `ROW_SHAPE_VERSION` is bumped by hand with any change to the functions that build a row. Each run finds the days holding a row with another digest, or none, in one query over the `created_at` and `export_rules` columns, and replaces those days too. A change to the rules or the key thus reaches every partition. A day that fails keeps its old rows, so the next run retries it with the window days and the count-mismatch days, and reloads no day that is already current. The table is partitioned by day on `created_at`: @@ -132,35 +105,15 @@ The table is partitioned by day on `created_at`: | `visitor_hash` | STRING | HMAC-SHA256 hex of `visitor_id`, null without one | | `user_hash` | STRING | HMAC-SHA256 hex of `user_id`, null without one | | `props` | JSON | the event's allow-listed props, `shareId` as its HMAC-SHA256 hex | +| `export_rules` | STRING | the digest of the rules the row was exported under | -`page` keeps a path only when it is a slash followed by letters, digits -and `_ - . : /`, up to 300 characters, the characters the site's routes -use (`PAGE_PATH` in `db/event-export.ts`). Any other text the browser -posts as its page exports as null. The id in `/s/`, `/embed/` and -the pages under them exports as `:id`, since a share id opens its share. - -`PROP_RULES` in `db/event-export.ts` lists the props each event keeps: -enums, booleans, counts and ids, each checked against its rule, since the -browser posts its own props. Search query text, refused terms, card units -and every list or nested object stay in Postgres. `shareId` exports as -its HMAC-SHA256 hex under `EXPORT_ID_HMAC_KEY`, so share, embed and -search events still join on it. A new event name fails -the typecheck until it has an entry there. Changing `EXPORT_ID_HMAC_KEY` -changes every digest, so drop the BigQuery table afterwards and let the -next run reload it. +`page` keeps a path only when it is a slash followed by letters, digits and `_ - . : /`, up to 300 characters, the characters the site's routes use (`PAGE_PATH` in `db/event-export.ts`). Any other text the browser posts as its page exports as null. The id in `/s/`, `/embed/` and the pages under them exports as `:id`, since a share id opens its share. + +`PROP_RULES` in `db/event-export.ts` lists the props each event keeps: enums, booleans, counts and ids, each checked against its rule, since the browser posts its own props. Search query text, refused terms, card units and every list or nested object stay in Postgres. `shareId` exports as its HMAC-SHA256 hex under `EXPORT_ID_HMAC_KEY`, so share, embed and search events still join on it. A new event name fails the typecheck until it has an entry there. Changing `EXPORT_ID_HMAC_KEY` changes every digest and the rules digest with them, so the next run reloads every day. ### Accounts -Each run first replaces the BigQuery table `account_daily` with every row -of the Postgres view `account_daily` (`db/account-export.ts`), in one -`WRITE_TRUNCATE` load job, so a failed run leaves the previous table. The -event export still runs when it fails, and the run then fails too. A read -with no rows fails the run and keeps the table. The view runs with the -migrator's rights, so the Job reads accounts per day and organisation and -no email address or user id. It holds every UTC day from the first -account's through yesterday's, so the latest day is the last complete -one, and a day without new accounts is one row with a null `organisation` -and 0 `accounts`. +Each run first replaces the BigQuery table `account_daily` with every row of the Postgres view `account_daily` (`db/account-export.ts`), in one `WRITE_TRUNCATE` load job, so a failed run leaves the previous table. The event export still runs when it fails, and the run then fails too. The view runs with the migrator's rights, so the Job reads accounts per day and organisation and no email address or user id. It holds every UTC day from the first account's through yesterday's, so the latest day is the last complete one, and a day without new accounts is one row with a null `organisation` and 0 `accounts`. It counts only the accounts created before today, UTC, so a domain it names holds at least 3 of the accounts the export carries. | Column | Type | Value | | -------------- | ------ | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | @@ -168,13 +121,9 @@ and 0 `accounts`. | `organisation` | STRING | `Personal email` for a webmail domain, else the lower-cased domain after the last `@` once it holds at least 3 accounts, else `Other organisations`; null on a day without new accounts, whose one row has 0 accounts | | `accounts` | INT64 | the accounts created that day, 0 on a day without new accounts | -A domain in `webmail_domain` is `Personal email` whatever its count. The -view holds no rows while that table is empty, so the run fails and keeps -the BigQuery table. The table holds the `free-email-domains` package's -list, which `db/migrate.ts` -writes after the migrations on every deploy, so bumping the package -updates it. pnpm skips the package's postinstall script, which would -refetch the list. +A domain in `webmail_domain` is `Personal email` whatever its count. The table holds the `free-email-domains` package's list, which `db/migrate.ts` writes after the migrations on every deploy, so bumping the package updates it. pnpm skips the package's postinstall script, which would refetch the list. + +A read with no rows fails the run and leaves the table as it was while `webmail_domain` is empty, since the view then holds no rows and webmail domains would show by name, and while the user table holds no account, which is a wrong database or an emptied table. When accounts exist and every one is from today, the run replaces the table with no rows, so a deleted account and the organisation it named leave the export. The view `account_daily_source` tells the cases apart, and the Job reads it in the same transaction as `account_daily`. ## GitHub vars and secrets From 1d34ca83b2b11d3c05b2750a720368528b1aa8dc Mon Sep 17 00:00:00 2001 From: Jorge Rivera Date: Sat, 24 Oct 2026 14:17:13 +0200 Subject: [PATCH 4/6] fix(analytics): write one request line per request, closed or finished (#61) registerRequestLogging attaches one close listener per response, so a request writes exactly one line with a finished flag, and a response that closes before the app sends a status logs 499. The path is the request target as it arrived, normalised without reading // as a host. A document prerender is kind page with a prerender flag. Static assets are dropped before the caller HMAC is computed. docs/analytics.md describes the line and the account and event export rules. --- docs/analytics.md | 10 +- src/lib/proxy/requestLog.ts | 229 ++++++++++++----- src/lib/proxy/test/requestLog.test.ts | 349 ++++++++++++++++++++++---- 3 files changed, 466 insertions(+), 122 deletions(-) diff --git a/docs/analytics.md b/docs/analytics.md index a81c71e..3a00f84 100644 --- a/docs/analytics.md +++ b/docs/analytics.md @@ -61,13 +61,15 @@ When `POSTHOG_KEY` and `POSTHOG_HOST` are set, `track()` also forwards each even A resolved part records what the question asked for, and counts the StatVars and places it expanded to: an aid query expands to hundreds of each, which would pass the 8 KB cap. A role asked for as a named group, such as the European Union, records the group, three of its members and the member count. A set-valued filter with more than three refs records three and the count. `sources` lists every source id while the whole event fits the cap, and the first three per part when it does not; `sourceCount` is always the full number, so a list shorter than the count is a sample. The run and settle fields stay on every form, and the floor drops only `byStep`. If the event still exceeds the cap, each resolved part keeps only `specId`, `measure`, `statVarCount`, `entityCount`, `sourceCount` and the per-role place `count`, and the event carries `truncated: true`. If that form is still too large, the event ends on a fixed-size floor: an empty `query`, no refused parts, and per resolved part only a clipped `specId` and the integer counts. The ladder runs on the complete props, `seeds` included, and measures the JSON length as the route does; the API's limit of six parts bounds the floor. -In production the `dfo-prod-website-export` Cloud Run Job (`db/export-events.ts`) copies the table every hour into the BigQuery table `event` in the `website_export` dataset, one partition per UTC day of `created_at`. Each run replaces every day from the latest loaded day minus one through today, plus any earlier day whose row count differs from its partition's, so a day that failed to load is retried until it matches. The copy hashes `visitor_id`, `user_id` and the `shareId` prop, keeps `page` only as a site path without its query string and with share ids written `:id`, and keeps only the props `PROP_RULES` in `db/event-export.ts` allows, so it holds no search text. `deploy/README.md` ("Event export") has the schema. Questions about the text itself stay in Postgres, e.g. the most-requested measures: +In production the `dfo-prod-website-export` Cloud Run Job (`db/export-events.ts`) copies the table every hour into the BigQuery table `event` in the `website_export` dataset, one partition per UTC day of `created_at`. Each run replaces every day from the latest loaded day minus one through today, plus any earlier day whose row count differs from its partition's, so a day that failed to load is retried until it matches, plus every day holding a row whose `export_rules` digest differs from the current one, so a change to the export rules or the hashing key reaches every partition already loaded. The copy hashes `visitor_id`, `user_id` and the `shareId` prop, keeps `page` only as a site path without its query string and with share ids written `:id`, and keeps only the props `PROP_RULES` in `db/event-export.ts` allows, so it holds no search text. `deploy/README.md` ("Event export") has the schema. Questions about the text itself stay in Postgres, e.g. the most-requested measures: ```sql select r->'measure' as measure, count(*) from event, jsonb_array_elements(props->'resolved') r where name = 'search.query' group by 1 order by 2 desc limit 20; ``` +The same Job first copies the Postgres view `account_daily` (`db/account-export.ts`) into the BigQuery table `account_daily` in the same dataset, replacing the whole table in one load job, so a failed run leaves the previous table. The view counts new accounts per UTC day and organisation, as `day`, `organisation` and `accounts`, from the first account's day through yesterday, so every day it holds is complete. An organisation is the lower-cased email domain once the domain holds at least 3 accounts, counting the accounts created through yesterday; `Personal email` for a webmail domain, whatever its count; and `Other organisations` for any other domain, so a domain with fewer than 3 accounts never shows by name. A day without new accounts is one row with a null `organisation` and 0 `accounts`. The table holds no email address and no user id. `deploy/README.md` ("Accounts") has the schema. + ## Sentry `@sentry/nextjs` on both sides: `instrumentation-client.ts` (browser), `sentry.server.config.ts` / `sentry.edge.config.ts` loaded from `src/instrumentation.ts`, `src/app/global-error.tsx` for a crash in the root layout. Everything is off without `NEXT_PUBLIC_SENTRY_DSN`. `sendDefaultPii` is false and there is no session replay, so it needs no cookie consent. @@ -92,13 +94,13 @@ To check it on production, open the network panel and filter on `google-analytic ## Request log -The site writes one JSON line to stdout for each request whose response completes, which Cloud Logging stores as a structured entry. `src/instrumentation.ts` registers `registerRequestLogging()` in `src/lib/proxy/requestLog.ts` at server startup. It observes Node's `http.server.response.finish` diagnostic channel and writes the line when the response finishes, from the request's method, path and headers and the response's status code. A request accepted during startup is logged too, since its response finishes after registration. A page render the visitor abandons, an `/mcp` event stream the client closes, and any connection closed before the response ends write no line. Visitor counts come from this line, because Cloud Run's own request log records Cloudflare's edge address as the client. +The site writes one JSON line to stdout for each logged request, which Cloud Logging stores as a structured entry. `src/instrumentation.ts` registers `registerRequestLogging()` in `src/lib/proxy/requestLog.ts` at server startup. It subscribes to Node's `http.server.request.start` diagnostic channel and attaches one `close` listener to each response. Node emits `close` after `finish`, so every request writes exactly one line, when its response closes, with `finished` true for a response that ended normally. A response that closes before it ends, such as a page render the visitor abandons, an aborted RSC fetch or an `/mcp` event stream the client closes, writes its line then, with the status code it had sent. A request accepted before the subscription starts has no listener, so its line is written when its response finishes. Visitor counts come from this line, because Cloud Run's own request log records Cloudflare's edge address as the client. ```json -{"severity":"INFO","message":"request","caller":"ip:3f9c0a…","method":"GET","path":"/embed/abc123","host":"developmentfinance.org","kind":"page","status":200,"bot":false} +{"severity":"INFO","message":"request","caller":"ip:3f9c0a…","method":"GET","path":"/embed/abc123","host":"developmentfinance.org","kind":"page","status":200,"finished":true,"bot":false,"prerender":false} ``` -`caller` is the same `ip:` the `/mcp` proxy sends upstream as `x-dfo-caller` (`src/lib/proxy/caller.ts`): an HMAC of the client address under `CALLER_HMAC_KEY`, with the address taken from `X-Forwarded-For` at the `TRUSTED_PROXY_HOPS` position. It is null when the key is unset or the request carries no usable address. `kind` is `page`, `api` (`/api` and `/mcp`), `rsc` (a client-side navigation) or `prefetch` (a Next.js or browser prefetch). Embeds under `/embed/` are logged as pages. `/_next/` files, images and fonts are not logged. `status` is the response's HTTP status code. `bot` is true when the `User-Agent` header is missing or empty, or when the `isbot` package flags it: crawlers such as Googlebot, bingbot and ClaudeBot, link previews such as Slack's and Discord's, headless browsers and tools such as curl. A client that sends a browser's user agent counts as a reader. The line holds no raw IP address, query string, cookie, `Authorization` header or user agent. +`caller` is the same `ip:` the `/mcp` proxy sends upstream as `x-dfo-caller` (`src/lib/proxy/caller.ts`): an HMAC of the client address under `CALLER_HMAC_KEY`, with the address taken from `X-Forwarded-For` at the `TRUSTED_PROXY_HOPS` position. It is null when the key is unset or the request carries no usable address. `path` is the request target as it arrived, captured when the request starts so a later rewrite does not change it. It has no query string or fragment, and dot segments are resolved, so `/a/../mcp` is logged as `/mcp`. A target such as `//mcp` is a path and not a host, and is logged as `//mcp`. An absolute-form target such as `http://host/path` is logged as its pathname, and an absolute-form target whose URL does not parse is logged as the raw target cut at its first `?` or `#`. The asterisk-form target of `OPTIONS *` is logged as `*`, with kind `page`. `kind` is `api` for `/api`, `/mcp`, `/openapi.json` and `/codes` and every path below each of them (`/apiary` is not one). That covers the site's own endpoints under `/api`, such as auth, events and share, as well as the platform proxy's routes. `kind` is `prefetch` for a Next.js prefetch (`Next-Router-Prefetch`) or a browser prefetch (`Sec-Purpose: prefetch`), `rsc` for a client-side navigation (`RSC: 1`) and `page` for everything else. A `Sec-Purpose` header does not change the kind of an RSC fetch or a Next.js prefetch. Embeds under `/embed/` are logged as pages. `/_next/` files, images and fonts are not logged, and are dropped before the line's headers are read or its caller computed. `status` is the response's HTTP status code. `finished` is true when the response ended normally and false when it closed first, so a status of 200 with `finished` false is a visitor who left a stream. A response that closes before the app sent a status has none of its own, so the line carries 499 (client closed request) with `finished` false. The 499 means the app sent no status before the connection closed. It also covers a response Node answered itself, such as a 408 on a request timeout or a 400 on a client error, which never passes through the app. A response that called `writeHead` but wrote nothing to the socket before the close is logged with that status and `finished` false. Infra's parse keeps the line and counts it as a 4xx, outside the readers' 2xx count. Infra's `website_requests_daily` counts a line whose response did not finish like a finished one. `prerender` is true for a document request (no `RSC` and no `Next-Router-Prefetch` header) with `Sec-Purpose: prefetch;prerender`: the browser renders the page ahead of time and shows it on activation with no second request, so that one line is the page view. It has kind `page` and not `prefetch`, which keeps infra's `website_requests_daily` counting it as a parsed page request. The line is a page view whether or not the visitor opens the page, because the server cannot see activation. `bot` is true when the `User-Agent` header is missing or empty, or when the `isbot` package flags it: crawlers such as Googlebot, bingbot and ClaudeBot, link previews such as Slack's and Discord's, headless browsers and tools such as curl. A client that sends a browser's user agent counts as a reader. The line holds no raw IP address, query string, cookie, `Authorization` header or user agent. The line reads the request's raw headers, which keep the `RSC` and `Next-Router-Prefetch` headers that Next.js removes from `request.headers`. Logging leaves request bodies unread, so API and MCP payloads stream to their handlers in full. A Next.js proxy would buffer those bodies and truncate them at its default 10 MB limit. diff --git a/src/lib/proxy/requestLog.ts b/src/lib/proxy/requestLog.ts index 25bbb05..b83b704 100644 --- a/src/lib/proxy/requestLog.ts +++ b/src/lib/proxy/requestLog.ts @@ -7,15 +7,23 @@ import { requestCaller } from './caller.ts'; /** * One JSON line on stdout per visitor request, written when its response - * finishes, so Cloud Logging can count visitors by caller. Cloud Run's own - * request log records Cloudflare's edge address, so it cannot. A response - * that never finishes, such as an abandoned page render or an `/mcp` event - * stream the client closes, writes no line. + * closes, so Cloud Logging can count visitors by caller. Cloud Run's own + * request log records Cloudflare's edge address, so it cannot. Node emits + * `close` after `finish`, so a response that ends normally writes its line + * there with `finished` true. A response that closes before it finishes, such + * as an abandoned page render or an `/mcp` event stream the client closes, + * writes it with `finished` false. Its `status` is the one already sent, or + * 499 (client closed request) when the app sent no status before the + * connection closed. * - * `caller` is the same `ip:` the /mcp proxy sends as x-dfo-caller - * (see caller.ts). `status` is the response's status code. `bot` is true - * when the User-Agent header is missing, empty or one isbot flags. The line - * holds no raw address, query string, cookie, auth header or user agent. + * `path` is the request target as it arrived at `http.server.request.start`, + * without its query string, with dot segments resolved. `caller` is the + * same `ip:` the /mcp proxy sends as x-dfo-caller (see caller.ts). + * `bot` is true when the User-Agent header is missing, empty or one isbot + * flags. `prerender` is true for a document request with `Sec-Purpose: + * prefetch;prerender`, so its kind is `page` whether or not the visitor opens + * the page, since the server cannot see activation. The line holds no raw + * address, query string, cookie, auth header or user agent. */ export type RequestKind = 'page' | 'api' | 'rsc' | 'prefetch'; @@ -28,10 +36,12 @@ export type RequestLogEntry = { host: string | null; kind: RequestKind; status: number; + finished: boolean; bot: boolean; + prerender: boolean; }; -type RequestMetadata = Pick; +type RequestMetadata = { path: string; method: string; headers: Headers }; // Framework files and images and fonts by extension. const STATIC_ASSET = /^\/_next\/|\.(?:png|jpe?g|gif|webp|avif|svg|ico|woff2?|ttf|otf)$/i; @@ -44,63 +54,100 @@ const API_PATHS = ['/api', '/mcp', '/openapi.json', '/codes']; const isApiPath = (path: string): boolean => API_PATHS.some((prefix) => path === prefix || path.startsWith(`${prefix}/`)); +/** True for a static asset, which is not logged. */ +export const isStaticAsset = (path: string): boolean => STATIC_ASSET.test(path); + +/** The tokens of a `Sec-Purpose` or `Purpose` header, such as `prefetch;prerender`. */ +const purposeOf = (headers: Headers): string[] => + (headers.get('sec-purpose') ?? headers.get('purpose')) + ?.split(';') + .map((token) => token.trim().toLowerCase()) ?? []; + /** - * What a request is, or undefined for a static asset, which is not logged. - * `headers` are the request's raw headers, which keep the RSC and prefetch - * headers Next.js removes from `request.headers`. + * What a request is, and whether it is a prerender. `headers` are the + * request's raw headers, which keep the RSC and prefetch headers Next.js + * removes from `request.headers`. An RSC fetch or router prefetch keeps its + * kind whatever `Sec-Purpose` says, and is not a prerender. A document request + * that prerenders is a page, because infra's `website_requests_daily` counts a + * kind outside the four as unparsed. */ -export const requestKind = (path: string, headers: Headers): RequestKind | undefined => { - if (STATIC_ASSET.test(path)) { - return undefined; - } - +const classifyRequest = ( + path: string, + headers: Headers, +): { kind: RequestKind; prerender: boolean } => { if (isApiPath(path)) { - return 'api'; + return { kind: 'api', prerender: false }; } - const purpose = headers.get('sec-purpose') ?? headers.get('purpose'); + if (headers.has('next-router-prefetch')) { + return { kind: 'prefetch', prerender: false }; + } - if (headers.has('next-router-prefetch') || purpose?.startsWith('prefetch')) { - return 'prefetch'; + if (headers.get('rsc') === '1') { + return { kind: 'rsc', prerender: false }; } - return headers.get('rsc') === '1' ? 'rsc' : 'page'; + const purpose = purposeOf(headers); + const prerender = purpose.includes('prerender'); + + return { kind: prerender || !purpose.includes('prefetch') ? 'page' : 'prefetch', prerender }; }; /** A request with no user agent comes from a script, so it counts as a bot. */ const isBot = (userAgent: string | null): boolean => !userAgent || isbot(userAgent); -/** The log entry for a request, or undefined when it is not logged. */ +/** The log entry for a logged request. */ export const requestLogEntry = ( - request: RequestMetadata, + { path, method, headers }: RequestMetadata, caller: string | undefined, - status: number, -): RequestLogEntry | undefined => { - const path = new URL(request.url).pathname; - const kind = requestKind(path, request.headers); - - if (!kind) { - return undefined; - } + { status, finished }: { status: number; finished: boolean }, +): RequestLogEntry => { + const { kind, prerender } = classifyRequest(path, headers); return { severity: 'INFO', message: 'request', caller: caller ?? null, - method: request.method, + method, path, - host: request.headers.get('host'), + host: headers.get('host'), kind, status, - bot: isBot(request.headers.get('user-agent')), + finished, + bot: isBot(headers.get('user-agent')), + prerender, }; }; -const requestMetadata = (request: RequestMetadata | IncomingMessage): RequestMetadata => { - if (!(request instanceof IncomingMessage)) { - return request; +// The request target as it arrived, kept because Next.js can rewrite +// `request.url` before the response ends. +const arrivedTargets = new WeakMap(); + +// Client closed request, the status for a response whose app sent no status +// before the connection closed. +const CLIENT_CLOSED_REQUEST = 499; + +/** + * The path of a request target. An origin-form target resolves against a + * placeholder host, which reads `//mcp` as a path and not a host and resolves + * dot segments; an absolute-form target keeps its own pathname. The + * asterisk-form target of `OPTIONS *` is its own path. A target whose URL does + * not parse is cut at its first `?` or `#`, so the request still writes a line. + */ +const targetPath = (target: string): string => { + if (target === '*') { + return target; + } + + try { + return new URL(/^https?:\/\//i.test(target) ? target : `http://localhost${target}`) + .pathname; + } catch { + return target.split(/[?#]/, 1)[0] ?? target; } +}; +const requestHeaders = (request: IncomingMessage): Headers => { const headers = new Headers(); // Keep the original headers even when Next.js has already handled the request. @@ -117,57 +164,109 @@ const requestMetadata = (request: RequestMetadata | IncomingMessage): RequestMet } } - return { - url: new URL(request.url ?? '/', 'http://localhost').href, - method: request.method ?? 'GET', - headers, - }; + return headers; }; -/** Write the request's log line. Never throws: a logging fault must not fail the request. */ -export const logRequest = (request: RequestMetadata | IncomingMessage, status: number): void => { +/** + * Write the request's log line. A static asset is dropped before its headers + * are read or its caller digest computed. Never throws: a logging fault must + * not fail the request. + */ +export const logRequest = ( + request: IncomingMessage, + response: { status: number; finished: boolean }, +): void => { try { - const metadata = requestMetadata(request); - const entry = requestLogEntry(metadata, requestCaller(metadata.headers), status); + const path = targetPath(arrivedTargets.get(request) ?? request.url ?? '/'); - if (entry) { - console.log(JSON.stringify(entry)); + if (isStaticAsset(path)) { + return; } + + const headers = requestHeaders(request); + const entry = requestLogEntry( + { path, method: request.method ?? 'GET', headers }, + requestCaller(headers), + response, + ); + + console.log(JSON.stringify(entry)); } catch { - // URL and header errors can include raw request data. + // Header errors can include raw request data. console.error('request log failed'); } }; +const REQUEST_START = 'http.server.request.start'; const RESPONSE_FINISH = 'http.server.response.finish'; -// Share the subscriber across Next dev reloads. +// Share the subscribers across Next dev reloads. const globalForRequestLog = globalThis as typeof globalThis & { - dfoRequestLogSubscriber?: (message: unknown) => void; + dfoRequestLogSubscribers?: { + start: (message: unknown) => void; + finish: (message: unknown) => void; + }; }; +const httpPair = ( + message: unknown, +): { request: IncomingMessage; response: ServerResponse } | undefined => + typeof message === 'object' && + message !== null && + 'request' in message && + message.request instanceof IncomingMessage && + 'response' in message && + message.response instanceof ServerResponse + ? { request: message.request, response: message.response } + : undefined; + +// The close listener logs every request that arrived after registration. +// ServerResponse emits `close` after `finish`, so one listener covers a +// response that ends and one that does not. +const onRequestStart = (message: unknown): void => { + const pair = httpPair(message); + + if (!pair) { + return; + } + + const { request, response } = pair; + + arrivedTargets.set(request, request.url ?? '/'); + response.once('close', () => { + logRequest(request, { + status: response.headersSent ? response.statusCode : CLIENT_CLOSED_REQUEST, + finished: response.writableFinished, + }); + }); +}; + +// A request accepted before registration has no close listener, so its finish +// writes the line. const onResponseFinish = (message: unknown): void => { - if ( - typeof message === 'object' && - message !== null && - 'request' in message && - message.request instanceof IncomingMessage && - 'response' in message && - message.response instanceof ServerResponse - ) { - logRequest(message.request, message.response.statusCode); + const pair = httpPair(message); + + if (pair && !arrivedTargets.has(pair.request)) { + logRequest(pair.request, { status: pair.response.statusCode, finished: true }); } }; /** * Observe HTTP headers without reading or buffering a request body. A request - * accepted before this runs is still logged, since its response finishes after. + * accepted before this runs is still logged when its response finishes. */ export const registerRequestLogging = (): void => { - if (globalForRequestLog.dfoRequestLogSubscriber) { - unsubscribe(RESPONSE_FINISH, globalForRequestLog.dfoRequestLogSubscriber); + const previous = globalForRequestLog.dfoRequestLogSubscribers; + + if (previous) { + unsubscribe(REQUEST_START, previous.start); + unsubscribe(RESPONSE_FINISH, previous.finish); } + subscribe(REQUEST_START, onRequestStart); subscribe(RESPONSE_FINISH, onResponseFinish); - globalForRequestLog.dfoRequestLogSubscriber = onResponseFinish; + globalForRequestLog.dfoRequestLogSubscribers = { + start: onRequestStart, + finish: onResponseFinish, + }; }; diff --git a/src/lib/proxy/test/requestLog.test.ts b/src/lib/proxy/test/requestLog.test.ts index bbf77cc..a59a3c2 100644 --- a/src/lib/proxy/test/requestLog.test.ts +++ b/src/lib/proxy/test/requestLog.test.ts @@ -4,50 +4,87 @@ * raw address, query string or user agent. */ import assert from 'node:assert/strict'; -import { createHash, createHmac } from 'node:crypto'; +import crypto, { createHash, createHmac } from 'node:crypto'; import { once } from 'node:events'; import { createServer, IncomingMessage, request as httpRequest } from 'node:http'; import { Socket } from 'node:net'; import test from 'node:test'; +import { syncBuiltinESMExports } from 'node:module'; // caller.ts reads its settings at import, so set them before loading it. process.env.CALLER_HMAC_KEY = 'test-key'; process.env.TRUSTED_PROXY_HOPS = '2'; -const { logRequest, registerRequestLogging, requestKind, requestLogEntry } = +const { isStaticAsset, logRequest, registerRequestLogging, requestLogEntry } = await import('../requestLog.ts'); const VISITOR = '203.0.113.7'; const CHROME = 'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/154.0.0.0 Safari/537.36'; -test('requestKind: pages, API calls, RSC and prefetch requests', () => { - const cases: [string, Record, string | undefined][] = [ - ['/', {}, 'page'], - ['/embed/abc123', {}, 'page'], - ['/docs/guide.md', {}, 'page'], - ['/api/v1/search', {}, 'api'], - ['/api', {}, 'api'], - ['/mcp', {}, 'api'], - ['/openapi.json', {}, 'api'], - ['/codes/rate_limited', {}, 'api'], - ['/apiary', {}, 'page'], - ['/codes', {}, 'api'], - ['/codesign', {}, 'page'], - ['/openapi.jsonx', {}, 'page'], - ['/studio', { rsc: '1' }, 'rsc'], - ['/studio', { rsc: '1', 'next-router-prefetch': '1' }, 'prefetch'], - ['/studio', { 'sec-purpose': 'prefetch;prerender' }, 'prefetch'], - ['/studio', { purpose: 'prefetch' }, 'prefetch'], - ['/_next/static/chunks/main.js', {}, undefined], - ['/_next/image', {}, undefined], - ['/favicon.ico', {}, undefined], - ['/images/logo.SVG', {}, undefined], - ['/fonts/outfit.woff2', {}, undefined], +test('requestLogEntry: kind and prerender for pages, API calls, RSC, prefetch and prerender requests', () => { + const cases: [string, Record, string, boolean][] = [ + ['/', {}, 'page', false], + ['/embed/abc123', {}, 'page', false], + ['/docs/guide.md', {}, 'page', false], + ['/api/v1/search', {}, 'api', false], + ['/api', {}, 'api', false], + ['/mcp', {}, 'api', false], + ['/openapi.json', {}, 'api', false], + ['/codes/rate_limited', {}, 'api', false], + ['/apiary', {}, 'page', false], + ['/codes', {}, 'api', false], + ['/codesign', {}, 'page', false], + ['/openapi.jsonx', {}, 'page', false], + ['/mcp', { 'sec-purpose': 'prefetch;prerender' }, 'api', false], + ['/studio', { rsc: '1' }, 'rsc', false], + ['/studio', { rsc: '1', 'next-router-prefetch': '1' }, 'prefetch', false], + ['/studio', { 'sec-purpose': 'prefetch' }, 'prefetch', false], + ['/studio', { purpose: 'prefetch' }, 'prefetch', false], + ['/studio', { 'sec-purpose': 'prefetch;prerender' }, 'page', true], + ['/studio', { 'sec-purpose': 'prefetch; prerender' }, 'page', true], + ['/studio', { rsc: '1', 'sec-purpose': 'prefetch;prerender' }, 'rsc', false], + ['/studio', { rsc: '1', 'sec-purpose': 'prefetch' }, 'rsc', false], + [ + '/studio', + { 'next-router-prefetch': '1', 'sec-purpose': 'prefetch;prerender' }, + 'prefetch', + false, + ], + ]; + + for (const [path, headers, kind, prerender] of cases) { + const entry = requestLogEntry( + { path, method: 'GET', headers: new Headers(headers) }, + undefined, + { + status: 200, + finished: true, + }, + ); + + assert.deepEqual( + { kind: entry.kind, prerender: entry.prerender }, + { kind, prerender }, + `${path} ${JSON.stringify(headers)}`, + ); + } +}); + +test('isStaticAsset: framework files, images and fonts', () => { + const cases: [string, boolean][] = [ + ['/_next/static/chunks/main.js', true], + ['/_next/image', true], + ['/favicon.ico', true], + ['/images/logo.SVG', true], + ['/fonts/outfit.woff2', true], + ['/', false], + ['/docs/guide.md', false], + ['/api/v1/search', false], ]; - for (const [path, headers, kind] of cases) { - assert.equal(requestKind(path, new Headers(headers)), kind, path); + for (const [path, expected] of cases) { + assert.equal(isStaticAsset(path), expected, path); } }); @@ -131,24 +168,33 @@ test('requestLogEntry: bot is true for crawlers, tools and a missing user agent, for (const [userAgent, bot] of cases) { const headers = new Headers(userAgent === undefined ? {} : { 'user-agent': userAgent }); - const entry = requestLogEntry( - { url: 'https://developmentfinance.org/', method: 'GET', headers }, - undefined, - 200, - ); + const entry = requestLogEntry({ path: '/', method: 'GET', headers }, undefined, { + status: 200, + finished: true, + }); - assert.equal(entry?.bot, bot, String(userAgent)); + assert.equal(entry.bot, bot, String(userAgent)); } }); -const captureLog = (request: Request, status = 200): unknown[] => { +// A server request as the HTTP parser hands it over: a raw target and raw headers. +const serverRequest = (target: string, headers: Record = {}): IncomingMessage => { + const request = new IncomingMessage(new Socket()); + request.url = target; + request.method = 'GET'; + request.rawHeaders = Object.entries(headers).flat(); + + return request; +}; + +const captureLog = (request: IncomingMessage, status = 200): unknown[] => { const lines: unknown[] = []; const original = console.log; console.log = (line: string) => lines.push(JSON.parse(line)); try { - logRequest(request, status); + logRequest(request, { status, finished: true }); } finally { console.log = original; } @@ -158,15 +204,13 @@ const captureLog = (request: Request, status = 200): unknown[] => { test('logRequest: one line with the caller digest and no address or query', () => { const raw = 'q=secret+search&token=abc'; - const request = new Request(`https://developmentfinance.org/embed/abc123?${raw}`, { - headers: { - host: 'developmentfinance.org', - 'user-agent': CHROME, - 'x-forwarded-for': `${VISITOR}, 198.51.100.1, 192.0.2.1`, - 'cf-connecting-ip': VISITOR, - cookie: 'session=s3cret', - authorization: 'Bearer t0ken', - }, + const request = serverRequest(`/embed/abc123?${raw}`, { + host: 'developmentfinance.org', + 'user-agent': CHROME, + 'x-forwarded-for': `${VISITOR}, 198.51.100.1, 192.0.2.1`, + 'cf-connecting-ip': VISITOR, + cookie: 'session=s3cret', + authorization: 'Bearer t0ken', }); const digest = createHmac('sha256', 'test-key').update(VISITOR).digest('hex').slice(0, 32); @@ -182,7 +226,9 @@ test('logRequest: one line with the caller digest and no address or query', () = host: 'developmentfinance.org', kind: 'page', status: 404, + finished: true, bot: false, + prerender: false, }, ]); @@ -193,23 +239,80 @@ test('logRequest: one line with the caller digest and no address or query', () = } }); -test('logRequest: a static asset writes nothing', () => { - assert.deepEqual(captureLog(new Request('https://developmentfinance.org/icon.svg')), []); -}); - test('logRequest: no client address logs a null caller', () => { - const [line] = captureLog(new Request('https://developmentfinance.org/api/events')); + const [line] = captureLog(serverRequest('/api/events')); assert.equal((line as { caller: unknown }).caller, null); }); -test('logRequest: malformed raw URLs keep the query out of error output', (t) => { +test('logRequest: the path is the target without its query, resolved, with //mcp kept as a path, * as itself and an unparsable URL cut at its query', () => { + // [target, logged path or null for a dropped static asset, kind] + const cases: [string, string | null, string][] = [ + ['//mcp', '//mcp', 'page'], + ['//api/v1/search?q=secret', '//api/v1/search', 'page'], + ['/api/v1/search?q=secret#frag', '/api/v1/search', 'api'], + ['/embed/abc123', '/embed/abc123', 'page'], + ['/a/../mcp', '/mcp', 'api'], + ['/x/../_next/static/a.js', null, 'page'], + ['http://host/_next/static/x.js', null, 'page'], + ['https://host/api/v1/search?q=secret', '/api/v1/search', 'api'], + ['*', '*', 'page'], + ['http://[bad/path?q=secret#frag', 'http://[bad/path', 'page'], + ]; + + for (const [target, path, kind] of cases) { + const lines = captureLog(serverRequest(target, { host: 'developmentfinance.org' })); + + assert.deepEqual( + lines.map((line) => ({ + path: (line as { path: string }).path, + kind: (line as { kind: string }).kind, + })), + path === null ? [] : [{ path, kind }], + target, + ); + } +}); + +test('logRequest: a static asset reads no headers and computes no caller digest', (t) => { + const hmac = t.mock.method(crypto, 'createHmac'); + syncBuiltinESMExports(); + t.after(() => { + hmac.mock.restore(); + syncBuiltinESMExports(); + }); + const headers = { 'X-Forwarded-For': `${VISITOR}, 198.51.100.1, 192.0.2.1` }; + const asset = serverRequest('/_next/static/chunks/main.js', headers); + let headerReads = 0; + Object.defineProperty(asset, 'rawHeaders', { + get: () => { + headerReads += 1; + return []; + }, + }); + + assert.deepEqual(captureLog(asset), []); + assert.equal(headerReads, 0); + assert.equal(hmac.mock.callCount(), 0); + + // Control: a logged request makes the same mock count the digest. + assert.equal(captureLog(serverRequest('/studio', headers)).length, 1); + assert.equal(hmac.mock.callCount(), 1); +}); + +test('logRequest: a logging fault does not throw and keeps request data out of the error', (t) => { const errors: unknown[][] = []; t.mock.method(console, 'error', (...args: unknown[]) => errors.push(args)); - const request = new IncomingMessage(new Socket()); - request.url = '//%zz/path?token=private-query'; + t.mock.method(console, 'log', () => { + throw new Error('GET /studio?token=private-query'); + }); - assert.doesNotThrow(() => logRequest(request, 200)); + assert.doesNotThrow(() => + logRequest(serverRequest('/studio?token=private-query'), { + status: 200, + finished: true, + }), + ); assert.deepEqual(errors, [['request log failed']]); }); @@ -331,8 +434,148 @@ test( host: 'developmentfinance.org', kind: 'api', status: 200, + finished: true, bot: true, + prerender: false, }, ]); }, ); + +const listen = async ( + t: test.TestContext, + handler: Parameters[1], +): Promise => { + const server = createServer(handler); + server.listen(0, '127.0.0.1'); + await once(server, 'listening'); + t.after(() => { + server.closeAllConnections(); + server.close(); + }); + const address = server.address(); + assert.ok(address && typeof address === 'object'); + + return address.port; +}; + +test('server logging writes one line with finished true for a response that finishes', async (t) => { + const lines: unknown[] = []; + t.mock.method(console, 'log', (line: string) => lines.push(JSON.parse(line))); + registerRequestLogging(); + const closed = Promise.withResolvers(); + const port = await listen(t, (_request, response) => { + response.once('close', () => closed.resolve()); + response.end('ok'); + }); + + await (await fetch(`http://127.0.0.1:${port}/studio`)).text(); + // The close event follows the finish event, and must write nothing more. + await closed.promise; + + assert.deepEqual( + lines.map((line) => (line as { finished: boolean }).finished), + [true], + ); +}); + +test( + 'server logging writes one line with finished false for a response closed early', + { timeout: 5000 }, + async (t) => { + const lines: unknown[] = []; + const logged = Promise.withResolvers(); + t.mock.method(console, 'log', (line: string) => { + lines.push(JSON.parse(line)); + logged.resolve(); + }); + registerRequestLogging(); + const closed = Promise.withResolvers(); + const port = await listen(t, (_request, response) => { + response.once('close', () => closed.resolve()); + // Headers and a first chunk go out, and the stream never ends. + response.write('first chunk'); + }); + + const upload = httpRequest({ + host: '127.0.0.1', + port, + path: '/mcp?token=private-query', + headers: { 'user-agent': 'stream-test' }, + }); + const responseReady = once(upload, 'response'); + upload.end(); + const [response] = await responseReady; + await once(response, 'data'); + upload.destroy(); + await closed.promise; + await logged.promise; + + assert.equal(lines.length, 1); + assert.deepEqual( + { + path: (lines[0] as { path: string }).path, + kind: (lines[0] as { kind: string }).kind, + status: (lines[0] as { status: number }).status, + finished: (lines[0] as { finished: boolean }).finished, + }, + { path: '/mcp', kind: 'api', status: 200, finished: false }, + ); + }, +); + +test( + 'server logging writes status 499 for a response closed before its headers were sent', + { timeout: 5000 }, + async (t) => { + const lines: unknown[] = []; + const logged = Promise.withResolvers(); + t.mock.method(console, 'log', (line: string) => { + lines.push(JSON.parse(line)); + logged.resolve(); + }); + registerRequestLogging(); + const received = Promise.withResolvers(); + const port = await listen(t, () => { + // The handler sends nothing, not even the headers. + received.resolve(); + }); + + const upload = httpRequest({ host: '127.0.0.1', port, path: '/studio' }); + upload.on('error', () => {}); + upload.end(); + await received.promise; + upload.destroy(); + await logged.promise; + + assert.equal(lines.length, 1); + assert.deepEqual( + { + path: (lines[0] as { path: string }).path, + status: (lines[0] as { status: number }).status, + finished: (lines[0] as { finished: boolean }).finished, + }, + { path: '/studio', status: 499, finished: false }, + ); + }, +); + +test('server logging logs the target as it arrived when a handler rewrites request.url', async (t) => { + const lines: unknown[] = []; + t.mock.method(console, 'log', (line: string) => lines.push(JSON.parse(line))); + registerRequestLogging(); + const port = await listen(t, (request, response) => { + request.url = '/_next/static/rewritten.js'; + response.end('ok'); + }); + + await (await fetch(`http://127.0.0.1:${port}/mcp?token=private-query`)).text(); + + assert.deepEqual( + lines.map((line) => ({ + path: (line as { path: string }).path, + kind: (line as { kind: string }).kind, + })), + [{ path: '/mcp', kind: 'api' }], + ); +}); From 94977f36d27bb458065222a3c25e2728cdcd6b36 Mon Sep 17 00:00:00 2001 From: Jorge Rivera Date: Sat, 24 Oct 2026 14:56:23 +0200 Subject: [PATCH 5/6] fix(proxy): answer unknown /api/v1 routes with a not_found problem document (#54) A path under /api/v1 that no proxy route handles fell through to the site's HTML 404 page, so the SDK saw a refusal with no code. The optional catch-all route src/app/api/v1/[[...path]]/route.ts now answers every method with the application/problem+json document the APIs use for their own unknown routes: code not_found, retryable false, and a fresh trace id repeated in x-dfo-trace-id. Next.js matches the datasets, graph, search and studio routes first, so nothing they serve changes, and the catch-all forwards nothing. --- src/app/api/v1/[[...path]]/route.ts | 17 +++++++++++++++ src/lib/proxy/problem.ts | 34 +++++++++++++++++++++++++++++ src/lib/proxy/test/problem.test.ts | 27 +++++++++++++++++++++++ 3 files changed, 78 insertions(+) create mode 100644 src/app/api/v1/[[...path]]/route.ts create mode 100644 src/lib/proxy/problem.ts create mode 100644 src/lib/proxy/test/problem.test.ts diff --git a/src/app/api/v1/[[...path]]/route.ts b/src/app/api/v1/[[...path]]/route.ts new file mode 100644 index 0000000..7e6b250 --- /dev/null +++ b/src/app/api/v1/[[...path]]/route.ts @@ -0,0 +1,17 @@ +import { NextRequest } from 'next/server'; + +import { notFoundProblem } from '@/lib/proxy/problem'; + +// Every /api/v1 path no other route here matches (Next.js tries the specific +// routes first), answered with the problem document dfo-apis gives its own +// unknown routes (see src/lib/proxy/problem) instead of the site's HTML 404 +// page. Nothing is forwarded: an unknown path is the site's to refuse, and +// the APIs the site does not publish stay out of reach. +const notFound = (req: NextRequest) => notFoundProblem(req.nextUrl.pathname); + +export const GET = notFound; +export const POST = notFound; +export const PUT = notFound; +export const PATCH = notFound; +export const DELETE = notFound; +export const OPTIONS = notFound; diff --git a/src/lib/proxy/problem.ts b/src/lib/proxy/problem.ts new file mode 100644 index 0000000..39dbc9b --- /dev/null +++ b/src/lib/proxy/problem.ts @@ -0,0 +1,34 @@ +/** + * The problem document the proxy answers with for a route it does not have, + * in the shape dfo-apis uses for its own refusals (the docs corpus's + * dfo-apis/conventions.md, "Problem details"): `application/problem+json` + * with the registry `code`, a `trace_id` repeated in the `x-dfo-trace-id` + * header, and `retryable`. A client such as the SDK branches on `code`, so a + * bare 404 reads as a refusal without one. Kept apart from the route so + * `node --test` can load it. + */ + +/** A 404 problem document for `path`, with a fresh trace id. */ +export const notFoundProblem = (path: string): Response => { + const traceId = crypto.randomUUID().replaceAll('-', ''); + + return Response.json( + { + type: '/codes/not_found', + title: 'Not Found', + status: 404, + detail: `There is no route ${path}.`, + code: 'not_found', + trace_id: traceId, + retryable: false, + }, + { + status: 404, + headers: { + 'Content-Type': 'application/problem+json', + 'x-dfo-trace-id': traceId, + 'Cache-Control': 'no-cache', + }, + }, + ); +}; diff --git a/src/lib/proxy/test/problem.test.ts b/src/lib/proxy/test/problem.test.ts new file mode 100644 index 0000000..c91467d --- /dev/null +++ b/src/lib/proxy/test/problem.test.ts @@ -0,0 +1,27 @@ +/** + * `problem.ts`: the problem document for a route the proxy does not have. + */ +import assert from 'node:assert/strict'; +import test from 'node:test'; + +import { notFoundProblem } from '../problem.ts'; + +test('notFoundProblem: answers 404 with a not_found problem document and a trace id', async () => { + const res = notFoundProblem('/api/v1/nowhere'); + const body = await res.json(); + + assert.equal(res.status, 404); + assert.equal(res.headers.get('content-type'), 'application/problem+json'); + assert.equal(body.code, 'not_found'); + assert.equal(body.type, '/codes/not_found'); + assert.equal(body.status, 404); + assert.equal(body.retryable, false); + assert.match(body.trace_id, /^[0-9a-f]{32}$/); + assert.equal(res.headers.get('x-dfo-trace-id'), body.trace_id); +}); + +test('notFoundProblem: each answer has its own trace id', () => { + const [a, b] = [notFoundProblem('/x'), notFoundProblem('/x')]; + + assert.notEqual(a.headers.get('x-dfo-trace-id'), b.headers.get('x-dfo-trace-id')); +}); From 5c73d728baea31d96a58ca4f1d0262135811b839 Mon Sep 17 00:00:00 2001 From: Jorge Rivera Date: Sat, 24 Oct 2026 18:55:21 +0200 Subject: [PATCH 6/6] fix(export): bound every export call and order current days first (#63) Every Postgres and BigQuery call in the event and account exports has a client-side bound, and a Postgres client that times out is destroyed. A 28-minute watchdog in runAndExit logs the phase in flight, the days not started and the faults so far, and exits 1 before the Job's 1800 s task timeout; every other failure is logged once with its phase. The window days run before the stale backlog. Day counts come from one exact query over the table, readDay stops on a short page, and the export_rules digest covers the readDay SQL, so a change to the exported row shape reloads history. A golden test pins exported rows to ROW_SHAPE_VERSION. The request log classifies the target at request start, adds no listener for static assets, and logs a placeholder path for any target other than an origin-form path, an http(s) URL or "*". --- db/account-export.ts | 75 ++-- db/bounded.ts | 105 +++++ db/connection.ts | 3 +- db/event-export.ts | 490 ++++++++++++++-------- db/export-events.ts | 79 ++-- db/test/account-export.test.ts | 33 +- db/test/bounded.test.ts | 62 +++ db/test/event-export.test.ts | 561 ++++++++++++++++++++------ db/test/runtime-pool.test.ts | 5 +- deploy/README.md | 17 +- docs/analytics.md | 4 +- src/lib/proxy/requestLog.ts | 79 +++- src/lib/proxy/test/requestLog.test.ts | 58 ++- 13 files changed, 1196 insertions(+), 375 deletions(-) create mode 100644 db/bounded.ts create mode 100644 db/test/bounded.test.ts diff --git a/db/account-export.ts b/db/account-export.ts index 01bf132..c45757a 100644 --- a/db/account-export.ts +++ b/db/account-export.ts @@ -1,7 +1,9 @@ import fs from 'node:fs/promises'; import type { BigQuery, TableField } from '@google-cloud/bigquery'; -import type { Pool } from 'pg'; +import type { Pool, PoolClient } from 'pg'; + +import { callWithin, loadWithin, QUERY_GRACE_MS, STATEMENT_TIMEOUT_MS } from './bounded.ts'; /** * The account export, which the event export Job (db/export-events.ts) runs @@ -56,53 +58,76 @@ export type AccountRead = { webmailDomains: boolean; }; +const readInTransaction = async (client: PoolClient): Promise => { + await client.query('BEGIN ISOLATION LEVEL REPEATABLE READ READ ONLY'); + + const { rows } = await client.query( + `SELECT to_char(day, 'YYYY-MM-DD') AS day, organisation, accounts + FROM account_daily + ORDER BY day, organisation`, + ); + const { rows: source } = await client.query<{ + accounts: boolean; + webmailDomains: boolean; + }>(`SELECT accounts, webmail_domains AS "webmailDomains" FROM account_daily_source`); + + await client.query('COMMIT'); + + return { rows, ...source[0]! }; +}; + +/** How long the account read may take: its two queries at the statement timeout, then the grace. */ +const ACCOUNT_READ_MS = 2 * STATEMENT_TIMEOUT_MS + QUERY_GRACE_MS; + /** * Every row of the view, oldest day first, with the facts that say why it * holds none. One read-only transaction reads both, so they share one - * `now()` and one snapshot. + * `now()` and one snapshot. A read still running at `timeoutMs`, as over a + * connection that stalls past Postgres's timeout, throws. */ -export const readAccountDaily = async (pool: Pool): Promise => { +export const readAccountDaily = async ( + pool: Pool, + { timeoutMs = ACCOUNT_READ_MS }: { timeoutMs?: number } = {}, +): Promise => { const client = await pool.connect(); try { - await client.query('BEGIN ISOLATION LEVEL REPEATABLE READ READ ONLY'); - - const { rows } = await client.query( - `SELECT to_char(day, 'YYYY-MM-DD') AS day, organisation, accounts - FROM account_daily - ORDER BY day, organisation`, + const read = await callWithin( + readInTransaction(client), + timeoutMs, + () => new Error(`account read ran past ${timeoutMs / 1000} s`), ); - const { rows: source } = await client.query<{ - accounts: boolean; - webmailDomains: boolean; - }>(`SELECT accounts, webmail_domains AS "webmailDomains" FROM account_daily_source`); - await client.query('COMMIT'); client.release(); - return { rows, ...source[0]! }; + return read; } catch (error) { - // A failed query leaves the transaction open, and a release with - // the error discards the connection and the transaction with it. + // A failed or timed-out read leaves the transaction open, or a query + // in flight, and a release with the error discards the connection + // with it. client.release(error instanceof Error ? error : true); throw error; } }; -/** Replaces the BigQuery table `account_daily` with the rows in `file`, one JSON object a line. */ +/** + * Replaces the BigQuery table `account_daily` with the rows in `file`, one + * JSON object a line. A load past its timeout is cancelled and throws + * (loadWithin). + */ export const bigQueryAccountTable = ({ datasetId, bigquery }: { datasetId: string; bigquery: BigQuery }) => async (file: string): Promise => { - // Creates the table when it does not exist. Resolves once the load - // job is done, and throws if it failed. - await bigquery - .dataset(datasetId) - .table('account_daily') - .load(file, { + // Creates the table when it does not exist. + await loadWithin({ + table: bigquery.dataset(datasetId).table('account_daily'), + file, + metadata: { sourceFormat: 'NEWLINE_DELIMITED_JSON', writeDisposition: 'WRITE_TRUNCATE', schema: { fields: ACCOUNT_SCHEMA }, - }); + }, + }); }; /** diff --git a/db/bounded.ts b/db/bounded.ts new file mode 100644 index 0000000..2721811 --- /dev/null +++ b/db/bounded.ts @@ -0,0 +1,105 @@ +import { setTimeout as sleep } from 'node:timers/promises'; + +import type { Job, JobLoadMetadata, Table } from '@google-cloud/bigquery'; + +/** + * Time bounds for the export Job's calls (db/export-events.ts) whose + * clients take none: a database query over a connection that stalls past + * Postgres's own timeout, a BigQuery call, and a BigQuery load of a local + * file and its cancel. + */ + +/** The `statement_timeout` of the export Job's pool. */ +export const STATEMENT_TIMEOUT_MS = 5 * 60_000; + +/** + * How long past its server-side bound a query may run before the Job stops + * waiting for it, for a connection that stalls where the server's timeout + * cannot reach it. + */ +export const QUERY_GRACE_MS = 5_000; + +/** How long one BigQuery load may run, upload included. */ +export const LOAD_TIMEOUT_MS = 2 * 60_000; + +/** How long the cancel of a load past its timeout is waited for. */ +export const CANCEL_TIMEOUT_MS = 10_000; + +/** What `within` resolves to when `work` is still running at `ms`. */ +export const TIMED_OUT = Symbol('timed out'); + +/** + * `work`'s outcome, or TIMED_OUT once `ms` pass with `work` left running. + * The timer is cleared when `work` settles first. + */ +export const within = async (work: Promise, ms: number): Promise => { + const timer = new AbortController(); + + try { + return await Promise.race([ + work, + sleep(ms, TIMED_OUT, { signal: timer.signal }).catch( + (): typeof TIMED_OUT => TIMED_OUT, + ), + ]); + } finally { + timer.abort(); + } +}; + +/** `call`'s result, or a throw of `timedOut()` once `ms` pass with it still running. */ +export const callWithin = async ( + call: Promise, + ms: number, + timedOut: () => Error, +): Promise => { + const result = await within(call, ms); + + if (result === TIMED_OUT) { + throw timedOut(); + } + + return result; +}; + +/** + * Loads `file` into `table` and resolves once the upload is done and the + * load job has finished, or throws if it failed. The client takes no + * timeout for an upload, so a load still running at `timeoutMs` is + * cancelled, the cancel waited for at most `cancelTimeoutMs`, and the call + * throws. A cancel that comes too late leaves the table holding the whole + * file. + */ +export const loadWithin = async ({ + table, + file, + metadata, + timeoutMs = LOAD_TIMEOUT_MS, + cancelTimeoutMs = CANCEL_TIMEOUT_MS, +}: { + table: Table; + file: string; + metadata: JobLoadMetadata; + timeoutMs?: number; + cancelTimeoutMs?: number; +}): Promise => { + let job: Job | undefined; + const load = (async () => { + [job] = await table.createLoadJob(file, metadata); + await job.promise(); + })(); + + // A load left running past its timeout settles unobserved. + load.catch(() => undefined); + + if ((await within(load, timeoutMs)) === TIMED_OUT) { + if (job) { + await within( + job.cancel().catch(() => undefined), + cancelTimeoutMs, + ); + } + + throw new Error(`load ran past ${timeoutMs / 1000} s and was cancelled`); + } +}; diff --git a/db/connection.ts b/db/connection.ts index 43c46c4..8aeb31b 100644 --- a/db/connection.ts +++ b/db/connection.ts @@ -194,7 +194,8 @@ export function getCloudSqlRuntimeStream(): DriverOptions['stream'] { if (!stream) { throw new Error( "Cloud SQL stream factory is not set on globalThis -- instrumentation.ts's " + - 'register() must run before the runtime pool connects.', + "register() or, in the export Job, db/export-events.ts's main() must set it " + + 'before the runtime pool connects.', ); } diff --git a/db/event-export.ts b/db/event-export.ts index 7b49a38..2bdef8d 100644 --- a/db/event-export.ts +++ b/db/event-export.ts @@ -20,6 +20,14 @@ import type { import type { SearchShareMode } from '../src/lib/search/searchShareRequest.ts'; import type { DeclinedReason, Known, ResolveResponse } from '../src/lib/search/types.ts'; +import { + callWithin, + loadWithin, + QUERY_GRACE_MS, + STATEMENT_TIMEOUT_MS, + TIMED_OUT, + within, +} from './bounded.ts'; import { requiredEnv } from './connection.ts'; /** @@ -292,25 +300,52 @@ const exportPage = (page: string | null): string | null => { // The version of the code that shapes a row: digest, passes, exportProps, // exportPage and exportRow. Bumped by hand with any change to them, so the -// change reaches every day (exportRules). -const ROW_SHAPE_VERSION = 1; +// change reaches every day (exportRules). READ_DAY_SQL, which shapes the +// rows they take, enters the digest as its text and needs no bump. The +// golden rows in db/test/event-export.test.ts pin each version's output. +export const ROW_SHAPE_VERSION = 1; /** - * The digest every row carries in `export_rules`: SHA-256 over PROP_RULES, - * TOKEN, PAGE_PATH, SHARE_PATH, EXPORT_SCHEMA, ROW_SHAPE_VERSION and an - * HMAC of a fixed string under `hmacKey`, so a new key changes it too. A - * day holding a row with another digest, or none, reloads (exportDays). + * One page of a UTC day's events (pgEventSource's readDay), with + * `created_at` as UTC text to the microsecond, the id as a JSON number, and + * `props` cut to the keys in $4. Parameters: the page's lower bound, the + * next midnight, the id of the last row read, the kept prop keys, the page + * size. + */ +const READ_DAY_SQL = `SELECT id::float8 AS id, + to_char(created_at AT TIME ZONE 'UTC', + 'YYYY-MM-DD"T"HH24:MI:SS.US"Z"') AS "createdAt", + name, user_id AS "userId", visitor_id AS "visitorId", page, + coalesce((SELECT jsonb_object_agg(key, value) + FROM jsonb_each(props) + WHERE key = ANY($4::text[])), '{}') AS props + FROM event + WHERE created_at >= $1 AND created_at < $2 AND (created_at, id) > ($1, $3) + ORDER BY created_at, id + LIMIT $5`; + +/** What shapes a row, the input exportRules digests. */ +export const ROW_SHAPE = { + PROP_RULES, + TOKEN: TOKEN.source, + PAGE_PATH: PAGE_PATH.source, + SHARE_PATH: SHARE_PATH.source, + EXPORT_SCHEMA, + READ_DAY_SQL, + ROW_SHAPE_VERSION, +}; + +/** + * The digest every row carries in `export_rules`: SHA-256 over ROW_SHAPE + * and an HMAC of a fixed string under `hmacKey`, so a new key changes it + * too. A day holding a row with another digest, or none, reloads + * (exportDays). */ export const exportRules = (hmacKey: string): string => createHash('sha256') .update( JSON.stringify({ - PROP_RULES, - TOKEN: TOKEN.source, - PAGE_PATH: PAGE_PATH.source, - SHARE_PATH: SHARE_PATH.source, - EXPORT_SCHEMA, - ROW_SHAPE_VERSION, + ...ROW_SHAPE, key: createHmac('sha256', hmacKey).update('export_rules').digest('hex'), }), ) @@ -338,18 +373,37 @@ export const exportRow = (row: SourceEvent, hmacKey: string, rules: string): Exp const DAY_MS = 86_400_000; +/** How long one BigQuery query may run. */ +const BIGQUERY_TIMEOUT_MS = 2 * 60_000; + +/** + * How long the Job waits for one BigQuery call, a query or a table read or + * create, before it gives up on it: BIGQUERY_TIMEOUT_MS plus the grace. + */ +const BIGQUERY_CALL_MS = BIGQUERY_TIMEOUT_MS + QUERY_GRACE_MS; + +/** The `connectionTimeoutMillis` of the export Job's pool (db/export-events.ts). */ +export const CONNECTION_TIMEOUT_MS = 30_000; + +/** + * How long the page queries of one day may take together, from the day's + * start, so the wait for its connection counts too. A read past it fails + * its day (pgEventSource). + */ +const DAY_READ_MS = 5 * 60_000; + /** - * How long a run starts new days for, 20 minutes, well inside the Job's - * 1800 s task timeout, so a run that has many days each waiting out a - * statement timeout ends and reports before the platform kills it. + * When runAndExit stops a Job run, 28 minutes from its start, two before + * the Job's 1800 s task timeout, so its report is out before the platform + * kills it. The days not reached by then wait for the next hourly run. */ -export const EXPORT_BUDGET_MS = 20 * 60_000; +export const JOB_DEADLINE_MS = 28 * 60_000; /** The most one BigQuery query may bill (`maximumBytesBilled`). */ const MAX_BYTES_BILLED = 1e9; -/** What the staleDays scan bills per event row, from its two columns. */ -const STALE_BYTES_PER_ROW = 74; +/** What the days query bills per event row, from its two columns. */ +const DAYS_BYTES_PER_ROW = 74; const dayOf = (ms: number): string => new Date(ms).toISOString().slice(0, 10); @@ -357,13 +411,15 @@ const dayOf = (ms: number): string => new Date(ms).toISOString().slice(0, 10); export type DayCounts = ReadonlyMap; /** - * The UTC days a run replaces, oldest first. They run from the day before - * the latest day BigQuery holds through `today`, or from the first event's - * day when BigQuery holds nothing, and add every day whose `events` count - * differs from its `partitions` count and every `stale` day. A day that - * loaded short, or failed to load under new rules, thus stays in every run - * until it matches, however many later days load. None when there is no - * event and BigQuery holds nothing. + * The UTC days a run replaces. First the window, oldest first: the day + * before the latest day BigQuery holds through `today`, or the first + * event's day through `today` when BigQuery holds nothing. Then the + * backlog, oldest first: every other day whose `events` count differs from + * its `partitions` count, and every other `stale` day. A day that loaded + * short, or failed to load under new rules, thus stays in every run until + * it matches, however many later days load, and a long backlog runs only + * after yesterday and today. None when there is no event and BigQuery holds + * nothing. */ export const exportDays = ({ today, @@ -379,21 +435,20 @@ export const exportDays = ({ const latest = [...partitions.keys()].sort().at(-1); const start = latest !== undefined ? dayOf(Date.parse(latest) - DAY_MS) : [...events.keys()].sort()[0]; - const days = new Set(stale); + const window = new Set(); if (start !== undefined) { for (let ms = Date.parse(start); ms <= Date.parse(today); ms += DAY_MS) { - days.add(dayOf(ms)); + window.add(dayOf(ms)); } } - for (const day of new Set([...events.keys(), ...partitions.keys()])) { - if ((events.get(day) ?? 0) !== (partitions.get(day) ?? 0)) { - days.add(day); - } - } + const mismatched = [...new Set([...events.keys(), ...partitions.keys()])].filter( + (day) => (events.get(day) ?? 0) !== (partitions.get(day) ?? 0), + ); + const backlog = new Set([...stale, ...mismatched].filter((day) => !window.has(day))); - return [...days].sort(); + return [...window, ...[...backlog].sort()]; }; /** The website database the rows come from. */ @@ -408,27 +463,57 @@ export type EventSource = { export type Warehouse = { /** Creates the table when it does not exist. */ ensureTable(): Promise; - /** The rows each day's partition holds. */ - dayCounts(): Promise; - /** The days holding a row whose `export_rules` is not `rules`, NULL included. */ - staleDays(rules: string): Promise>; + /** + * The rows each day's partition holds, and the days holding a row whose + * `export_rules` is not `rules`, NULL included. + */ + days(rules: string): Promise<{ counts: DayCounts; stale: ReadonlySet }>; /** Replaces the day's partition with the rows in `file`, one JSON object a line. */ replaceDay(day: string, file: string): Promise; }; const PAGE_SIZE = 5_000; -export const pgEventSource = (pool: Pool, pageSize = PAGE_SIZE): EventSource => ({ +/** + * The event table over `pool`. Each query has a client-side bound: the day + * counts the pool's `statement_timeout` plus `graceMs`, and a day's pages + * together `readMs` plus `graceMs`. A client whose query runs past its + * bound is still mid-query, so it is released with the error, which + * destroys it. + */ +export const pgEventSource = ( + pool: Pool, + { + pageSize = PAGE_SIZE, + readMs = DAY_READ_MS, + graceMs = QUERY_GRACE_MS, + }: { pageSize?: number; readMs?: number; graceMs?: number } = {}, +): EventSource => ({ async dayCounts() { - // The UTC date of created_at, the same day readDay's range bounds. - const { rows } = await pool.query<{ day: string; n: number }>( - `SELECT to_char(day, 'YYYY-MM-DD') AS day, n - FROM (SELECT (created_at AT TIME ZONE 'UTC')::date AS day, count(*)::int AS n - FROM event - GROUP BY 1) AS days`, - ); + const client = await pool.connect(); + const boundMs = Number(pool.options.statement_timeout ?? STATEMENT_TIMEOUT_MS) + graceMs; + + try { + // The UTC date of created_at, the same day readDay's range bounds. + const { rows } = await callWithin( + client.query<{ day: string; n: number }>( + `SELECT to_char(day, 'YYYY-MM-DD') AS day, n + FROM (SELECT (created_at AT TIME ZONE 'UTC')::date AS day, count(*)::int AS n + FROM event + GROUP BY 1) AS days`, + ), + boundMs, + () => new Error(`the day counts ran past ${boundMs / 1000} s`), + ); - return new Map(rows.map(({ day, n }) => [day, n])); + client.release(); + + return new Map(rows.map(({ day, n }) => [day, n])); + } catch (error) { + // Destroyed, since a query that ran past its bound is still in flight. + client.release(error instanceof Error ? error : true); + throw error; + } }, async *readDay(day) { const to = `${dayOf(Date.parse(day) + DAY_MS)}T00:00:00Z`; @@ -437,29 +522,40 @@ export const pgEventSource = (pool: Pool, pageSize = PAGE_SIZE): EventSource => // (midnight, 0) precedes the day's first row. `props` keeps only the keys some // event keeps; exportProps picks each event's own. let after = { createdAt: `${day}T00:00:00Z`, id: 0 }; + const deadline = Date.now() + readMs; + const client = await pool.connect(); + let failure: Error | undefined; - for (;;) { - const { rows } = await pool.query( - `SELECT id::float8 AS id, - to_char(created_at AT TIME ZONE 'UTC', - 'YYYY-MM-DD"T"HH24:MI:SS.US"Z"') AS "createdAt", - name, user_id AS "userId", visitor_id AS "visitorId", page, - coalesce((SELECT jsonb_object_agg(key, value) - FROM jsonb_each(props) - WHERE key = ANY($4::text[])), '{}') AS props - FROM event - WHERE created_at >= $1 AND created_at < $2 AND (created_at, id) > ($1, $3) - ORDER BY created_at, id - LIMIT $5`, - [after.createdAt, to, after.id, KEPT_PROPS, pageSize], - ); + try { + for (;;) { + const { rows } = await callWithin( + client.query(READ_DAY_SQL, [ + after.createdAt, + to, + after.id, + KEPT_PROPS, + pageSize, + ]), + deadline - Date.now() + graceMs, + () => new Error(`read ran past its ${readMs / 1000} s deadline`), + ); - if (rows.length === 0) { - return; - } + if (rows.length > 0) { + yield rows; + } + + // A short page is the day's last. + if (rows.length < pageSize) { + return; + } - yield rows; - after = rows[rows.length - 1]!; + after = rows[rows.length - 1]!; + } + } catch (error) { + failure = error instanceof Error ? error : new Error(String(error)); + throw error; + } finally { + client.release(failure); } }, }); @@ -476,23 +572,34 @@ export const bigQueryWarehouse = ({ const dataset = bigquery.dataset(datasetId); const table = dataset.table('event'); - // A query job fails past 1 GB billed or past 2 minutes, well inside the - // Job's 1800 s task timeout, and the run fails with it. + // A query job fails past 1 GB billed or past BIGQUERY_TIMEOUT_MS, and + // the run fails with it. + // The client takes no overall timeout for a call, so the Job stops + // waiting at BIGQUERY_CALL_MS. + const call = (work: Promise): Promise => + callWithin( + work, + BIGQUERY_CALL_MS, + () => new Error(`a BigQuery call ran past ${BIGQUERY_CALL_MS / 1000} s`), + ); + const query = async (sql: string, params?: Record): Promise => { try { - const [rows] = await bigquery.query({ - query: sql, - params, - maximumBytesBilled: String(MAX_BYTES_BILLED), - jobTimeoutMs: 120_000, - }); + const [rows] = await call( + bigquery.query({ + query: sql, + params, + maximumBytesBilled: String(MAX_BYTES_BILLED), + jobTimeoutMs: BIGQUERY_TIMEOUT_MS, + }), + ); return rows; } catch (error) { if (/bytes billed/i.test(messageOf(error))) { throw new Error( `a query exceeded the ${MAX_BYTES_BILLED / 1e9} GB maximumBytesBilled cap, ` + - `which staleDays reaches at about ${(MAX_BYTES_BILLED / STALE_BYTES_PER_ROW / 1e6).toFixed(1)} million event rows`, + `which the days query reaches at about ${(MAX_BYTES_BILLED / DAYS_BYTES_PER_ROW / 1e6).toFixed(1)} million event rows`, { cause: error }, ); } @@ -501,69 +608,57 @@ export const bigQueryWarehouse = ({ } }; - const dayCounts = async (): Promise => { - // Each partition's row count from the table's metadata, which a - // finished load updates, so the query scans no table data. - // partition_id is the UTC day as YYYYMMDD, and the pattern leaves - // out the special partitions such as __NULL__. - const rows = await query<{ partition_id: string; total_rows: unknown }>( - `SELECT partition_id, total_rows - FROM \`${projectId}.${datasetId}.INFORMATION_SCHEMA.PARTITIONS\` - WHERE table_name = 'event' AND total_rows > 0 - AND REGEXP_CONTAINS(partition_id, r'^\\d{8}$')`, - ); - - return new Map( - rows.map((row) => [ - row.partition_id.replace(/^(\d{4})(\d{2})(\d{2})$/, '$1-$2-$3'), - Number(row.total_rows), - ]), - ); - }; - return { async ensureTable() { - const [exists] = await table.exists(); + const [exists] = await call(table.exists()); if (!exists) { - await dataset.createTable('event', { - schema: { fields: EXPORT_SCHEMA }, - timePartitioning: { type: 'DAY', field: 'created_at' }, - }); + await call( + dataset.createTable('event', { + schema: { fields: EXPORT_SCHEMA }, + timePartitioning: { type: 'DAY', field: 'created_at' }, + }), + ); } }, - dayCounts, - async staleDays(rules) { - const [metadata] = await table.getMetadata(); + async days(rules) { + const [metadata] = await call(table.getMetadata()); const fields: TableField[] = metadata.schema?.fields ?? []; - // A table created without the column holds no digest, so every // day with rows is stale. The next load adds the column. - if (!fields.some((field) => field.name === 'export_rules')) { - return new Set((await dayCounts()).keys()); - } - - // Scans the created_at and export_rules columns, about - // STALE_BYTES_PER_ROW bytes a row. - const rows = await query<{ day: string }>( - `SELECT FORMAT_DATE('%F', DATE(created_at)) AS day + const stale = fields.some((field) => field.name === 'export_rules') + ? 'LOGICAL_OR(export_rules IS DISTINCT FROM @rules)' + : 'TRUE'; + + // Counts the rows themselves, one group per partition day, and + // scans the created_at and export_rules columns, about + // DAYS_BYTES_PER_ROW bytes a row. + const rows = await query<{ day: string; n: unknown; stale: boolean }>( + `SELECT FORMAT_DATE('%F', DATE(created_at)) AS day, + COUNT(*) AS n, + ${stale} AS stale FROM \`${projectId}.${datasetId}.event\` - WHERE export_rules IS DISTINCT FROM @rules GROUP BY day`, { rules }, ); - return new Set(rows.map(({ day }) => day)); + return { + counts: new Map(rows.map(({ day, n }) => [day, Number(n)])), + stale: new Set(rows.filter((row) => row.stale).map(({ day }) => day)), + }; }, async replaceDay(day, file) { - // Resolves once the load job is done, and throws if it failed. - await dataset.table(`event$${day.replaceAll('-', '')}`).load(file, { - sourceFormat: 'NEWLINE_DELIMITED_JSON', - writeDisposition: 'WRITE_TRUNCATE', - schema: { fields: EXPORT_SCHEMA }, - // A NULLABLE column added to EXPORT_SCHEMA reaches the table - // on the next load (ExportField). - schemaUpdateOptions: ['ALLOW_FIELD_ADDITION'], + await loadWithin({ + table: dataset.table(`event$${day.replaceAll('-', '')}`), + file, + metadata: { + sourceFormat: 'NEWLINE_DELIMITED_JSON', + writeDisposition: 'WRITE_TRUNCATE', + schema: { fields: EXPORT_SCHEMA }, + // A NULLABLE column added to EXPORT_SCHEMA reaches the + // table on the next load (ExportField). + schemaUpdateOptions: ['ALLOW_FIELD_ADDITION'], + }, }); }, }; @@ -572,6 +667,20 @@ export const bigQueryWarehouse = ({ const messageOf = (error: unknown): string => error instanceof Error ? error.message : String(error); +/** + * What a Job run has in flight, which runAndExit names when its deadline + * fires: the phase, the days the event export has yet to start, and the + * faults so far. + */ +export type JobProgress = { + phase: string; + unstarted: readonly string[]; + /** The failed and short days so far, as the run's report names them. */ + faults: () => readonly string[]; +}; + +const jobProgress = (): JobProgress => ({ phase: 'the start', unstarted: [], faults: () => [] }); + /** * One export run over the days exportDays picks. Each day is written to * `scratchFile` page by page before its load, so memory holds one page of @@ -593,11 +702,10 @@ const messageOf = (error: unknown): string => * days still load, and the run then rejects naming every such day with its * error. Each row carries the run's exportRules digest, so a day that * fails under new rules still holds the old digest and is the one day the - * next run reloads for them. A run starts no new day once `budgetMs` has - * passed since it began (`now` is its clock); it ends the day in hand, then - * rejects naming the days it did not reach as well as the failed and short - * ones, and the next run picks those days up. Logs each day as it is done - * and returns the rows read per day. + * next run reloads for them. A read or load past its bound fails its day + * the same way. `progress` names the phase in flight, the days not yet + * started and the faults so far, for runAndExit's deadline. Logs each day + * as it is done and returns the rows read per day. */ export const runExport = async ({ source, @@ -606,8 +714,7 @@ export const runExport = async ({ today, scratchFile, log, - budgetMs = EXPORT_BUDGET_MS, - now = Date.now, + progress = jobProgress(), }: { source: EventSource; warehouse: Warehouse; @@ -615,38 +722,41 @@ export const runExport = async ({ today: string; scratchFile: string; log: (line: string) => void; - budgetMs?: number; - now?: () => number; + progress?: JobProgress; }): Promise<{ day: string; rows: number }[]> => { - const startedAt = now(); const rules = exportRules(hmacKey); + progress.phase = 'the event table check and day counts'; await warehouse.ensureTable(); - const [events, partitions, stale] = await Promise.all([ + const [events, { counts: partitions, stale }] = await Promise.all([ source.dayCounts(), - warehouse.dayCounts(), - warehouse.staleDays(rules), + warehouse.days(rules), ]); const days = exportDays({ today, events, partitions, stale }); const read: { day: string; rows: number }[] = []; const failed: { day: string; error: unknown }[] = []; const short: string[] = []; - const unreached: string[] = []; + const faultsSoFar = () => [ + ...failed.map(({ day, error }) => `${day}: ${messageOf(error)}`), + ...(short.length > 0 ? [`short days: ${short.join(', ')}`] : []), + ]; + const earlierFaults = progress.faults; - try { - for (const day of days) { - if (now() - startedAt >= budgetMs) { - unreached.push(day); - continue; - } + progress.faults = () => [...earlierFaults(), ...faultsSoFar()]; + try { + for (const [index, day] of days.entries()) { + progress.unstarted = days.slice(index + 1); let rows = 0; const held = partitions.get(day) ?? 0; const counted = events.get(day) ?? 0; try { - await fs.writeFile(scratchFile, ''); + // Unlinked, so a load that ran past its timeout and still + // uploads keeps reading the day before's file. + await fs.rm(scratchFile, { force: true }); + progress.phase = `the read of ${day}`; for await (const page of source.readDay(day)) { const lines = page.map( @@ -658,6 +768,7 @@ export const runExport = async ({ } if (rows > 0 && rows >= held) { + progress.phase = `the load of ${day}`; await warehouse.replaceDay(day, scratchFile); } } catch (error) { @@ -685,18 +796,12 @@ export const runExport = async ({ read.push({ day, rows }); } } finally { + progress.phase = "the run's report"; + progress.unstarted = []; await fs.rm(scratchFile, { force: true }); } - const faults = [ - ...failed.map(({ day, error }) => `${day}: ${messageOf(error)}`), - ...(short.length > 0 ? [`short days: ${short.join(', ')}`] : []), - ...(unreached.length > 0 - ? [ - `days not reached in the ${budgetMs / 60_000} minute budget: ${unreached.join(', ')}`, - ] - : []), - ]; + const faults = faultsSoFar(); if (faults.length > 0) { throw new Error(`event export ${faults.join('; ')}`, { @@ -712,36 +817,99 @@ export const runExport = async ({ /** * The export Job's run (db/export-events.ts): the account export, then the - * event export, which runs whether or not the account export failed. Logs - * an account export failure as it happens and rejects with it once the - * event export is done, so a failing one leaves the other's tables - * current. An event export failure rejects as it is. + * event export, which runs whether or not the account export failed, so a + * failing one leaves the other's tables current. Rejects once both are + * done with the one that failed, or with both in one AggregateError. */ export const runExportJob = async ({ exportAccounts, exportEvents, - logError, + progress = jobProgress(), }: { exportAccounts: () => Promise; exportEvents: () => Promise; - logError: (error: unknown) => void; + progress?: JobProgress; }): Promise => { let accountFailure: Error | null = null; + progress.phase = 'the account export'; + progress.faults = () => (accountFailure !== null ? [accountFailure.message] : []); + try { await exportAccounts(); } catch (error) { - accountFailure = new Error('account export failed', { cause: error }); - logError(error); + accountFailure = new Error(`account export failed: ${messageOf(error)}`, { cause: error }); } - await exportEvents(); + try { + await exportEvents(); + } catch (error) { + throw accountFailure === null + ? error + : new AggregateError( + [accountFailure, error], + `${accountFailure.message}; ${messageOf(error)}`, + ); + } + + progress.phase = "the run's report"; if (accountFailure !== null) { throw accountFailure; } }; +/** + * Runs the Job's `main`, then exits the process with 0, or with 1 after + * logging one error that names the phase, so a socket left open, such as a + * load upload past its timeout or the pool's own connections, cannot hold + * the Job to its task timeout. A rejection is logged with the phase it + * left. A `main` still running at `deadlineMs` is stopped: the error names + * the phase in flight, the days not started and the faults so far, after + * the lines each finished day logged. Cloud Run's stdout and stderr are + * pipes, which Node writes synchronously on Linux, so every logged line is + * out before the exit. + */ +export const runAndExit = async ( + main: (progress: JobProgress) => Promise, + { + deadlineMs = JOB_DEADLINE_MS, + exit = process.exit, + logError, + }: { + deadlineMs?: number; + exit?: (code: number) => void; + logError: (error: unknown) => void; + }, +): Promise => { + const progress = jobProgress(); + let code = 0; + + try { + if ((await within(main(progress), deadlineMs)) === TIMED_OUT) { + const report = [ + `export Job stopped at its deadline, ${deadlineMs / 1000} s from its start, during ${progress.phase}`, + ...(progress.unstarted.length > 0 + ? [`days not started: ${progress.unstarted.join(', ')}`] + : []), + ...progress.faults(), + ]; + + logError(new Error(report.join('; '))); + code = 1; + } + } catch (error) { + logError( + new Error(`export Job failed during ${progress.phase}: ${messageOf(error)}`, { + cause: error, + }), + ); + code = 1; + } + + exit(code); +}; + /** The export's own settings. The database settings are the runtime's (db/connection.ts). */ export const readExportEnv = () => ({ projectId: requiredEnv('EXPORT_BQ_PROJECT'), diff --git a/db/export-events.ts b/db/export-events.ts index aaabd3e..c8c4219 100644 --- a/db/export-events.ts +++ b/db/export-events.ts @@ -2,6 +2,7 @@ import os from 'node:os'; import path from 'node:path'; import { BigQuery } from '@google-cloud/bigquery'; import { bigQueryAccountTable, readAccountDaily, runAccountExport } from './account-export'; +import { STATEMENT_TIMEOUT_MS } from './bounded'; import { buildRuntimePool, connectCloudSqlRuntime, @@ -10,8 +11,11 @@ import { } from './connection'; import { bigQueryWarehouse, + CONNECTION_TIMEOUT_MS, + type JobProgress, pgEventSource, readExportEnv, + runAndExit, runExport, runExportJob, } from './event-export'; @@ -19,8 +23,9 @@ import { // The event export Job's command (`node dist/export-events.cjs`, see // deploy/Dockerfile). It reads the database as the runtime does, through // WEBSITE_DB_* over the Cloud SQL connector, or DATABASE_URL locally, and -// runs the account export, then the event export (runExportJob). -async function main(): Promise { +// runs the account export, then the event export (runExportJob), under +// runAndExit's deadline, which names the phase in `progress` if it fires. +async function main(progress: JobProgress): Promise { const settings = readExportEnv(); const connection = resolveRuntimeConnection(); const cloudSql = @@ -31,46 +36,42 @@ async function main(): Promise { } // One connection suffices, since the run sends one query at a time. A - // query that runs past 5 minutes, the per-day count over the whole - // table, a page read or an account read, fails that read. The event - // export starts no new day after 20 minutes (EXPORT_BUDGET_MS), so - // days that each wait out the timeout still end the run, with a - // report naming the days it did not reach, inside the Job's 1800 s - // task timeout and before the next hourly run starts. - const pool = buildRuntimePool(process.env, { max: 1, statement_timeout: 300_000 }); + // query past 5 minutes fails on the server, and a connection not made + // in 30 seconds fails the query that asked for it. Each call also has a + // bound on the Job's side (db/bounded.ts). runAndExit stops the run at + // 28 minutes whatever is in flight, inside the Job's 1800 s task timeout + // and before the next hourly run starts, and its exit closes the pool + // and the connector. + const pool = buildRuntimePool(process.env, { + max: 1, + statement_timeout: STATEMENT_TIMEOUT_MS, + connectionTimeoutMillis: CONNECTION_TIMEOUT_MS, + }); const bigquery = new BigQuery({ projectId: settings.projectId }); const log = (line: string) => console.log(line); - try { - await runExportJob({ - exportAccounts: () => - runAccountExport({ - read: () => readAccountDaily(pool), - replace: bigQueryAccountTable({ datasetId: settings.datasetId, bigquery }), - scratchFile: path.join(os.tmpdir(), `account-export-${process.pid}.ndjson`), - log, - }), - exportEvents: () => - runExport({ - source: pgEventSource(pool), - warehouse: bigQueryWarehouse({ ...settings, bigquery }), - hmacKey: settings.hmacKey, - today: new Date().toISOString().slice(0, 10), - scratchFile: path.join(os.tmpdir(), `event-export-${process.pid}.ndjson`), - log, - }), - logError: (error) => - console.error('ERROR:', error instanceof Error ? error.stack : error), - }); - } finally { - // The pool first, so its connections close over the connector's tunnel. - await pool.end(); - cloudSql?.connector.close(); - } + await runExportJob({ + exportAccounts: () => + runAccountExport({ + read: () => readAccountDaily(pool), + replace: bigQueryAccountTable({ datasetId: settings.datasetId, bigquery }), + scratchFile: path.join(os.tmpdir(), `account-export-${process.pid}.ndjson`), + log, + }), + exportEvents: () => + runExport({ + source: pgEventSource(pool), + warehouse: bigQueryWarehouse({ ...settings, bigquery }), + hmacKey: settings.hmacKey, + today: new Date().toISOString().slice(0, 10), + progress, + scratchFile: path.join(os.tmpdir(), `event-export-${process.pid}.ndjson`), + log, + }), + progress, + }); } -main().catch((error: unknown) => { - console.error('ERROR:', error instanceof Error ? error.stack : error); - process.exitCode = 1; -}); +// console.error prints the error's stack and its cause's. +void runAndExit(main, { logError: (error) => console.error('ERROR:', error) }); diff --git a/db/test/account-export.test.ts b/db/test/account-export.test.ts index 7c010f7..37ad9bb 100644 --- a/db/test/account-export.test.ts +++ b/db/test/account-export.test.ts @@ -248,9 +248,9 @@ const fakeBigQuery = () => { const bigquery = { dataset: (dataset: string) => ({ table: (table: string) => ({ - load: async (file: string, metadata: Record) => { + createLoadJob: async (file: string, metadata: Record) => { loads.push({ table: `${dataset}.${table}`, file, metadata }); - return [{}]; + return [{ promise: async () => [{}] }]; }, }), }), @@ -278,6 +278,35 @@ test('bigQueryAccountTable replaces the whole table in one load', async () => { assert.ok(ACCOUNT_SCHEMA.every((field) => field.description)); }); +test( + 'readAccountDaily fails a read that hangs past its bound and destroys its client', + { timeout: 5_000 }, + async () => { + const queries: string[] = []; + const released: unknown[] = []; + const pool = { + connect: async () => ({ + // BEGIN answers, and the view's read never does, as over a stalled tunnel. + query: (text: string) => { + queries.push(text.trim().split(/\s/, 1)[0]!); + return text.startsWith('BEGIN') + ? Promise.resolve({ rows: [] }) + : new Promise(() => undefined); + }, + release: (error?: unknown) => released.push(error), + }), + } as unknown as Pool; + + await assert.rejects( + readAccountDaily(pool, { timeoutMs: 20 }), + /account read ran past 0.02 s/, + ); + assert.deepEqual(queries, ['BEGIN', 'SELECT']); + assert.equal(released.length, 1); + assert.ok(released[0] instanceof Error); + }, +); + const ROWS: AccountRow[] = [ { day: '2026-10-20', organisation: 'Personal email', accounts: 4 }, { day: '2026-10-21', organisation: 'one.org', accounts: 3 }, diff --git a/db/test/bounded.test.ts b/db/test/bounded.test.ts new file mode 100644 index 0000000..aa99f21 --- /dev/null +++ b/db/test/bounded.test.ts @@ -0,0 +1,62 @@ +import assert from 'node:assert/strict'; +import test from 'node:test'; +import type { Table } from '@google-cloud/bigquery'; +import { loadWithin } from '../bounded.ts'; + +// A table whose load job settles as `promise` does and whose cancel as `cancel` does. +const fakeTable = (promise: () => Promise, cancel: () => Promise) => { + const calls: string[] = []; + const table = { + createLoadJob: async () => { + calls.push('load'); + return [ + { + promise, + cancel: () => { + calls.push('cancel'); + return cancel(); + }, + }, + ]; + }, + } as unknown as Table; + + return { table, calls }; +}; + +const never = () => new Promise(() => undefined); + +test('loadWithin bounds a load and its cancel', { timeout: 5_000 }, async (t) => { + const cases: [string, () => Promise, () => Promise, RegExp | null][] = [ + ['a load that finishes', async () => [{}], async () => [{}], null], + [ + 'a load that fails', + async () => Promise.reject(new Error('load job failed')), + never, + /load job failed/, + ], + ['a load past its timeout', never, async () => [{}], /ran past/], + ['a load past its timeout whose cancel hangs', never, never, /ran past/], + ]; + + for (const [label, promise, cancel, error] of cases) { + await t.test(label, async () => { + const { table, calls } = fakeTable(promise, cancel); + const load = loadWithin({ + table, + file: '/tmp/day.ndjson', + metadata: {}, + timeoutMs: 20, + cancelTimeoutMs: 20, + }); + + if (error === null) { + await load; + } else { + await assert.rejects(load, error); + } + + assert.deepEqual(calls, /ran past/.test(String(error)) ? ['load', 'cancel'] : ['load']); + }); + } +}); diff --git a/db/test/event-export.test.ts b/db/test/event-export.test.ts index cd3abf2..80f596e 100644 --- a/db/test/event-export.test.ts +++ b/db/test/event-export.test.ts @@ -14,9 +14,13 @@ import { exportDays, type ExportField, exportRow, + type ExportRow, exportRules, pgEventSource, runExport, + ROW_SHAPE, + ROW_SHAPE_VERSION, + runAndExit, runExportJob, type SourceEvent, type Warehouse, @@ -98,6 +102,19 @@ test('exportRules changes with the HMAC key', () => { assert.notEqual(exportRules('rotated-key'), RULES); }); +test('exportRules changes with the SQL that reads a day', () => { + // The reader test checks that readDay sends ROW_SHAPE.READ_DAY_SQL. + const sql = ROW_SHAPE.READ_DAY_SQL; + + ROW_SHAPE.READ_DAY_SQL = `${sql} `; + + try { + assert.notEqual(exportRules(KEY), RULES); + } finally { + ROW_SHAPE.READ_DAY_SQL = sql; + } +}); + test('exportRow drops a value its rule refuses', async (t) => { const cases: [string, Record][] = [ [ @@ -184,6 +201,111 @@ test('exportRow exports a share id as its digest, so share events still join', ( assert.deepEqual(refused.props, {}); }); +// A fixed sample that reaches every rule and branch of exportRow. +const GOLDEN_SAMPLE: SourceEvent[] = [ + sourceEvent({ + id: 1, + name: 'search.query', + userId: 'user-1', + visitorId: 'visitor-1', + page: '/data?q=aid%20to%20kenya#top', + props: { + searchId: '0b7c6f1e-2d4a-4f7e-9a51-3c1d2e4f5a6b', + post: 0, + source: 'typed', + edited: false, + ms: 812, + outcome: 'definite', + kind: 'resolution', + query: 'aid to kenya', + engineMs: -1, + traceId: 'two words', + }, + }), + sourceEvent({ + id: 2, + createdAt: '2026-10-21T00:00:00.000001Z', + name: 'share.open', + visitorId: 'visitor-2', + page: '/s/aB3dE5fG7h/download/preparing', + props: { shareId: 'aB3dE5fG7h', kind: 'card', mode: 'snapshot', host: 'example.org' }, + }), + sourceEvent({ id: 3, name: 'feedback.submit', page: '/a page', props: { kind: 'widget' } }), + sourceEvent({ id: 4, name: 'retired.event', page: '/embed/x1', props: { kind: 'card' } }), +]; + +// Each ROW_SHAPE_VERSION's rows for GOLDEN_SAMPLE under KEY, with rules +// `r`. A change to the rows adds the next version with its rows, and an +// entry never changes. +const GOLDEN_ROWS: Record = { + 1: [ + { + id: 1, + created_at: '2026-10-20T13:04:05.123456Z', + name: 'search.query', + page: '/data', + signed_in: true, + visitor_hash: '77a3c0b044582bfb514a3a3ad8521316635e2256261861c83b7498ee2e420f65', + user_hash: 'e0e98314ed3ee6ea685abd3f0862870e2a07b68d95d053c7f483cda192ae40c4', + props: { + searchId: '0b7c6f1e-2d4a-4f7e-9a51-3c1d2e4f5a6b', + post: 0, + source: 'typed', + edited: false, + ms: 812, + outcome: 'definite', + kind: 'resolution', + }, + export_rules: 'r', + }, + { + id: 2, + created_at: '2026-10-21T00:00:00.000001Z', + name: 'share.open', + page: '/s/:id/download/preparing', + signed_in: false, + visitor_hash: '656d62821b3df7e629e0d8af562ac6a21302f71aeed8fa018b46c7fa00d54f88', + user_hash: null, + props: { + shareId: '7e8148cb3a5192589abc81da275c6e151ebb4c2d702234f8a68e870138326bc4', + kind: 'card', + mode: 'snapshot', + host: 'example.org', + }, + export_rules: 'r', + }, + { + id: 3, + created_at: '2026-10-20T13:04:05.123456Z', + name: 'feedback.submit', + page: null, + signed_in: false, + visitor_hash: null, + user_hash: null, + props: { kind: 'widget' }, + export_rules: 'r', + }, + { + id: 4, + created_at: '2026-10-20T13:04:05.123456Z', + name: 'retired.event', + page: '/embed/:id', + signed_in: false, + visitor_hash: null, + user_hash: null, + props: {}, + export_rules: 'r', + }, + ], +}; + +test('exportRow writes the rows pinned to the current ROW_SHAPE_VERSION', () => { + assert.deepEqual( + GOLDEN_SAMPLE.map((row) => exportRow(row, KEY, 'r')), + GOLDEN_ROWS[ROW_SHAPE_VERSION], + ); +}); + const counts = (days: Record) => new Map(Object.entries(days)); test('exportDays replaces from the day before the latest loaded day through today', async (t) => { @@ -228,7 +350,17 @@ test('exportDays replaces from the day before the latest loaded day through toda partitions: counts({ '2026-10-17': 1, '2026-10-20': 2, '2026-10-23': 1 }), stale: new Set(['2026-10-17', '2026-10-20']), }, - ['2026-10-17', '2026-10-20', '2026-10-22', '2026-10-23'], + ['2026-10-22', '2026-10-23', '2026-10-17', '2026-10-20'], + ], + [ + 'a backlog of stale and mismatched days, oldest first, after the window', + { + today: '2026-10-23', + events: counts({ '2026-10-15': 2, '2026-10-20': 2, '2026-10-23': 1 }), + partitions: counts({ '2026-10-15': 1, '2026-10-20': 2, '2026-10-23': 1 }), + stale: new Set(['2026-10-20', '2026-10-12', '2026-10-23']), + }, + ['2026-10-22', '2026-10-23', '2026-10-12', '2026-10-15', '2026-10-20'], ], [ 'a month boundary', @@ -255,25 +387,25 @@ test('exportDays adds every earlier day whose counts differ', async (t) => { 'a short day stays once later days load', { '2026-10-19': 5, ...loaded }, { '2026-10-19': 4, ...loaded }, - ['2026-10-19', '2026-10-22', '2026-10-23'], + ['2026-10-22', '2026-10-23', '2026-10-19'], ], [ 'a day missing from BigQuery', { '2026-10-15': 2, ...loaded }, loaded, - ['2026-10-15', '2026-10-22', '2026-10-23'], + ['2026-10-22', '2026-10-23', '2026-10-15'], ], [ 'a day BigQuery holds more of than the source', { '2026-10-17': 2, ...loaded }, { '2026-10-17': 3, ...loaded }, - ['2026-10-17', '2026-10-22', '2026-10-23'], + ['2026-10-22', '2026-10-23', '2026-10-17'], ], [ 'a day BigQuery holds that the source lacks', loaded, { '2026-10-16': 1, ...loaded }, - ['2026-10-16', '2026-10-22', '2026-10-23'], + ['2026-10-22', '2026-10-23', '2026-10-16'], ], ['days that match', loaded, loaded, ['2026-10-22', '2026-10-23']], ]; @@ -306,19 +438,19 @@ const fakeWarehouse = ( async ensureTable() { calls.push('ensureTable'); }, - async dayCounts() { - return new Map([...partitions].map(([day, rows]) => [day, rows.length])); - }, - async staleDays(rules) { - return new Set( - [...partitions] - .filter(([, rows]) => - rows.some( - (row) => (row as { export_rules?: string }).export_rules !== rules, - ), - ) - .map(([day]) => day), - ); + async days(rules) { + return { + counts: new Map([...partitions].map(([day, rows]) => [day, rows.length])), + stale: new Set( + [...partitions] + .filter(([, rows]) => + rows.some( + (row) => (row as { export_rules?: string }).export_rules !== rules, + ), + ) + .map(([day]) => day), + ), + }; }, async replaceDay(day, file) { if (failLoad.includes(day)) { @@ -502,9 +634,9 @@ test('runExport rechecks an earlier day whose counts differ until they match', a read: [at(1, '2026-10-19'), at(2, '2026-10-19')], calls: [ 'ensureTable', - 'replace 2026-10-19', 'replace 2026-10-22', 'replace 2026-10-23', + 'replace 2026-10-19', ], short: null, }, @@ -523,9 +655,9 @@ test('runExport rechecks an earlier day whose counts differ until they match', a counted: { '2026-10-19': 3 }, calls: [ 'ensureTable', - 'replace 2026-10-19', 'replace 2026-10-22', 'replace 2026-10-23', + 'replace 2026-10-19', ], short: /2026-10-19\D+2\D+3\b/, }, @@ -671,9 +803,9 @@ test('runExport reloads the days holding rows under other rules, and retries a f ); assert.deepEqual(first.calls, [ 'ensureTable', - 'replace 2026-10-20', 'replace 2026-10-21', 'replace 2026-10-22', + 'replace 2026-10-20', ]); assert.deepEqual(partitions.get('2026-10-20'), [exportRow(at(3, '2026-10-20'), KEY, RULES)]); @@ -689,9 +821,9 @@ test('runExport reloads the days holding rows under other rules, and retries a f }); assert.deepEqual(second.calls, [ 'ensureTable', - 'replace 2026-10-18', 'replace 2026-10-21', 'replace 2026-10-22', + 'replace 2026-10-18', ]); }); @@ -726,54 +858,111 @@ test('runExport names the short days beside a failed day', async () => { assert.equal(partitions.get('2026-10-21')?.length, 2); }); -test('runExport starts no new day past its budget and fails naming the days it did not reach', async () => { - const partitions = new Map(); - const { warehouse, calls } = fakeWarehouse(partitions, { failLoad: ['2026-10-21'] }); - const clock = { ms: 0 }; - const source = fakeSource({ - '2026-10-20': [[sourceEvent({ id: 1, createdAt: '2026-10-20T08:00:00.000000Z' })]], - '2026-10-21': [[sourceEvent({ id: 2, createdAt: '2026-10-21T08:00:00.000000Z' })]], - '2026-10-22': [[sourceEvent({ id: 3, createdAt: '2026-10-22T08:00:00.000000Z' })]], - '2026-10-23': [[sourceEvent({ id: 4, createdAt: '2026-10-23T08:00:00.000000Z' })]], - }); - - await assert.rejects( - runExport({ - source: { - ...source, - // Each day read costs 4 minutes of the injected clock. - readDay: (day) => { - clock.ms += 240_000; - return source.readDay(day); - }, +test( + 'a page query that hangs past the read deadline fails its day, destroys its client, and the next day loads', + { timeout: 5_000 }, + async () => { + const partitions = new Map(); + const { warehouse, calls } = fakeWarehouse(partitions); + // Each client's queries by text, and what it was released with. + const clients: { queries: string[]; released?: Error | 'reused' }[] = []; + const pool = { + options: {}, + connect: async () => { + const client: (typeof clients)[number] = { queries: [] }; + clients.push(client); + + return { + query: (text: string, values?: unknown[]) => { + client.queries.push(text.split(/\s/, 1)[0]!); + + if (text.includes('count(*)')) { + return Promise.resolve({ + rows: [ + { day: '2026-10-21', n: 1 }, + { day: '2026-10-22', n: 1 }, + ], + }); + } + + if (text !== ROW_SHAPE.READ_DAY_SQL) { + return Promise.resolve({ rows: [] }); + } + + // 21 October's page never answers, as over a stalled tunnel. + return String(values?.[0]).startsWith('2026-10-21') + ? new Promise(() => undefined) + : Promise.resolve({ + rows: [ + sourceEvent({ + id: 2, + createdAt: '2026-10-22T08:00:00.000000Z', + }), + ], + }); + }, + release: (error?: Error) => { + client.released = error ?? 'reused'; + }, + }; }, - warehouse, - hmacKey: KEY, - today: '2026-10-23', - scratchFile: scratch(), - log: () => undefined, - budgetMs: 600_000, - now: () => clock.ms, - }), - (error: unknown) => { - assert.ok(error instanceof Error); - assert.match(error.message, /2026-10-21: load job failed/); - assert.match(error.message, /not reached\D+10 minute budget: 2026-10-23$/); - return true; - }, - ); + } as unknown as Pool; + const started = Date.now(); - assert.deepEqual(calls, ['ensureTable', 'replace 2026-10-20', 'replace 2026-10-22']); -}); + await assert.rejects( + runExport({ + source: pgEventSource(pool, { readMs: 50, graceMs: 20 }), + warehouse, + hmacKey: KEY, + today: '2026-10-22', + scratchFile: scratch(), + log: () => undefined, + }), + /event export 2026-10-21: read ran past its 0.05 s deadline$/, + ); + + // The 50 ms deadline plus the 20 ms grace, with room for a slow machine. + assert.ok(Date.now() - started < 1_000); + // The day counts' client, then each day's. + assert.deepEqual(clients[0], { queries: ['SELECT'], released: 'reused' }); + assert.deepEqual(clients[1]?.queries, ['SELECT']); + assert.ok(clients[1]?.released instanceof Error); + assert.deepEqual(clients[2], { queries: ['SELECT'], released: 'reused' }); + assert.deepEqual(calls, ['ensureTable', 'replace 2026-10-22']); + }, +); + +test( + 'pgEventSource dayCounts fails a count that hangs past its bound and destroys its client', + { timeout: 5_000 }, + async () => { + const released: unknown[] = []; + const pool = { + options: { statement_timeout: 20 }, + connect: async () => ({ + // The count never answers, as over a stalled tunnel. + query: () => new Promise(() => undefined), + release: (error?: unknown) => released.push(error), + }), + } as unknown as Pool; + + await assert.rejects( + pgEventSource(pool, { graceMs: 20 }).dayCounts(), + /day counts ran past 0.04 s/, + ); + assert.equal(released.length, 1); + assert.ok(released[0] instanceof Error); + }, +); test('bigQueryWarehouse loads a day into its partition and lets the schema gain columns', async () => { const loads: { table: string; file: string; metadata: Record }[] = []; - const fake = { + const bigquery = { dataset: () => ({ table: (table: string) => ({ - load: async (file: string, metadata: Record) => { + createLoadJob: async (file: string, metadata: Record) => { loads.push({ table, file, metadata }); - return [{}]; + return [{ promise: async () => [{}] }]; }, }), }), @@ -781,7 +970,7 @@ test('bigQueryWarehouse loads a day into its partition and lets the schema gain const warehouse = bigQueryWarehouse({ projectId: 'p', datasetId: 'd', - bigquery: fake as unknown as BigQuery, + bigquery: bigquery as unknown as BigQuery, }); await warehouse.replaceDay('2026-10-22', '/tmp/day.ndjson'); @@ -801,7 +990,7 @@ test('EXPORT_SCHEMA admits a REQUIRED column only among those the table was crea assert.ok(required && nullable); }); -test('bigQueryWarehouse creates the table, finds stale days and counts from partition metadata', async (t) => { +test('bigQueryWarehouse creates the table, and counts rows and finds stale days per day', async (t) => { const fakeTable = ({ exists, fields = [] }: { exists: boolean; fields?: string[] }) => { const calls: unknown[] = []; const table = { @@ -817,15 +1006,15 @@ test('bigQueryWarehouse creates the table, finds stale days and counts from part }, }), query: async ({ query, params }: { query: string; params?: unknown }) => { - calls.push(['query', params]); - return query.includes('PARTITIONS') - ? [ - [ - { partition_id: '20261021', total_rows: 3 }, - { partition_id: '20261022', total_rows: '1434' }, - ], - ] - : [[{ day: '2026-10-21' }]]; + // The table itself, so each count is exact. + calls.push(['query', query.match(/FROM `([^`]+)`/)?.[1], params]); + const stale = fields.includes('export_rules') ? [true, false] : [true, true]; + return [ + [ + { day: '2026-10-21', n: 3, stale: stale[0] }, + { day: '2026-10-22', n: 1434, stale: stale[1] }, + ], + ]; }, }; const warehouse = bigQueryWarehouse({ @@ -836,6 +1025,10 @@ test('bigQueryWarehouse creates the table, finds stale days and counts from part return { warehouse, calls }; }; + const counts = new Map([ + ['2026-10-21', 3], + ['2026-10-22', 1434], + ]); await t.test('a missing table is created with the schema', async () => { const { warehouse, calls } = fakeTable({ exists: false }); @@ -844,18 +1037,24 @@ test('bigQueryWarehouse creates the table, finds stale days and counts from part assert.deepEqual(calls, [['createTable', 'event', { fields: EXPORT_SCHEMA }]]); }); - await t.test('staleDays queries the days whose rows carry other rules', async () => { + await t.test('one query over the table counts each day and finds the stale ones', async () => { const { warehouse, calls } = fakeTable({ exists: true, fields: ['id', 'export_rules'] }); - assert.deepEqual(await warehouse.staleDays('r1'), new Set(['2026-10-21'])); - assert.deepEqual(calls, [['query', { rules: 'r1' }]]); + assert.deepEqual(await warehouse.days('r1'), { + counts, + stale: new Set(['2026-10-21']), + }); + assert.deepEqual(calls, [['query', 'p.d.event', { rules: 'r1' }]]); }); await t.test('a table without export_rules is stale on every day', async () => { - assert.deepEqual( - await fakeTable({ exists: true, fields: ['id'] }).warehouse.staleDays('r1'), - new Set(['2026-10-21', '2026-10-22']), - ); + const { warehouse, calls } = fakeTable({ exists: true, fields: ['id'] }); + + assert.deepEqual(await warehouse.days('r1'), { + counts, + stale: new Set(['2026-10-21', '2026-10-22']), + }); + assert.deepEqual(calls, [['query', 'p.d.event', { rules: 'r1' }]]); }); await t.test('a query over the bytes-billed cap fails naming the cap', async () => { @@ -875,45 +1074,156 @@ test('bigQueryWarehouse creates the table, finds stale days and counts from part bigquery: bigquery as unknown as BigQuery, }); - await assert.rejects(warehouse.staleDays('r1'), /maximumBytesBilled cap/); - }); - - await t.test('dayCounts reads each partition_id as its day', async () => { - assert.deepEqual( - await fakeTable({ exists: true }).warehouse.dayCounts(), - new Map([ - ['2026-10-21', 3], - ['2026-10-22', 1434], - ]), - ); + await assert.rejects(warehouse.days('r1'), /maximumBytesBilled cap/); }); }); -test('runExportJob runs the event export after a failed account export, then fails', async () => { - const ran: string[] = []; - const logged: unknown[] = []; +test('runExportJob runs the event export after a failed account export, then fails with every failure', async (t) => { const accountError = new Error('bigquery down'); - - await assert.rejects( - runExportJob({ - exportAccounts: async () => { - ran.push('accounts'); - throw accountError; + const eventError = new Error('event export 2026-10-21: load job failed'); + const cases: [string, () => Promise, RegExp, number][] = [ + [ + 'the account export alone', + async () => undefined, + /^account export failed: bigquery down$/, + 1, + ], + [ + 'both', + async () => { + throw eventError; }, - exportEvents: async () => { - ran.push('events'); + /^account export failed: bigquery down; event export 2026-10-21: load job failed$/, + 2, + ], + ]; + + for (const [label, exportEvents, message, causes] of cases) { + await t.test(label, async () => { + const ran: string[] = []; + + await assert.rejects( + runExportJob({ + exportAccounts: async () => { + ran.push('accounts'); + throw accountError; + }, + exportEvents: async () => { + ran.push('events'); + await exportEvents(); + }, + }), + (error: unknown) => { + assert.ok(error instanceof Error); + assert.match(error.message, message); + assert.equal(error instanceof AggregateError ? error.errors.length : 1, causes); + return true; + }, + ); + assert.deepEqual(ran, ['accounts', 'events']); + }); + } +}); + +test( + 'runAndExit stops a run hung past its deadline, names the phase and exits 1', + { timeout: 5_000 }, + async (t) => { + const hang = () => new Promise(() => undefined); + const source = fakeSource({ + '2026-10-21': [[sourceEvent({ id: 1, createdAt: '2026-10-21T08:00:00.000000Z' })]], + '2026-10-22': [[sourceEvent({ id: 2 })]], + '2026-10-23': [[sourceEvent({ id: 3 })]], + }); + const cases: [string, Parameters[0], RegExp][] = [ + [ + 'a hung account export', + (progress) => + runExportJob({ + exportAccounts: hang, + exportEvents: async () => undefined, + progress, + }), + /deadline, 0.02 s from its start, during the account export$/, + ], + [ + "a hung day's read after a failed day", + (progress) => + runExport({ + source: { + ...source, + async *readDay(day) { + if (day === '2026-10-22') { + yield await hang(); + } + + yield* source.readDay(day); + }, + }, + warehouse: fakeWarehouse(new Map(), { failLoad: ['2026-10-21'] }).warehouse, + hmacKey: KEY, + today: '2026-10-23', + scratchFile: scratch(), + log: () => undefined, + progress, + }), + /during the read of 2026-10-22; days not started: 2026-10-23; 2026-10-21: load job failed$/, + ], + ]; + + for (const [label, main, message] of cases) { + // A run with no watchdog never ends, so each case is bounded. + await t.test(label, { timeout: 2_000 }, async () => { + const exits: number[] = []; + const logged: unknown[] = []; + + await runAndExit(main, { + deadlineMs: 20, + exit: (code) => exits.push(code), + logError: (error) => logged.push(error), + }); + + assert.deepEqual(exits, [1]); + assert.equal(logged.length, 1); + assert.match(String((logged[0] as Error).message), message); + }); + } + }, +); + +test('runAndExit exits with 0 after main resolves, and with 1 after one line naming the phase when it rejects', async (t) => { + const failure = new Error('table check failed'); + const cases: [string, Parameters[0], number, string[]][] = [ + ['a run that succeeds', async () => undefined, 0, []], + [ + 'a run that fails', + async (progress) => { + progress.phase = 'the event table check and day counts'; + throw failure; }, - logError: (error) => logged.push(error), - }), - (error: unknown) => { - assert.ok(error instanceof Error); - assert.equal(error.cause, accountError); - return true; - }, - ); + 1, + ['export Job failed during the event table check and day counts: table check failed'], + ], + ]; + + for (const [label, main, code, messages] of cases) { + await t.test(label, async () => { + const exits: number[] = []; + const logged: Error[] = []; - assert.deepEqual(ran, ['accounts', 'events']); - assert.deepEqual(logged, [accountError]); + await runAndExit(main, { + exit: (exitCode) => exits.push(exitCode), + logError: (error) => logged.push(error as Error), + }); + + assert.deepEqual(exits, [code]); + assert.deepEqual( + logged.map(({ message }) => message), + messages, + ); + assert.ok(logged.every(({ cause }) => cause === failure)); + }); + } }); /** @@ -922,7 +1232,7 @@ test('runExportJob runs the event export after a failed account export, then fai * against Postgres's own per-day count. The page size is 2, so every day * spans pages, rows sit either side of a midnight, three rows share one * time across a page boundary, and each row's props hold a key no event - * keeps. + * keeps. A short page ends a day's read without a further query. */ test('the export reader reads every row of each UTC day and no other table', async (t) => { const database = await createTestDatabase(); @@ -974,7 +1284,26 @@ test('the export reader reads every row of each UTC day and no other table', asy max: 1, }); - const source = pgEventSource(readerPool, 2); + const pool = readerPool; + // The page queries readDay sends, by text. + const pageQueries: string[] = []; + const source = pgEventSource( + { + options: pool.options, + connect: async () => { + const client = await pool.connect(); + + return { + query: (text: string, values?: unknown[]) => { + pageQueries.push(text); + return client.query(text, values); + }, + release: (error?: Error) => client.release(error), + }; + }, + } as unknown as Pool, + { pageSize: 2 }, + ); const { rows: expected } = await admin.query<{ day: string; count: number }>( `select to_char(date_trunc('day', created_at at time zone 'UTC'), 'YYYY-MM-DD') as day, count(*)::int as count @@ -997,6 +1326,10 @@ test('the export reader reads every row of each UTC day and no other table', asy } assert.deepEqual(read, expected); + // Days of 1, 3, 1 and 3 rows take 1, 2, 1 and 2 page queries, each the + // SQL the export_rules digest covers. + assert.equal(pageQueries.length, 6); + assert.ok(pageQueries.every((text) => text === ROW_SHAPE.READ_DAY_SQL)); // The three rows that share 05:00 on 22 October span two pages. assert.deepEqual(ids, [1, 2, 3, 4, 5, 6, 7, 8]); assert.deepEqual( diff --git a/db/test/runtime-pool.test.ts b/db/test/runtime-pool.test.ts index 7bd2597..5a422a8 100644 --- a/db/test/runtime-pool.test.ts +++ b/db/test/runtime-pool.test.ts @@ -76,7 +76,10 @@ class FakeCloudSqlSocket extends EventEmitter { * them. */ test('getCloudSqlRuntimeStream throws a clear error before anything is registered', () => { - assert.throws(() => getCloudSqlRuntimeStream(), /register\(\) must run/); + assert.throws( + () => getCloudSqlRuntimeStream(), + /instrumentation\.ts's register\(\).+export-events\.ts's main\(\) must set it/, + ); }); test('buildRuntimePool wires the Cloud SQL path to the registered stream factory', async (t) => { diff --git a/deploy/README.md b/deploy/README.md index 36ebeb3..07040e0 100644 --- a/deploy/README.md +++ b/deploy/README.md @@ -83,15 +83,26 @@ The Job reads the database as its own IAM user, a member of the NOLOGIN role `we | `EXPORT_BQ_DATASET` | The BigQuery dataset | | `EXPORT_ID_HMAC_KEY` | Key for the visitor and user id digests | -Each run replaces every UTC day from the latest day in the table minus one through today, so a missed run is made up by the next one. When the table is empty or missing, the Job creates it and loads every day from the first event. The run also replaces every earlier day whose count of `event` rows differs from its partition's row count. It takes both counts per day up front, one `GROUP BY` over the whole `event` table and the partitions' row counts from the dataset's `INFORMATION_SCHEMA.PARTITIONS`, which reads table metadata and scans no rows. Each day is read in pages, in `created_at` and id order with each page starting after the last row of the one before, and only with the prop keys `PROP_RULES` keeps. The pages go to a scratch file, then load into the day's partition (`event$YYYYMMDD`, `WRITE_TRUNCATE`, `ALLOW_FIELD_ADDITION`). A load adds a new NULLABLE column to the table, and fails on a new REQUIRED one, so `ExportField` in `db/event-export.ts` lets a column be REQUIRED only if the table was created with it. +Each run replaces every UTC day from the latest day in the table minus one through today, so a missed run is made up by the next one. When the table is empty or missing, the Job creates it and loads every day from the first event. The run also replaces every earlier day whose count of `event` rows differs from its partition's row count. It takes both counts per day up front: one `GROUP BY` over the whole `event` table in Postgres, and one query over the BigQuery table that counts each day's rows and finds its stale days (below). The window days load first, oldest first, then the earlier days, oldest first, so yesterday and today load before any backlog. Each day is read in pages, in `created_at` and id order with each page starting after the last row of the one before, and only with the prop keys `PROP_RULES` keeps. A page shorter than the page size ends the day's read. The pages go to a scratch file, then load into the day's partition (`event$YYYYMMDD`, `WRITE_TRUNCATE`, `ALLOW_FIELD_ADDITION`). A load adds a new NULLABLE column to the table, and fails on a new REQUIRED one, so `ExportField` in `db/event-export.ts` lets a column be REQUIRED only if the table was created with it. The scratch file sits in `os.tmpdir()`, which on Cloud Run is in memory, so a run holds one page of rows plus one day's file, about 360 bytes an event. The busiest day so far holds 1,434 events, about 0.5 MB, against the Job's 512 MiB. The file is written in full before its load starts, so a day loads only once it has been read to its end. A replace never shrinks a partition. Nothing deletes `event` rows, and they carry no foreign key to `user`, so deleting an account leaves them in place. A day that reads fewer rows than its partition holds is therefore a fault, such as a wrong database, an emptied table or a lagging replica. That day keeps its partition, the other days still load, and the run then fails naming each short day with both counts, as it does for a day that reads fewer rows than its source count from the start of the run, whatever its partition holds. Its counts still differ, so the day stays in every later run, however many later days load, and fails each one until it matches. The Job's failure alert therefore fires on every run until the export is complete. A day that reads no rows and holds none loads nothing. -A day whose read or load fails keeps its partition as it was, and the later days still load. The run then fails naming every such day with its error, and any short day. The Job logs each day as it finishes. A database query that runs past 5 minutes fails its day (`statement_timeout` on the Job's pool); a query that fails outside a day's read, such as the per-day count, fails the run. A BigQuery query that bills more than 1 GB or runs past 2 minutes fails the run (`maximumBytesBilled` and `jobTimeoutMs`). The stale-day query scans about 74 bytes an event row, so it reaches the 1 GB cap at about 13.5 million rows, and the run then fails with an error naming the cap. Days that each wait out a 5 minute timeout could outlast the Job's 1800 s task timeout, so a run starts no new day once 20 minutes have passed since it began (`EXPORT_BUDGET_MS` in `db/event-export.ts`). It finishes the day in hand, then fails naming every day it did not reach, with any failed or short day, and the next run picks those days up. +A day whose read or load fails keeps its partition as it was, and the later days still load. The run then fails naming every such day with its error, and any short day. The Job logs each day as it finishes, and a failure outside a day's read or load, such as the per-day count, fails the run. Either way the Job logs one error naming the phase it failed in, and exits 1 (`runAndExit` in `db/event-export.ts`). A BigQuery query that bills more than 1 GB fails the run (`maximumBytesBilled`). The BigQuery query that counts each day and finds its stale days scans about 74 bytes an event row, so it reaches the 1 GB cap at about 13.5 million rows, and the run then fails with an error naming the cap. -Every row carries in `export_rules` a digest of what shapes it (`exportRules` in `db/event-export.ts`): `PROP_RULES`, `PAGE_PATH`, `SHARE_PATH`, the token rule, the schema, `ROW_SHAPE_VERSION` and an HMAC of a fixed string under `EXPORT_ID_HMAC_KEY`. `ROW_SHAPE_VERSION` is bumped by hand with any change to the functions that build a row. Each run finds the days holding a row with another digest, or none, in one query over the `created_at` and `export_rules` columns, and replaces those days too. A change to the rules or the key thus reaches every partition. A day that fails keeps its old rows, so the next run retries it with the window days and the count-mismatch days, and reloads no day that is already current. +Every call the Job makes has its own time bound, and a call past it fails its day or its phase: + +- a database connection, 30 seconds (`connectionTimeoutMillis` on the Job's pool); +- the per-day count, 5 minutes on the server (`statement_timeout`), and 5 seconds more on the Job's side for a connection that stalls where the server's timeout cannot reach it; +- the account read, 5 minutes a query on the server, and 10 minutes 5 seconds on the Job's side for its two queries together; +- a day's page queries together, 5 minutes from the day's start plus 5 seconds, on the Job's side; +- a BigQuery query, 2 minutes on the server (`jobTimeoutMs`) and 5 seconds more on the Job's side, as for each table read or create; +- a load, the account export's included, 2 minutes, after which the Job cancels it and waits at most 10 seconds for the cancel (`loadWithin` in `db/bounded.ts`). + +A database call past its bound on the Job's side leaves its connection mid-query, so the Job destroys that connection and the next call opens a new one (`callWithin` in `db/bounded.ts`). The Job stops a run still going 28 minutes after its start (`JOB_DEADLINE_MS`), two minutes before the task timeout, whatever call is in flight. It logs one error naming the phase (the account export, the day counts, or a named day's read or load), the days not started, and the failed and short days so far, after the lines each finished day already logged, and exits 1. The window days run first, so a run stopped this way has loaded yesterday and today before the backlog, and the next hourly run picks up the days it did not reach. The Job also exits as soon as the run ends, which closes the pool, the connector and any upload socket a load past its timeout left open. + +Every row carries in `export_rules` a digest of what shapes it (`exportRules` in `db/event-export.ts`): `PROP_RULES`, `PAGE_PATH`, `SHARE_PATH`, the token rule, the schema, the SQL that reads a day's page, `ROW_SHAPE_VERSION` and an HMAC of a fixed string under `EXPORT_ID_HMAC_KEY`. `ROW_SHAPE_VERSION` is bumped by hand with any change to the functions that build a row, and a test pins each version's rows for a fixed sample of events, so a change to the rows without a bump fails CI. Each run finds the days holding a row with another digest, or none, in the same query over the `created_at` and `export_rules` columns that counts each day's rows, and replaces those days too. A change to the rules or the key thus reaches every partition. A day that fails keeps its old rows, so the next run retries it with the window days and the count-mismatch days, and reloads no day that is already current. The table is partitioned by day on `created_at`: diff --git a/docs/analytics.md b/docs/analytics.md index 3a00f84..c3df018 100644 --- a/docs/analytics.md +++ b/docs/analytics.md @@ -94,13 +94,13 @@ To check it on production, open the network panel and filter on `google-analytic ## Request log -The site writes one JSON line to stdout for each logged request, which Cloud Logging stores as a structured entry. `src/instrumentation.ts` registers `registerRequestLogging()` in `src/lib/proxy/requestLog.ts` at server startup. It subscribes to Node's `http.server.request.start` diagnostic channel and attaches one `close` listener to each response. Node emits `close` after `finish`, so every request writes exactly one line, when its response closes, with `finished` true for a response that ended normally. A response that closes before it ends, such as a page render the visitor abandons, an aborted RSC fetch or an `/mcp` event stream the client closes, writes its line then, with the status code it had sent. A request accepted before the subscription starts has no listener, so its line is written when its response finishes. Visitor counts come from this line, because Cloud Run's own request log records Cloudflare's edge address as the client. +The site writes one JSON line to stdout for each logged request, which Cloud Logging stores as a structured entry. `src/instrumentation.ts` registers `registerRequestLogging()` in `src/lib/proxy/requestLog.ts` at server startup. It subscribes to Node's `http.server.request.start` diagnostic channel, reads each request's target there, and attaches one `close` listener to each response it logs. A static asset gets no listener. Node emits `close` after `finish`, so every request writes exactly one line, when its response closes, with `finished` true for a response that ended normally. A response that closes before it ends, such as a page render the visitor abandons, an aborted RSC fetch or an `/mcp` event stream the client closes, writes its line then, with the status code it had sent. A request accepted before the subscription starts has no listener, so its line is written when its response finishes. Visitor counts come from this line, because Cloud Run's own request log records Cloudflare's edge address as the client. ```json {"severity":"INFO","message":"request","caller":"ip:3f9c0a…","method":"GET","path":"/embed/abc123","host":"developmentfinance.org","kind":"page","status":200,"finished":true,"bot":false,"prerender":false} ``` -`caller` is the same `ip:` the `/mcp` proxy sends upstream as `x-dfo-caller` (`src/lib/proxy/caller.ts`): an HMAC of the client address under `CALLER_HMAC_KEY`, with the address taken from `X-Forwarded-For` at the `TRUSTED_PROXY_HOPS` position. It is null when the key is unset or the request carries no usable address. `path` is the request target as it arrived, captured when the request starts so a later rewrite does not change it. It has no query string or fragment, and dot segments are resolved, so `/a/../mcp` is logged as `/mcp`. A target such as `//mcp` is a path and not a host, and is logged as `//mcp`. An absolute-form target such as `http://host/path` is logged as its pathname, and an absolute-form target whose URL does not parse is logged as the raw target cut at its first `?` or `#`. The asterisk-form target of `OPTIONS *` is logged as `*`, with kind `page`. `kind` is `api` for `/api`, `/mcp`, `/openapi.json` and `/codes` and every path below each of them (`/apiary` is not one). That covers the site's own endpoints under `/api`, such as auth, events and share, as well as the platform proxy's routes. `kind` is `prefetch` for a Next.js prefetch (`Next-Router-Prefetch`) or a browser prefetch (`Sec-Purpose: prefetch`), `rsc` for a client-side navigation (`RSC: 1`) and `page` for everything else. A `Sec-Purpose` header does not change the kind of an RSC fetch or a Next.js prefetch. Embeds under `/embed/` are logged as pages. `/_next/` files, images and fonts are not logged, and are dropped before the line's headers are read or its caller computed. `status` is the response's HTTP status code. `finished` is true when the response ended normally and false when it closed first, so a status of 200 with `finished` false is a visitor who left a stream. A response that closes before the app sent a status has none of its own, so the line carries 499 (client closed request) with `finished` false. The 499 means the app sent no status before the connection closed. It also covers a response Node answered itself, such as a 408 on a request timeout or a 400 on a client error, which never passes through the app. A response that called `writeHead` but wrote nothing to the socket before the close is logged with that status and `finished` false. Infra's parse keeps the line and counts it as a 4xx, outside the readers' 2xx count. Infra's `website_requests_daily` counts a line whose response did not finish like a finished one. `prerender` is true for a document request (no `RSC` and no `Next-Router-Prefetch` header) with `Sec-Purpose: prefetch;prerender`: the browser renders the page ahead of time and shows it on activation with no second request, so that one line is the page view. It has kind `page` and not `prefetch`, which keeps infra's `website_requests_daily` counting it as a parsed page request. The line is a page view whether or not the visitor opens the page, because the server cannot see activation. `bot` is true when the `User-Agent` header is missing or empty, or when the `isbot` package flags it: crawlers such as Googlebot, bingbot and ClaudeBot, link previews such as Slack's and Discord's, headless browsers and tools such as curl. A client that sends a browser's user agent counts as a reader. The line holds no raw IP address, query string, cookie, `Authorization` header or user agent. +`caller` is the same `ip:` the `/mcp` proxy sends upstream as `x-dfo-caller` (`src/lib/proxy/caller.ts`): an HMAC of the client address under `CALLER_HMAC_KEY`, with the address taken from `X-Forwarded-For` at the `TRUSTED_PROXY_HOPS` position. It is null when the key is unset or the request carries no usable address. `path` is the request target as it arrived, captured when the request starts so a later rewrite does not change it. It has no query string or fragment, and dot segments are resolved, so `/a/../mcp` is logged as `/mcp`. A target such as `//mcp` is read as a path and logged as `//mcp`. An http or https absolute-form target such as `http://host/path` is logged as its pathname. Any other target, such as one with another scheme (`ftp://`, `file:`, `mailto:`), an authority-form `host:port`, or an http or https URL that does not parse, is logged as the fixed path `/:unparsable`, since it can hold a user name, a password or an IP address. The asterisk-form target of `OPTIONS *` is logged as `*`, with kind `page`. `kind` is `api` for `/api`, `/mcp`, `/openapi.json` and `/codes` and every path below each of them (`/apiary` is not one). That covers the site's own endpoints under `/api`, such as auth, events and share, as well as the platform proxy's routes. `kind` is `prefetch` for a Next.js prefetch (`Next-Router-Prefetch`) or a browser prefetch (`Sec-Purpose: prefetch`), `rsc` for a client-side navigation (`RSC: 1`) and `page` for everything else. A `Sec-Purpose` header does not change the kind of an RSC fetch or a Next.js prefetch. Embeds under `/embed/` are logged as pages. `/_next/` files, images and fonts are not logged, and are dropped before the line's headers are read or its caller computed. `status` is the response's HTTP status code. `finished` is true when the response ended normally and false when it closed first, so a status of 200 with `finished` false is a visitor who left a stream. A response that closes before the app sent a status has none of its own, so the line carries 499 (client closed request) with `finished` false. The 499 means the app sent no status before the connection closed. It also covers a response Node answered itself, such as a 408 on a request timeout or a 400 on a client error, which never passes through the app. A response that called `writeHead` but wrote nothing to the socket before the close is logged with that status and `finished` false. Infra's parse keeps the line and counts it as a 4xx, outside the readers' 2xx count. Infra's `website_requests_daily` counts a line whose response did not finish like a finished one. `prerender` is true for a document request (no `RSC` and no `Next-Router-Prefetch` header) with `Sec-Purpose: prefetch;prerender`: the browser renders the page ahead of time and shows it on activation with no second request, so that one line is the page view. It has kind `page`, which keeps infra's `website_requests_daily` counting it as a parsed page request. The line is a page view whether or not the visitor opens the page, because the server cannot see activation. `bot` is true when the `User-Agent` header is missing or empty, or when the `isbot` package flags it: crawlers such as Googlebot, bingbot and ClaudeBot, link previews such as Slack's and Discord's, headless browsers and tools such as curl. A client that sends a browser's user agent counts as a reader. The line holds no raw IP address, query string, cookie, `Authorization` header or user agent. The line reads the request's raw headers, which keep the `RSC` and `Next-Router-Prefetch` headers that Next.js removes from `request.headers`. Logging leaves request bodies unread, so API and MCP payloads stream to their handlers in full. A Next.js proxy would buffer those bodies and truncate them at its default 10 MB limit. diff --git a/src/lib/proxy/requestLog.ts b/src/lib/proxy/requestLog.ts index b83b704..78d11d0 100644 --- a/src/lib/proxy/requestLog.ts +++ b/src/lib/proxy/requestLog.ts @@ -17,7 +17,9 @@ import { requestCaller } from './caller.ts'; * connection closed. * * `path` is the request target as it arrived at `http.server.request.start`, - * without its query string, with dot segments resolved. `caller` is the + * without its query string, with dot segments resolved, or `/:unparsable` for + * a target that is not origin-form, `*`, or an http or https URL that + * parses. `caller` is the * same `ip:` the /mcp proxy sends as x-dfo-caller (see caller.ts). * `bot` is true when the User-Agent header is missing, empty or one isbot * flags. `prerender` is true for a document request with `Sec-Purpose: @@ -119,31 +121,53 @@ export const requestLogEntry = ( }; }; -// The request target as it arrived, kept because Next.js can rewrite -// `request.url` before the response ends. -const arrivedTargets = new WeakMap(); +// The path of each logged request's target as it arrived, kept because +// Next.js can rewrite `request.url` before the response ends. +const arrivedPaths = new WeakMap(); // Client closed request, the status for a response whose app sent no status // before the connection closed. const CLIENT_CLOSED_REQUEST = 499; /** - * The path of a request target. An origin-form target resolves against a - * placeholder host, which reads `//mcp` as a path and not a host and resolves - * dot segments; an absolute-form target keeps its own pathname. The - * asterisk-form target of `OPTIONS *` is its own path. A target whose URL does - * not parse is cut at its first `?` or `#`, so the request still writes a line. + * The path a target is logged as when it is neither origin-form, an http or + * https absolute-form target that parses, nor `*`, since a target of any + * other form or scheme can hold userinfo or an IP address. + */ +const UNPARSABLE_TARGET_PATH = '/:unparsable'; + +const HTTP_ABSOLUTE_FORM = /^https?:\/\//i; + +/** + * The path of a request target. An origin-form target (one starting with + * `/`) resolves against a placeholder host, which reads `//mcp` as the path + * `//mcp` and resolves dot segments, and is cut at its first `?` or `#` + * if its URL does not parse. An http or https absolute-form target keeps + * its own pathname. The asterisk-form target of `OPTIONS *` is its own + * path. Every other target is UNPARSABLE_TARGET_PATH, so the request still + * writes a line. */ const targetPath = (target: string): string => { if (target === '*') { return target; } + if (target.startsWith('/')) { + try { + return new URL(`http://localhost${target}`).pathname; + } catch { + return target.split(/[?#]/, 1)[0] ?? target; + } + } + + if (!HTTP_ABSOLUTE_FORM.test(target)) { + return UNPARSABLE_TARGET_PATH; + } + try { - return new URL(/^https?:\/\//i.test(target) ? target : `http://localhost${target}`) - .pathname; + return new URL(target).pathname; } catch { - return target.split(/[?#]/, 1)[0] ?? target; + return UNPARSABLE_TARGET_PATH; } }; @@ -177,7 +201,7 @@ export const logRequest = ( response: { status: number; finished: boolean }, ): void => { try { - const path = targetPath(arrivedTargets.get(request) ?? request.url ?? '/'); + const path = arrivedPaths.get(request) ?? targetPath(request.url ?? '/'); if (isStaticAsset(path)) { return; @@ -220,7 +244,8 @@ const httpPair = ( ? { request: message.request, response: message.response } : undefined; -// The close listener logs every request that arrived after registration. +// The close listener logs every request that arrived after registration, +// apart from a static asset, which gets no listener and no entry. // ServerResponse emits `close` after `finish`, so one listener covers a // response that ends and one that does not. const onRequestStart = (message: unknown): void => { @@ -231,8 +256,13 @@ const onRequestStart = (message: unknown): void => { } const { request, response } = pair; + const path = targetPath(request.url ?? '/'); + + if (isStaticAsset(path)) { + return; + } - arrivedTargets.set(request, request.url ?? '/'); + arrivedPaths.set(request, path); response.once('close', () => { logRequest(request, { status: response.headersSent ? response.statusCode : CLIENT_CLOSED_REQUEST, @@ -242,11 +272,14 @@ const onRequestStart = (message: unknown): void => { }; // A request accepted before registration has no close listener, so its finish -// writes the line. +// writes the line. A static asset that arrived after it has no entry either, +// so logRequest reads its path from `request.url` at finish and drops it. A +// handler that rewrote it to a logged path would log it under that path; no +// rewrite in next.config.ts does that. const onResponseFinish = (message: unknown): void => { const pair = httpPair(message); - if (pair && !arrivedTargets.has(pair.request)) { + if (pair && !arrivedPaths.has(pair.request)) { logRequest(pair.request, { status: pair.response.statusCode, finished: true }); } }; @@ -254,8 +287,9 @@ const onResponseFinish = (message: unknown): void => { /** * Observe HTTP headers without reading or buffering a request body. A request * accepted before this runs is still logged when its response finishes. + * Returns a function that removes the subscribers. */ -export const registerRequestLogging = (): void => { +export const registerRequestLogging = (): (() => void) => { const previous = globalForRequestLog.dfoRequestLogSubscribers; if (previous) { @@ -269,4 +303,13 @@ export const registerRequestLogging = (): void => { start: onRequestStart, finish: onResponseFinish, }; + + return () => { + unsubscribe(REQUEST_START, onRequestStart); + unsubscribe(RESPONSE_FINISH, onResponseFinish); + + if (globalForRequestLog.dfoRequestLogSubscribers?.start === onRequestStart) { + delete globalForRequestLog.dfoRequestLogSubscribers; + } + }; }; diff --git a/src/lib/proxy/test/requestLog.test.ts b/src/lib/proxy/test/requestLog.test.ts index a59a3c2..8ebe2b6 100644 --- a/src/lib/proxy/test/requestLog.test.ts +++ b/src/lib/proxy/test/requestLog.test.ts @@ -245,7 +245,7 @@ test('logRequest: no client address logs a null caller', () => { assert.equal((line as { caller: unknown }).caller, null); }); -test('logRequest: the path is the target without its query, resolved, with //mcp kept as a path, * as itself and an unparsable URL cut at its query', () => { +test('logRequest: the path is the target without its query, resolved, with //mcp kept as a path, * as itself and any other target as a placeholder', () => { // [target, logged path or null for a dropped static asset, kind] const cases: [string, string | null, string][] = [ ['//mcp', '//mcp', 'page'], @@ -257,7 +257,13 @@ test('logRequest: the path is the target without its query, resolved, with //mcp ['http://host/_next/static/x.js', null, 'page'], ['https://host/api/v1/search?q=secret', '/api/v1/search', 'api'], ['*', '*', 'page'], - ['http://[bad/path?q=secret#frag', 'http://[bad/path', 'page'], + ['http://[bad/path?q=secret#frag', '/:unparsable', 'page'], + ['http://user:pw@203.0.113.7:99999/x?q=secret', '/:unparsable', 'page'], + ['ftp://user:pw@203.0.113.7/x?q=secret', '/:unparsable', 'page'], + ['ws://user:pw@203.0.113.7/mcp', '/:unparsable', 'page'], + ['file:///etc/passwd', '/:unparsable', 'page'], + ['mailto:a@b', '/:unparsable', 'page'], + ['example.com:443', '/:unparsable', 'page'], ]; for (const [target, path, kind] of cases) { @@ -323,7 +329,7 @@ test('server logging catches a request accepted during startup with its original // Next.js may normalise these headers before a startup request finishes. delete request.headers.rsc; delete request.headers['x-forwarded-for']; - registerRequestLogging(); + t.after(registerRequestLogging()); response.statusCode = 404; response.end('ok'); }); @@ -364,8 +370,8 @@ test( // A dev reload evaluates the module again, so its subscriber is a new function. const reloadedModule = '../requestLog.ts?reload'; const reloaded = (await import(reloadedModule)) as typeof import('../requestLog.ts'); - registerRequestLogging(); - reloaded.registerRequestLogging(); + t.after(registerRequestLogging()); + t.after(reloaded.registerRequestLogging()); const firstChunk = Promise.withResolvers(); const server = createServer(async (request, response) => { @@ -462,7 +468,7 @@ const listen = async ( test('server logging writes one line with finished true for a response that finishes', async (t) => { const lines: unknown[] = []; t.mock.method(console, 'log', (line: string) => lines.push(JSON.parse(line))); - registerRequestLogging(); + t.after(registerRequestLogging()); const closed = Promise.withResolvers(); const port = await listen(t, (_request, response) => { response.once('close', () => closed.resolve()); @@ -489,7 +495,7 @@ test( lines.push(JSON.parse(line)); logged.resolve(); }); - registerRequestLogging(); + t.after(registerRequestLogging()); const closed = Promise.withResolvers(); const port = await listen(t, (_request, response) => { response.once('close', () => closed.resolve()); @@ -534,7 +540,7 @@ test( lines.push(JSON.parse(line)); logged.resolve(); }); - registerRequestLogging(); + t.after(registerRequestLogging()); const received = Promise.withResolvers(); const port = await listen(t, () => { // The handler sends nothing, not even the headers. @@ -563,13 +569,17 @@ test( test('server logging logs the target as it arrived when a handler rewrites request.url', async (t) => { const lines: unknown[] = []; t.mock.method(console, 'log', (line: string) => lines.push(JSON.parse(line))); - registerRequestLogging(); + t.after(registerRequestLogging()); + const closed = Promise.withResolvers(); const port = await listen(t, (request, response) => { + response.once('close', () => closed.resolve()); request.url = '/_next/static/rewritten.js'; response.end('ok'); }); await (await fetch(`http://127.0.0.1:${port}/mcp?token=private-query`)).text(); + // The line is written on close, which can follow the body's arrival. + await closed.promise; assert.deepEqual( lines.map((line) => ({ @@ -579,3 +589,33 @@ test('server logging logs the target as it arrived when a handler rewrites reque [{ path: '/mcp', kind: 'api' }], ); }); + +test('server logging attaches no close listener to a static asset response', async (t) => { + const lines: unknown[] = []; + t.mock.method(console, 'log', (line: string) => lines.push(JSON.parse(line))); + t.after(registerRequestLogging()); + const listeners = new Map(); + const closed: Promise[] = []; + const port = await listen(t, (request, response) => { + listeners.set(request.url ?? '', response.listenerCount('close')); + const done = Promise.withResolvers(); + closed.push(done.promise); + response.once('close', () => done.resolve()); + response.end('ok'); + }); + + for (const path of ['/_next/static/chunks/main.js', '/studio']) { + await (await fetch(`http://127.0.0.1:${port}${path}`)).text(); + } + await Promise.all(closed); + + // The logged page carries the one listener the asset lacks. + assert.equal( + listeners.get('/studio'), + (listeners.get('/_next/static/chunks/main.js') ?? 0) + 1, + ); + assert.deepEqual( + lines.map((line) => (line as { path: string }).path), + ['/studio'], + ); +});