Skip to content

Commit c7d05fc

Browse files
committed
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 91d83c3 commit c7d05fc

File tree

5 files changed

+309
-2
lines changed

5 files changed

+309
-2
lines changed

doc/api/test.md

Lines changed: 87 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3701,6 +3701,91 @@ When called from within a hook (before, beforeEach, after, afterEach), this
37013701
function returns the context of the test or suite that the hook is associated
37023702
with.
37033703

3704+
## Test instrumentation and OpenTelemetry
3705+
3706+
<!-- YAML
3707+
added: REPLACEME
3708+
-->
3709+
3710+
The test runner publishes test execution events through the Node.js
3711+
[`diagnostics_channel`][] module, enabling integration with observability tools
3712+
like OpenTelemetry without requiring changes to the test runner itself.
3713+
3714+
### Tracing events
3715+
3716+
The test runner publishes events to the `'node.test'` tracing channel. Subscribers
3717+
can use the [`TracingChannel`][] API to bind context or perform custom
3718+
instrumentation.
3719+
3720+
#### Channel: `'tracing:node.test:start'`
3721+
3722+
* `data` {Object}
3723+
* `name` {string} The name of the test.
3724+
* `nesting` {number} The nesting level of the test.
3725+
* `file` {string|undefined} The path to the test file, or `undefined` when
3726+
running in the REPL.
3727+
* `type` {string} The type of test. Either `'test'` or `'suite'`.
3728+
3729+
Emitted when a test or suite starts execution. The test's span encompasses all
3730+
of its before, beforeEach, and afterEach hooks, as well as the test body.
3731+
3732+
#### Channel: `'tracing:node.test:end'`
3733+
3734+
* `data` {Object}
3735+
* `name` {string} The name of the test.
3736+
* `nesting` {number} The nesting level of the test.
3737+
* `file` {string|undefined} The path to the test file, or `undefined` when
3738+
running in the REPL.
3739+
* `type` {string} The type of test. Either `'test'` or `'suite'`.
3740+
3741+
Emitted when a test or suite finishes execution.
3742+
3743+
#### Channel: `'tracing:node.test:error'`
3744+
3745+
* `data` {Object}
3746+
* `name` {string} The name of the test.
3747+
* `nesting` {number} The nesting level of the test.
3748+
* `file` {string|undefined} The path to the test file, or `undefined` when
3749+
running in the REPL.
3750+
* `type` {string} The type of test. Either `'test'` or `'suite'`.
3751+
* `error` {Error} The error that was thrown.
3752+
3753+
Emitted when a test or suite throws an error.
3754+
3755+
### Context propagation with `bindStore()`
3756+
3757+
The tracing channel can be used to propagate context through test execution by
3758+
binding an `AsyncLocalStorage` instance. This allows context to be automatically
3759+
available in the test function and all async operations within the test.
3760+
3761+
```mjs
3762+
import dc from 'node:diagnostics_channel';
3763+
import { AsyncLocalStorage } from 'node:async_hooks';
3764+
3765+
const testStorage = new AsyncLocalStorage();
3766+
const testChannel = dc.tracingChannel('node.test');
3767+
3768+
// Bind context to test execution — the returned value becomes the store
3769+
testChannel.start.bindStore(testStorage, (data) => {
3770+
return { testName: data.name, startTime: Date.now() };
3771+
});
3772+
3773+
// Optionally handle errors and cleanup
3774+
testChannel.error.subscribe((data) => {
3775+
const store = testStorage.getStore();
3776+
console.log(`Test "${data.name}" failed after ${Date.now() - store.startTime}ms`);
3777+
});
3778+
3779+
testChannel.end.subscribe((data) => {
3780+
const store = testStorage.getStore();
3781+
console.log(`Test "${data.name}" completed in ${Date.now() - store.startTime}ms`);
3782+
});
3783+
```
3784+
3785+
When using `bindStore()`, the context provided will be automatically propagated
3786+
to the test function and all async operations within the test, without requiring
3787+
any additional instrumentation in the test code.
3788+
37043789
## Class: `TestContext`
37053790

37063791
<!-- YAML
@@ -4433,11 +4518,13 @@ test.describe('my suite', (suite) => {
44334518
[`NODE_V8_COVERAGE`]: cli.md#node_v8_coveragedir
44344519
[`SuiteContext`]: #class-suitecontext
44354520
[`TestContext`]: #class-testcontext
4521+
[`TracingChannel`]: diagnostics_channel.md#class-tracingchannel
44364522
[`assert.throws`]: assert.md#assertthrowsfn-error-message
44374523
[`context.diagnostic`]: #contextdiagnosticmessage
44384524
[`context.skip`]: #contextskipmessage
44394525
[`context.todo`]: #contexttodomessage
44404526
[`describe()`]: #describename-options-fn
4527+
[`diagnostics_channel`]: diagnostics_channel.md
44414528
[`glob(7)`]: https://man7.org/linux/man-pages/man7/glob.7.html
44424529
[`it()`]: #itname-options-fn
44434530
[`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,
@@ -1211,6 +1212,17 @@ class Test extends AsyncResource {
12111212
}
12121213
this.startTime ??= hrtime();
12131214

1215+
// Channel context object shared across all lifecycle events for this test run.
1216+
// Only tests emit events; hooks do not. This way, the test's span encompasses
1217+
// its before/beforeEach hooks, the test body, and its afterEach/after hooks.
1218+
const channelContext = this.hookType === undefined ? {
1219+
__proto__: null,
1220+
name: this.name,
1221+
nesting: this.nesting,
1222+
file: this.entryFile,
1223+
type: this.reportedType,
1224+
} : null;
1225+
12141226
if (this[kShouldAbort]()) {
12151227
this.postRun();
12161228
return;
@@ -1248,7 +1260,20 @@ class Test extends AsyncResource {
12481260
}
12491261
stopPromise = stopTest(this.timeout, this.signal);
12501262
const runArgs = ArrayPrototypeSlice(args);
1251-
ArrayPrototypeUnshift(runArgs, this.fn, ctx);
1263+
1264+
// Wrap the test function with runStores if the channel has subscribers.
1265+
// The wrapped function is what gets passed to runInAsyncScope, ensuring that
1266+
// the test runs within both the runStores context (for AsyncLocalStorage/bindStore)
1267+
// AND the AsyncResource scope. It's critical that runStores wraps the function,
1268+
// not the runInAsyncScope call itself, to maintain AsyncLocalStorage bindings.
1269+
let testFn = this.fn;
1270+
if (channelContext !== null && testChannel.start.hasSubscribers) {
1271+
testFn = (...fnArgs) => testChannel.start.runStores(channelContext,
1272+
() => ReflectApply(this.fn, this, fnArgs),
1273+
);
1274+
}
1275+
1276+
ArrayPrototypeUnshift(runArgs, testFn, ctx);
12521277

12531278
const promises = [];
12541279
if (this.fn.length === runArgs.length - 1) {
@@ -1297,6 +1322,10 @@ class Test extends AsyncResource {
12971322
await afterEach();
12981323
await after();
12991324
} catch (err) {
1325+
// Publish diagnostics_channel error event if the channel has subscribers
1326+
if (channelContext !== null && testChannel.error.hasSubscribers) {
1327+
testChannel.error.publish({ __proto__: null, ...channelContext, error: err });
1328+
}
13001329
if (isTestFailureError(err)) {
13011330
if (err.failureType === kTestTimeoutFailure) {
13021331
this.#cancel(err);
@@ -1316,6 +1345,11 @@ class Test extends AsyncResource {
13161345
if (this.parent !== null) {
13171346
this.abortController.abort();
13181347
}
1348+
1349+
// Publish diagnostics_channel end event if the channel has subscribers (in both success and error cases)
1350+
if (channelContext !== null && testChannel.end.hasSubscribers) {
1351+
testChannel.end.publish(channelContext);
1352+
}
13191353
}
13201354

13211355
if (this.parent !== null || typeof this.hookType === 'string') {
@@ -1643,13 +1677,42 @@ class Suite extends Test {
16431677
}
16441678

16451679
async createBuild() {
1680+
const channelContext = {
1681+
__proto__: null,
1682+
name: this.name,
1683+
nesting: this.nesting,
1684+
file: this.entryFile,
1685+
type: this.reportedType,
1686+
};
16461687
try {
16471688
const { ctx, args } = this.getRunArgs();
1648-
const runArgs = [this.fn, ctx];
1689+
1690+
// Wrap the suite function with runStores if the channel has subscribers.
1691+
// The wrapped function is what gets passed to runInAsyncScope, ensuring that
1692+
// the suite runs within both the runStores context (for AsyncLocalStorage/bindStore)
1693+
// AND the AsyncResource scope. It's critical that runStores wraps the function,
1694+
// not the runInAsyncScope call itself, to maintain AsyncLocalStorage bindings.
1695+
let suiteFn = this.fn;
1696+
if (testChannel.start.hasSubscribers) {
1697+
const baseFn = this.fn;
1698+
suiteFn = (...fnArgs) => testChannel.start.runStores(channelContext,
1699+
() => ReflectApply(baseFn, this, fnArgs),
1700+
);
1701+
}
1702+
1703+
const runArgs = [suiteFn, ctx];
16491704
ArrayPrototypePushApply(runArgs, args);
1705+
16501706
await ReflectApply(this.runInAsyncScope, this, runArgs);
16511707
} catch (err) {
1708+
if (testChannel.error.hasSubscribers) {
1709+
testChannel.error.publish({ __proto__: null, ...channelContext, error: err });
1710+
}
16521711
this.fail(new ERR_TEST_FAILURE(err, kTestCodeFailure));
1712+
} finally {
1713+
if (testChannel.end.hasSubscribers) {
1714+
testChannel.end.publish(channelContext);
1715+
}
16531716
}
16541717

16551718
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)