diff --git a/Source/index.ts b/Source/index.ts index 4b4124f..d4f3a31 100644 --- a/Source/index.ts +++ b/Source/index.ts @@ -107,8 +107,7 @@ const ValidateSession = async (sessionID: string): Promise => { export {NotificationManager}; -export default { - async fetch(RequestData: Request, Environment: Environment, Context: any) { +const HandleRequest = async (RequestData: Request, Environment: Environment): Promise => { const origin = RequestData.headers.get("Origin") || ""; if (RequestData.method === "OPTIONS") { const allowedOrigin = getAllowedOrigin(origin); @@ -152,6 +151,36 @@ export default { let Processor = new Process(RequestData, Environment); return addCorsHeaders(await Processor.Process(), origin); +}; + +// Workers' automatic invocation logs are off (see wrangler.toml) because they +// record full URLs and headers, and the notification WebSocket carries the +// session ID in its query string. This is our replacement: one line per request +// with what we need for debugging, and never the query string or headers. +export const RequestLogLine = (RequestData: Request, Status: number, Duration: number, Failure?: unknown) => { + const Cf: any = (RequestData as any).cf || {}; + return { + method: RequestData.method, + path: new URL(RequestData.url).pathname, + status: Status, + durationMs: Duration, + colo: Cf.colo, + country: Cf.country, + error: Failure === undefined ? undefined : Failure instanceof Error ? (Failure.stack ?? Failure.message) : String(Failure) + }; +}; + +export default { + async fetch(RequestData: Request, Environment: Environment, Context: any) { + const Start = Date.now(); + try { + const Response = await HandleRequest(RequestData, Environment); + console.log(RequestLogLine(RequestData, Response.status, Date.now() - Start)); + return Response; + } catch (Failure) { + console.error(RequestLogLine(RequestData, 500, Date.now() - Start, Failure)); + throw Failure; + } }, async scheduled(Event: any, Environment: { DB: D1Database; kv: KVNamespace; }, Context: { waitUntil: (arg0: Promise) => void; diff --git a/test/index.test.js b/test/index.test.js new file mode 100644 index 0000000..2c479f8 --- /dev/null +++ b/test/index.test.js @@ -0,0 +1,28 @@ +const test = require('node:test'); +const assert = require('node:assert'); +const { RequestLogLine } = require('../Source/index.ts'); + +test('RequestLogLine never includes the query string', () => { + const req = new Request('https://api.xmoj-script.uk/ws/notifications?SessionID=abc123secret'); + const line = RequestLogLine(req, 101, 12); + assert.strictEqual(line.path, '/ws/notifications'); + assert.strictEqual(line.status, 101); + assert.strictEqual(line.durationMs, 12); + assert.ok(!JSON.stringify(line).includes('abc123secret')); +}); + +test('RequestLogLine records the failure when one is given', () => { + const line = RequestLogLine(new Request('https://api.xmoj-script.uk/GetPost', { method: 'POST' }), 500, 3, new Error('boom')); + assert.strictEqual(line.method, 'POST'); + assert.match(line.error, /^Error: boom\n\s+at /, 'errors keep their stack'); +}); + +test('RequestLogLine stringifies non-Error throws', () => { + const line = RequestLogLine(new Request('https://api.xmoj-script.uk/GetPost'), 500, 3, 'plain failure'); + assert.strictEqual(line.error, 'plain failure'); +}); + +test('RequestLogLine leaves error unset on success', () => { + const line = RequestLogLine(new Request('https://api.xmoj-script.uk/GetNotice'), 200, 1); + assert.strictEqual(line.error, undefined); +}); diff --git a/wrangler.toml b/wrangler.toml index a656c22..e842396 100644 --- a/wrangler.toml +++ b/wrangler.toml @@ -20,6 +20,12 @@ binding = "logdb" [observability] enabled = true +# Invocation logs record every request's URL and headers. The notification +# WebSocket carries the session ID in its URL (/ws/notifications?SessionID=...), +# so they would store raw PHPSESSIDs. Our own console logs (hash-only) are kept. +[observability.logs] +invocation_logs = false + [[durable_objects.bindings]] name = "NOTIFICATIONS"