fix(realtime): bound the debug-log sink and stop blocking on its writes

Ported onto the split provider layout: the route now lives in
server/providers/openai/debug-log.js and its state belongs to the handler
the factory returns rather than to module scope.

/api/realtime/debug-log is the one route in its family left unhardened.
Both siblings enforce a limiter through openai/rate-limit.js, and this was
the only handler still writing with fs.appendFileSync on the request path.

- Always-on per-IP limiter (120/min, 400 global). Deliberately not the
  opt-in openAiRateLimiter(): that one defaults to unlimited so throttling
  cannot silently change what a user spends, and this sink spends disk and
  event-loop time rather than provider quota.
- Serialized async appends with a 32 MB rotation ceiling and one retained
  generation. REALTIME_DEBUG_LOG_MAX_BYTES caps a single request body; it
  never bounded the file those bodies accumulate into, so any local page
  could grow .gev-logs/realtime-conversations.jsonl for as long as the dev
  server ran. Serializing also closes a read-then-write race on the size
  check, where concurrent callers all stat under the ceiling and none
  rotates.
- Generic 400/500 answers separating a malformed record or oversized body
  from a failed write, instead of echoing error.message — an errno and an
  absolute path for an fs failure.
- readRequestBody marks an oversized body with code 'BODY_TOO_LARGE', the
  marker its sibling readRequestBodyCapped already sets, so the two cases
  are distinguishable without matching on text.

Coverage extends src/tooling/localServices.test.mjs, which already drives
the real handler over a temporary sourceRoot. Both new tests fail on the
previous implementation and pass with this one.

Refs #23. Does not add authentication: these proxies have no auth
mechanism today, so introducing one is a maintainer design decision.
This commit is contained in:
Pedro Lobato committed 2026-09-14 21:24:12 -05:00
1 parent 96a6b49477
commit 44817e1286
5 files changed
+154 -16

No files matched your search

+76
View File
@@ -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');
});