Skip to content

Commit c85f73e

Browse files
committed
fix(core): prevent late console logs from failing the run (isolate: false)
With `isolate: false`, all test files share one worker but each file owns its own birpc channel. The host disposes a file's channel as soon as the file finishes, while the worker only closes it when the next file starts. A console reference captured by a file (e.g. a logger that flushes from a late `setTimeout`/microtask) could fire in or after that window and forward the log over a disposed/closed channel. Because `onConsoleLog` was a normal birpc call, the late log registered a pending request that `$close()` then rejected with `[birpc] rpc is closed`. Since the console interceptor does not await it, the rejection surfaced as an `unhandledRejection` that failed the run even though every assertion passed, and was misattributed to whichever file happened to be running. `onConsoleLog` is fire-and-forget telemetry whose result the worker never reads, so model it as a one-way birpc event (`eventNames`): it no longer registers a pending request, so there is nothing for `$close()` to reject. Forwarding is also made best-effort — a send that races channel teardown is swallowed rather than crashing the run, and a dropped late log stays subject to the host's `onConsoleLog` policy, matching `isolate: true` where such logs are lost as the worker is torn down. Covered by an e2e regression test (with console suppression) across both the forks and threads pools and both isolate modes, plus a unit test asserting `onConsoleLog` is registered as a one-way event. Originally surfaced while migrating Rsbuild's e2e runner to rstest (web-infra-dev/rsbuild#7776), then reduced to the minimal repro in #1367. Closes #1367
1 parent f03b1df commit c85f73e

7 files changed

Lines changed: 134 additions & 18 deletions

File tree

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,17 @@
1+
import { test } from '@rstest/core';
2+
3+
// A captured `console` reference, like a logger that grabs `console` once.
4+
const log = globalThis.console;
5+
6+
test('schedules console calls that outlive the test file', () => {
7+
// None of these are awaited, so they fire after this file's tests finish. With
8+
// `isolate: false` the host disposes this file's birpc channel as soon as the
9+
// file finishes, but the worker only closes it once the next file starts.
10+
// Spread the logs across that handoff window so some fire while the channel is
11+
// disposed-but-open (the one-way-event path) and the later one fires after the
12+
// worker has closed it (the closed-channel path). Neither may crash the run.
13+
for (let delay = 0; delay <= 60; delay += 5) {
14+
setTimeout(() => log.log('late log from a.test.ts'), delay);
15+
}
16+
setTimeout(() => log.log('late log from a.test.ts'), 250);
17+
});
Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
import { test } from '@rstest/core';
2+
3+
test('keeps the worker alive while a.test.ts logs late', async () => {
4+
// Stay running long enough for a.test.ts's late `setTimeout` to fire.
5+
await new Promise((resolve) => setTimeout(resolve, 1000));
6+
});
Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,12 @@
1+
import { defineConfig } from '@rstest/core';
2+
3+
export default defineConfig({
4+
// `isolate` is driven per case by the test via `--isolate`. Run files
5+
// sequentially on a single worker so that, under `isolate: false`, `a.test.ts`
6+
// and `b.test.ts` share one process and exercise the closed-channel path.
7+
pool: { maxWorkers: 1 },
8+
// Suppress all console output. A late log that outlives its file must not only
9+
// avoid crashing the run, it must also stay suppressed — forwarding it after
10+
// teardown (or writing it to the raw stream) would bypass this filter.
11+
onConsoleLog: () => false,
12+
});

e2e/log/late-console.test.ts

Lines changed: 45 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,45 @@
1+
import { dirname, join } from 'node:path';
2+
import { fileURLToPath } from 'node:url';
3+
import { describe, expect, it } from '@rstest/core';
4+
import { runRstestCli } from '../scripts';
5+
6+
const __filename = fileURLToPath(import.meta.url);
7+
const __dirname = dirname(__filename);
8+
9+
// Regression test for https://github.com/web-infra-dev/rstest/issues/1367.
10+
// `a.test.ts` captures a `console` reference and flushes it from `setTimeout`s
11+
// that outlive the file. With `isolate: false` every file shares one worker, so
12+
// the late logs fire after the host has disposed a's birpc channel (and, later,
13+
// after the worker has closed it). Forwarding such a log used to leave a pending
14+
// birpc request that `$close()` rejected as `[birpc] rpc is closed`, failing the
15+
// run and misattributing it to `b.test.ts`.
16+
//
17+
// `onConsoleLog` is now a one-way event and forwarding is best-effort, so a late
18+
// log can neither crash the run nor leak past the `onConsoleLog: () => false`
19+
// suppression filter. Assert this across both pools and both isolate modes: with
20+
// `isolate: true` each file gets a fresh worker so the bug cannot occur, which
21+
// guards against a regression that only fixes one mode.
22+
describe('late console log (issue #1367)', () => {
23+
for (const pool of ['forks', 'threads'] as const) {
24+
for (const isolate of [true, false] as const) {
25+
it(`should not fail the run when a console call outlives its test file (${pool} pool, isolate: ${isolate})`, async () => {
26+
const { cli, expectExecSuccess } = await runRstestCli({
27+
command: 'rstest',
28+
args: ['run', '--pool', pool, '--isolate', String(isolate)],
29+
options: {
30+
nodeOptions: {
31+
cwd: join(__dirname, 'fixtures/late-console'),
32+
},
33+
},
34+
});
35+
36+
await expectExecSuccess();
37+
38+
// The late log must not crash the run via a closed/disposed channel...
39+
expect(cli.log).not.toContain('rpc is closed');
40+
// ...and it must stay suppressed, not leak to the raw worker stream.
41+
expect(cli.log).not.toContain('late log from a.test.ts');
42+
});
43+
}
44+
}
45+
});

packages/core/src/runtime/worker/rpc.ts

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,14 @@ export function createRuntimeRpc(
4040
{},
4141
{
4242
...options,
43+
// `onConsoleLog` is fire-and-forget telemetry whose result the worker never
44+
// reads. Send it as a one-way event so it never registers a pending request
45+
// in birpc's promise map — otherwise a log emitted in the window after the
46+
// host has disposed this file's rpc (but before the worker closes it, which
47+
// only happens with `isolate: false`) would leave a promise that the later
48+
// `$close()` rejects as `[birpc] rpc is closed`, crashing the run.
49+
// See https://github.com/web-infra-dev/rstest/issues/1367.
50+
eventNames: ['onConsoleLog'],
4351
// Disable timeout for worker RPC calls, as some operations may take a long time and we don't want them to fail due to timeout.
4452
timeout: -1,
4553
},

packages/core/src/runtime/worker/runInPool.ts

Lines changed: 13 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -167,8 +167,19 @@ const preparePool = async (
167167
disableConsoleIntercept,
168168
silent,
169169
},
170-
emitInterceptedLog: async (log) => {
171-
await rpc.onConsoleLog(log);
170+
emitInterceptedLog: (log) => {
171+
// Forwarding console output to the host is best-effort, fire-and-forget
172+
// telemetry. With `isolate: false` a captured console (e.g. a logger that
173+
// flushes from a late `setTimeout`/microtask) can fire after this file's
174+
// birpc channel has been closed or disposed by the host. `onConsoleLog` is
175+
// a one-way event (see `createRuntimeRpc`), so it leaves no pending request
176+
// to reject; swallowing any send error drops such an orphan log rather than
177+
// surfacing it as an `unhandledRejection` that fails the run and is
178+
// misattributed to whichever file is currently running. A dropped late log
179+
// also stays subject to the host's `onConsoleLog` policy, matching
180+
// `isolate: true` where late logs are lost as the worker is torn down.
181+
// See https://github.com/web-infra-dev/rstest/issues/1367.
182+
void rpc.onConsoleLog(log).catch(() => {});
172183
},
173184
writeOriginalLog: createOriginalLogWriter(),
174185
});
Lines changed: 33 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -1,23 +1,40 @@
11
import { createRuntimeRpc } from '../../../src/runtime/worker/rpc';
22

3+
// Capture the birpc options that `createRuntimeRpc` constructs, by injecting a
4+
// stub `createBirpc` that records them.
5+
const captureBirpcOptions = (): Record<string, unknown> => {
6+
let options: Record<string, unknown> | undefined;
7+
8+
createRuntimeRpc(
9+
{
10+
serialize: (v) => v as Uint8Array,
11+
deserialize: (v) => v as unknown,
12+
post() {},
13+
on() {},
14+
},
15+
(_functions, birpcOptions) => {
16+
options = birpcOptions as unknown as Record<string, unknown>;
17+
return {} as any;
18+
},
19+
);
20+
21+
if (!options) {
22+
throw new Error('createRuntimeRpc did not construct birpc options');
23+
}
24+
25+
return options;
26+
};
27+
328
describe('createRuntimeRpc', () => {
429
it('should disable birpc timeout', () => {
5-
let options: Record<string, unknown> | undefined;
6-
7-
createRuntimeRpc(
8-
{
9-
serialize: (v) => v as Uint8Array,
10-
deserialize: (v) => v as unknown,
11-
post() {},
12-
on() {},
13-
},
14-
(_functions, birpcOptions) => {
15-
options = birpcOptions as unknown as Record<string, unknown>;
16-
return {} as any;
17-
},
18-
);
30+
expect(captureBirpcOptions().timeout).toBe(-1);
31+
});
1932

20-
expect(options).toBeDefined();
21-
expect(options?.timeout).toBe(-1);
33+
it('should send `onConsoleLog` as a one-way event', () => {
34+
// `onConsoleLog` must be a fire-and-forget event so a late log (emitted after
35+
// the host disposed this file's rpc) never leaves a pending request that
36+
// `$close()` rejects as `[birpc] rpc is closed`.
37+
// See https://github.com/web-infra-dev/rstest/issues/1367.
38+
expect(captureBirpcOptions().eventNames).toContain('onConsoleLog');
2239
});
2340
});

0 commit comments

Comments
 (0)