From 66c69a7be18d5d4906773bc402eddd7be9035f17 Mon Sep 17 00:00:00 2001 From: Peter Amiri Date: Mon, 5 Oct 2026 17:50:18 -0700 Subject: [PATCH] fix(docs): stagger wheels JVM starts so concurrent blocks don't race in Lucee's bundle cache JVMs starting at the same moment in one CLI home race in Lucee's OSGi bundle cache ('Bundle symbolic name and version are not unique', then a null script engine) and fail or stall. runExec() now starts wheels commands one at a time, each WHEELS_START_GAP_MS (default 1 s) after the previous one; they still run in parallel once started. On 12 four-way runs: no gap failed 6, 250 ms and up failed none. felix.cache.locking=true did not help (3/12 failed). The verify-docs counts test runs the real four-way path again and no longer skips on CI. Closes #4450. Co-Authored-By: Claude Opus 5.5 Signed-off-by: Peter Amiri --- .../guides/scripts/verify-docs/lib/exec.mjs | 30 ++++++++++++- .../scripts/verify-docs/test/exec.test.mjs | 42 +++++++++++++++++++ .../verify-docs/test/orchestrator.test.mjs | 23 +++------- 3 files changed, 76 insertions(+), 19 deletions(-) diff --git a/web/sites/guides/scripts/verify-docs/lib/exec.mjs b/web/sites/guides/scripts/verify-docs/lib/exec.mjs index aa7e2a9c04..cc069d85d0 100644 --- a/web/sites/guides/scripts/verify-docs/lib/exec.mjs +++ b/web/sites/guides/scripts/verify-docs/lib/exec.mjs @@ -118,7 +118,34 @@ function killGroup(proc, signal) { * process still holds its output pipes. That leftover keeps running while the harness does (a block * may legitimately leave a server running, `wheels start`), and is stopped when the harness exits. */ -export function runExec(program, args = [], opts = {}) { +// Starts of `wheels` JVMs, one at a time: each waits until the previous one has had startGap() ms +// to boot. JVMs starting at the same moment in one CLI home race in Lucee's OSGi bundle cache +// ("Bundle symbolic name and version are not unique", then a null script engine) and fail or stall +// (#4450). Measured on 12 runs of four-way verify-docs: no gap failed 6, 250 ms and up failed none; +// 1 s leaves room for slower CI machines. Once started, commands still run in parallel. +let wheelsStartGate = Promise.resolve(); +export function startGap(env = process.env) { + const ms = Number(env.WHEELS_START_GAP_MS); + return Number.isFinite(ms) && ms >= 0 ? ms : 1_000; +} +function nextWheelsStart() { + const turn = wheelsStartGate; + let release; + wheelsStartGate = new Promise((r) => (release = r)); + return turn.then(() => () => setTimeout(release, startGap())); +} + +export async function runExec(program, args = [], opts = {}) { + const releaseStart = program === 'wheels' ? await nextWheelsStart() : null; + try { + return await runExecNow(program, args, opts, releaseStart); + } finally { + // If the spawn never happened (it threw), still hand over, so the next start isn't stuck. + releaseStart?.(); + } +} + +function runExecNow(program, args, opts, releaseStart) { const { cwd, env } = opts; const timeout = opts.timeout ?? defaultExecTimeout(); const spawnOpts = { @@ -143,6 +170,7 @@ export function runExec(program, args = [], opts = {}) { return new Promise((resolve) => { const proc = spawn(resolvedProgram, args, spawnOpts); + releaseStart?.(); running.add(proc); let stdout = ''; let stderr = ''; diff --git a/web/sites/guides/scripts/verify-docs/test/exec.test.mjs b/web/sites/guides/scripts/verify-docs/test/exec.test.mjs index af624206d1..f9e2db875c 100644 --- a/web/sites/guides/scripts/verify-docs/test/exec.test.mjs +++ b/web/sites/guides/scripts/verify-docs/test/exec.test.mjs @@ -130,3 +130,45 @@ test('a leftover from a command that exited is stopped when the harness exits', if (grandchild) try { process.kill(grandchild, 'SIGKILL'); } catch {} } }); + +test('wheels starts are staggered, so JVMs never start at the same moment', { timeout: 60_000 }, async () => { + // Simultaneous `wheels` JVM starts in one CLI home race in Lucee's OSGi bundle cache (#4450). + // A fake `wheels` prints when it started; three called at once must start at least the gap apart. + const { mkdtempSync, writeFileSync, chmodSync, rmSync } = await import('node:fs'); + const { tmpdir } = await import('node:os'); + const { join } = await import('node:path'); + const { spawn } = await import('node:child_process'); + const dir = mkdtempSync(join(tmpdir(), 'vd-gate-')); + try { + const fake = join(dir, 'wheels'); + writeFileSync(fake, `#!${process.execPath}\nconsole.log(Date.now()); setTimeout(() => {}, 300);\n`); + chmodSync(fake, 0o755); + const lib = new URL('../lib/exec.mjs', import.meta.url).href; + const harness = [ + `const { runExec } = await import(${JSON.stringify(lib)});`, + "const rs = await Promise.all([1, 2, 3].map(() => runExec('wheels', ['x'])));", + "console.log(JSON.stringify(rs.map((r) => Number(r.stdout.trim()))));", + ].join('\n'); + const env = { ...process.env, WHEELS_BIN: fake, WHEELS_START_GAP_MS: '1000' }; + const proc = spawn(NODE, ['--input-type=module', '-e', harness], { env, stdio: ['ignore', 'pipe', 'inherit'] }); + let out = ''; + proc.stdout.on('data', (d) => (out += d)); + await new Promise((resolve) => proc.once('exit', resolve)); + const starts = JSON.parse(out.trim().split('\n').pop()).sort((a, b) => a - b); + assert.equal(starts.length, 3); + for (let i = 1; i < starts.length; i++) { + // The fake records its start after its own Node boot, which varies; leave room for that. + assert.ok(starts[i] - starts[i - 1] >= 600, `starts ${starts[i - 1]} and ${starts[i]} are under the gap apart`); + } + } finally { + rmSync(dir, { recursive: true, force: true }); + } +}); + +test('the start gap comes from WHEELS_START_GAP_MS', async () => { + const { startGap } = await import('../lib/exec.mjs'); + assert.equal(startGap({ WHEELS_START_GAP_MS: '250' }), 250); + assert.equal(startGap({ WHEELS_START_GAP_MS: '0' }), 0); + assert.equal(startGap({}), 1000); + assert.equal(startGap({ WHEELS_START_GAP_MS: 'nope' }), 1000); +}); diff --git a/web/sites/guides/scripts/verify-docs/test/orchestrator.test.mjs b/web/sites/guides/scripts/verify-docs/test/orchestrator.test.mjs index bd5970d11d..a4144338af 100644 --- a/web/sites/guides/scripts/verify-docs/test/orchestrator.test.mjs +++ b/web/sites/guides/scripts/verify-docs/test/orchestrator.test.mjs @@ -27,24 +27,11 @@ function runEntry(args, env = {}) { }); } -test('verify-docs reports pass/fail counts', { timeout: 300_000 }, async (t) => { - // Several `wheels` JVMs starting at once in a fresh isolated home race in Lucee's OSGi bundle cache - // ("Bundle symbolic name and version are not unique") and fail or stall (#4450). The sample has two - // per-block examples, so run them one at a time. If it still fails, bound each command at 60 s so a - // stall surfaces quickly, show the child's output (which names the command), and skip on CI while - // #4450 is open. Locally a failure still fails. - const { code, stdout, stderr } = await runEntry([fixture], { - VERIFY_DOCS_CONCURRENCY: '1', - WHEELS_EXEC_TIMEOUT_MS: '60000', - }); - if (code !== 0) { - t.diagnostic(`verify-docs exited ${code}`); - for (const line of `--- stdout ---\n${stdout}\n--- stderr ---\n${stderr}`.split('\n')) t.diagnostic(line); - if (process.env.CI) { - t.skip('a wheels command stalls on CI (#4450); the output above names it'); - return; - } - } +test('verify-docs reports pass/fail counts', { timeout: 300_000 }, async () => { + // Runs the per-block examples four at a time, as a real run does: `wheels` JVM starts are staggered + // in runExec() because simultaneous starts in one CLI home race (#4450). Each command is bounded at + // 60 s so a stall surfaces quickly, and a failure shows the child's output. + const { code, stdout, stderr } = await runEntry([fixture], { WHEELS_EXEC_TIMEOUT_MS: '60000' }); // Phase 1 drivers: cli + tutorial + compile. Fixture has compile + cli + // tutorial; all three pass (compile falls back to bracket-check when // LuCLI PR #1 isn't installed, which still accepts the balanced sample).