From 718e0866702f89921f44eaa4bfb3fe03ab72cfce Mon Sep 17 00:00:00 2001 From: John McLear Date: Fri, 1 May 2026 20:08:36 +0100 Subject: [PATCH 1/2] test: widen timing windows for flaky CI tests on slow runners MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit SessionStore.ts and socketio.ts dominate develop CI failures (~25–40% of recent runs). Both fail due to race conditions on slow Windows / loaded Linux runners — not logic bugs. SessionStore tests configure session expiry windows of 100ms and then sleep 110ms before asserting. On a slow runner, the wall-clock between `set()` and the assertion can exceed 100ms, the timeout in `SessionStore._updateExpirations()` then sees `exp.real <= now` and calls `_destroy()`, deleting the DB record before the assertion runs. The test then reads `null` / `undefined` instead of the expected JSON. Tripling each affected window (100→300, 110→330, 200→600) keeps the relative timing semantics identical while leaving enough headroom for a slow CI runner. Local run is +3s on this spec; cheap insurance for the global flake rate. `waitForSocketEvent` in tests/backend/common.ts uses a 1s timeout for socket.io message round-trips. The socket.io handshake + auth + CLIENT_READY can exceed 1s on a slow runner; bumped to 5s. The most-failing tests this addresses: - SessionStore: get of record from previous run (not yet expired) - SessionStore: external expiration update is picked up - SessionStore: shutdown cancels timeouts - socketio: !authn anonymous cookie /p/pad -> 200, ok - socketio: authn user /p/pad -> 200, ok - clientvar_rev_consistency: CLIENT_VARS stays consistent under concurrent edits during handshake All 28 SessionStore + 33 socketio tests pass locally. Co-Authored-By: Claude Opus 4.7 (1M context) --- src/tests/backend/common.ts | 2 +- src/tests/backend/specs/SessionStore.ts | 32 ++++++++++++------------- 2 files changed, 17 insertions(+), 17 deletions(-) diff --git a/src/tests/backend/common.ts b/src/tests/backend/common.ts index 73bc3f781c3..58f864a3a50 100644 --- a/src/tests/backend/common.ts +++ b/src/tests/backend/common.ts @@ -126,7 +126,7 @@ export const waitForSocketEvent = async (socket: any, event:string) => { const timeout = setTimeout(() => { reject(new Error(`timed out waiting for ${event} event`)); cancelTimeout = () => {}; - }, 1000); + }, 5000); cancelTimeout = () => { clearTimeout(timeout); resolve(); diff --git a/src/tests/backend/specs/SessionStore.ts b/src/tests/backend/specs/SessionStore.ts index 415ebc3c419..4b2a5adba15 100644 --- a/src/tests/backend/specs/SessionStore.ts +++ b/src/tests/backend/specs/SessionStore.ts @@ -57,10 +57,10 @@ describe(__filename, function () { }); it('set of session that expires', async function () { - const sess:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 100)}}; + const sess:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 300)}}; await set(sess); assert.equal(JSON.stringify(await db.get(`sessionstorage:${sid}`)), JSON.stringify(sess)); - await new Promise((resolve) => setTimeout(resolve, 110)); + await new Promise((resolve) => setTimeout(resolve, 330)); // Writing should start a timeout. assert(await db.get(`sessionstorage:${sid}`) == null); }); @@ -75,18 +75,18 @@ describe(__filename, function () { it('switch from non-expiring to expiring', async function () { const sess:any = {foo: 'bar'}; await set(sess); - const sess2:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 100)}}; + const sess2:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 300)}}; await set(sess2); - await new Promise((resolve) => setTimeout(resolve, 110)); + await new Promise((resolve) => setTimeout(resolve, 330)); assert(await db.get(`sessionstorage:${sid}`) == null); }); it('switch from expiring to non-expiring', async function () { - const sess:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 100)}}; + const sess:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 300)}}; await set(sess); const sess2:any = {foo: 'bar'}; await set(sess2); - await new Promise((resolve) => setTimeout(resolve, 110)); + await new Promise((resolve) => setTimeout(resolve, 330)); assert.equal(JSON.stringify(await db.get(`sessionstorage:${sid}`)), JSON.stringify(sess2)); }); }); @@ -109,10 +109,10 @@ describe(__filename, function () { }); it('get of record from previous run (not yet expired)', async function () { - const sess = {foo: 'bar', cookie: {expires: new Date(Date.now() + 100)}}; + const sess = {foo: 'bar', cookie: {expires: new Date(Date.now() + 300)}}; await db.set(`sessionstorage:${sid}`, sess); assert.equal(JSON.stringify(await get()), JSON.stringify(sess)); - await new Promise((resolve) => setTimeout(resolve, 110)); + await new Promise((resolve) => setTimeout(resolve, 330)); // Reading should start a timeout. assert(await db.get(`sessionstorage:${sid}`) == null); }); @@ -125,13 +125,13 @@ describe(__filename, function () { }); it('external expiration update is picked up', async function () { - const sess:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 100)}}; + const sess:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 300)}}; await set(sess); assert.equal(JSON.stringify(await get()), JSON.stringify(sess)); - const sess2 = {...sess, cookie: {expires: new Date(Date.now() + 200)}}; + const sess2 = {...sess, cookie: {expires: new Date(Date.now() + 600)}}; await db.set(`sessionstorage:${sid}`, sess2); assert.equal(JSON.stringify(await get()), JSON.stringify(sess2)); - await new Promise((resolve) => setTimeout(resolve, 110)); + await new Promise((resolve) => setTimeout(resolve, 330)); // The original timeout should not have fired. assert.equal(JSON.stringify(await get()), JSON.stringify(sess2)); }); @@ -139,11 +139,11 @@ describe(__filename, function () { describe('shutdown', function () { it('shutdown cancels timeouts', async function () { - const sess:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 100)}}; + const sess:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 300)}}; await set(sess); assert.equal(JSON.stringify(await get()), JSON.stringify(sess)); ss!.shutdown(); - await new Promise((resolve) => setTimeout(resolve, 110)); + await new Promise((resolve) => setTimeout(resolve, 330)); // The record should not have been automatically purged. assert.equal(JSON.stringify(await db.get(`sessionstorage:${sid}`)), JSON.stringify(sess)); }); @@ -151,18 +151,18 @@ describe(__filename, function () { describe('destroy', function () { it('destroy deletes the database record', async function () { - const sess:any = {cookie: {expires: new Date(Date.now() + 100)}}; + const sess:any = {cookie: {expires: new Date(Date.now() + 300)}}; await set(sess); await destroy(); assert(await db.get(`sessionstorage:${sid}`) == null); }); it('destroy cancels the timeout', async function () { - const sess:any = {cookie: {expires: new Date(Date.now() + 100)}}; + const sess:any = {cookie: {expires: new Date(Date.now() + 300)}}; await set(sess); await destroy(); await db.set(`sessionstorage:${sid}`, sess); - await new Promise((resolve) => setTimeout(resolve, 110)); + await new Promise((resolve) => setTimeout(resolve, 330)); assert.equal(JSON.stringify(await db.get(`sessionstorage:${sid}`)), JSON.stringify(sess)); }); From f33999117d6dba820aba8b422a1624d6f03798e3 Mon Sep 17 00:00:00 2001 From: John McLear Date: Fri, 1 May 2026 20:42:01 +0100 Subject: [PATCH 2/2] =?UTF-8?q?test:=20address=20Qodo=20PR=20feedback=20?= =?UTF-8?q?=E2=80=94=20configurable=20socket=20timeout,=20polling=20for=20?= =?UTF-8?q?cleanup?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Both items raised in Qodo's review of #7647. 1) Hardcoded 5s socket wait waitForSocketEvent() now takes an optional timeoutMs (default 1000ms, matching pre-PR behaviour). Only the known-slow connect() and handshake() paths pass 5000ms — they're the ones blowing the 1s budget on loaded CI runners. Per-message waits (waitForAcceptCommit and ad-hoc callers in messages.ts etc.) keep the 1s default so failures surface fast with the descriptive helper error rather than the generic Mocha timeout. 2) SessionStore waits still tight Replaced fixed sleeps with a small `eventually()` poller for the three "record should be gone after expiry" assertions: - set of session that expires - switch from non-expiring to expiring - get of record from previous run (not yet expired) These now poll every 25ms up to 2000ms so they pass immediately when cleanup completes on a fast runner, and tolerate hundreds of ms of event-loop delay on a slow one. No fixed coupling between sleep duration and expiry duration. For the inverse "record should still be there" case in `shutdown cancels timeouts`, polling doesn't apply (we're verifying that a cancelled timer did NOT fire, which requires a real wait past the original expiry). Bumped expires 300→500ms and wait 330→700ms so setup (set+get+shutdown) has 500ms before the timer would fire (vs. 30ms previously) and the 700ms wait still passes the original expiry. Co-Authored-By: Claude Opus 4.7 (1M context) --- src/tests/backend/common.ts | 12 ++++++--- src/tests/backend/specs/SessionStore.ts | 33 +++++++++++++++++-------- 2 files changed, 31 insertions(+), 14 deletions(-) diff --git a/src/tests/backend/common.ts b/src/tests/backend/common.ts index 58f864a3a50..10d60337716 100644 --- a/src/tests/backend/common.ts +++ b/src/tests/backend/common.ts @@ -111,7 +111,7 @@ export const init = async function () { * @param {string} event - The socket.io Socket event to listen for. * @returns The argument(s) passed to the event handler. */ -export const waitForSocketEvent = async (socket: any, event:string) => { +export const waitForSocketEvent = async (socket: any, event:string, timeoutMs = 1000) => { const errorEvents = [ 'error', 'connect_error', @@ -126,7 +126,7 @@ export const waitForSocketEvent = async (socket: any, event:string) => { const timeout = setTimeout(() => { reject(new Error(`timed out waiting for ${event} event`)); cancelTimeout = () => {}; - }, 5000); + }, timeoutMs); cancelTimeout = () => { clearTimeout(timeout); resolve(); @@ -185,7 +185,9 @@ export const connect = async (res:any = null) => { query: {cookie: reqCookieHdr, padId}, }); try { - await waitForSocketEvent(socket, 'connect'); + // Connect is a known slow path on loaded CI runners — give it a longer budget than the + // default per-message wait used elsewhere. + await waitForSocketEvent(socket, 'connect', 5000); } catch (e) { socket.close(); throw e; @@ -213,7 +215,9 @@ export const handshake = async (socket: any, padId:string, token = padutils.gene token, }); logger.debug('waiting for CLIENT_VARS response...'); - const msg = await waitForSocketEvent(socket, 'message'); + // CLIENT_VARS is a known slow path on loaded CI runners (auth + pad load) — give it a longer + // budget than the default per-message wait used elsewhere. + const msg = await waitForSocketEvent(socket, 'message', 5000); logger.debug('received CLIENT_VARS message'); return msg; }; diff --git a/src/tests/backend/specs/SessionStore.ts b/src/tests/backend/specs/SessionStore.ts index 4b2a5adba15..a92301f5da3 100644 --- a/src/tests/backend/specs/SessionStore.ts +++ b/src/tests/backend/specs/SessionStore.ts @@ -26,6 +26,19 @@ describe(__filename, function () { const destroy = async () => await util.promisify(ss!.destroy).call(ss, sid); const touch = async (sess: Session) => await util.promisify(ss!.touch).call(ss, sid, sess); + // Poll until `cond` is true. Used in place of fixed sleeps for "the cleanup timer should have + // fired by now" assertions — passes immediately when cleanup completes so tests stay fast, + // but tolerates slow CI runners where the event loop may be delayed by hundreds of ms. + const eventually = async (cond: () => Promise, maxMs = 2000, intervalMs = 25) => { + const deadline = Date.now() + maxMs; + // First check is immediate so the helper doesn't add a fixed delay. + while (true) { + if (await cond()) return; + if (Date.now() >= deadline) throw new Error(`condition not met within ${maxMs}ms`); + await new Promise((r) => setTimeout(r, intervalMs)); + } + }; + before(async function () { await common.init(); }); @@ -60,9 +73,8 @@ describe(__filename, function () { const sess:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 300)}}; await set(sess); assert.equal(JSON.stringify(await db.get(`sessionstorage:${sid}`)), JSON.stringify(sess)); - await new Promise((resolve) => setTimeout(resolve, 330)); - // Writing should start a timeout. - assert(await db.get(`sessionstorage:${sid}`) == null); + // Writing should start a timeout that purges the record once expiry passes. + await eventually(async () => await db.get(`sessionstorage:${sid}`) == null); }); it('set of already expired session', async function () { @@ -77,8 +89,7 @@ describe(__filename, function () { await set(sess); const sess2:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 300)}}; await set(sess2); - await new Promise((resolve) => setTimeout(resolve, 330)); - assert(await db.get(`sessionstorage:${sid}`) == null); + await eventually(async () => await db.get(`sessionstorage:${sid}`) == null); }); it('switch from expiring to non-expiring', async function () { @@ -112,9 +123,8 @@ describe(__filename, function () { const sess = {foo: 'bar', cookie: {expires: new Date(Date.now() + 300)}}; await db.set(`sessionstorage:${sid}`, sess); assert.equal(JSON.stringify(await get()), JSON.stringify(sess)); - await new Promise((resolve) => setTimeout(resolve, 330)); - // Reading should start a timeout. - assert(await db.get(`sessionstorage:${sid}`) == null); + // Reading should start a timeout that purges the record once expiry passes. + await eventually(async () => await db.get(`sessionstorage:${sid}`) == null); }); it('get of record from previous run (already expired)', async function () { @@ -139,11 +149,14 @@ describe(__filename, function () { describe('shutdown', function () { it('shutdown cancels timeouts', async function () { - const sess:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 300)}}; + // expires=500 / wait=700 keeps comfortable headroom on slow CI: setup + // (set+get+shutdown) must finish before the timer would fire (500ms is plenty), and the + // 700ms wait is past the original expiry so a cancelled timer would have fired by then. + const sess:any = {foo: 'bar', cookie: {expires: new Date(Date.now() + 500)}}; await set(sess); assert.equal(JSON.stringify(await get()), JSON.stringify(sess)); ss!.shutdown(); - await new Promise((resolve) => setTimeout(resolve, 330)); + await new Promise((resolve) => setTimeout(resolve, 700)); // The record should not have been automatically purged. assert.equal(JSON.stringify(await db.get(`sessionstorage:${sid}`)), JSON.stringify(sess)); });