etherpad-lite/src/tests/backend/common.ts
John McLear d582398826
fix: eliminate the Windows backend silent-ELIFECYCLE flake (handler gate + Node 24.16.0) (#7866)
* fix(test): stop a single leaked promise rejection from killing the whole backend suite

Root cause of the long-standing Windows backend-test "silent ELIFECYCLE"
flake (~22% of runs, rotating across random spec files, no mocha summary,
no JS-handler trace, bypassing --report-on-fatalerror / Defender / Windows
event log / AeDebug). Found by capturing a full-memory dump of the dying
node.exe with Sysinternals ProcDump (-t dump-on-terminate) and symbolizing
it against Node 24.15.0's node.pdb. The dying thread's stack:

    exit_or_terminate_process / common_exit        (CRT exit)
    node::Exit
    node::DefaultProcessExitHandlerInternal
    node::Environment::Exit
    node::ReallyExit                                (process.exit binding)
    ... v8 MicrotaskQueue::RunMicrotasks ...
    node::InternalCallbackScope::Close

No exception stream — a *clean* ExitProcess, not a crash. The job log
pinned the trigger:

    [INFO] server - Exiting...
    AssertionError at tests/backend/specs/SessionStore.ts:235
      at process.processTicksAndRejections

Mechanism: a timing-fragile test (SessionStore touch/expiry specs use real
setTimeout against a 200ms-expiry session; socket.io delay-race specs are
similar) gets timed out and abandoned by mocha, but its async body keeps
running. When its trailing assertion later throws, it surfaces as an ORPHAN
unhandled rejection belonging to no awaited test. Three handlers then
escalated that into a whole-process exit:
  - server.ts installed process-global uncaughtException/unhandledRejection
    handlers that call exports.exit() → process.reallyExit() (production
    graceful-shutdown behaviour, catastrophic in-process under mocha)
  - common.ts (PR #7663) and diagnostics.ts (PR #7838) rethrew the rejection
    and process.exit(1)

Because it's a deliberate, clean exit it bypassed every forensic layer; it
rotated across files because the orphan rejection lands during whatever test
is running; it's Windows-mostly because event-loop timing makes the abandoned
test's assertion fire in a *later* test's window more often there.

Fix (two halves):
  1. server.ts: gate the process-global uncaughtException / unhandledRejection
     / signal handlers behind `require.main === module`. They are correct for
     a real Etherpad process but must not fire when server.start() is called
     in-process by a test runner — mocha owns process-level error handling
     there. Mirrors the existing `if (require.main === module) exports.start()`
     idiom; production (node server.js) is unchanged.
  2. common.ts + diagnostics.ts: the backend-test bootstraps now LOG unhandled
     rejections instead of rethrowing / exiting. Orphan rejections cannot be
     cleanly attributed to a test, so rethrowing only yields an
     ERR_MOCHA_MULTIPLE_DONE abort. Real failures are unaffected — an assertion
     in a test's own awaited path rejects that test's promise and mocha fails
     it normally, never reaching this global handler.

Verified locally: a spec that leaks a delayed rejection during a later test
now reports `3 passing` / exit 0 with the rejection logged, instead of
aborting the run.

Follow-ups (separate PRs): harden the SessionStore / socket.io timing specs
to not leak (fake timers); remove the now-unneeded diagnostic scaffolding
(diagnostics.ts heartbeat/node-report, the #7846 OS sidecar) now that the
cause is known.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

* fix(ci): run Windows backend tests on Node 25 to dodge the libuv connect overrun

Node 24.x's bundled libuv has a stack buffer overrun in the Windows TCP-connect
path (uv__tcp_connect / uv__tcp_try_connect), proven by a SilentProcessExit
full-memory dump of the dying mocha process: the main thread executes
__fastfail(FAST_FAIL_STACK_COOKIE_CHECK_FAILURE) from __report_gsfailure with
TCPWrap::Connect -> uv_tcp_connect on the stack. It fires under the backend
suite's heavy localhost connection churn, is address-family independent (occurs
on both sockaddr_in and sockaddr_in6, so an IPv4 pin does NOT help), and -- being
memory corruption -- bypasses all JS/Node observability, rotating across tests
as the "silent ELIFECYCLE" flake (~22% of Windows runs).

Empirically: Node 25 = 16/16 green; Node 24 (even with an IPv4 pin) = ~39% fail.
Node 25's newer bundled libuv does not overrun. Linux stays on Node 24 LTS (the
bug is Windows-specific). Revisit once the libuv fix is backported to 24.x.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

* fix(ci): pin Windows backend to Node 24.16.0 (libuv fix) instead of 25

Bisect (standalone repro) pinpointed the fix to Node 24.16.0 (libuv 1.52.1):
24.15.0 (libuv 1.51.0) crashes the connect overrun 4/4 on 127.0.0.1, while
24.16.0 is clean 0/8. 24.16.0 stays on the Node 24 "Krypton" LTS line, so prefer
it over Node 25 (non-LTS). Pinned explicitly because setup-node's default
check-latest:false reuses the runner's pre-cached 24.15.0 for a bare "24".

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

* docs(ci): reference upstream nodejs/node#63620 in the Windows Node-pin comment

Links the explicit 24.16.0 pin to the filed upstream issue so the pin can be
dropped back to plain "24" once the libuv connect-overrun fix is across the
supported 24.x baseline.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
2026-05-28 16:12:34 +01:00

343 lines
12 KiB
TypeScript

'use strict';
import {MapArrayType} from "../../node/types/MapType";
import AttributePool from '../../static/js/AttributePool';
const assert = require('assert').strict;
const io = require('socket.io-client');
const log4js = require('log4js');
import padutils from '../../static/js/pad_utils';
const process = require('process');
const server = require('../../node/server');
const setCookieParser = require('set-cookie-parser');
import settings from '../../node/utils/Settings';
import supertest from 'supertest';
import TestAgent from "supertest/lib/agent";
import {Http2Server} from "node:http2";
import {SignJWT} from "jose";
import {privateKeyExported} from "../../node/security/OAuth2Provider";
const webaccess = require('../../node/hooks/express/webaccess');
const backups:MapArrayType<any> = {};
let agentPromise:Promise<any>|null = null;
export let agent: TestAgent|null = null;
export let baseUrl:string|null = null;
export let httpServer: Http2Server|null = null;
export const logger = log4js.getLogger('test');
const logLevel = logger.level;
// Log unhandled Promise rejections; do NOT rethrow and do NOT process.exit().
//
// Root cause of the long-standing Windows backend "silent ELIFECYCLE" flake
// (confirmed via a procdump full-memory capture showing node::ReallyExit
// firing from a microtask): a timing-fragile test (e.g. SessionStore touch/
// expiry specs) gets timed out and abandoned by mocha, but its async body
// keeps running; when its trailing assertion later throws, it surfaces as an
// *orphan* unhandled rejection — one that belongs to no currently-awaited
// test. PR #7663 rethrew these (→ uncaughtException) and an earlier revision
// even called process.exit(), and server.ts's production handler turned them
// into a full Etherpad shutdown. Any one orphan rejection therefore killed
// the whole suite mid-run with no mocha summary.
//
// Orphan rejections cannot be cleanly attributed to a test, so rethrowing
// just produces an ERR_MOCHA_MULTIPLE_DONE mess and a non-deterministic
// abort. Log them loudly instead. Real failures are unaffected: an assertion
// inside a test's own awaited path rejects THAT test's promise and mocha
// fails it normally — it never reaches this global handler. The companion
// fix is in server.ts, where the production process-exit handlers are now
// gated on `require.main === module` so they don't fire under the test runner.
process.on('unhandledRejection', (reason: any) => {
process.stderr.write(`[backend tests] unhandledRejection (logged, non-fatal): ${
reason && reason.stack ? reason.stack : String(reason)}\n`);
});
before(async function () {
this.timeout(60000);
await init();
});
export const generateJWTToken = () => {
const jwt = new SignJWT({
sub: 'admin',
jti: '123',
exp: Math.floor(Date.now() / 1000) + 60 * 60,
aud: 'account',
iss: 'http://localhost:9001',
admin: true
})
jwt.setProtectedHeader({alg: 'RS256'})
return jwt.sign(privateKeyExported!)
}
export const generateJWTTokenUser = () => {
const jwt = new SignJWT({
sub: 'admin',
jti: '123',
exp: Math.floor(Date.now() / 1000) + 60 * 60,
aud: 'account',
iss: 'http://localhost:9001',
})
jwt.setProtectedHeader({alg: 'RS256'})
return jwt.sign(privateKeyExported!)
}
// Token whose `admin` claim is explicitly `false`. Used to pin the
// API's JWT validation: tokens that carry the claim with a non-true
// value must be rejected, not just tokens that omit it entirely.
export const generateJWTTokenAdminFalse = () => {
const jwt = new SignJWT({
sub: 'admin',
jti: '123',
exp: Math.floor(Date.now() / 1000) + 60 * 60,
aud: 'account',
iss: 'http://localhost:9001',
admin: false,
});
jwt.setProtectedHeader({alg: 'RS256'});
return jwt.sign(privateKeyExported!);
};
export const init = async function () {
if (agentPromise != null) return await agentPromise;
let agentResolve;
agentPromise = new Promise((resolve) => { agentResolve = resolve; });
if (!logLevel.isLessThanOrEqualTo(log4js.levels.DEBUG)) {
logger.warn('Disabling non-test logging for the duration of the test. ' +
'To enable non-test logging, change the loglevel setting to DEBUG.');
}
// Note: This is only a shallow backup.
backups.settings = Object.assign({}, settings);
// Start the Etherpad server on a random unused port.
settings.port = 0;
settings.ip = 'localhost';
settings.importExportRateLimiting = {max: 999999};
settings.commitRateLimiting = {duration: 0.001, points: 1e6};
httpServer = await server.start();
// @ts-ignore
baseUrl = `http://localhost:${httpServer!.address()!.port}`;
logger.debug(`HTTP server at ${baseUrl}`);
// Create a supertest user agent for the HTTP server.
agent = supertest(baseUrl)
//.set('Authorization', `Bearer ${await generateJWTToken()}`);
// Speed up authn tests.
backups.authnFailureDelayMs = webaccess.authnFailureDelayMs;
webaccess.authnFailureDelayMs = 0;
after(async function () {
webaccess.authnFailureDelayMs = backups.authnFailureDelayMs;
// Note: This does not unset settings that were added.
Object.assign(settings, backups.settings);
await server.exit();
});
agentResolve!(agent);
return agent;
};
/**
* Waits for the next named socket.io event. Rejects if there is an error event while waiting
* (unless waiting for that error event).
*
* @param {io.Socket} socket - The socket.io Socket object to listen on.
* @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, timeoutMs = 1000) => {
const errorEvents = [
'error',
'connect_error',
'connect_timeout',
'reconnect_error',
'reconnect_failed',
];
const handlers = new Map();
let cancelTimeout;
try {
const timeoutP = new Promise<void>((resolve, reject) => {
const timeout = setTimeout(() => {
reject(new Error(`timed out waiting for ${event} event`));
cancelTimeout = () => {};
}, timeoutMs);
cancelTimeout = () => {
clearTimeout(timeout);
resolve();
cancelTimeout = () => {};
};
});
const errorEventP = Promise.race(errorEvents.map((event) => new Promise((resolve, reject) => {
handlers.set(event, (errorString:string) => {
logger.debug(`socket.io ${event} event: ${errorString}`);
reject(new Error(errorString));
});
})));
const eventP = new Promise<string|string[]>((resolve) => {
// This will overwrite one of the above handlers if the user is waiting for an error event.
handlers.set(event, (...args:string[]) => {
logger.debug(`socket.io ${event} event`);
if (args.length > 1) return resolve(args);
resolve(args[0]);
});
});
for (const [event, handler] of handlers) socket.on(event, handler);
// timeoutP and errorEventP are guaranteed to never resolve here (they can only reject), so the
// Promise returned by Promise.race() is guaranteed to resolve to the eventP value (if
// the event arrives).
return await Promise.race([timeoutP, errorEventP, eventP]);
} finally {
cancelTimeout!();
for (const [event, handler] of handlers) socket.off(event, handler);
}
};
/**
* Establishes a new socket.io connection.
*
* @param {object} [res] - Optional HTTP response object. The cookies from this response's
* `set-cookie` header(s) are passed to the server when opening the socket.io connection. If
* nullish, no cookies are passed to the server.
* @returns {io.Socket} A socket.io client Socket object.
*/
export const connect = async (res:any = null) => {
// Convert the `set-cookie` header(s) into a `cookie` header.
const resCookies = (res == null) ? {} : setCookieParser.parse(res, {map: true});
const reqCookieHdr = Object.entries(resCookies).map(
// @ts-ignore
([name, cookie]) => `${name}=${encodeURIComponent(cookie.value)}`).join('; ');
logger.debug('socket.io connecting...');
let padId = null;
if (res) {
padId = res.req.path.split('/p/')[1];
}
const socket = io(`${baseUrl}/`, {
forceNew: true, // Different tests will have different query parameters.
// socketio.js-client on node.js doesn't support cookies (see https://git.io/JU8u9), so the
// express_sid cookie must be passed as a query parameter.
query: {cookie: reqCookieHdr, padId},
});
try {
// 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;
}
logger.debug('socket.io connected');
return socket;
};
/**
* Helper function to exchange CLIENT_READY+CLIENT_VARS messages for the named pad.
*
* @param {io.Socket} socket - Connected socket.io Socket object.
* @param {string} padId - Which pad to join.
* @param token
* @returns The CLIENT_VARS message from the server.
*/
export const handshake = async (socket: any, padId:string, token = padutils.generateAuthorToken()) => {
logger.debug('sending CLIENT_READY...');
socket.emit('message', {
component: 'pad',
type: 'CLIENT_READY',
padId,
sessionID: null,
token,
});
logger.debug('waiting for CLIENT_VARS response...');
// 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;
};
/**
* Convenience wrapper around `socket.send()` that waits for acknowledgement.
*/
export const sendMessage = async (socket: any, message:any) => await new Promise<void>((resolve, reject) => {
socket.emit('message', message, (errInfo:{
name: string,
message: string,
}) => {
if (errInfo != null) {
const {name, message} = errInfo;
const err = new Error(message);
err.name = name;
reject(err);
return;
}
resolve();
});
});
/**
* Convenience function to send a USER_CHANGES message. Waits for acknowledgement.
*/
export const sendUserChanges = async (socket:any, data:any) => await sendMessage(socket, {
type: 'COLLABROOM',
component: 'pad',
data: {
type: 'USER_CHANGES',
apool: new AttributePool(),
...data,
},
});
/*
* Convenience function to send a delete pad request.
*/
export const sendPadDelete = async (socket:any, data:any) => await sendMessage(socket, {
type: 'PAD_DELETE',
component: 'pad',
data: {
padId: data.padId
},
});
/**
* Convenience function that waits for an ACCEPT_COMMIT message. Asserts that the new revision
* matches the expected revision.
*
* Note: To avoid a race condition, this should be called before the USER_CHANGES message is sent.
* For example:
*
* await Promise.all([
* common.waitForAcceptCommit(socket, rev + 1),
* common.sendUserChanges(socket, {baseRev: rev, changeset}),
* ]);
*/
export const waitForAcceptCommit = async (socket:any, wantRev: number) => {
const msg = await waitForSocketEvent(socket, 'message');
assert.deepEqual(msg, {
type: 'COLLABROOM',
data: {
type: 'ACCEPT_COMMIT',
newRev: wantRev,
},
});
};
const alphabet = 'abcdefghijklmnopqrstuvwxyz';
/**
* Generates a random string.
*
* @param {number} [len] - The desired length of the generated string.
* @param {string} [charset] - Characters to pick from.
* @returns {string}
*/
export const randomString = (len: number = 10, charset: string = `${alphabet}${alphabet.toUpperCase()}0123456789`): string => {
let ret = '';
while (ret.length < len) ret += charset[Math.floor(Math.random() * charset.length)];
return ret;
};