Skip to content

Commit 5c27704

Browse files
MoLowaduh95
authored andcommitted
test_runner: publish to TracingChannel for OTel instrumentation
Signed-off-by: Moshe Atlow <moshe@atlow.co.il> PR-URL: #62502 Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com> Reviewed-By: Chemi Atlow <chemi@atlow.co.il>
1 parent d14029b commit 5c27704

5 files changed

Lines changed: 309 additions & 2 deletions

File tree

doc/api/test.md

Lines changed: 87 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3655,6 +3655,91 @@ Emitted when no more tests are queued for execution in watch mode.
36553655

36563656
Emitted when one or more tests are restarted due to a file change in watch mode.
36573657

3658+
## Test instrumentation and OpenTelemetry
3659+
3660+
<!-- YAML
3661+
added: REPLACEME
3662+
-->
3663+
3664+
The test runner publishes test execution events through the Node.js
3665+
[`diagnostics_channel`][] module, enabling integration with observability tools
3666+
like OpenTelemetry without requiring changes to the test runner itself.
3667+
3668+
### Tracing events
3669+
3670+
The test runner publishes events to the `'node.test'` tracing channel. Subscribers
3671+
can use the [`TracingChannel`][] API to bind context or perform custom
3672+
instrumentation.
3673+
3674+
#### Channel: `'tracing:node.test:start'`
3675+
3676+
* `data` {Object}
3677+
* `name` {string} The name of the test.
3678+
* `nesting` {number} The nesting level of the test.
3679+
* `file` {string|undefined} The path to the test file, or `undefined` when
3680+
running in the REPL.
3681+
* `type` {string} The type of test. Either `'test'` or `'suite'`.
3682+
3683+
Emitted when a test or suite starts execution. The test's span encompasses all
3684+
of its before, beforeEach, and afterEach hooks, as well as the test body.
3685+
3686+
#### Channel: `'tracing:node.test:end'`
3687+
3688+
* `data` {Object}
3689+
* `name` {string} The name of the test.
3690+
* `nesting` {number} The nesting level of the test.
3691+
* `file` {string|undefined} The path to the test file, or `undefined` when
3692+
running in the REPL.
3693+
* `type` {string} The type of test. Either `'test'` or `'suite'`.
3694+
3695+
Emitted when a test or suite finishes execution.
3696+
3697+
#### Channel: `'tracing:node.test:error'`
3698+
3699+
* `data` {Object}
3700+
* `name` {string} The name of the test.
3701+
* `nesting` {number} The nesting level of the test.
3702+
* `file` {string|undefined} The path to the test file, or `undefined` when
3703+
running in the REPL.
3704+
* `type` {string} The type of test. Either `'test'` or `'suite'`.
3705+
* `error` {Error} The error that was thrown.
3706+
3707+
Emitted when a test or suite throws an error.
3708+
3709+
### Context propagation with `bindStore()`
3710+
3711+
The tracing channel can be used to propagate context through test execution by
3712+
binding an `AsyncLocalStorage` instance. This allows context to be automatically
3713+
available in the test function and all async operations within the test.
3714+
3715+
```mjs
3716+
import dc from 'node:diagnostics_channel';
3717+
import { AsyncLocalStorage } from 'node:async_hooks';
3718+
3719+
const testStorage = new AsyncLocalStorage();
3720+
const testChannel = dc.tracingChannel('node.test');
3721+
3722+
// Bind context to test execution — the returned value becomes the store
3723+
testChannel.start.bindStore(testStorage, (data) => {
3724+
return { testName: data.name, startTime: Date.now() };
3725+
});
3726+
3727+
// Optionally handle errors and cleanup
3728+
testChannel.error.subscribe((data) => {
3729+
const store = testStorage.getStore();
3730+
console.log(`Test "${data.name}" failed after ${Date.now() - store.startTime}ms`);
3731+
});
3732+
3733+
testChannel.end.subscribe((data) => {
3734+
const store = testStorage.getStore();
3735+
console.log(`Test "${data.name}" completed in ${Date.now() - store.startTime}ms`);
3736+
});
3737+
```
3738+
3739+
When using `bindStore()`, the context provided will be automatically propagated
3740+
to the test function and all async operations within the test, without requiring
3741+
any additional instrumentation in the test code.
3742+
36583743
## Class: `TestContext`
36593744

36603745
<!-- YAML
@@ -4387,11 +4472,13 @@ test.describe('my suite', (suite) => {
43874472
[`NODE_V8_COVERAGE`]: cli.md#node_v8_coveragedir
43884473
[`SuiteContext`]: #class-suitecontext
43894474
[`TestContext`]: #class-testcontext
4475+
[`TracingChannel`]: diagnostics_channel.md#class-tracingchannel
43904476
[`assert.throws`]: assert.md#assertthrowsfn-error-message
43914477
[`context.diagnostic`]: #contextdiagnosticmessage
43924478
[`context.skip`]: #contextskipmessage
43934479
[`context.todo`]: #contexttodomessage
43944480
[`describe()`]: #describename-options-fn
4481+
[`diagnostics_channel`]: diagnostics_channel.md
43954482
[`glob(7)`]: https://man7.org/linux/man-pages/man7/glob.7.html
43964483
[`it()`]: #itname-options-fn
43974484
[`run()`]: #runoptions

lib/internal/test_runner/test.js

Lines changed: 65 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -55,6 +55,7 @@ const {
5555
countCompletedTest,
5656
isTestFailureError,
5757
reporterScope,
58+
testChannel,
5859
} = require('internal/test_runner/utils');
5960
const {
6061
kEmptyObject,
@@ -1217,6 +1218,17 @@ class Test extends AsyncResource {
12171218
}
12181219
this.startTime ??= hrtime();
12191220

1221+
// Channel context object shared across all lifecycle events for this test run.
1222+
// Only tests emit events; hooks do not. This way, the test's span encompasses
1223+
// its before/beforeEach hooks, the test body, and its afterEach/after hooks.
1224+
const channelContext = this.hookType === undefined ? {
1225+
__proto__: null,
1226+
name: this.name,
1227+
nesting: this.nesting,
1228+
file: this.entryFile,
1229+
type: this.reportedType,
1230+
} : null;
1231+
12201232
if (this[kShouldAbort]()) {
12211233
this.postRun();
12221234
return;
@@ -1254,7 +1266,20 @@ class Test extends AsyncResource {
12541266
}
12551267
stopPromise = stopTest(this.timeout, this.signal);
12561268
const runArgs = ArrayPrototypeSlice(args);
1257-
ArrayPrototypeUnshift(runArgs, this.fn, ctx);
1269+
1270+
// Wrap the test function with runStores if the channel has subscribers.
1271+
// The wrapped function is what gets passed to runInAsyncScope, ensuring that
1272+
// the test runs within both the runStores context (for AsyncLocalStorage/bindStore)
1273+
// AND the AsyncResource scope. It's critical that runStores wraps the function,
1274+
// not the runInAsyncScope call itself, to maintain AsyncLocalStorage bindings.
1275+
let testFn = this.fn;
1276+
if (channelContext !== null && testChannel.start.hasSubscribers) {
1277+
testFn = (...fnArgs) => testChannel.start.runStores(channelContext,
1278+
() => ReflectApply(this.fn, this, fnArgs),
1279+
);
1280+
}
1281+
1282+
ArrayPrototypeUnshift(runArgs, testFn, ctx);
12581283

12591284
const promises = [];
12601285
if (this.fn.length === runArgs.length - 1) {
@@ -1303,6 +1328,10 @@ class Test extends AsyncResource {
13031328
await afterEach();
13041329
await after();
13051330
} catch (err) {
1331+
// Publish diagnostics_channel error event if the channel has subscribers
1332+
if (channelContext !== null && testChannel.error.hasSubscribers) {
1333+
testChannel.error.publish({ __proto__: null, ...channelContext, error: err });
1334+
}
13061335
if (isTestFailureError(err)) {
13071336
if (err.failureType === kTestTimeoutFailure) {
13081337
this.#cancel(err);
@@ -1322,6 +1351,11 @@ class Test extends AsyncResource {
13221351
if (this.parent !== null) {
13231352
this.abortController.abort();
13241353
}
1354+
1355+
// Publish diagnostics_channel end event if the channel has subscribers (in both success and error cases)
1356+
if (channelContext !== null && testChannel.end.hasSubscribers) {
1357+
testChannel.end.publish(channelContext);
1358+
}
13251359
}
13261360

13271361
if (this.parent !== null || typeof this.hookType === 'string') {
@@ -1649,13 +1683,42 @@ class Suite extends Test {
16491683
}
16501684

16511685
async createBuild() {
1686+
const channelContext = {
1687+
__proto__: null,
1688+
name: this.name,
1689+
nesting: this.nesting,
1690+
file: this.entryFile,
1691+
type: this.reportedType,
1692+
};
16521693
try {
16531694
const { ctx, args } = this.getRunArgs();
1654-
const runArgs = [this.fn, ctx];
1695+
1696+
// Wrap the suite function with runStores if the channel has subscribers.
1697+
// The wrapped function is what gets passed to runInAsyncScope, ensuring that
1698+
// the suite runs within both the runStores context (for AsyncLocalStorage/bindStore)
1699+
// AND the AsyncResource scope. It's critical that runStores wraps the function,
1700+
// not the runInAsyncScope call itself, to maintain AsyncLocalStorage bindings.
1701+
let suiteFn = this.fn;
1702+
if (testChannel.start.hasSubscribers) {
1703+
const baseFn = this.fn;
1704+
suiteFn = (...fnArgs) => testChannel.start.runStores(channelContext,
1705+
() => ReflectApply(baseFn, this, fnArgs),
1706+
);
1707+
}
1708+
1709+
const runArgs = [suiteFn, ctx];
16551710
ArrayPrototypePushApply(runArgs, args);
1711+
16561712
await ReflectApply(this.runInAsyncScope, this, runArgs);
16571713
} catch (err) {
1714+
if (testChannel.error.hasSubscribers) {
1715+
testChannel.error.publish({ __proto__: null, ...channelContext, error: err });
1716+
}
16581717
this.fail(new ERR_TEST_FAILURE(err, kTestCodeFailure));
1718+
} finally {
1719+
if (testChannel.end.hasSubscribers) {
1720+
testChannel.end.publish(channelContext);
1721+
}
16591722
}
16601723

16611724
this.buildPhaseFinished = true;

lib/internal/test_runner/utils.js

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@ const {
3131
} = primordials;
3232

3333
const { AsyncResource } = require('async_hooks');
34+
const { tracingChannel } = require('diagnostics_channel');
3435
const { relative, sep, resolve } = require('path');
3536
const { createWriteStream, readFileSync } = require('fs');
3637
const { pathToFileURL } = require('internal/url');
@@ -256,6 +257,7 @@ async function getReportersMap(reporters, destinations) {
256257
}
257258

258259
const reporterScope = new AsyncResource('TestReporterScope');
260+
const testChannel = tracingChannel('node.test');
259261
let globalTestOptions;
260262

261263
function parseCommandLine() {
@@ -730,4 +732,5 @@ module.exports = {
730732
getCoverageReport,
731733
setupGlobalSetupTeardownFunctions,
732734
parsePreviousRuns,
735+
testChannel,
733736
};
Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,17 @@
1+
'use strict';
2+
const dc = require('node:diagnostics_channel');
3+
const { test } = require('node:test');
4+
5+
const events = [];
6+
dc.subscribe('tracing:node.test:error', (data) => {
7+
events.push(data.name);
8+
});
9+
10+
test('test that intentionally fails', async () => {
11+
throw new Error('expected failure for error event testing');
12+
});
13+
14+
// Report events on exit
15+
process.on('exit', () => {
16+
console.log(JSON.stringify({ errorEvents: events }));
17+
});
Lines changed: 137 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,137 @@
1+
'use strict';
2+
require('../common');
3+
const assert = require('node:assert');
4+
const { AsyncLocalStorage } = require('node:async_hooks');
5+
const dc = require('node:diagnostics_channel');
6+
const { describe, it, test } = require('node:test');
7+
const { spawnSync } = require('child_process');
8+
const { join } = require('path');
9+
10+
const events = [];
11+
12+
dc.subscribe('tracing:node.test:start', (data) => events.push({ event: 'start', name: data.name }));
13+
dc.subscribe('tracing:node.test:end', (data) => events.push({ event: 'end', name: data.name }));
14+
dc.subscribe('tracing:node.test:error', (data) => events.push({ event: 'error', name: data.name }));
15+
16+
test('passing test fires start and end', async () => {});
17+
18+
// Validate events were emitted (check after all tests via process.on('exit'))
19+
process.on('exit', () => {
20+
// Check passing test
21+
const testName1 = 'passing test fires start and end';
22+
const startEvents = events.filter((e) => e.event === 'start' && e.name === testName1);
23+
const endEvents = events.filter((e) => e.event === 'end' && e.name === testName1);
24+
assert.strictEqual(startEvents.length, 1);
25+
assert.strictEqual(endEvents.length, 1);
26+
27+
// Check nested tests fire events
28+
const nested1Start = events.filter((e) => e.event === 'start' && e.name === 'nested test 1');
29+
const nested1End = events.filter((e) => e.event === 'end' && e.name === 'nested test 1');
30+
const nested2Start = events.filter((e) => e.event === 'start' && e.name === 'nested test 2');
31+
const nested2End = events.filter((e) => e.event === 'end' && e.name === 'nested test 2');
32+
assert.strictEqual(nested1Start.length, 1);
33+
assert.strictEqual(nested1End.length, 1);
34+
assert.strictEqual(nested2Start.length, 1);
35+
assert.strictEqual(nested2End.length, 1);
36+
37+
// Check describe block tests fire events
38+
const describeStart = events.filter((e) => e.event === 'start' && e.name === 'test inside describe');
39+
const describeEnd = events.filter((e) => e.event === 'end' && e.name === 'test inside describe');
40+
const describeStart2 = events.filter(
41+
(e) => e.event === 'start' && e.name === 'another test inside describe',
42+
);
43+
const describeEnd2 = events.filter(
44+
(e) => e.event === 'end' && e.name === 'another test inside describe',
45+
);
46+
assert.strictEqual(describeStart.length, 1);
47+
assert.strictEqual(describeEnd.length, 1);
48+
assert.strictEqual(describeStart2.length, 1);
49+
assert.strictEqual(describeEnd2.length, 1);
50+
51+
// Check async operations test fires events
52+
const asyncTestName = 'context is available in async operations within test';
53+
const asyncStart = events.filter((e) => e.event === 'start' && e.name === asyncTestName);
54+
const asyncEnd = events.filter((e) => e.event === 'end' && e.name === asyncTestName);
55+
assert.strictEqual(asyncStart.length, 1);
56+
assert.strictEqual(asyncEnd.length, 1);
57+
});
58+
59+
// Test bindStore context propagation
60+
const testStorage = new AsyncLocalStorage();
61+
62+
// bindStore on the start channel: whenever a test fn runs, set testStorage to the test name
63+
dc.channel('tracing:node.test:start').bindStore(testStorage, (data) => data.name);
64+
65+
const expectedName = 'bindStore propagates into test body via start channel';
66+
test(expectedName, async () => {
67+
const storedValueDuringTest = testStorage.getStore();
68+
assert.strictEqual(storedValueDuringTest, expectedName);
69+
70+
// Propagates into async operations inside the test
71+
const valueInSetImmediate = await new Promise((resolve) => {
72+
setImmediate(() => resolve(testStorage.getStore()));
73+
});
74+
assert.strictEqual(valueInSetImmediate, expectedName);
75+
});
76+
77+
test('bindStore value is isolated between tests', async () => {
78+
assert.strictEqual(testStorage.getStore(), 'bindStore value is isolated between tests');
79+
});
80+
81+
test('nested tests fire events with correct names', async (t) => {
82+
await t.test('nested test 1', async () => {
83+
const stored = testStorage.getStore();
84+
assert.strictEqual(stored, 'nested test 1');
85+
});
86+
87+
await t.test('nested test 2', async () => {
88+
const stored = testStorage.getStore();
89+
assert.strictEqual(stored, 'nested test 2');
90+
});
91+
});
92+
93+
describe('describe block with tests', () => {
94+
it('test inside describe', async () => {
95+
const stored = testStorage.getStore();
96+
assert.strictEqual(stored, 'test inside describe');
97+
});
98+
99+
it('another test inside describe', async () => {
100+
const stored = testStorage.getStore();
101+
assert.strictEqual(stored, 'another test inside describe');
102+
});
103+
});
104+
105+
test('context is available in async operations within test', async () => {
106+
const testName = 'context is available in async operations within test';
107+
assert.strictEqual(testStorage.getStore(), testName);
108+
109+
// Verify context is available in setImmediate
110+
const valueInImmediate = await new Promise((resolve) => {
111+
setImmediate(() => resolve(testStorage.getStore()));
112+
});
113+
assert.strictEqual(valueInImmediate, testName);
114+
115+
// Verify context is available in setTimeout
116+
const valueInTimeout = await new Promise((resolve) => {
117+
setTimeout(() => resolve(testStorage.getStore()), 0);
118+
});
119+
assert.strictEqual(valueInTimeout, testName);
120+
});
121+
122+
test('error events fire for failing tests in fixture', async () => {
123+
// Run the fixture test that intentionally fails
124+
const fixturePath = join(__dirname, '../fixtures/test-runner/diagnostics-channel-error-test.js');
125+
const result = spawnSync(process.execPath, [fixturePath], { encoding: 'utf8' });
126+
127+
// The fixture test intentionally fails, so exit code should be non-zero
128+
assert.notStrictEqual(result.status, 0);
129+
130+
// Extract and verify error events from fixture output
131+
// The fixture outputs JSON with errorEvents array on exit
132+
const lines = result.stdout.split('\n');
133+
const eventLine = lines.find((line) => line.includes('errorEvents'));
134+
assert.ok(eventLine, 'Expected errorEvents line in fixture output');
135+
const { errorEvents } = JSON.parse(eventLine);
136+
assert.strictEqual(errorEvents.includes('test that intentionally fails'), true);
137+
});

0 commit comments

Comments
 (0)