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' }], + ); +});