[api] audit logging

apps/notify/README.md

@@ -23,6 +23,15 @@ instance holds the shared hub state (one process across all connections).
   `MessageReceived` to every connected client (online-only; not persisted). Same
   admin-role gate.
 
+Every `/internal/*` call — including one the role gate refuses, and one that 404s — is
+recorded on the shared database's `audit_log` table, against the account that made it:
+`player_id` is the caller, `action` is the path as a snake_case verb (`coach_message`),
+and `data` carries the request body or query string plus the response status. The write
+happens in the admin gate, so a new `/internal/*` endpoint is audited the day it is added.
+A token carrying an admin role but no usable `sub` is refused (401) rather than let through
+unattributable. A failed audit write never fails the call; it leaves an error in the worker
+log. The table is owned by the `api` worker (`apps/api/migrations/0024_audit_log.sql`).
+
 ## Hub protocol
 
 1. Client `POST /hub/v1/negotiate`, then opens a WebSocket to `/hub/v1?id=<token>`.

apps/notify/src/notify.app.ts

@@ -1,7 +1,7 @@
 import { Hono } from 'hono'
 import { useWorkersLogger } from 'workers-tagged-logger'
 
-import { createNotification } from '@repo/domain'
+import { createNotification, writeAuditLog } from '@repo/domain'
 import { logger, withDefaultCors, withNotFound, withOnError } from '@repo/hono-helpers'
 import { validateAndGetAccountId, validateAndGetRoles } from '@repo/jwt'
 
@@ -119,16 +119,100 @@ async function connectionOwner(c: Context<App>): Promise<number | null> {
 	)
 }
 
+/**
+ * The `action` an `/internal/<path>` call is recorded under — the path after the prefix as a
+ * stable snake_case verb, so `/internal/coach-message` files under `coach_message`.
+ *
+ * Derived rather than mapped, so the audit trail can't fall behind the routes: a new
+ * `/internal/*` endpoint is logged the day it is added, with no second list to keep in sync.
+ * The cost is that the value comes from the request, so it is squeezed down to `[a-z0-9_]`
+ * and capped — this middleware also runs for `/internal/` paths that match no route at all
+ * (they 404 just after it), and an admin token reaching for one is still worth a row.
+ */
+function auditAction(path: string): string {
+	const slug = path
+		.replace(/^\/internal\/?/, '')
+		.toLowerCase()
+		.replace(/[^a-z0-9]+/g, '_')
+		.replace(/^_+|_+$/g, '')
+		.slice(0, 64)
+	return slug === '' ? 'unknown' : slug
+}
+
+/**
+ * Record one `/internal/*` call against the account that made it.
+ *
+ * What is kept is what was ASKED FOR plus how it was answered: the request body (or the
+ * query string, for the reads) is the substance of the action — a coach message's text and
+ * recipient exist nowhere else once the frame has gone out, and a broadcast is a WebSocket
+ * frame and then nothing — and the status says whether it happened. Reading the body here
+ * costs nothing: Hono caches a parsed body on the request, so this is the same object the
+ * handler parsed rather than a second read of a consumed stream.
+ *
+ * Never throws. By the time this runs the action has usually already taken place, so a
+ * failed insert must not turn a delivered coach message into an error for the caller — it
+ * leaves a loud line in the worker log instead, which is the one thing a gap in an audit
+ * trail should never do quietly.
+ */
+async function recordInternalCall(c: Context<App>, playerId: number, status: number) {
+	const action = auditAction(c.req.path)
+	const data: Record<string, unknown> = { method: c.req.method, path: c.req.path, status }
+
+	// A GET carries no body by definition; everything else may, and a request whose body
+	// isn't JSON (or is empty, as the DELETE's is) simply records none.
+	const body = c.req.method === 'GET' ? null : await c.req.json().catch(() => null)
+	if (body !== null) data.body = body
+	const query = c.req.query()
+	if (Object.keys(query).length > 0) data.query = query
+
+	try {
+		await writeAuditLog(c.env.DB, { playerId, action, data })
+	} catch (err) {
+		logger.error('could not write an audit log row', {
+			action,
+			playerId,
+			error: err instanceof Error ? err.message : String(err),
+		})
+	}
+}
+
 /**
  * Gates the `/internal/*` endpoints on a valid Bearer token that carries one of the
  * {@link ADMIN_ROLES} in its `role` claim. 401 for a missing/invalid token, 403 for a
  * valid token that lacks an admin role.
+ *
+ * Also where every call through here is AUDITED (see {@link recordInternalCall}). It sits in
+ * the gate rather than in each handler for the same reason the gate does: these endpoints
+ * are the operator's remote control over every connected client, and a record of who used
+ * it should not be something a new endpoint can forget to add.
  */
 const requireAdmin: MiddlewareHandler<App> = async (c, next) => {
-	const roles = await validateAndGetRoles(c.req.raw, await c.env.JWT_SECRET.get())
+	const secret = await c.env.JWT_SECRET.get()
+	const roles = await validateAndGetRoles(c.req.raw, secret)
 	if (roles === null) return c.json({ error: 'Unauthorized' }, 401)
-	if (!roles.some((role) => ADMIN_ROLES.has(role))) return c.json({ error: 'Forbidden' }, 403)
-	await next()
+
+	// Every call is filed under the account that made it, so a token with an admin role but
+	// no usable `sub` is refused rather than let through unattributable. One minted by `auth`
+	// always has one, so this costs a real caller nothing.
+	const accountId = await validateAndGetAccountId(c.req.raw, secret)
+	if (accountId === null) return c.json({ error: 'Unauthorized' }, 401)
+
+	if (!roles.some((role) => ADMIN_ROLES.has(role))) {
+		// Recorded like any other call: a signed-in account reaching for an admin endpoint is
+		// exactly what an audit trail is kept for, and unlike the 401 above we know who it was.
+		await recordInternalCall(c, accountId, 403)
+		return c.json({ error: 'Forbidden' }, 403)
+	}
+
+	// Recorded AFTER the handler so the row can carry the outcome, and from a `finally` so a
+	// handler that throws is recorded too — as the 500 `onError` is about to answer with.
+	let status = 500
+	try {
+		await next()
+		status = c.res.status
+	} finally {
+		await recordInternalCall(c, accountId, status)
+	}
 }
 
 const app = new Hono<App>()

apps/notify/src/test/integration/api.test.ts

@@ -2,7 +2,7 @@ import { adminSecretsStore, env, runInDurableObject } from 'cloudflare:test'
 import { exports } from 'cloudflare:workers'
 import { beforeAll, describe, expect, test } from 'vitest'
 
-import { NOTIFICATION_SCHEMA_DDL } from '@repo/domain'
+import { AUDIT_LOG_SCHEMA_DDL, NOTIFICATION_SCHEMA_DDL } from '@repo/domain'
 
 import '../../notify.app'
 
@@ -55,6 +55,9 @@ beforeAll(async () => {
 	// The notification store a targeted coach message writes to. Owned by the `api` worker's
 	// migrations, which don't run here, so build it from the mirrored DDL.
 	for (const ddl of NOTIFICATION_SCHEMA_DDL) await env.DB.prepare(ddl).run()
+	// The audit trail every /internal/* call is filed on. Owned by `api` too, so likewise
+	// built from the mirrored DDL.
+	for (const ddl of AUDIT_LOG_SCHEMA_DDL) await env.DB.prepare(ddl).run()
 })
 
 /** Who `connect` is by default — kept clear of the player ids the tests notify. */
@@ -801,3 +804,119 @@ describe('CORS', () => {
 		expect(res.headers.get('access-control-allow-origin')).toBe('*')
 	})
 })
+
+// Every /internal/* call is recorded on the `audit_log` table, against the account that
+// made it. These endpoints are the operator's remote control over every connected client
+// and most of what they do leaves no other trace on the database — a maintenance broadcast
+// is a WebSocket frame and then nothing — so the row is the only lasting answer to "who
+// sent that".
+describe('audit log', () => {
+	interface AuditRow {
+		player_id: number
+		action: string
+		data: string | null
+		date: string
+	}
+
+	/** Everything recorded against one actor, oldest first. */
+	const auditRows = async (playerId: number): Promise<AuditRow[]> => {
+		const { results } = await env.DB.prepare(
+			'SELECT player_id, action, data, date FROM audit_log WHERE player_id = ?1 ORDER BY audit_log_id'
+		)
+			.bind(playerId)
+			.all<AuditRow>()
+		return results
+	}
+
+	const auditData = (row: AuditRow): Record<string, unknown> =>
+		JSON.parse(row.data ?? '{}') as Record<string, unknown>
+
+	// A distinct actor per test: the rest of the file drives these endpoints as account 1,
+	// so filtering on the caller is what keeps each assertion about its own call.
+	test('records a successful call against the caller, with what was asked for', async () => {
+		const actor = 4242
+		const res = await post(
+			'/internal/coach-message',
+			{ playerId: 9500, messageContent: 'audited' },
+			await bearer(String(actor), ['moderator'])
+		)
+		expect(res.status).toBe(200)
+
+		const rows = await auditRows(actor)
+		expect(rows).toHaveLength(1)
+		// The action is the path after `/internal/`, as a snake_case verb.
+		expect(rows[0].action).toBe('coach_message')
+		expect(Number.isNaN(Date.parse(rows[0].date))).toBe(false)
+		expect(auditData(rows[0])).toMatchObject({
+			method: 'POST',
+			path: '/internal/coach-message',
+			status: 200,
+			// The message and its recipient exist nowhere else once the frame has gone out.
+			body: { playerId: 9500, messageContent: 'audited' },
+		})
+	})
+
+	// A refused call is still a call someone made, and here — unlike the 401 below — we know
+	// who made it. A signed-in account reaching for an admin endpoint is close to the whole
+	// point of keeping the trail.
+	test('records a call the role gate refused, with the status that refused it', async () => {
+		const actor = 4243
+		const res = await post(
+			'/internal/broadcast',
+			{ notificationType: 1 },
+			await bearer(String(actor), ['gameClient'])
+		)
+		expect(res.status).toBe(403)
+
+		const rows = await auditRows(actor)
+		expect(rows).toHaveLength(1)
+		expect(rows[0].action).toBe('broadcast')
+		expect(auditData(rows[0]).status).toBe(403)
+	})
+
+	test('records a rejected body as the attempt it was', async () => {
+		const actor = 4244
+		const res = await post(
+			'/internal/coach-message',
+			{ playerId: 9501 },
+			await bearer(String(actor), ['moderator'])
+		)
+		expect(res.status).toBe(400)
+
+		const rows = await auditRows(actor)
+		expect(rows).toHaveLength(1)
+		expect(auditData(rows[0])).toMatchObject({ status: 400, body: { playerId: 9501 } })
+	})
+
+	// The reads are recorded too, and a call that carries its arguments in the query string
+	// rather than a body records those instead.
+	test('records a read, with its query string', async () => {
+		const actor = 4245
+		const res = await exports.default.fetch(`${ORIGIN}/internal/hub-state/pending?all=true`, {
+			method: 'DELETE',
+			headers: await bearer(String(actor), ['developer']),
+		})
+		expect(res.status).toBe(200)
+
+		const rows = await auditRows(actor)
+		expect(rows).toHaveLength(1)
+		expect(rows[0].action).toBe('hub_state_pending')
+		expect(auditData(rows[0])).toMatchObject({ method: 'DELETE', query: { all: 'true' } })
+	})
+
+	// Nothing to file it under: `player_id` is the actor, and a request with no valid token
+	// names nobody. The 401 is the record of that one, in the worker log.
+	test('records nothing for a call with no valid token', async () => {
+		const count = async () =>
+			(await env.DB.prepare('SELECT COUNT(*) AS n FROM audit_log').first<{ n: number }>())!.n
+
+		const before = await count()
+		const res = await exports.default.fetch(`${ORIGIN}/internal/broadcast`, {
+			method: 'POST',
+			headers: { 'Content-Type': 'application/json' },
+			body: JSON.stringify({ notificationType: 1 }),
+		})
+		expect(res.status).toBe(401)
+		expect(await count()).toBe(before)
+	})
+})

apps/notify/wrangler.jsonc

@@ -8,14 +8,21 @@
 		"bindings": [{ "name": "RECFLARE_NOTIFICATIONS_HUB", "class_name": "NotificationsHub" }]
 	},
 	"migrations": [{ "tag": "v1", "new_sqlite_classes": ["NotificationsHub"] }],
-	// The shared `recflare` D1 database, for the message store behind
-	// `GET /api/messages/v2/get`: a coach message to ONE player is a durable message and is
-	// written here before it is pushed. No `migrations_dir` — the `api` worker owns this
-	// schema (apps/api/migrations/0019_message.sql); notify only writes rows.
+	// The shared `recflare` D1 database. Two tables, both owned (and migrated) by the `api`
+	// worker — no `migrations_dir` here; notify only writes rows:
 	//
-	// The coach BROADCAST is deliberately not stored: it reaches everyone online at once, so
-	// persisting it would write a row per player — thousands per maintenance notice, for
-	// something nobody needs to re-read.
+	//  - `notification` (apps/api/migrations/0019_notification.sql), the message store behind
+	//    `GET /api/messages/v2/get`: a coach message to ONE player is a durable message and is
+	//    written there before it is pushed.
+	//  - `audit_log` (apps/api/migrations/0024_audit_log.sql), where EVERY `/internal/*` call
+	//    is recorded against the staff account that made it. These endpoints are the
+	//    operator's remote control over every connected client and most of what they do leaves
+	//    no other trace, so the row is the only lasting answer to "who sent that".
+	//
+	// The coach BROADCAST is deliberately not stored as a notification: it reaches everyone
+	// online at once, so persisting it would write a row per player — thousands per
+	// maintenance notice, for something nobody needs to re-read. Its audit row is one row
+	// either way, which is part of why that trail is worth keeping.
 	"d1_databases": [
 		{
 			"binding": "DB",