test(ci): heartbeat + running-test pointer to debug the silent backend-test ELIFECYCLE (#7838)

* test(ci): heartbeat + running-test pointer in backend test diagnostics

Backend tests silently die with code 255 mid-suite ~22% of the time on
develop (most often Windows-with-plugins, Node 24). Each kill lands
300±50 ms after the previous test's clean ✔ teardown line and produces
no failing-test marker, no error, no Mocha summary, and — despite the
unconditional handlers in `diagnostics.ts` — none of the JS-level death
events fire either. Recent example: run 26311025244 (`Windows with
Plugins (24)`); both attempts crashed at completely different "last
test" locations, so the dying test itself isn't to blame.

The existing diagnostics only set lastSeenTest in afterEach, so if the
kill lands during the NEXT test's setup or body — which is exactly the
~300ms gap we observe — the pointer reads as the previous (passing)
test. That hides whether we're between tests or inside one, and which
one.

Two changes:

1. Track currentTest in beforeEach as well as lastFinishedTest in
   afterEach. Every diag line now carries both, so the death point is
   bracketable regardless of which lifecycle phase the kill interrupts.

2. Add a 1Hz heartbeat that writeSyncs the running-test name plus
   `process.memoryUsage()` (rss, heap) and the active-handle and
   active-request counts. The interval is unref'd so it never holds the
   event loop open by itself. Cost is roughly one extra log line per
   second of mocha runtime (~60-120 lines per CI run).

When the next failure fires, the last heartbeat narrows the kill window
to ≤1s, the running pointer names the test on the rails at that moment,
and the handle/memory trace gives a sparkline that exposes sudden
spikes — a leaked socket, an unref'd timer, a runaway map — that
would otherwise be invisible at the runner-log level.

No behavior change on successful runs.

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

* fix: heartbeat _getActiveHandles optional chain bug (Qodo #2)

Qodo correctly flagged `_getActiveHandles?.().length` as a latent
TypeError: `?.()` guards the call but the call's `undefined` return
on a missing method still hits `.length`, which throws. Since the
heartbeat fires on a setInterval inside the mocha bootstrap, a Node
build without the underscore-prefixed internals would take down the
whole backend test run.

Capture the array first, then read `.length` only when it actually
exists. -1 stays as the "API missing" sentinel.

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

* test(ci): per-test start diag + drop stray console.log noise

Follow-up to the heartbeat PR after run 26397693748 confirmed the
diagnostic works (the kill landed at importexportGetPost.ts
'Import authorization checks > authn anonymous !exist -> fail',
~300 ms after the previous test's ✔). Two cleanups so the next
failure pinpoints faster and reads cleaner:

1. diagnostics.ts: emit a `test start: <name>` diag line in the
   mocha beforeEach hook, after setting the currentTest pointer.
   The 1Hz heartbeat misses tests that take less than a second,
   and the silent kills land ~300 ms after a test boundary —
   precisely the gap where heartbeat resolution fails. A start
   line per test gives sub-millisecond resolution on which test
   was on the rails when the process died.

2. specs/api/importexportGetPost.ts: drop a stray
   `console.log(importedPads)` debug leftover (and the duplicate
   `await importEtherpad(records)` only present to feed it) in
   the `malformed .etherpad files are rejected` block. The leftover
   dumped a ~600-line reflection of a supertest Response object
   to the CI log on every successful run, drowning the surrounding
   test output and making the silent-kill window much harder to
   read.

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

* test(ci): write node-report on every heartbeat tick

Run 26398054688 narrowed the kill to a specific test
(pad.ts > Gets text on a pad Id and doesn't have an excess newline)
but the test body is a trivial supertest GET — the kill bypasses
all JS handlers, so we can't capture stack state at death.
Two failures across two runs share the shape: an agent.{get,post}
+ common.generateJWTToken() call dies ~300-600 ms after test start,
with no JS-visible cause. The next step is V8 + native stack.

Hook into the existing 1Hz heartbeat to call
process.report.writeReport(path) whenever a report directory is set.
The Windows backend-tests workflow already wires up
`--report-directory=${{ github.workspace }}/node-report` via
NODE_OPTIONS and uploads that directory as an artifact on failure,
so the rolling snapshots ride for free on the existing upload step.

Each report (~50 KB) contains:
  - V8 + native call stacks for all threads
  - libuv active handles (open TCP, timers, file handles)
  - JS heap statistics
  - resourceUsage + system info
  - shared-object list

On the next reproduction the latest report before ELIFECYCLE will
sit ~0-1 s before the kill — enough to see whether the V8 stack
is inside jose's WebCrypto sign path, inside supertest's TCP
roundtrip, or somewhere unexpected entirely.

NODE_REPORT_DIR is also honored as an explicit override for local
repro / non-workflow runs.

Cost: ~6 files (~300 KB) per Windows backend-test failure, plus
~50 ms event-loop pause per heartbeat. No-op when neither env var
is set.

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

* fix: writeReport with bare filename, not mixed-slash absolute path

Run 26398830249 exposed the path-separator bug in the previous commit:
every heartbeat tick on the Windows runner logged

  Failed to open Node.js report file:
  D:\a\etherpad\etherpad/node-report/hb-NNNN-...json
  directory: D:\a\etherpad\etherpad/node-report (errno: 22)

— EINVAL. The workflow sets --report-directory with forward-slash
separators on Windows, then this code concatenated another `/` plus
the filename, producing a path Node's report writer rejects.

writeReport(fileName) takes a BARE filename and resolves it against
the configured report directory using the platform-correct separator
internally. Switch to that. For local repro overrides via
NODE_REPORT_DIR, push the path into process.report.directory (the
documented config knob) instead of joining it into the call site.

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

* test(ci): write node-report on test boundaries, throttled to 4Hz

Run 26398985832 proved the heartbeat-only report cadence isn't tight
enough: the last report before the kill was hb-0013 at +16201ms,
~1.5 s before ELIFECYCLE at +17701ms — during which ~30 tests fired,
including the dying one (`authn anonymous !exist -> fail`). The
captured V8 stack is just our heartbeat code, not the dying test.

Move the writeReport call to a shared tryWriteReport() helper and
invoke it from BOTH the heartbeat AND mocha's beforeEach hook,
throttled to one report per 250 ms. That gives ≤250 ms resolution
on the kill window — close enough that the latest report captures
state from inside the dying test rather than from the test ~30
slots earlier. The heartbeat always writes (so we don't lose the
no-test-running ticks during setup); beforeEach only writes when
the throttle window has elapsed.

Cost ceiling: ~4 reports/sec × ~12 s test phase ≈ 48 reports
(~2.5 MB) per failing run. Each writeReport adds ~50 ms of
event-loop pause — at 4Hz that's 20% of wall time spent in
diagnostics, which is acceptable for a temporary debug-only
bootstrap.

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

* test(ci): drop beforeEach report throttle from 250ms to 100ms

Run 26399285213's rerun captured a sixth death point on the new 4Hz
cadence (`socketio.ts > Duplicate-author handling > cookie identity:
same-author second socket kicks the first`, kill at +45953ms, 271ms
after test start). The throttle suppressed the dying test's own
beforeEach: previous boundary write landed 128 ms earlier and the
next 31 ms after that, both inside the 250 ms window. Last captured
report (be-0100) is from the previous test.

100 ms is still well above the inter-test cadence in fast burst
suites (tests fire 2-5 ms apart, so 20-50 of them get throttled to a
single write, ceiling ~10 writes/sec). But it's tight enough that
any death-window neighbour ≥100 ms after the previous report — the
shape we keep observing — gets its own boundary snapshot.

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

---------

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

Author: JohnMcLear

src/tests/backend/diagnostics.ts

@@ -10,6 +10,14 @@
 // in a way that bypassed JS handlers — SIGKILL, OOM, or a fatal native
 // error — OR mocha itself called process.exit before the handlers ran.
 //
+// Subsequent runs on develop (e.g. 26311025244, Windows with plugins,
+// Node 24) reproduced the same fingerprint: `[diag +0ms] diagnostics
+// loaded` lands but no other diag line appears before the silent
+// ELIFECYCLE. Death lands 300±50 ms after the previous test's teardown
+// and the lastSeenTest pointer (only updated in afterEach) tells us
+// nothing about whether the next test had started or whether mocha was
+// between tests at the kill moment.
+//
 // This file:
 //   1. Registers handlers UNCONDITIONALLY at mocha startup (common.ts is
 //      only imported by ~27 of 47 specs, so its handlers may register
@@ -18,9 +26,17 @@
 //      complete before the kernel returns from the syscall, so the line
 //      lands in the runner log even if the process is killed
 //      milliseconds later.
-//   3. Tracks the last-seen test via a mocha root afterEach hook so the
-//      death point is identified.
-//   4. Logs exit-related events so we can discriminate:
+//   3. Tracks BOTH the currently-running test (set in beforeEach) and the
+//      last-finished test (set in afterEach), so the death point can be
+//      bracketed even when the kill lands inside the next test's setup or
+//      body, before its own afterEach has a chance to update the pointer.
+//   4. Emits a 1Hz heartbeat carrying the running-test name, RSS / heap
+//      usage, and active handle / request counts. If the process dies
+//      without firing any JS handler, the last heartbeat narrows the
+//      kill window to <=1s and the handle-count trace exposes leaks
+//      (sockets, timers, native bindings) that would otherwise be
+//      invisible at the runner-log level.
+//   5. Logs exit-related events so we can discriminate:
 //        beforeExit + exit  -> clean event-loop drain (Linux CI, local)
 //        only exit          -> process.exit() called — expected when mocha
 //                              is launched with --exit (the Windows CI
@@ -35,7 +51,8 @@
 import {writeSync} from 'node:fs';
 
 const t0 = Date.now();
-let lastSeenTest = '<no test seen yet>';
+let currentTest = '<no test running>';
+let lastFinishedTest = '<no test finished yet>';
 
 const diag = (msg: string): void => {
   const line = `[diag +${Date.now() - t0}ms] ${msg}\n`;
@@ -48,18 +65,92 @@ const diag = (msg: string): void => {
 
 diag('diagnostics loaded');
 
+// Heartbeat. unref()'d so it never holds the event loop open by itself —
+// it only fires if mocha is otherwise alive. The interval cadence (1Hz) is
+// the trade-off between log noise (~60-120 extra lines per run) and how
+// tightly we can bracket the kill timestamp.
+//
+// When the backend-test workflow has `--report-directory` set (only the
+// Windows jobs do at time of writing), every heartbeat also writes a Node
+// diagnostic report into that directory. The previous two failing CI runs
+// proved the kill bypasses all JS handlers (uncaughtException, signal,
+// beforeExit — none fire), so we can't capture stack state at the moment
+// of death. The next-best thing is a rolling 1Hz snapshot of:
+//   - V8 / native call stacks (all threads)
+//   - libuv active handles (open TCP connections, timers, file handles)
+//   - JS heap statistics
+//   - System info (CPU, memory, environment)
+// On the next failure the workflow uploads node-report/ as an artifact,
+// and the latest report before the kill bracket gives us 0-1s of pre-death
+// state — including, critically, whether the V8 stack is inside jose's
+// JWT signing path, supertest's TCP roundtrip, or somewhere else.
+// Honor NODE_REPORT_DIR as a local-repro override by pushing it into
+// process.report.directory, which is the documented config knob. We can NOT
+// pass an absolute path into writeReport(): on Windows the runner sets
+// `--report-directory=D:\a\etherpad\etherpad/node-report` (mixed slashes),
+// and Node's report writer rejects any subsequent absolute path with errno
+// 22 / EINVAL. Pass a bare filename and let Node concatenate it against the
+// configured directory using its own platform-correct separator.
+if (process.env.NODE_REPORT_DIR && (process as any).report) {
+  (process as any).report.directory = process.env.NODE_REPORT_DIR;
+}
+const canWriteReport =
+  typeof (process as any).report?.writeReport === 'function'
+  && !!((process as any).report?.directory
+    || (process.env.NODE_OPTIONS || '').includes('--report-directory='));
+let reportCounter = 0;
+let lastReportT = 0;
+
+// Shared writer used by both the heartbeat tick and the beforeEach hook.
+// Throttled by minGapMs so a burst of fast tests doesn't produce hundreds of
+// reports — we just need dense enough coverage to bracket the kill.
+const tryWriteReport = (prefix: string, minGapMs: number): void => {
+  if (!canWriteReport) return;
+  const now = Date.now();
+  if (now - lastReportT < minGapMs) return;
+  lastReportT = now;
+  reportCounter += 1;
+  const safeTest = currentTest
+    .replace(/[^a-zA-Z0-9._-]+/g, '_')
+    .slice(0, 80);
+  const name = `${prefix}-${String(reportCounter).padStart(4, '0')}-${safeTest}.json`;
+  try {
+    // Bare filename only — see comment at canWriteReport definition above.
+    (process as any).report.writeReport(name);
+  } catch { /* swallow — diagnostics must not throw */ }
+};
+const heartbeat = setInterval(() => {
+  const mem = process.memoryUsage();
+  // _getActiveHandles / _getActiveRequests are undocumented Node internals.
+  // The earlier shape `_getActiveHandles?.().length ?? -1` was a bug: `?.()`
+  // only guards the call, so a missing method returns `undefined` and then
+  // `.length` throws TypeError — which would take down the whole test run.
+  // Capture the array first, then read .length only when it actually exists.
+  const handlesArr = (process as any)._getActiveHandles?.();
+  const handles = handlesArr ? handlesArr.length : -1;
+  const requestsArr = (process as any)._getActiveRequests?.();
+  const requests = requestsArr ? requestsArr.length : -1;
+  diag(`hb running="${currentTest}" lastFinished="${lastFinishedTest}" ` +
+    `rss=${Math.round(mem.rss / 1024 / 1024)}M ` +
+    `heap=${Math.round(mem.heapUsed / 1024 / 1024)}M ` +
+    `handles=${handles} requests=${requests}`);
+  // Heartbeat always writes — its 1Hz cadence is the floor.
+  tryWriteReport('hb', 0);
+}, 1000);
+heartbeat.unref();
+
 process.on('unhandledRejection', (reason: any) => {
   diag(`unhandledRejection: ${
     reason && reason.stack ? reason.stack : String(reason)
-  } (lastTest="${lastSeenTest}")`);
+  } (running="${currentTest}", lastFinished="${lastFinishedTest}")`);
   // Re-throw so existing common.ts handlers / mocha behavior is preserved.
   throw reason;
 });
 
 process.on('uncaughtException', (err: any) => {
   diag(`uncaughtException: ${
     err && err.stack ? err.stack : String(err)
-  } (lastTest="${lastSeenTest}")`);
+  } (running="${currentTest}", lastFinished="${lastFinishedTest}")`);
   // Force fail-fast. Specs that don't import common.ts only have THIS handler,
   // and Node won't exit on its own once an uncaughtException listener is
   // registered. Without the explicit exit a fatal error would be swallowed.
@@ -69,18 +160,18 @@ process.on('uncaughtException', (err: any) => {
 
 process.on('beforeExit', (code: number) => {
   diag(`beforeExit code=${code} exitCode=${process.exitCode} ` +
-    `lastTest="${lastSeenTest}"`);
+    `running="${currentTest}" lastFinished="${lastFinishedTest}"`);
 });
 
 process.on('exit', (code: number) => {
-  diag(`exit code=${code} lastTest="${lastSeenTest}"`);
+  diag(`exit code=${code} running="${currentTest}" lastFinished="${lastFinishedTest}"`);
 });
 
 for (const sig of ['SIGINT', 'SIGTERM', 'SIGHUP', 'SIGBREAK'] as const) {
   // SIGHUP / SIGBREAK don't exist on every platform; ignore registration errors.
   try {
     process.on(sig as any, () => {
-      diag(`received ${sig} (lastTest="${lastSeenTest}")`);
+      diag(`received ${sig} (running="${currentTest}", lastFinished="${lastFinishedTest}")`);
       // Let the default behavior (exit) happen.
       process.exit(128);
     });
@@ -89,12 +180,36 @@ for (const sig of ['SIGINT', 'SIGTERM', 'SIGHUP', 'SIGBREAK'] as const) {
   }
 }
 
-// Mocha root hook — only registered if mocha picks up this file via --require.
-// We track the most recently-finished test so the death point is visible.
+// Mocha root hooks — only registered if mocha picks up this file via --require.
+// beforeEach sets the running pointer so a mid-test kill is attributable to a
+// specific test, not just the previous one that successfully finished.
+//
+// We also emit a synchronous diag line on every test start. The 1Hz heartbeat
+// misses tests that take less than a second, and the silent backend-test
+// kills land ~300 ms after a test boundary — exactly the gap where heartbeat
+// resolution fails us. A `start` line per test gives sub-millisecond
+// resolution on which test was on the rails when the process died.
 export const mochaHooks = {
+  beforeEach(this: any) {
+    if (this.currentTest) {
+      currentTest = this.currentTest.fullTitle();
+      diag(`test start: ${currentTest}`);
+      // Drop a node-report at test-boundary granularity when the inter-report
+      // gap is wide enough. Run 26399285213's rerun caught the kill on the
+      // socketio.ts duplicate-author test, but the previous boundary write
+      // had landed 128 ms earlier — inside our 250 ms throttle, so the
+      // dying test's own beforeEach was suppressed. 100 ms is tighter than
+      // the inter-test cadence of fast burst suites (~2-5 ms per test, so
+      // ~20-50× throttled = max ~10 writes/sec) yet still captures
+      // boundary writes for any test whose neighbour fired ≥100 ms ago,
+      // including the socketio tests in the dying-test pattern.
+      tryWriteReport('be', 100);
+    }
+  },
   afterEach(this: any) {
     if (this.currentTest) {
-      lastSeenTest = this.currentTest.fullTitle();
+      lastFinishedTest = this.currentTest.fullTitle();
+      currentTest = '<no test running>';
     }
   },
 };

src/tests/backend/specs/api/importexportGetPost.ts

@@ -418,8 +418,6 @@ describe(__filename, function () {
         // that a buggy makeGoodExport() doesn't cause checks to accidentally pass.
         const records = makeGoodExport();
         await deleteTestPad();
-        const importedPads = await importEtherpad(records)
-        console.log(importedPads)
         await importEtherpad(records)
             .expect(200)
             .expect('Content-Type', /json/)