diff --git a/frontend/src/lib/diagnostics.dom.test.ts b/frontend/src/lib/diagnostics.dom.test.ts index 90edbb63..09210665 100644 --- a/frontend/src/lib/diagnostics.dom.test.ts +++ b/frontend/src/lib/diagnostics.dom.test.ts @@ -190,6 +190,87 @@ describe("diagnostics level", () => { expect(later).toContain("diagnostics level raised"); }); + it("a batch refused after a re-raise is still not sent: it was taken under the old consent", async () => { + // The test above settles the refusal while the stream is STOPPED, so `unsubscribe` is what + // blocks the requeue there. Here it settles after the new consent is already streaming — the + // ordering only the `session` counter can catch, and the one that would leak events across a + // withdrawal if it did not. + const d = await fresh(); + let refuse: (err: unknown) => void = () => {}; + answer = () => new Promise((_, reject) => (refuse = reject)); + d.applyDiagnostics(raised("DEBUG"), () => {}); + d.log.debug("ui.click", "under the first consent"); + await vi.advanceTimersByTimeAsync(5_000); // in flight + d.applyDiagnostics({ level: "INFO", until: null, retention_days: 7 }, () => {}); + answer = () => Promise.resolve({ ok: true, stored: 0 }); + d.applyDiagnostics(raised("TRACE"), () => {}); + refuse(new d.HttpError(429, "slow down")); // only now does the old consent's batch come back + await vi.advanceTimersByTimeAsync(60_000); + const later = sent + .slice(1) + .flat() + .map((e) => (e as { msg: string }).msg); + expect(later).not.toContain("under the first consent"); + expect(later).toContain("diagnostics level raised"); + }); + + it("a 409 for a batch taken under the old consent does not lapse the new one", async () => { + const d = await fresh(); + const lapsed = vi.fn(); + let refuse: (err: unknown) => void = () => {}; + answer = () => new Promise((_, reject) => (refuse = reject)); + d.applyDiagnostics(raised("DEBUG"), lapsed); + d.log.debug("ui.click", "under the first consent"); + await vi.advanceTimersByTimeAsync(5_000); // in flight + d.applyDiagnostics({ level: "INFO", until: null, retention_days: 7 }, lapsed); + answer = () => Promise.resolve({ ok: true, stored: 0 }); + d.applyDiagnostics(raised("TRACE"), lapsed); + refuse(new d.HttpError(409, "off")); + await vi.advanceTimersByTimeAsync(60_000); + expect(lapsed).not.toHaveBeenCalled(); + expect(d.enabled("TRACE")).toBe(true); + }); + + it("a 409 answering a batch the user themselves cancelled is not called a lapse", async () => { + // "Alap" is the user revoking their own consent; the server answers the still-flying batch with + // the same 409 a real expiry gets. Their own log must not tell them the consent ran out. + const d = await fresh(); + const lapsed = vi.fn(); + let refuse: (err: unknown) => void = () => {}; + answer = () => new Promise((_, reject) => (refuse = reject)); + d.applyDiagnostics(raised("DEBUG"), lapsed); + d.log.debug("ui.click", "under the consent"); + await vi.advanceTimersByTimeAsync(5_000); // in flight + d.applyDiagnostics({ level: "INFO", until: null, retention_days: 7 }, lapsed); + refuse(new d.HttpError(409, "off")); + await vi.advanceTimersByTimeAsync(0); + expect(lapsed).not.toHaveBeenCalled(); + expect(d.events().map((e) => e.msg)).not.toContain("diagnostics level lapsed"); + }); + + it("a refused batch that comes back to a full queue is what goes, not the events since", async () => { + // The cap test above fills the queue AFTER the refusal landed, so the trim it measures is the + // one on the subscribe path. This one has the queue already at the cap when the batch comes + // back — the only state where the trim in the 429 handler decides anything. + const d = await fresh(); + let refuse: (err: unknown) => void = () => {}; + answer = () => new Promise((_, reject) => (refuse = reject)); + d.applyDiagnostics(raised("DEBUG"), () => {}); + for (let i = 0; i < 99; i++) d.log.debug("ui.click", `old ${i}`); + await vi.advanceTimersByTimeAsync(0); // the 100 oldest are in flight, the queue is empty + for (let i = 0; i < 1_000; i++) d.log.debug("ui.click", `new ${i}`); + answer = () => Promise.resolve({ ok: true, stored: 0 }); + refuse(new d.HttpError(429, "slow down")); // 1_000 + 100 back = 1_100, over the cap + await vi.advanceTimersByTimeAsync(60_000); + const msgs = sent + .slice(1) + .flat() + .map((e) => (e as { msg: string }).msg); + expect(msgs).toHaveLength(1_000); + expect(msgs).not.toContain("old 0"); + expect([msgs[0], msgs[msgs.length - 1]]).toEqual(["new 0", "new 999"]); + }); + it("a closing tab sends what is still waiting with a keepalive request", async () => { const d = await fresh(); d.applyDiagnostics(raised("DEBUG"), () => {}); diff --git a/frontend/src/lib/diagnostics.ts b/frontend/src/lib/diagnostics.ts index 90e8cc91..801dcef7 100644 --- a/frontend/src/lib/diagnostics.ts +++ b/frontend/src/lib/diagnostics.ts @@ -128,8 +128,17 @@ async function flush(): Promise { queue.unshift(...batch); keepNewest(); } - } else if (err instanceof HttpError && err.status === 409 && takenIn === session) { - lapse(); // the server has it off: withdrawn in another tab, or lapsed by its clock + } else if ( + err instanceof HttpError && + err.status === 409 && + takenIn === session && + unsubscribe + ) { + // The server has it off: withdrawn in another tab, or lapsed by its clock. `unsubscribe` + // means THIS tab does not already know — without it, the 409 answering a batch that was in + // flight when the user picked Alap writes "lapsed" into their own log for a level they + // revoked, and a lapse this tab has already announced gets announced a second time. + lapse(); } } finally { inFlight = false;