ci,test: a #4250 stall now names its own culprit; test kernels stop intercepting SIGTERM (#4250) (#4341)

Investigation results behind this change (full analysis on #4250):

- Both stall-point files sit in packages/objectql, but neither the
  in-test drivers (pure in-memory no-ops) nor bare ObjectQL engines hold
  event-loop handles, lifecycle sweep timers are unref'd, and the logger
  is threadless -- the issue's unreleased-handle hypothesis does not fit
  this package's unit suites.
- What DID show up: one objectql run booted 47 kernels whose
  gracefulShutdown default installed SIGINT/SIGTERM/SIGQUIT handlers
  inside vitest fork workers -- 48 SIGTERM interceptions per run, every
  worker recycle running a multi-kernel async shutdown race (3 of 47
  graceful shutdowns never completed, cut short by another kernel's
  process.exit). Every path does eventually exit, so this is not proven
  to BE #4250 -- but it is the machinery standing closest to it, and it
  serves no test purpose.
- Those same kernels declared `logLevel: 'silent'` -- a config key
  ObjectKernelConfig never had (the real shape is `logger.level`; CI
  type-checks spec and examples, not these tests, which is why the dead
  key survived). All 47 boots logged at info: ~half the package's log
  volume, the exact "engine init sequences" frozen at the top of both
  #4250 logs.

Changes:

- plugin.integration.test.ts / plugin.step2.test.ts: kernels boot with
  the real silence key (`logger: { level: 'silent' }`) and
  gracefulShutdown:false, and afterEach shuts down what it booted.
  Verified: kernel bootstrap log lines in a full run drop 47 -> 0,
  worker SIGTERM interceptions 48 -> 0, package log 4579 -> 2096 lines,
  87 files / 1374 tests stay green.
- run-with-stall-guard.mjs: on a declared stall, before killing, it now
  (1) samples every process in the frozen group twice via /proc and
  classifies each as ON-CPU (sync spin / GC thrash) or idle (awaiting
  something that never settles), and (2) with --report-dir set, sends
  SIGUSR2 so every node process whose event loop is alive dumps a
  diagnostic report -- digested into the log as an exact JS stack; a
  process that produces NO report is named as loop-blocked (verified
  behavior: node's report-on-signal is served by the event loop).
  Forensics are Linux-/proc best-effort, add at most ~6s before the
  kill, and never fail the kill path.
- ci.yml: Test Core and Dogfood test steps arm the harvest via
  NODE_OPTIONS (--report-on-signal) and pass --report-dir; on failure
  the full reports upload as artifacts (14-day retention).

The next real stall stops being a mystery: the step log will say which
process froze, in which mode, and -- for the await-forever class -- on
exactly which stack.


Claude-Session: https://claude.ai/code/session_014NNaWXVEyG6Pv4EFRfYGg6

Co-authored-by: Claude <noreply@anthropic.com>

Author: os-zhuang

.changeset/stall-forensics-and-kernel-test-hygiene.md

@@ -0,0 +1,4 @@
+---
+---
+
+ci/test: #4250 stall forensics (SIGUSR2 stack harvest in run-with-stall-guard) + objectql kernel tests stop intercepting worker SIGTERM. Releases nothing.

.github/workflows/ci.yml

@@ -145,12 +145,22 @@ jobs:
       # stall — a labeled red naming the last output line — instead of a
       # 20-minute wait for a human (or the job timeout) to notice. 10 min is
       # ~5× the longest healthy quiet gap and still under half a normal run.
+      #
+      # NODE_OPTIONS arms every node process (vitest workers included) to dump
+      # a diagnostic report on SIGUSR2; on a stall the guard signals the frozen
+      # process group and digests the reports into the log — exact JS stack for
+      # a process whose event loop is alive, and a named "no report = blocked
+      # loop" verdict for one that is sync-spinning. The next #4250 occurrence
+      # identifies its own culprit instead of costing a diagnosis.
       - name: Run affected tests (PR)
         if: github.event_name == 'pull_request'
         env:
           TURBO_SCM_BASE: ${{ github.event.pull_request.base.sha }}
+          NODE_OPTIONS: --report-on-signal --report-signal=SIGUSR2 --report-directory=${{ runner.temp }}/stall-reports
         run: |
-          node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/test-core.log" --stall-minutes 10 -- \
+          mkdir -p "$RUNNER_TEMP/stall-reports"
+          node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/test-core.log" --stall-minutes 10 \
+            --report-dir "$RUNNER_TEMP/stall-reports" -- \
             pnpm turbo run test --affected --filter=!@objectstack/dogfood --concurrency=4
 
       # Push to main: full run. Spec's suite runs here plain (uninstrumented);
@@ -161,8 +171,12 @@ jobs:
       # Dogfood job runs it.
       - name: Run all tests (push)
         if: github.event_name == 'push'
+        env:
+          NODE_OPTIONS: --report-on-signal --report-signal=SIGUSR2 --report-directory=${{ runner.temp }}/stall-reports
         run: |
-          node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/test-core.log" --stall-minutes 10 -- \
+          mkdir -p "$RUNNER_TEMP/stall-reports"
+          node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/test-core.log" --stall-minutes 10 \
+            --report-dir "$RUNNER_TEMP/stall-reports" -- \
             pnpm turbo run test --filter=!@objectstack/dogfood --concurrency=4
 
       # Runs even when the suite failed — that is when it earns its keep. A red
@@ -178,6 +192,19 @@ jobs:
           fi
           node scripts/check-test-completeness.mjs "$RUNNER_TEMP/test-core.log"
 
+      # A stall's full diagnostic reports (JS stacks, libuv handles, heap
+      # summary per process) outlive the in-log digest — keep them so a #4250
+      # occurrence can be dissected offline. Free when nothing stalled: the
+      # directory is empty and if-no-files-found skips the upload.
+      - name: Upload stall diagnostic reports
+        if: failure()
+        uses: actions/upload-artifact@v7
+        with:
+          name: stall-reports-test-core
+          path: ${{ runner.temp }}/stall-reports/
+          if-no-files-found: ignore
+          retention-days: 14
+
       # Seed the shared Turbo cache from main only (see the restore step
       # above). always(): keep the seed fresh even when a test fails, matching
       # the old actions/cache post-step behavior.
@@ -462,10 +489,15 @@ jobs:
       # below, propagates the suite's real exit status (no `| tee` + pipefail),
       # and turns frozen output into a labeled red after 10 min of silence.
       # Dogfood boots real engines in-process — exactly the population #4250's
-      # stalls came from.
+      # stalls came from. NODE_OPTIONS + --report-dir arm the stall forensics
+      # (SIGUSR2 stack harvest) — see the Test Core comment.
       - name: Boot example apps and exercise real user flows
+        env:
+          NODE_OPTIONS: --report-on-signal --report-signal=SIGUSR2 --report-directory=${{ runner.temp }}/stall-reports
         run: |
-          node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/dogfood.log" --stall-minutes 10 -- \
+          mkdir -p "$RUNNER_TEMP/stall-reports"
+          node scripts/run-with-stall-guard.mjs --log "$RUNNER_TEMP/dogfood.log" --stall-minutes 10 \
+            --report-dir "$RUNNER_TEMP/stall-reports" -- \
             pnpm turbo run test --filter=@objectstack/dogfood -- --shard=${{ matrix.shard }}/2
 
       # Dogfood boots real apps in-process, so a native/OOM abort is likelier
@@ -480,6 +512,17 @@ jobs:
           fi
           node scripts/check-test-completeness.mjs "$RUNNER_TEMP/dogfood.log"
 
+      # Same offline-forensics artifact as Test Core; shard-scoped name so the
+      # two matrix jobs don't collide.
+      - name: Upload stall diagnostic reports
+        if: failure()
+        uses: actions/upload-artifact@v7
+        with:
+          name: stall-reports-dogfood-${{ matrix.shard }}
+          path: ${{ runner.temp }}/stall-reports/
+          if-no-files-found: ignore
+          retention-days: 14
+
       # Replaces the former auto-verify dogfood tests: runs the published
       # `objectstack verify` engine over each example app through the CLI —
       # auto-derived CRUD round-trip fidelity + the cross-owner RLS invariant.

packages/objectql/src/plugin.integration.test.ts

@@ -1,6 +1,6 @@
 // Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license.
 
-import { describe, it, expect, beforeEach } from 'vitest';
+import { describe, it, expect, beforeEach, afterEach } from 'vitest';
 import { ObjectKernel } from '@objectstack/core';
 import { ObjectQLPlugin } from '../src/plugin';
 import { ObjectSchema } from '@objectstack/spec/data';
@@ -10,7 +10,21 @@ describe('ObjectQLPlugin - Metadata Service Integration', () => {
   let kernel: ObjectKernel;
 
   beforeEach(() => {
-    kernel = new ObjectKernel({ logLevel: 'silent' });
+    // logger.level — NOT `logLevel`, which ObjectKernelConfig never had: every
+    // kernel here logged its whole bootstrap at info while declaring itself
+    // silent, ~40 boots' worth of noise per run in the Test Core log (#4250).
+    // gracefulShutdown:false — a test kernel must not install process-wide
+    // SIGINT/SIGTERM handlers: vitest recycles each fork worker with SIGTERM,
+    // and a kernel that intercepts it makes worker exit depend on the kernel's
+    // async shutdown race instead of Node's default die-on-signal.
+    kernel = new ObjectKernel({ logger: { level: 'silent' }, gracefulShutdown: false });
+  });
+
+  afterEach(async () => {
+    // Shut down what we booted: a kernel left running defers its plugins'
+    // stop() work (engine destroy, driver disconnect) to worker teardown,
+    // where nothing awaits or reports it.
+    if (kernel.getState() === 'running') await kernel.shutdown();
   });
 
   describe('Simple Mode (ObjectQL-only)', () => {

packages/objectql/src/plugin.step2.test.ts

@@ -10,7 +10,7 @@
  * on objectql, even as a devDependency — turbo flags the cycle.)
  */
 
-import { describe, it, expect, beforeEach } from 'vitest';
+import { describe, it, expect, beforeEach, afterEach } from 'vitest';
 import { ObjectKernel } from '@objectstack/core';
 import { createMetadataProtocolPlugin, ObjectStackProtocolImplementation } from '@objectstack/metadata-protocol';
 import { ObjectQLPlugin } from './plugin';
@@ -19,7 +19,15 @@ describe('ADR-0076 Step 2 — delegated protocol assembly', () => {
   let kernel: ObjectKernel;
 
   beforeEach(() => {
-    kernel = new ObjectKernel({ logLevel: 'silent' });
+    // See plugin.integration.test.ts for both choices: `logger.level` is the
+    // real config key (`logLevel` never existed on ObjectKernelConfig and
+    // silenced nothing), and gracefulShutdown:false keeps process signal
+    // handlers out of vitest's fork workers (#4250).
+    kernel = new ObjectKernel({ logger: { level: 'silent' }, gracefulShutdown: false });
+  });
+
+  afterEach(async () => {
+    if (kernel.getState() === 'running') await kernel.shutdown();
   });
 
   it('registerProtocol:false + MetadataProtocolPlugin reproduces the built-in service surface', async () => {

scripts/run-with-stall-guard.mjs

@@ -16,7 +16,8 @@
 // (EX_TEMPFAIL: the sanctioned response is a rerun -- every #4250 occurrence
 // passed on rerun of the same commit).
 //
-//   node scripts/run-with-stall-guard.mjs --log <file> [--stall-minutes N] -- <command...>
+//   node scripts/run-with-stall-guard.mjs --log <file> [--stall-minutes N] \
+//     [--report-dir <dir>] -- <command...>
 //
 // It also owns the log tee: combined stdout+stderr is forwarded to this
 // process's stdout AND appended to --log (which check-test-completeness.mjs
@@ -25,11 +26,33 @@
 // child's real exit status is propagated by construction, so there is no pipe
 // to guard. Do not reintroduce `| tee`.
 //
+// ## Stall forensics (before the kill)
+//
+// A declared stall triages itself instead of leaving a mystery for a human:
+//
+//   1. Every process in the command's process group is sampled twice via
+//      /proc (state + CPU time, ~2s apart) and classified: a process that is
+//      BURNING CPU is sync-spinning or GC-thrashing; one that is idle is
+//      waiting on something that never settles.
+//   2. With --report-dir set AND the processes launched with
+//      NODE_OPTIONS="--report-on-signal --report-signal=SIGUSR2
+//      --report-directory=<dir>", each node process in the group gets a
+//      SIGUSR2: a live event loop responds with a diagnostic report (exact JS
+//      stack + open libuv handles), which is digested into the output. A node
+//      process that produces NO report has a BLOCKED event loop -- the
+//      no-report fact plus its CPU classification is itself the diagnosis.
+//      (Verified: report-on-signal is served BY the event loop, so a
+//      sync-blocked process stays silent -- that is signal, not failure.)
+//
+// Forensics are best-effort (Linux /proc; every step try/caught) and never
+// delay the kill by more than ~6s.
+//
 // Exit status: the child's own code when it finishes; 75 on a declared stall;
 // 1 when the child dies on a signal this guard did not send.
 
 import { spawn } from 'node:child_process';
-import { createWriteStream } from 'node:fs';
+import { createWriteStream, readFileSync, readdirSync, existsSync } from 'node:fs';
+import { join } from 'node:path';
 
 const STALL_EXIT_CODE = 75; // EX_TEMPFAIL
 const CHECK_INTERVAL_MS = 5_000;
@@ -38,11 +61,13 @@ const SIGKILL_GRACE_MS = 10_000;
 const argv = process.argv.slice(2);
 let logPath = '';
 let stallMinutes = 10;
+let reportDir = '';
 let command = [];
 
 for (let i = 0; i < argv.length; i++) {
   if (argv[i] === '--log') logPath = argv[++i] ?? '';
   else if (argv[i] === '--stall-minutes') stallMinutes = Number(argv[++i]);
+  else if (argv[i] === '--report-dir') reportDir = argv[++i] ?? '';
   else if (argv[i] === '--') {
     command = argv.slice(i + 1);
     break;
@@ -105,6 +130,113 @@ function killGroup(signal) {
   }
 }
 
+const sleep = (ms) => new Promise((r) => setTimeout(r, ms));
+
+/** One /proc sample of every process in the child's process group.
+ *  Returns Map<pid, {comm, state, cpuTicks, rssPages, cmdline}>. */
+function sampleGroup() {
+  const procs = new Map();
+  for (const entry of readdirSync('/proc')) {
+    if (!/^\d+$/.test(entry)) continue;
+    const pid = Number(entry);
+    try {
+      const stat = readFileSync(`/proc/${pid}/stat`, 'utf8');
+      // comm may contain spaces/parens -- split at the LAST ')'.
+      const rp = stat.lastIndexOf(')');
+      const comm = stat.slice(stat.indexOf('(') + 1, rp);
+      const f = stat.slice(rp + 2).split(' '); // f[0]=state f[2]=pgrp f[11]=utime f[12]=stime f[21]=rss
+      if (Number(f[2]) !== child.pid) continue;
+      let cmdline = '';
+      try {
+        cmdline = readFileSync(`/proc/${pid}/cmdline`, 'utf8').replace(/\0/g, ' ').trim();
+      } catch { /* raced with exit */ }
+      procs.set(pid, {
+        comm,
+        state: f[0],
+        cpuTicks: Number(f[11]) + Number(f[12]),
+        rssPages: Number(f[21]),
+        cmdline: cmdline || `[${comm}]`,
+      });
+    } catch { /* process vanished between readdir and read */ }
+  }
+  return procs;
+}
+
+/** Classify every group member from two /proc samples and, when report-dir
+ *  plumbing is armed, harvest SIGUSR2 diagnostic reports from the node
+ *  processes. Returns the forensics text block (empty string off-Linux). */
+async function collectForensics() {
+  if (!existsSync('/proc')) return '';
+  const lines = [];
+  try {
+    const before = sampleGroup();
+    await sleep(2_000);
+    const after = sampleGroup();
+
+    lines.push('Process group at stall time (2s CPU sample):');
+    for (const [pid, b] of before) {
+      const a = after.get(pid);
+      const cpuDelta = a ? a.cpuTicks - b.cpuTicks : 0;
+      // 2s sample at 100Hz ticks: >20 ticks ~= >10% of a core.
+      const verdict =
+        a === undefined ? 'exited during sampling'
+        : cpuDelta > 20 || a.state === 'R' ? 'ON-CPU -- sync-spinning or GC-thrashing'
+        : 'idle -- waiting on something that never settles';
+      const rssMb = Math.round(((a ?? b).rssPages * 4096) / 1_048_576);
+      const cmd = b.cmdline.length > 120 ? `${b.cmdline.slice(0, 117)}...` : b.cmdline;
+      lines.push(`  pid ${pid} [${b.state}${a ? `->${a.state}` : ''}] cpuΔ=${cpuDelta} ticks rss=${rssMb}MB  ${cmd}`);
+      lines.push(`       -> ${verdict}`);
+    }
+
+    if (reportDir && existsSync(reportDir)) {
+      const already = new Set(readdirSync(reportDir));
+      const nodePids = [...after.entries()]
+        .filter(([, p]) => /(^|\/)node(\s|$)/.test(p.cmdline) || p.comm === 'node')
+        .map(([pid]) => pid);
+      for (const pid of nodePids) {
+        try { process.kill(pid, 'SIGUSR2'); } catch { /* gone */ }
+      }
+      await sleep(3_000);
+      const fresh = readdirSync(reportDir).filter(
+        (f) => f.startsWith('report.') && f.endsWith('.json') && !already.has(f),
+      );
+      const reportedPids = new Set();
+      lines.push('');
+      lines.push(`Diagnostic reports (SIGUSR2 -> ${nodePids.length} node process(es), ${fresh.length} responded):`);
+      for (const file of fresh.slice(0, 6)) {
+        try {
+          const report = JSON.parse(readFileSync(join(reportDir, file), 'utf8'));
+          const pid = report.header?.processId;
+          reportedPids.add(pid);
+          const js = report.javascriptStack ?? {};
+          lines.push(
+            `  -- pid ${pid} (${file}): ${js.message || 'event loop responsive, no active JS frame -- awaiting something that never settles; check the report\'s libuv handles'}`,
+          );
+          for (const frame of (js.stack ?? []).slice(0, 10)) lines.push(`       ${frame.trim()}`);
+        } catch (e) {
+          lines.push(`  -- ${file}: unreadable (${e.message})`);
+        }
+      }
+      for (const pid of nodePids) {
+        if (reportedPids.has(pid)) continue;
+        lines.push(
+          `  -- pid ${pid}: NO report -- its event loop is BLOCKED (the report is served ` +
+          'by the loop). Cross-check its CPU verdict above: on-CPU = sync spin / GC; ' +
+          'idle = wedged outside JS.',
+        );
+      }
+      lines.push('  Full reports kept in the report dir -- upload/inspect for handles and heap.');
+    } else if (reportDir) {
+      lines.push(`Report dir ${reportDir} does not exist -- SIGUSR2 harvest skipped.`);
+    } else {
+      lines.push('No --report-dir -- SIGUSR2 stack harvest not armed for this run.');
+    }
+  } catch (e) {
+    lines.push(`(forensics incomplete: ${e.message})`);
+  }
+  return lines.length ? `\n${lines.join('\n')}\n` : '';
+}
+
 const watchdog = setInterval(() => {
   const silentMs = Date.now() - lastOutputAt;
   if (silentMs < stallMs) return;
@@ -126,12 +258,20 @@ ${'═'.repeat(72)}
    Triage: every #4250 stall so far passed on a plain rerun of the same
    commit -- rerun this job before suspecting the diff. If it stalls twice
    at the same test file, add that occurrence to #4250.
+
+   Collecting forensics before the kill (process states + JS stacks)...
 ${'═'.repeat(72)}
 `;
   process.stdout.write(banner);
   log.write(banner);
-  killGroup('SIGTERM');
-  setTimeout(() => killGroup('SIGKILL'), SIGKILL_GRACE_MS).unref();
+  void collectForensics().then((forensics) => {
+    if (forensics) {
+      process.stdout.write(forensics);
+      log.write(forensics);
+    }
+    killGroup('SIGTERM');
+    setTimeout(() => killGroup('SIGKILL'), SIGKILL_GRACE_MS).unref();
+  });
 }, CHECK_INTERVAL_MS);
 
 child.on('error', (err) => {