diff --git a/docs/analytics.md b/docs/analytics.md index 4e6e8a7..e22d7a9 100644 --- a/docs/analytics.md +++ b/docs/analytics.md @@ -54,6 +54,18 @@ Enhanced measurement records page views on App Router navigations (history chang To check it on production, open the network panel and filter on `google-analytics.com/g/collect`. Before consent the requests carry `gcs=G100`, and after accepting in the banner they carry `gcs=G111`. The visit then shows in GA under Reports → Realtime. Localhost and dev make no `gtag/js` request. +## Request log + +The site writes one JSON line to stdout for each page view and API call, 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.request.start` diagnostic channel and reads the request's method, path, and headers. A request accepted during startup is logged when its response finishes, if it was not already logged at the start. 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","userAgent":"Mozilla/5.0 …"} +``` + +`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. The line holds no raw IP address, query string, cookie or `Authorization` header. + +The diagnostic event carries `RSC` and `Next-Router-Prefetch` headers before Next.js normalises them. 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. + ## Guest Studio The Studio is open without an account: `GUEST_LIMIT` (5, `src/components/organisms/Studio/GuestWall.tsx`) prompts, counted in localStorage, then the prompt is replaced by a sign-in wall. Front-end only by design — a cleared localStorage resets it. Guests get no history, saving or sharing (all need an account). diff --git a/src/instrumentation.ts b/src/instrumentation.ts index 3167d9c..6bd99e7 100644 --- a/src/instrumentation.ts +++ b/src/instrumentation.ts @@ -25,6 +25,9 @@ export async function register(): Promise { await import('../sentry.server.config'); + const { registerRequestLogging } = await import('./lib/proxy/requestLog'); + registerRequestLogging(); + const { assertTrustedHops } = await import('./lib/proxy/caller'); try { diff --git a/src/lib/proxy/caller.ts b/src/lib/proxy/caller.ts index 539edd6..5bb543d 100644 --- a/src/lib/proxy/caller.ts +++ b/src/lib/proxy/caller.ts @@ -190,7 +190,9 @@ export const requestCaller = (incoming: Headers): string | undefined => { if ('problem' in config) { if (!warned) { warned = true; - console.warn(`${config.problem}; MCP calls go upstream without ${CALLER_HEADER}`); + console.warn( + `${config.problem}; MCP calls go upstream without ${CALLER_HEADER} and request logs carry no caller`, + ); } return undefined; diff --git a/src/lib/proxy/requestLog.ts b/src/lib/proxy/requestLog.ts new file mode 100644 index 0000000..9e340eb --- /dev/null +++ b/src/lib/proxy/requestLog.ts @@ -0,0 +1,159 @@ +import { subscribe, unsubscribe } from 'node:diagnostics_channel'; +import { IncomingMessage } from 'node:http'; + +import { requestCaller } from './caller.ts'; + +/** + * One JSON line on stdout per visitor request, registered at server startup, so + * Cloud Logging can count visitors by caller. Cloud Run's own request log + * records Cloudflare's edge address, so it cannot. + * + * `caller` is the same `ip:` the /mcp proxy sends as x-dfo-caller + * (see caller.ts). The line holds no raw address, query string, cookie or + * auth header. + */ +export type RequestKind = 'page' | 'api' | 'rsc' | 'prefetch'; + +export type RequestLogEntry = { + severity: 'INFO'; + message: 'request'; + caller: string | null; + method: string; + path: string; + host: string | null; + kind: RequestKind; + userAgent: string | null; +}; + +type RequestMetadata = Pick; + +// Framework files and images and fonts by extension. +const STATIC_ASSET = /^\/_next\/|\.(?:png|jpe?g|gif|webp|avif|svg|ico|woff2?|ttf|otf)$/i; + +const isApiPath = (path: string): boolean => + /^\/api(?:\/|$)/.test(path) || /^\/mcp(?:\/|$)/.test(path); + +/** + * What a request is, or undefined for a static asset, which is not logged. + * The HTTP diagnostic event carries headers before Next.js normalises them. + */ +export const requestKind = (path: string, headers: Headers): RequestKind | undefined => { + if (STATIC_ASSET.test(path)) { + return undefined; + } + + if (isApiPath(path)) { + return 'api'; + } + + const purpose = headers.get('sec-purpose') ?? headers.get('purpose'); + + if (headers.has('next-router-prefetch') || purpose?.startsWith('prefetch')) { + return 'prefetch'; + } + + return headers.get('rsc') === '1' ? 'rsc' : 'page'; +}; + +/** The log entry for a request, or undefined when it is not logged. */ +export const requestLogEntry = ( + request: RequestMetadata, + caller: string | undefined, +): RequestLogEntry | undefined => { + const path = new URL(request.url).pathname; + const kind = requestKind(path, request.headers); + + if (!kind) { + return undefined; + } + + return { + severity: 'INFO', + message: 'request', + caller: caller ?? null, + method: request.method, + path, + host: request.headers.get('host'), + kind, + userAgent: request.headers.get('user-agent'), + }; +}; + +const requestMetadata = (request: RequestMetadata | IncomingMessage): RequestMetadata => { + if (!(request instanceof IncomingMessage)) { + return request; + } + + const headers = new Headers(); + + // Keep the original headers even when Next.js has already handled the request. + for (let index = 0; index < request.rawHeaders.length; index += 2) { + const name = request.rawHeaders[index]; + const value = request.rawHeaders[index + 1]; + + if (name === undefined) { + continue; + } + + if (value !== undefined) { + headers.append(name, value); + } + } + + return { + url: new URL(request.url ?? '/', 'http://localhost').href, + method: request.method ?? 'GET', + headers, + }; +}; + +/** Write the request's log line. Never throws: a logging fault must not fail the request. */ +export const logRequest = (request: RequestMetadata | IncomingMessage): void => { + try { + const metadata = requestMetadata(request); + const entry = requestLogEntry(metadata, requestCaller(metadata.headers)); + + if (entry) { + console.log(JSON.stringify(entry)); + } + } catch { + // URL and header errors can include raw request data. + console.error('request log failed'); + } +}; + +const REQUEST_CHANNELS = ['http.server.request.start', 'http.server.response.finish']; + +// Share the subscriber and request set across Next dev reloads. +const globalForRequestLog = globalThis as typeof globalThis & { + dfoRequestLogSubscriber?: (message: unknown) => void; + dfoLoggedRequests?: WeakSet; +}; +const loggedRequests = (globalForRequestLog.dfoLoggedRequests ??= new WeakSet()); + +const onServerRequest = (message: unknown): void => { + if ( + typeof message === 'object' && + message !== null && + 'request' in message && + message.request instanceof IncomingMessage && + !loggedRequests.has(message.request) + ) { + loggedRequests.add(message.request); + logRequest(message.request); + } +}; + +/** Observe HTTP headers without reading or buffering a request body. */ +export const registerRequestLogging = (): void => { + for (const channel of REQUEST_CHANNELS) { + if (globalForRequestLog.dfoRequestLogSubscriber) { + unsubscribe(channel, globalForRequestLog.dfoRequestLogSubscriber); + } + + // Finish catches a request accepted before instrumentation registered. + subscribe(channel, onServerRequest); + } + + globalForRequestLog.dfoRequestLogSubscriber = onServerRequest; +}; diff --git a/src/lib/proxy/test/requestLog.test.ts b/src/lib/proxy/test/requestLog.test.ts new file mode 100644 index 0000000..2f263f8 --- /dev/null +++ b/src/lib/proxy/test/requestLog.test.ts @@ -0,0 +1,230 @@ +/** + * `requestLog.ts`: which requests are logged and as what, and that the line + * carries the caller digest but no raw address or query string. + */ +import assert from 'node:assert/strict'; +import { 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'; + +// 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 } = await import('../requestLog.ts'); + +const VISITOR = '203.0.113.7'; + +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'], + ['/apiary', {}, '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], + ]; + + for (const [path, headers, kind] of cases) { + assert.equal(requestKind(path, new Headers(headers)), kind, path); + } +}); + +const captureLog = (request: Request): unknown[] => { + const lines: unknown[] = []; + const original = console.log; + + console.log = (line: string) => lines.push(JSON.parse(line)); + + try { + logRequest(request); + } finally { + console.log = original; + } + + return lines; +}; + +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': 'Mozilla/5.0', + '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); + + const lines = captureLog(request); + + assert.deepEqual(lines, [ + { + severity: 'INFO', + message: 'request', + caller: `ip:${digest}`, + method: 'GET', + path: '/embed/abc123', + host: 'developmentfinance.org', + kind: 'page', + userAgent: 'Mozilla/5.0', + }, + ]); + + const text = JSON.stringify(lines); + + for (const secret of [VISITOR, 'secret', 'token', 's3cret', 't0ken']) { + assert.ok(!text.includes(secret), secret); + } +}); + +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')); + + assert.equal((line as { caller: unknown }).caller, null); +}); + +test('logRequest: malformed raw URLs keep the query out of error output', (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'; + + assert.doesNotThrow(() => logRequest(request)); + assert.deepEqual(errors, [['request log failed']]); +}); + +test('server logging catches a request accepted during startup with its original headers', async (t) => { + const lines: unknown[] = []; + t.mock.method(console, 'log', (line: string) => lines.push(JSON.parse(line))); + const server = createServer((request, response) => { + // Next.js may normalise these headers before a startup request finishes. + delete request.headers.rsc; + delete request.headers['x-forwarded-for']; + registerRequestLogging(); + response.end('ok'); + }); + 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'); + + const response = await fetch(`http://127.0.0.1:${address.port}/studio?token=private-query`, { + headers: { + rsc: '1', + 'x-forwarded-for': `${VISITOR}, 198.51.100.1, 192.0.2.1`, + }, + }); + assert.equal(await response.text(), 'ok'); + assert.equal(lines.length, 1); + assert.equal((lines[0] as { kind: string }).kind, 'rsc'); + assert.equal((lines[0] as { path: string }).path, '/studio'); + assert.equal( + (lines[0] as { caller: string }).caller, + `ip:${createHmac('sha256', 'test-key').update(VISITOR).digest('hex').slice(0, 32)}`, + ); +}); + +test( + 'server logging preserves a streamed body over 10 MiB and logs it once', + { timeout: 10_000 }, + async (t) => { + const lines: unknown[] = []; + t.mock.method(console, 'log', (line: string) => lines.push(JSON.parse(line))); + registerRequestLogging(); + registerRequestLogging(); + + const firstChunk = Promise.withResolvers(); + const server = createServer(async (request, response) => { + assert.equal(request.readableFlowing, null); + const hash = createHash('sha256'); + let bytes = 0; + + for await (const chunk of request) { + bytes += chunk.length; + hash.update(chunk); + firstChunk.resolve(); + } + + response.end(JSON.stringify({ bytes, digest: hash.digest('hex') })); + }); + 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'); + + const upload = httpRequest({ + host: '127.0.0.1', + port: address.port, + method: 'POST', + path: '/mcp?token=private-query', + headers: { + host: 'developmentfinance.org', + 'user-agent': 'body-test', + 'x-forwarded-for': `${VISITOR}, 198.51.100.1, 192.0.2.1`, + cookie: 'session=private-cookie', + authorization: 'Bearer private-token', + }, + }); + t.after(() => upload.destroy()); + const responseReady = once(upload, 'response'); + const head = Buffer.alloc(64 * 1024, 'a'); + const tail = Buffer.alloc(11 * 1024 * 1024 - head.length, 'b'); + upload.write(head); + + // The handler must receive data while the client is still uploading. + await firstChunk.promise; + upload.end(tail); + const [response] = await responseReady; + let body = ''; + + for await (const chunk of response) { + body += chunk; + } + + assert.equal(response.statusCode, 200); + assert.deepEqual(JSON.parse(body), { + bytes: head.length + tail.length, + digest: createHash('sha256').update(head).update(tail).digest('hex'), + }); + assert.deepEqual(lines, [ + { + severity: 'INFO', + message: 'request', + caller: `ip:${createHmac('sha256', 'test-key').update(VISITOR).digest('hex').slice(0, 32)}`, + method: 'POST', + path: '/mcp', + host: 'developmentfinance.org', + kind: 'api', + userAgent: 'body-test', + }, + ]); + }, +);