From 4d7575ec3bcdcdc9ec1caeaf76a2e4ca2efbb3c6 Mon Sep 17 00:00:00 2001 From: phantomptr Date: Sat, 17 Oct 2026 10:29:15 -0700 Subject: [PATCH] console page: the input log's last batch gets past the helper's rate gate MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Fix round 2. The helper refused a request under 500 ms after the last one (429), which caught the final batch sent as Controls closes, right after a regular one, so ○ was still lost. The gate is now a pure, host-tested function: one request marked {"final":true} is admitted inside the window, once per window, each body still at most 4 KiB. The page marks its final batch (keepalive, cut to fit with the flag) and sends it only after a regular send still on the wire, so the two never arrive out of order. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RxCGb8Asp1A1AQYiv1kbgS --- client/src/console/inputLog.test.ts | 62 +++++++++++++++++++++++++ client/src/console/inputLog.ts | 51 +++++++++++++------- payload/include/webui_inputlog.h | 15 ++++++ payload/src/webui_api.c | 16 +++---- payload/src/webui_inputlog.c | 13 ++++++ payload/tests/webui_inputlog_selftest.c | 27 +++++++++++ 6 files changed, 158 insertions(+), 26 deletions(-) diff --git a/client/src/console/inputLog.test.ts b/client/src/console/inputLog.test.ts index 7633f1e2..ecf329f7 100644 --- a/client/src/console/inputLog.test.ts +++ b/client/src/console/inputLog.test.ts @@ -182,4 +182,66 @@ describe("createInputLog", () => { expect(log.enabled()).toBe(true); vi.useRealTimers(); }); + + it("the final batch passes the helper's 500 ms gate and never overtakes a regular send", async () => { + vi.useFakeTimers(); + let now = 0; + // The helper's rule (webui_inputlog_gate_admit): 500 ms between admitted requests, except one + // request marked final per 500 ms window. + const gate = { last: -1e6, lastFinal: -1e6 }; + const admit = (final: boolean) => { + if (now - gate.last >= 500) { + gate.last = now; + return true; + } + if (final && now - gate.lastFinal >= 500) { + gate.last = gate.lastFinal = now; + return true; + } + return false; + }; + const stored: string[] = []; + const order: string[] = []; + let releaseRegular: (() => void) | null = null; + const log = createInputLog({ + send: (lines, final) => { + order.push(final ? "final" : "regular"); + const arrive = () => { + if (admit(!!final)) stored.push(...lines); + }; + if (final) { + arrive(); + return Promise.resolve(); + } + // A regular send that is still on the wire when Controls closes. + return new Promise((res) => { + releaseRegular = () => { + arrive(); + res(); + }; + }); + }, + now: () => now, + }); + log.setEnabled(true); + log.record({ type: "keydown", key: "Enter", code: "Enter", keyCode: 13, target: null }); + await vi.advanceTimersByTimeAsync(0); + expect(order).toEqual(["regular"]); + now += 120; + log.record({ type: "popstate", target: null }); + log.setEnabled(false); + // Not sent alongside: it waits for the regular one. + expect(order).toEqual(["regular"]); + now += 30; + releaseRegular!(); + await vi.advanceTimersByTimeAsync(0); + expect(order).toEqual(["regular", "final"]); + // Both admitted although the final came 0 ms after the regular one; ○'s popstate is kept. + expect(stored.map((l) => l.split(" ")[1])).toEqual(["keydown", "popstate"]); + + // Without the final mark the helper would have refused it (the bug this guards against). + gate.last = now; + expect(admit(false)).toBe(false); + vi.useRealTimers(); + }); }); diff --git a/client/src/console/inputLog.ts b/client/src/console/inputLog.ts index 354a7f53..05db78bb 100644 --- a/client/src/console/inputLog.ts +++ b/client/src/console/inputLog.ts @@ -30,6 +30,8 @@ export const INPUT_LOG_MAX_LINE = 160; const MOVE_SAMPLE_MS = 250; /** `{"events":[]}` */ const BODY_OVERHEAD = 13; +/** `,"final":true` on the last batch. */ +const FINAL_OVERHEAD = 13; /** The event fields read (a real Event has them; tests pass plain objects). */ export interface LoggedEvent { @@ -142,6 +144,8 @@ export function createInputLog(deps: InputLogDeps): InputLog { let lastMove = -Infinity; let timer: ReturnType | null = null; let inFlight = false; + /** The regular send on the wire, if any: a final batch goes after it, never alongside. */ + let inFlightDone: Promise | null = null; const schedule = () => { if (!on || timer !== null || inFlight || (!queue.length && !dropped)) return; @@ -150,12 +154,13 @@ export function createInputLog(deps: InputLogDeps): InputLog { }; /** The next batch, with the "dropped" note when it fits. */ - function nextBatch(): string[] { - const batch = takeBatch(queue); + function nextBatch(final = false): string[] { + const max = INPUT_LOG_MAX_BODY - (final ? FINAL_OVERHEAD : 0); + const batch = takeBatch(queue, max); if (!queue.length && dropped) { const note = `${Math.round(deps.now() - t0)} dropped n=${dropped}`; const size = JSON.stringify({ events: batch.concat(note) }).length; - if (size <= INPUT_LOG_MAX_BODY) { + if (size <= max) { batch.push(note); dropped = 0; } @@ -163,14 +168,22 @@ export function createInputLog(deps: InputLogDeps): InputLog { return batch; } - /** One batch now, outside the once-a-second pacing (at most once per stop or page hide). */ + /** + * One batch now, outside the once-a-second pacing (at most once per stop or page hide). Marked + * final: the helper admits it even right after a regular batch (once per its 500 ms window, + * webui_inputlog_gate_admit). Sent after a regular send still on the wire, so the two never + * reach the helper out of order (the later one would be refused). + */ function sendFinal() { - const batch = nextBatch(); + const batch = nextBatch(true); if (!batch.length) return; lastSend = deps.now(); - deps.send(batch, true).catch(() => { - // measurement only - }); + const go = () => + deps.send(batch, true).catch(() => { + // measurement only + }); + if (inFlightDone) void inFlightDone.then(go, go); + else void go(); } function flush() { @@ -180,15 +193,15 @@ export function createInputLog(deps: InputLogDeps): InputLog { if (!batch.length) return; inFlight = true; lastSend = deps.now(); - deps - .send(batch) - .catch(() => { - // measurement only: a lost batch is not retried - }) - .then(() => { - inFlight = false; - schedule(); - }); + const done = deps.send(batch).catch(() => { + // measurement only: a lost batch is not retried + }); + inFlightDone = done; + void done.then(() => { + inFlight = false; + if (inFlightDone === done) inFlightDone = null; + schedule(); + }); } return { @@ -251,7 +264,9 @@ const DOCUMENT_EVENTS = ["visibilitychange", "fullscreenchange", "webkitfullscre const pageLog = createInputLog({ send: (lines, final) => - final ? callKeepalive(INPUT_LOG_ROUTE, { events: lines }) : call(INPUT_LOG_ROUTE, { events: lines }), + final + ? callKeepalive(INPUT_LOG_ROUTE, { events: lines, final: true }) + : call(INPUT_LOG_ROUTE, { events: lines }), now: () => (typeof performance !== "undefined" ? performance.now() : Date.now()), }); diff --git a/payload/include/webui_inputlog.h b/payload/include/webui_inputlog.h index 82126adb..b9a414d9 100644 --- a/payload/include/webui_inputlog.h +++ b/payload/include/webui_inputlog.h @@ -34,4 +34,19 @@ long webui_inputlog_lines(const char *arr, size_t n, char *out, size_t cap); * the previous file whole and no temp file behind. 0, or -1. */ int webui_inputlog_append(const char *path, const char *add, size_t add_len, size_t cap, char *work, size_t work_cap); +/* The route's rate gate. A request is admitted when at least `gap_ms` passed since the last + * admitted one. A request the page marks final ({"final":true}: the last batch as the Controls + * screen closes or the page is hidden) may come sooner, but only one final per `gap_ms` window, + * so the mark cannot be used to flood: at most two appends per window, each body still capped at + * WEBUI_INPUTLOG_BODY_MAX. Pure (the caller holds its lock and passes a monotonic clock). + * 1 = admitted (the gate is updated), 0 = refused (429; the gate is unchanged). */ +typedef struct { + long long last_ms; /* last admitted request */ + long long last_final_ms; /* last admitted request that used the final exemption */ +} webui_inputlog_gate; + +#define WEBUI_INPUTLOG_GATE_INIT { -1000000, -1000000 } + +int webui_inputlog_gate_admit(webui_inputlog_gate *g, long long now_ms, int final, long long gap_ms); + #endif diff --git a/payload/src/webui_api.c b/payload/src/webui_api.c index 19691824..2e1da54b 100644 --- a/payload/src/webui_api.c +++ b/payload/src/webui_api.c @@ -863,10 +863,12 @@ static void r_cheats_toggle(const char *b, size_t n, uint8_t *out, int fd) { /* ---- input log ---- */ -/* One append at a time (the file is a ring rewritten in place), and the time of the last one: a - * page that ignores its one-a-second rule is told 429 instead of making the helper write. */ +/* One append at a time (the file is a ring rewritten in place), and a rate gate: a page that + * ignores its one-a-second rule is told 429 instead of making the helper write. Its last batch + * ({"final":true}, as Controls closes or the page is hidden) may follow a regular one sooner, once + * per window (webui_inputlog_gate_admit). */ static pthread_mutex_t g_inlog_mu = PTHREAD_MUTEX_INITIALIZER; -static long long g_inlog_last_ms = -1000000; +static webui_inputlog_gate g_inlog_gate = WEBUI_INPUTLOG_GATE_INIT; #define INLOG_MIN_GAP_MS 500 /* half the page's period: its timer jitter never trips it */ #define INLOG_LINES_CAP (8u * 1024u) @@ -882,8 +884,7 @@ static void r_input_log(const char *b, size_t n, uint8_t *out, int fd) { const char *arr; size_t alen; long lines; - long long now; - int rc; + int rc, final = 0; _Static_assert(INLOG_LINES_CAP + WEBUI_INPUTLOG_CAP <= API_OUT_MAX, "input log scratch must fit the route buffer"); if (n > WEBUI_INPUTLOG_BODY_MAX) { send_error(fd, 413, "too_large", 9); @@ -898,14 +899,13 @@ static void r_input_log(const char *b, size_t n, uint8_t *out, int fd) { send_bad(fd, "bad_events"); return; } + if (webui_json_bool(b, n, "final", &final) != 1) final = 0; pthread_mutex_lock(&g_inlog_mu); - now = mono_ms(); - if (now - g_inlog_last_ms < INLOG_MIN_GAP_MS) { + if (!webui_inputlog_gate_admit(&g_inlog_gate, mono_ms(), final != 0, INLOG_MIN_GAP_MS)) { pthread_mutex_unlock(&g_inlog_mu); send_error(fd, 429, "too_many", 8); return; } - g_inlog_last_ms = now; rc = webui_inputlog_append(WEBUI_INPUTLOG_PATH, (const char *)out, (size_t)lines, WEBUI_INPUTLOG_CAP, (char *)out + INLOG_LINES_CAP, API_OUT_MAX - INLOG_LINES_CAP); pthread_mutex_unlock(&g_inlog_mu); diff --git a/payload/src/webui_inputlog.c b/payload/src/webui_inputlog.c index 6e423166..124ef00d 100644 --- a/payload/src/webui_inputlog.c +++ b/payload/src/webui_inputlog.c @@ -137,3 +137,16 @@ int webui_inputlog_append(const char *path, const char *add, size_t add_len, siz } return 0; } + +int webui_inputlog_gate_admit(webui_inputlog_gate *g, long long now_ms, int final, long long gap_ms) { + if (now_ms - g->last_ms >= gap_ms) { + g->last_ms = now_ms; + return 1; + } + if (final && now_ms - g->last_final_ms >= gap_ms) { + g->last_ms = now_ms; + g->last_final_ms = now_ms; + return 1; + } + return 0; +} diff --git a/payload/tests/webui_inputlog_selftest.c b/payload/tests/webui_inputlog_selftest.c index 3b3a7efa..5ba2ea78 100644 --- a/payload/tests/webui_inputlog_selftest.c +++ b/payload/tests/webui_inputlog_selftest.c @@ -162,6 +162,32 @@ static void ring_keeps_newest_whole_lines_under_cap(void) { free(buf); } +static void gate_admits_one_final_per_window(void) { + webui_inputlog_gate g = WEBUI_INPUTLOG_GATE_INIT; + const long long gap = 500; + CHECK(webui_inputlog_gate_admit(&g, 1000, 0, gap) == 1); + /* A regular batch too soon: refused, gate unchanged. */ + CHECK(webui_inputlog_gate_admit(&g, 1200, 0, gap) == 0); + CHECK(g.last_ms == 1000); + /* The final batch 300 ms after a regular one (Controls closed): admitted. */ + CHECK(webui_inputlog_gate_admit(&g, 1300, 1, gap) == 1); + /* A second final, or a regular one, inside the window: refused (no flooding with the mark). */ + CHECK(webui_inputlog_gate_admit(&g, 1400, 1, gap) == 0); + CHECK(webui_inputlog_gate_admit(&g, 1700, 0, gap) == 0); + CHECK(webui_inputlog_gate_admit(&g, 1790, 1, gap) == 0); + /* A full gap after the final: regular traffic again. */ + CHECK(webui_inputlog_gate_admit(&g, 1800, 0, gap) == 1); + /* Final right after that: the last final was 500+ ms ago, so admitted once more. */ + CHECK(webui_inputlog_gate_admit(&g, 1850, 1, gap) == 1); + CHECK(webui_inputlog_gate_admit(&g, 1900, 1, gap) == 0); + /* A final that is on time anyway does not use the exemption. */ + webui_inputlog_gate h = WEBUI_INPUTLOG_GATE_INIT; + CHECK(webui_inputlog_gate_admit(&h, 5000, 1, gap) == 1); + CHECK(h.last_final_ms == -1000000); + CHECK(webui_inputlog_gate_admit(&h, 5100, 1, gap) == 1); + CHECK(webui_inputlog_gate_admit(&h, 5200, 1, gap) == 0); +} + int main(void) { snprintf(g_dir, sizeof g_dir, "/tmp/ps5upload-inputlog-XXXXXX"); if (!mkdtemp(g_dir)) { @@ -171,6 +197,7 @@ int main(void) { lines_from_events(); lines_refuse_anything_but_plain_strings(); ring_keeps_newest_whole_lines_under_cap(); + gate_admits_one_final_per_window(); rmdir(g_dir); if (failures) { fprintf(stderr, "webui_inputlog_selftest: %d failure(s)\n", failures);