diff --git a/CHANGELOG.md b/CHANGELOG.md index c18e8da84..7f90284a2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,7 @@ # Changelog +- The Realtime debug-log endpoint is bounded on every axis it was not: an always-on per-client rate limit, asynchronous appends through a serialized queue instead of a synchronous write on the request path, and rotation of the log file at 32 MB keeping one prior generation. The 8 MB cap applied to a single request body and never to the file those requests accumulated into, so any local page could grow it for as long as the dev server ran. A malformed record and a failed write are now told apart, 400 from 500, and neither answer carries the error text. + - Separate vessel records and feed acquisition from rendering while preserving selection, partial-feed retention, sea-surface placement and request cancellation. - Separate military-flight records and acquisition from rendering while preserving ground-model ownership, source units and follow behavior. diff --git a/docs/CURRENT-STATE.md b/docs/CURRENT-STATE.md index ee9ee6015..277521d3b 100644 --- a/docs/CURRENT-STATE.md +++ b/docs/CURRENT-STATE.md @@ -3201,6 +3201,7 @@ are omitted rather than framing the wrong part of the globe. - `/api/route` proxies bounded OSRM route requests for annotation routes, with profile allowlisting, distance caps, response caps, caching, and sanitized "no route found" errors. - Track endpoints: `/api/ais-live/track?mmsi=` (server-accumulated ring buffers; sub-route handled before the rows snapshot), `/api/opensky-track?icao24=` (OAuth, 60s cache, sanitized errors, independent OpenSky credit bucket), `/api/adsblol/trace?hex=` (60s cache, 5MB cap, ODbL attribution required in UI). - Realtime debug logs redact API keys, bearer tokens, client secrets, and image data URLs before writing to disk; request bodies are size-capped. +- `/api/realtime/debug-log` enforces an always-on 120-per-client/400-global one-minute limiter (not the opt-in `GEV_RATELIMIT_OPENAI_PER_MIN` bucket the cost-bearing OpenAI routes share), appends asynchronously through a serialized queue, and rotates `realtime-conversations.jsonl` at 32 MB keeping one prior generation, so the sink is bounded at twice that regardless of session length. A malformed record answers 400 and a failed write 500, both with a fixed message. ## UI/UX Runtime Defaults diff --git a/server/providers/common/request.js b/server/providers/common/request.js index ab261d779..11e0f128f 100644 --- a/server/providers/common/request.js +++ b/server/providers/common/request.js @@ -21,7 +21,11 @@ function readRequestBody(req, maxBytes = 1024 * 1024) { req.on('data', (chunk) => { total += chunk.length; if (total > maxBytes) { - reject(new Error(`Request body exceeds ${maxBytes} bytes`)); + // Same marker readRequestBodyCapped sets, so a caller can tell an + // oversized body from a genuine failure without matching on text. + const error = new Error(`Request body exceeds ${maxBytes} bytes`); + error.code = 'BODY_TOO_LARGE'; + reject(error); req.destroy(); return; } diff --git a/server/providers/openai/debug-log.js b/server/providers/openai/debug-log.js index f7dd42154..c5c60f6e0 100644 --- a/server/providers/openai/debug-log.js +++ b/server/providers/openai/debug-log.js @@ -1,16 +1,61 @@ import { defaultSourceRoot } from '../common/source-root.js'; import path from 'node:path'; import { readRequestBody } from '../common/request.js'; -import fs from 'node:fs'; +import { promises as fsp } from 'node:fs'; +import { makeRateLimiter, clientKey } from '../common/rate-limit.js'; +/** Cap on one request body. */ const REALTIME_DEBUG_LOG_MAX_BYTES = 8 * 1024 * 1024; +/** + * Ceiling for the live log before it rotates. One generation is kept + * (`…jsonl.1`), so the sink is bounded at twice this however long a session + * runs. REALTIME_DEBUG_LOG_MAX_BYTES caps a single request; it never bounded + * the file those requests accumulate into. + */ +const REALTIME_DEBUG_LOG_MAX_FILE_BYTES = 32 * 1024 * 1024; + +/** + * Per-IP write ceiling. Always on, unlike the opt-in limiter the cost-bearing + * OpenAI routes share: throttling those by default would change what a user + * spends, while this sink spends disk and event-loop time. A voice session + * writes far below this, so the cap needs no configuration to stay invisible. + */ +const REALTIME_DEBUG_LOG_MAX_PER_MIN = 120; + function createDebugLogHandler({ sourceRoot = defaultSourceRoot } = {}) { - const REALTIME_DEBUG_LOG_DIR = path.join(sourceRoot, '.gev-logs'); - const REALTIME_DEBUG_LOG_FILE = path.join( - REALTIME_DEBUG_LOG_DIR, - 'realtime-conversations.jsonl', - ); + const logDir = path.join(sourceRoot, '.gev-logs'); + const logFile = path.join(logDir, 'realtime-conversations.jsonl'); + const allow = makeRateLimiter({ + windowMs: 60_000, + max: REALTIME_DEBUG_LOG_MAX_PER_MIN, + globalMax: 400, + }); + + // Appends are chained rather than fired concurrently because the rotation + // check is a read-then-write on file size: run in parallel, every caller + // stats a file still under the ceiling, none of them rotates, and the log + // grows past it. The records themselves are O_APPEND and never interleave. + let queue = Promise.resolve(); + + function append(line) { + const done = queue.then(async () => { + await fsp.mkdir(logDir, { recursive: true }); + const size = await fsp.stat(logFile).then( + (stat) => stat.size, + () => 0, + ); + if (size + Buffer.byteLength(line) > REALTIME_DEBUG_LOG_MAX_FILE_BYTES) { + await fsp.rename(logFile, `${logFile}.1`); + } + await fsp.appendFile(logFile, line); + }); + // The caller still sees its own rejection, but one failed append must not + // poison the chain for every request queued behind it. + queue = done.catch(() => {}); + return done; + } + return async (req, res) => { if (req.method !== 'POST') { res.statusCode = 405; @@ -19,12 +64,19 @@ function createDebugLogHandler({ sourceRoot = defaultSourceRoot } = {}) { return; } + if (!allow(clientKey(req))) { + res.writeHead(429, { + 'Content-Type': 'application/json', + 'Retry-After': '5', + }); + res.end(JSON.stringify({ error: 'Rate limit exceeded' })); + return; + } + try { const body = await readRequestBody(req, REALTIME_DEBUG_LOG_MAX_BYTES); const record = JSON.parse(body || '{}'); - fs.mkdirSync(REALTIME_DEBUG_LOG_DIR, { recursive: true }); - fs.appendFileSync( - REALTIME_DEBUG_LOG_FILE, + await append( `${JSON.stringify({ loggedAt: new Date().toISOString(), ...record, @@ -33,13 +85,16 @@ function createDebugLogHandler({ sourceRoot = defaultSourceRoot } = {}) { res.statusCode = 204; res.end(); } catch (error) { - res.statusCode = 400; + // A malformed record or an oversized body is the caller's fault; a failed + // write is ours, and only the second is worth a log line. Neither answer + // carries the error text, which for an fs failure is an errno and an + // absolute path. + const callerFault = + error instanceof SyntaxError || error?.code === 'BODY_TOO_LARGE'; + if (!callerFault) console.warn('[realtime-debug-log] append failed'); + res.statusCode = callerFault ? 400 : 500; res.setHeader('Content-Type', 'application/json'); - res.end( - JSON.stringify({ - error: error?.message || 'Failed to write Realtime debug log', - }), - ); + res.end(JSON.stringify({ error: 'Failed to write Realtime debug log' })); } }; } diff --git a/src/tooling/localServices.test.mjs b/src/tooling/localServices.test.mjs index d7f2e4ba3..3ed1ef504 100644 --- a/src/tooling/localServices.test.mjs +++ b/src/tooling/localServices.test.mjs @@ -283,3 +283,79 @@ test('Realtime service configuration selects compatible endpoint/model without f assert.equal(response.headers['cache-control'], 'no-store'); assert.doesNotMatch(response.body, /server-fixture|voice\.example/); }); + +test('the debug-log sink stays bounded, rate limited, and quiet about failures', async (t) => { + const sourceRoot = root(t); + const handler = install(openAiRealtimeProxy({ sourceRoot })).get( + '/api/realtime/debug-log', + ); + const file = path.join(sourceRoot, '.gev-logs/realtime-conversations.jsonl'); + const write = (record) => + request(handler, { method: 'POST', body: JSON.stringify(record) }); + + // A malformed record is the caller's fault and a 400; neither answer carries + // the error text, which for a write failure is an errno and an absolute path. + const malformed = await request(handler, { method: 'POST', body: '{nope' }); + assert.equal(malformed.status, 400); + assert.deepEqual(malformed.json(), { + error: 'Failed to write Realtime debug log', + }); + + // The limiter is always on, unlike the opt-in one the cost-bearing routes + // share: 120/min per IP, far above what a voice session writes. + let limited = null; + let accepted = 0; + for (let n = 0; n < 130 && !limited; n += 1) { + const response = await write({ n }); + if (response.status === 429) limited = response; + else if (response.status === 204) accepted += 1; + } + assert.ok(limited, 'the sink refuses a caller past its per-minute ceiling'); + assert.equal(limited.headers['retry-after'], '5'); + assert.deepEqual(limited.json(), { error: 'Rate limit exceeded' }); + // The limiter counts requests rather than successful writes, so the malformed + // record above already spent one of the 120 slots. + assert.equal(accepted, 119); + + // Every accepted record is on disk and parses: the queue serializes appends, + // so none was lost or truncated by the ones beside it. + const lines = readFileSync(file, 'utf8').split('\n').filter(Boolean); + assert.equal(lines.length, accepted); + for (const line of lines) assert.doesNotThrow(() => JSON.parse(line)); + assert.ok(lines.every((line) => JSON.parse(line).loggedAt)); +}); + +test('the debug log rotates instead of growing without bound', async (t) => { + const sourceRoot = root(t); + const handler = install(openAiRealtimeProxy({ sourceRoot })).get( + '/api/realtime/debug-log', + ); + const file = path.join(sourceRoot, '.gev-logs/realtime-conversations.jsonl'); + + // 8 MB bounds one request body; nothing bounded the file until now, so a + // single page could grow it for as long as the dev server ran. Each record + // here is ~1 MB, well inside the body cap. + const pad = 'x'.repeat(1024 * 1024); + for (let n = 0; n < 40; n += 1) { + assert.equal( + ( + await request(handler, { + method: 'POST', + body: JSON.stringify({ n, pad }), + }) + ).status, + 204, + ); + } + + const live = statSync(file).size; + const previous = statSync(`${file}.1`).size; + assert.ok(live <= 32 * 1024 * 1024, `live log under the ceiling (${live})`); + assert.ok( + live + previous <= 64 * 1024 * 1024, + 'both generations together stay within twice the ceiling', + ); + // Unrotated, these records would be ~42 MB in one file. + assert.ok(live + previous < 42 * 1024 * 1024); + assert.ok(!existsSync(`${file}.2`), 'exactly one generation is retained'); +});