worker_threads test: make the stop-ordering fixture's log termination-safe by robobun · Pull Request #38194 · oven-sh/bun

robobun · 2026-08-13T17:40:53Z

Behaviour change: none

Test-only fix for the flaky test "terminate(): nothing of the worker's runs after the request" in test/js/node/worker_threads/worker_threads.test.ts.

Problem

expect(tags).toEqual([TAG.ready]) receives [12, 0]. No tag is 0. CI: 54 of 875 sampled builds since 2026-09-02, all on the x64-asan lane.
The fixture's put() bumps the count of a shared log with Atomics.add, then writes the tag with Atomics.store. worker.terminate() can stop the worker between the two. The parent then reads a slot that nothing wrote.

Fix

put() stores the tag first and publishes the count last. A put() that the stop cuts short records nothing.
Correct: the worker thread is the only writer, and the parent reads only the slots under the count. A handler that runs to its end is still recorded.
Verified: under bun bd test (debug+ASAN) the describe block fails 7 of 260 runs before, 0 of 200 after. Release+ASAN: 2 of 600 before, 0 of 600 after. The whole file passes.

Background

JSC stops a VM from another thread with a trap flag. The VM throws the uncatchable TerminationException at its next check. RETURN_IF_EXCEPTION in a host function is such a check, so the stop can land between two Atomics calls.
A probe records the put() in flight. In 35 of 35 runs with a 0 entry it is an interval tick. The 0 stays after the thread is joined.
Considered: stop logging interval ticks, as test(worker_threads): run worker_threads.test.ts concurrently and tighten its subprocess assertions #39067 does. That removes the trigger, and the logger can still tear. The two PRs do not conflict.

Notes

The failure as CI prints it

error: expect(received).toEqual(expected)

  [
    12,
+   0,
  ]

✗ worker stop ordering as seen by the worker's own handlers > terminate(): nothing of the worker's runs after the request

CI rate

Source: the Buildkite annotations of 1016 builds, sampled in windows between build 100000 and build 132961.

Builds of	Hits	Builds
2026-08-17 to 2026-09-01	0	141
2026-09-02 to 2026-09-07	11	286
2026-09-13 to 2026-09-26	7	135
2026-10-08 to 2026-10-09	4	54
2026-10-17 to 2026-10-24	11	215
2026-10-25 to 2026-10-26	21	185

Each of the 54 hits is [12, 0] on debian 13 x64-asan. 47 pass on the first retry and 7 on the second.
The first hit in the sample is build 109323 (2026-09-02).
Builds 132804 to 132961 have 16 hits in 137 builds: 132830, 132836, 132839, 132847, 132858, 132866, 132896, 132914, 132927, 132929, 132934, 132938, 132950, 132958, 132959, 132960.
An earlier version of this description called the flake rare (one CI hit, 0 of 300 local runs). That was the state on 2026-08-13.

What did not change, and what is not known

The describe block is byte-identical at the old base of this PR (b7a0431, 2026-08-12) and at main (449877f). tls: consolidate the open TLS fixes (both engines, node:tls, node:https, WebSocket, SQL) #44618, worker_threads: array methods see indexed keys of a SHARE_ENV process.env prototype #45283 and Hardening: fix crashes across the runtime, bundler, dev server, shell and CLI #46021 change other parts of the file.
The sampled rate is 25 of 580 from 2026-09-02 to 2026-10-19, and 29 of 295 from 2026-10-20 on. I did not bisect the rise in early September or the rise in late October. No commit is named here because no measurement names one.
Local rates are lower than the rate of the CI lane. I did not reproduce the rate of the lane.

Why the stop lands in a put() so often

The parent calls terminate() when it gets "ready". The first interval tick of the worker runs at almost the same moment.
Release+ASAN, 300 runs with a clock stamp in the worker: no tick runs before "ready". In 27 runs the stop lands before the first tick starts. In the other 273 the first tick starts 430 µs after "ready" (median, p10 253 µs, p90 534 µs).
Release+ASAN, 6000 probe runs: the stop lands before that first tick ends in 13.9% of the runs. It lands before the second tick ends in 90.5%. 24 of the 25 cut ticks are that first tick.
The rate thus depends on how two short code paths on two threads line up. A small change of either path moves it.

The mechanism in the code

RETURN_IF_EXCEPTION handles pending traps: Source/JavaScriptCore/runtime/ExceptionScope.h:131 at the pinned WebKit commit 680ef47cec (vm.traps().maybeNeedHandling(), then vm.hasExceptionsAfterHandlingTraps()).
Atomics.store passes at least four of these checks before its write: runtime/AtomicsObject.cpp:360, :363, :341, :343. The write is at :349. Atomics.add returns directly after its atomic step (:119).
Only a tick that already runs can be cut. VmHandle::request_termination (src/jsc/VmHandle.rs:391) sets the handle to Stopping before it fires the trap. TimerObjectInternals::fire (src/runtime/timer/timer_object_internals.rs:493) does not call the callback when script_execution_status() is not Running.
The worker reports its exit last: shutdown() (src/jsc/web_worker.rs:1013) calls WebWorker__workerGlobalScopeDestroyed after it destroys the VM.

Probe results

The probe runs the fixture's worker source and the fixture's parent steps. It adds a slot that holds the tag of the put() in flight. It also reads the log a second time, 100 ms after terminate() resolves. Both builds are main at 449877f. Six probe processes run at a time, three for each logger.

Build	Logger	Runs	Fixture fails	0 entry	Tag in flight	0 stays after join	Cut before the count store
debug+ASAN	count first (main)	750	10	10	7, all 10	10
debug+ASAN	publish last (this PR)	750	0	0			0
release+ASAN	count first (main)	3000	25	25	7, all 25	25
release+ASAN	publish last (this PR)	3000	0	0			9, all tag 7

Tag 7 is TAG.intervalTick. No run has a tag of a handler that the stop starts (exit, close, error, cancel).
"Log changes after 'exit'" is 0 in all 7500 runs: no script of the worker runs after the parent sees 'exit'.
"Cut before the count store": with the new logger, 9 runs have a tag in the slot after the count. The stop cut those put() calls, and the log shows nothing of them.

Loops of the test command

Each run is one bun process. Runs of the old fixture and of the new fixture alternate.

Build	Command	Old fixture fails	New fixture fails
debug+ASAN	`-t "worker stop ordering"`, one at a time	1 of 60
debug+ASAN	`-t "worker stop ordering"`, four at a time	6 of 200	0 of 200
release+ASAN	`-t "worker stop ordering"`, four at a time	2 of 600	0 of 600
release+ASAN	whole file, four at a time	0 of 48	0 of 48

Each of the 9 failures is [12, 0] in the terminate test.
debug+ASAN is bun bd. release+ASAN is bun run build:asan. The CI lane builds --profile=ci-build --asan=on.
bun bd test test/js/node/worker_threads/worker_threads.test.ts on this branch: 161 pass, 0 fail.

Earlier probe (2026-08-13)

That probe put N Atomics.load(log, 0); statements between the two steps of put(). It terminated 500 workers for each logger on a release build.

N = 3000: the old logger leaves a 0 entry in 2 of 500 runs. The new logger leaves none, and the stop cuts 5 put() calls before the count store.
N = 10000: 4 of 500 for the old logger, 0 of 500 for the new logger.
N = 0: 0 of 300.

Probe source

// Probe for the "worker stop ordering" fixture of test/js/node/worker_threads/worker_threads.test.ts.
//
// usage: bun stop-ordering-probe.ts <count-first|publish-last> <iterations>
//
// The worker source is the fixture's `workerSource("terminate")` and the parent does what the
// fixture's `run("terminate")` does. Two things are added, both outside the logger's own steps:
//   - `trace[0]` holds the tag of the put() in flight: a plain typed-array write before the
//     logger's first step, cleared by a plain write after its last. A put() that never finished
//     names its tag there.
//   - the parent reads the log at 'exit' (where the fixture reads it), and again after
//     terminate() has resolved plus 100ms. A worker that still ran script after 'exit' would
//     show up as a log that changed.
import { once } from "node:events";
import { Worker } from "node:worker_threads";

const [loggerKind = "count-first", itersStr = "100"] = process.argv.slice(2);

const TAG = {
  exitHandler: 1,
  serverClose: 2,
  socketClose: 3,
  socketError: 4,
  udpClose: 5,
  watcherClose: 6,
  intervalTick: 7,
  streamCancel: 8,
  portClose: 9,
  beforeExit: 10,
  afterExitCall: 11,
  ready: 12,
} as const;

const loggers: Record<string, string> = {
  // main: bump the count, then store the tag.
  "count-first": `const i = Atomics.add(log, 0, 1) + 1; if (i < log.length) Atomics.store(log, i, tag);`,
  // the fix: store the tag, then publish the count.
  "publish-last": `const i = Atomics.load(log, 0) + 1; if (i < log.length) Atomics.store(log, i, tag); Atomics.store(log, 0, i);`,
};
if (!(loggerKind in loggers)) throw new Error("unknown logger " + loggerKind);

const workerSource = `
    const { workerData, parentPort } = require("node:worker_threads");
    const log = workerData.log;
    const trace = workerData.trace;
    const put = tag => { trace[0] = tag; ${loggers[loggerKind]} trace[0] = 0; };
    process.on("exit", () => put(${TAG.exitHandler}));
    process.on("beforeExit", () => put(${TAG.beforeExit}));
    const net = require("node:net"), dgram = require("node:dgram"), fs = require("node:fs"), os = require("node:os");
    const server = net.createServer(() => {}).listen(0, "127.0.0.1");
    server.on("close", () => put(${TAG.serverClose}));
    const udp = dgram.createSocket("udp4"); udp.bind(0, "127.0.0.1"); udp.on("close", () => put(${TAG.udpClose}));
    const watcher = fs.watch(os.tmpdir(), () => {}); watcher.on("close", () => put(${TAG.watcherClose}));
    setInterval(() => put(${TAG.intervalTick}), 1).unref();
    const { port1, port2 } = new MessageChannel(); port1.on("message", () => {}); port1.on("close", () => put(${TAG.portClose})); globalThis.keepPeer = port2;
    Bun.serve({ port: 0, development: false, fetch: () => new Response("x") });
    new ReadableStream({ pull() {}, cancel() { put(${TAG.streamCancel}); } }).getReader().read();
    server.on("listening", () => {
      const sock = net.connect(server.address().port, "127.0.0.1");
      sock.on("close", () => put(${TAG.socketClose}));
      sock.on("error", () => put(${TAG.socketError}));
      sock.on("connect", () => {
        put(${TAG.ready});
        parentPort.postMessage("ready");
        parentPort.on("message", () => {});
      });
    });
  `;

const iters = Number(itersStr);
const total = {
  logger: loggerKind,
  runs: 0,
  fixtureWouldFail: 0, // tags !== [ready], which is what the fixture asserts
  zeroEntry: 0, // a 0 among the tags: a count that points at a slot no one wrote
  zeroEntryInFlightTag: {} as Record<number, number>, // which put() left it
  zeroEntryStillThereAfterJoin: 0,
  logChangedAfterJoin: 0, // script ran after 'exit'
  unpublishedTailTag: {} as Record<number, number>, // publish-last: a put() cut before its count store
  otherShapes: [] as number[][],
  ticksAfterReady: {} as Record<number, number>,
  exitCodes: {} as Record<number, number>,
  workerErrors: 0,
};
const bump = (h: Record<number, number>, k: number) => (h[k] = (h[k] ?? 0) + 1);

for (let iter = 0; iter < iters; iter++) {
  const log = new Int32Array(new SharedArrayBuffer(4 * 256));
  const trace = new Int32Array(new SharedArrayBuffer(4 * 4));
  const w = new Worker(workerSource, { eval: true, workerData: { log, trace } });
  const errors: unknown[] = [];
  w.on("error", e => errors.push(e));
  const exited = once(w, "exit").then(([code]) => code as number);
  await once(w, "message"); // "ready": every resource is up
  const t = w.terminate();
  const code = await exited;
  const atExit = Array.from(log); // what the fixture reads, when it reads it
  const inFlight = trace[0];
  await t;
  await Bun.sleep(100);
  const afterJoin = Array.from(log);

  const n = Math.min(atExit[0], log.length - 1);
  const raw = atExit.slice(1, 1 + n);
  const tags = raw.filter(tag => tag !== TAG.intervalTick);
  const ok = tags.length === 1 && tags[0] === TAG.ready;
  const changed = atExit.some((v, k) => v !== afterJoin[k]);
  const tail = n + 1 < log.length ? atExit[n + 1] : 0;
  const readyAt = raw.indexOf(TAG.ready);
  const ticksAfterReady = readyAt < 0 ? -1 : raw.slice(readyAt + 1).filter(tag => tag === TAG.intervalTick).length;

  total.runs++;
  if (!ok) total.fixtureWouldFail++;
  if (tags.includes(0)) {
    total.zeroEntry++;
    bump(total.zeroEntryInFlightTag, inFlight);
    if (!changed) total.zeroEntryStillThereAfterJoin++;
  } else if (!ok) total.otherShapes.push(tags);
  if (changed) total.logChangedAfterJoin++;
  if (tail !== 0) bump(total.unpublishedTailTag, tail);
  bump(total.ticksAfterReady, ticksAfterReady);
  bump(total.exitCodes, code);
  if (errors.length) total.workerErrors++;

  // One line per notable run, written as it happens, so a run that is cut short keeps its data.
  if (!ok || changed || tail !== 0 || errors.length)
    console.log("RUN", JSON.stringify({ iter, code, tags, inFlight, tail, changed, ticksAfterReady, n, errors: errors.map(String) }));
  if ((iter + 1) % 50 === 0) console.log("PROGRESS", JSON.stringify(total));
}
console.log("TOTAL", JSON.stringify({ ...total, rssMB: Math.round(process.memoryUsage().rss / 1048576) }));

…-safe The fixture's put() bumped the shared count with Atomics.add and then stored the tag. worker.terminate() can throw the TerminationException inside the host call between those two steps (JSC handles VM traps in RETURN_IF_EXCEPTION), leaving a count that points at an unwritten slot, which the terminate() test then read as [ready, 0]. Store the tag first and publish the count last, so a put() that is cut off records nothing. The worker is the log's only writer, so a plain load/store pair is enough.

robobun · 2026-08-13T17:41:28Z

Status: test-only fix, ready for review. The branch now includes main (449877f).

Reproduced how: a loop of bun bd test test/js/node/worker_threads/worker_threads.test.ts -t "worker stop ordering" on main, one bun process for each run.

Debug+ASAN: 7 of 260 runs fail with [12, 0]. With this branch, 0 of 200 fail.
Release+ASAN: 2 of 600 runs fail. With this branch, 0 of 600 fail.
A probe records the put() in flight. In 35 of 35 runs with a 0 entry, it is an interval tick.

The PR description has the CI rate, the probe and its results.

coderabbitai · 2026-08-13T17:43:52Z

No actionable comments were generated in the recent review.

Recent review info

Run configuration

Source mode: Auto
Repository: oven-sh/bun
Branch: farm/1ff45ebd/worker-stop-ordering-fixture-logger
File: .coderabbit.yaml
Commit: 021f6b2
Layers: Repository YAML
Review profile: ASSERTIVE
Plan: Advanced
Run ID: 8bbb66d8-9659-48c6-bae7-44cb3ca10149

Commits

Reviewing files that changed from the base of the PR and between 4ae0cca and 021f6b2.

Files selected for processing: 1

test/js/node/worker_threads/worker_threads.test.ts

Included review availability: This review used your included allowance. Your plan provides up to 10 included reviews per hour; 4 remain after this review.

Walkthrough

The worker event-log helper now stores each event tag before publishing the updated shared count. The prior atomic increment-before-write sequence is removed.

Changes

Worker event-log consistency

Layer / File(s)	Summary
Write event tags before publishing counts `test/js/node/worker_threads/worker_threads.test.ts`	The `put` helper stores the event tag before updating the shared count.

Possibly related PRs

oven-sh/bun#40132: Changes worker shutdown behavior during exit-listener execution, which is also relevant to worker termination and event logging.

Suggested reviewers: dylan-conway

Priority: Low

Merge Risk: Minimal · up to 021f6

The change improves test reliability without altering production behavior.

Pre-merge checks: 4

Check name	Status	Explanation
Title check		The title clearly and concisely describes the main test-only change: making the worker_threads stop-ordering fixture termination-safe.
Description check		The description explains the problem, fix, impact, and verification results in detail. It does not use the exact template headings, but it provides the required information for both sections.
Linked Issues check		Check skipped because no linked issues were found for this pull request.
Out of Scope Changes check		Check skipped because no linked issues were found for this pull request.

Autofix · Keep fixing CodeRabbit findings and required CI, and resolving merge conflicts

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

_{Comment @coderabbitai help to get the list of available commands.}

claude

LGTM — targeted test-fixture fix for a documented CI flake.

Reviewed: the reordered put() (write tag, then publish count) is safe because the worker is the log's sole writer and the parent reads only after 'exit'; Atomics.store is seq-cst so the tag is visible before the count. Confirmed the count store stays unconditional (overflow clamp at line 2568 still works) and the second test (process.exit path, no async termination trap) is unaffected. The invariant the test protects — a handler that completes after the stop request is recorded — is preserved; only a put() already in flight when termination landed changes from a spurious 0 to nothing.

Extended reasoning...

Overview

One-line change (plus a four-line explanatory comment) inside the inline worker source string in test/js/node/worker_threads/worker_threads.test.ts, describe block "worker stop ordering as seen by the worker's own handlers". The old put bumped the shared count with Atomics.add and then stored the tag; the new put reads the count, stores the tag into its slot, and stores the incremented count last. The parent's read logic (Math.min(Atomics.load(log, 0), log.length - 1) slots, interval ticks filtered) and both tests' assertions are untouched.

Security risks

None. Test-only; no production code, no user-facing behavior, no external inputs.

Level of scrutiny

Low-to-medium. It is a de-flake, so per REVIEW.md the key question is whether the change silently weakens the assertion. It does not: a handler that runs to completion after terminate() still writes its tag and publishes its count, so the expect(tags).toEqual([TAG.ready]) assertion still fails on it. Only a put() that termination interrupts mid-flight — i.e., one that started before the request was serviced, not after — now records nothing instead of a bogus 0. That is exactly the flake shape reported ([12, 0]) and is not something the test intended to catch.

Correctness details checked:

Single-writer: all put() callers (interval, event handlers, process 'exit' handler) run on the worker's thread, so replacing Atomics.add with load/store cannot lose an increment.
Ordering: JS Atomics.store is sequentially consistent, so the tag store happens-before the count store; the parent's Atomics.load(log, 0) after the 'exit' event sees the count only after the tag is visible.
Overflow path: the count store is outside the if (i < log.length) guard, matching the old unconditional Atomics.add; the parent's Math.min clamp at line 2568 still bounds the slice.
The process.exit() test (second case in the describe) does not involve async termination traps between host calls, so its recorded sequence is unchanged.

Other factors

The PR description is unusually thorough: it names the mechanism (JSC VM traps serviced inside RETURN_IF_EXCEPTION, so TerminationException can be thrown between two consecutive host calls), rules out the alternative hypothesis (parent seeing 'exit' before the worker VM is gone) with source references, and includes a probe that widens the window and reproduces the 0-entry only with the old ordering. Verified to pass under bun bd test and 40/40 release loops. No prior reviews or comments on the PR.

robobun · 2026-08-15T16:39:36Z

Cross-reference: #39067 (making worker_threads.test.ts concurrent) touches the same describe. It hit the same [12, 0] torn write while looping the file and, because the interval's ticks would also fill the 255-entry log once the parent is busy with other tests, it stops the interval from logging at all. It deliberately leaves put() as it is, so this PR's publish-last logger applies unchanged whether it lands before or after #39067; the two are complementary, and the analysis here (a put() that a termination lands inside started before the stop was requested, so it is never a violation) is the right one.

robobun · 2026-09-12T13:25:10Z

Seen again on main at b993710. A full-file bun bd test test/js/node/worker_threads/worker_threads.test.ts run on a debug+ASAN build (linux x64, machine under load) failed "terminate(): nothing of the worker's runs after the request" with the same [12, 0]. The test passed 3 of 3 runs alone with -t.

The fixture on main still has the two-step put() (Atomics.add, then Atomics.store). This branch still merges into main without conflicts.

…ogger

robobun · 2026-10-26T07:44:04Z

^{Updated 1:38 AM PT - Oct 26th, 2026}

✅ @robobun, your commit 021f6b2869b7c866b24b11461165a4aca2892159 passed in Build #132979! 🎉

🧪 To try this PR locally:

bunx bun-pr 38194

That installs a local version of the PR into your bun-38194 executable, so you can run:

bun-38194 --bun

claude

Code review found no issues

No high-confidence issues detected in this change.

github-actions Bot added the claude label Aug 13, 2026

claude Bot reviewed Aug 13, 2026

View reviewed changes

robobun mentioned this pull request Aug 15, 2026

test(worker_threads): run worker_threads.test.ts concurrently and tighten its subprocess assertions #39067

Open

robobun mentioned this pull request Sep 19, 2026

Close a MessagePort transferred to a worker that never starts #43374

Open

This was referenced Oct 18, 2026

worker: take a listener's termination at the native boundary, end the tick pass on a stopped VM #45298

Open

test: keep the worker alive until terminate() in the work-in-flight tests of worker_threads.test.ts #46647

Open

Merge branch 'main' into farm/1ff45ebd/worker-stop-ordering-fixture-l…

021f6b2

…ogger

claude Bot reviewed Oct 26, 2026

View reviewed changes

This was referenced Oct 27, 2026

worker_threads: start a node worker natively and build its stdio on first use #47052

Open

worker_threads: ack a stdio batch whose 'data' listener throws #47413

Open

Navigation Menu

Repository navigation

worker_threads test: make the stop-ordering fixture's log termination-safe - #38194

worker_threads test: make the stop-ordering fixture's log termination-safe#38194
robobun wants to merge 2 commits into
mainfrom
farm/1ff45ebd/worker-stop-ordering-fixture-logger

robobun commented Aug 13, 2026 •

edited

Loading

Uh oh!

robobun commented Aug 13, 2026 •

edited

Loading

Uh oh!

coderabbitai Bot commented Aug 13, 2026 •

edited

Loading

Uh oh!

claude Bot left a comment

Uh oh!

robobun commented Aug 15, 2026

Uh oh!

robobun commented Sep 12, 2026

Uh oh!

robobun commented Oct 26, 2026 •

edited

Loading

Uh oh!

claude Bot left a comment

Uh oh!

This branch has not been deployed

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

Conversation

robobun commented Aug 13, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Problem

Fix

Background

Uh oh!

robobun commented Aug 13, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

coderabbitai Bot commented Aug 13, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Walkthrough

Changes

Uh oh!

claude Bot left a comment

Choose a reason for hiding this comment

Overview

Security risks

Level of scrutiny

Other factors

Uh oh!

robobun commented Aug 15, 2026

Uh oh!

robobun commented Sep 12, 2026

Uh oh!

robobun commented Oct 26, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

claude Bot left a comment

Choose a reason for hiding this comment

Uh oh!

This branch has not been deployed

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

robobun commented Aug 13, 2026 •

edited

Loading

robobun commented Aug 13, 2026 •

edited

Loading

coderabbitai Bot commented Aug 13, 2026 •

edited

Loading

robobun commented Oct 26, 2026 •

edited

Loading