diff --git a/.changeset/stall-forensics-and-kernel-test-hygiene.md b/.changeset/stall-forensics-and-kernel-test-hygiene.md new file mode 100644 index 0000000000..eefc587edc --- /dev/null +++ b/.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. diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 9dbecfcd13..5270b650d1 100644 --- a/.github/workflows/ci.yml +++ b/.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. @@ -444,10 +471,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 @@ -462,6 +494,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. diff --git a/packages/objectql/src/plugin.integration.test.ts b/packages/objectql/src/plugin.integration.test.ts index 202647e6ab..34b4b944e7 100644 --- a/packages/objectql/src/plugin.integration.test.ts +++ b/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)', () => { diff --git a/packages/objectql/src/plugin.step2.test.ts b/packages/objectql/src/plugin.step2.test.ts index 838631f953..45289a9b97 100644 --- a/packages/objectql/src/plugin.step2.test.ts +++ b/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 () => { diff --git a/scripts/run-with-stall-guard.mjs b/scripts/run-with-stall-guard.mjs index 6f83cecf65..42d6d88fa5 100644 --- a/scripts/run-with-stall-guard.mjs +++ b/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 [--stall-minutes N] -- +// node scripts/run-with-stall-guard.mjs --log [--stall-minutes N] \ +// [--report-dir ] -- // // 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=", 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. */ +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) => {