Nodejs/node
1
0
Fork 0
mirror of https://github.com/nodejs/node.git synced 2024-11-21 10:59:27 +00:00
Code Issues Actions 25 Packages Projects Releases Wiki Activity

lib: add diagnostics_channel events to module loading

Browse Source 
This commit adds a tracing channel for module loading
through `import()` and `require()`.

Co-Authored-By: Stephen Belanger <admin@stephenbelanger.com>
PR-URL: https://github.com/nodejs/node/pull/44340
Reviewed-By: Geoffrey Booth <webadmin@geoffreybooth.com>
Reviewed-By: Santiago Gimeno <santiago.gimeno@gmail.com>
Reviewed-By: Rafael Gonzaga <rafael.nunu@hotmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Gerhard Stöbich <deb2001-github@yahoo.de>
This commit is contained in:
RafaelGSS 2024-06-19 11:12:59 -03:00
parent 2cb3504064
commit fbdfe9399c
25 changed files with 398 additions and 37 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

52
doc/api/diagnostics_channel.md
View File

@ -1117,6 +1117,58 @@ Emitted when server receives a request.
Emitted when server sends a response.
#### Modules
`module.require.start`
* `event` {Object} containing the following properties
* `id` - Argument passed to `require()`. Module name.
* `parentFilename` - Name of the module that attempted to require(id).
Emitted when `require()` is executed. See [`start` event][].
`module.require.end`
* `event` {Object} containing the following properties
* `id` - Argument passed to `require()`. Module name.
* `parentFilename` - Name of the module that attempted to require(id).
Emitted when a `require()` call returns. See [`end` event][].
`module.require.error`
* `event` {Object} containing the following properties
* `id` - Argument passed to `require()`. Module name.
* `parentFilename` - Name of the module that attempted to require(id).
* `error` {Error}
Emitted when a `require()` throws an error. See [`error` event][].
`module.import.asyncStart`
* `event` {Object} containing the following properties
* `id` - Argument passed to `import()`. Module name.
* `parentURL` - URL object of the module that attempted to import(id).
Emitted when `import()` is invoked. See [`asyncStart` event][].
`module.import.asyncEnd`
* `event` {Object} containing the following properties
* `id` - Argument passed to `import()`. Module name.
* `parentURL` - URL object of the module that attempted to import(id).
Emitted when `import()` has completed. See [`asyncEnd` event][].
`module.import.error`
* `event` {Object} containing the following properties
* `id` - Argument passed to `import()`. Module name.
* `parentURL` - URL object of the module that attempted to import(id).
* `error` {Error}
Emitted when a `import()` throws an error. See [`error` event][].
#### NET
`net.client.socket`

19
lib/diagnostics_channel.js
View File

@ -269,7 +269,8 @@ function tracingChannelFrom(nameOrChannels, name) {
class TracingChannel {
constructor(nameOrChannels) {
for (const eventName of traceEvents) {
for (let i = 0; i < traceEvents.length; ++i) {
const eventName = traceEvents[i];
ObjectDefineProperty(this, eventName, {
__proto__: null,
value: tracingChannelFrom(nameOrChannels, eventName),
@ -278,15 +279,16 @@ class TracingChannel {
}
get hasSubscribers() {
return this.start.hasSubscribers ||
this.end.hasSubscribers ||
this.asyncStart.hasSubscribers ||
this.asyncEnd.hasSubscribers ||
this.error.hasSubscribers;
return this.start?.hasSubscribers ||
this.end?.hasSubscribers ||
this.asyncStart?.hasSubscribers ||
this.asyncEnd?.hasSubscribers ||
this.error?.hasSubscribers;
}
subscribe(handlers) {
for (const name of traceEvents) {
for (let i = 0; i < traceEvents.length; ++i) {
const name = traceEvents[i];
if (!handlers[name]) continue;
this[name]?.subscribe(handlers[name]);
@ -296,7 +298,8 @@ class TracingChannel {
unsubscribe(handlers) {
let done = true;
for (const name of traceEvents) {
for (let i = 0; i < traceEvents.length; ++i) {
const name = traceEvents[i];
if (!handlers[name]) continue;
if (!this[name]?.unsubscribe(handlers[name])) {

9
lib/internal/modules/cjs/loader.js
View File

@ -189,6 +189,9 @@ let { startTimer, endTimer } = debugWithTimer('module_timer', (start, end) => {
endTimer = end;
});
const { tracingChannel } = require('diagnostics_channel');
const onRequire = getLazy(() => tracingChannel('module.require'));
const isWindows = process.platform === 'win32';
const relativeResolveCache = { __proto__: null };
@ -209,7 +212,11 @@ function wrapModuleLoad(request, parent, isMain) {
startTimer(logLabel, traceLabel);
try {
return Module._load(request, parent, isMain);
return onRequire().traceSync(Module._load, {
__proto__: null,
parentFilename: parent?.filename,
id: request,
}, Module, request, parent, isMain);
} finally {
endTimer(logLabel, traceLabel);
}

16
lib/internal/modules/esm/loader.js
View File

@ -42,6 +42,9 @@ const {
} = require('internal/modules/helpers');
let defaultResolve, defaultLoad, defaultLoadSync, importMetaInitializer;
const { tracingChannel } = require('diagnostics_channel');
const onImport = tracingChannel('module.import');
/**
* @typedef {import('url').URL} URL
*/
@ -210,10 +213,17 @@ class ModuleLoader {
return compileSourceTextModule(url, source, this);
};
const { ModuleJob } = require('internal/modules/esm/module_job');
const module = await onImport.tracePromise(async () => {
const job = new ModuleJob(
this, url, undefined, evalInstance, false, false);
this.loadCache.set(url, undefined, job);
const { module } = await job.run(isEntryPoint);
return module;
}, {
__proto__: null,
parentURL: '<eval>',
url,
});
return {
__proto__: null,
@ -470,9 +480,15 @@ class ModuleLoader {
* @returns {Promise<ModuleExports>}
*/
async import(specifier, parentURL, importAttributes, isEntryPoint = false) {
return onImport.tracePromise(async () => {
const moduleJob = await this.getModuleJob(specifier, parentURL, importAttributes);
const { module } = await moduleJob.run(isEntryPoint);
return module.getNamespace();
}, {
__proto__: null,
parentURL,
url: specifier,
});
}
/**

1
test/fixtures/console/console.snapshot vendored
View File

@ -7,3 +7,4 @@ Trace: foo
at *
at *
at *
at *

1
test/fixtures/errors/force_colors.snapshot vendored
View File

@ -11,5 +11,6 @@ Error: Should include grayed stack trace
 at *
 at *
 at *
 at *
Node.js *

1
test/fixtures/errors/promise_unhandled_warn_with_error.snapshot vendored
View File

@ -7,5 +7,6 @@
at *
at *
at *
at *
(Use `node --trace-warnings ...` to show where the warning was created)
(node:*) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https:*nodejs.org*api*cli.html#cli_unhandled_rejections_mode). (rejection id: 1)

2
test/fixtures/errors/unhandled_promise_trace_warnings.snapshot vendored
View File

@ -11,6 +11,7 @@
at *
at *
at *
at *
(node:*) Error: This was rejected
at *
at *
@ -20,6 +21,7 @@
at *
at *
at *
at *
(node:*) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 1)
at *
at *

1
test/message/assert_throws_stack.out
View File

@ -16,6 +16,7 @@ AssertionError [ERR_ASSERTION]: Expected values to be strictly deep-equal:
at *
at *
at *
at *
at * {
generatedMessage: true,
code: 'ERR_ASSERTION',

1
test/message/internal_assert.out
View File

@ -13,6 +13,7 @@ Please open an issue with this stack trace at https://github.com/nodejs/node/iss
at *
at *
at *
at *
at * {
code: 'ERR_INTERNAL_ASSERTION'
}

1
test/message/internal_assert_fail.out
View File

@ -14,6 +14,7 @@ Please open an issue with this stack trace at https://github.com/nodejs/node/iss
at *
at *
at *
at *
at * {
code: 'ERR_INTERNAL_ASSERTION'
}

30
test/message/util-inspect-error-cause.out
View File

@ -6,6 +6,7 @@ Error: Number error cause
at *
at *
at *
at *
at * {
[cause]: 42
}
@ -17,6 +18,7 @@ Error: Object cause
at *
at *
at *
at *
at * {
[cause]: {
message: 'Unique',
@ -33,6 +35,7 @@ Error: undefined cause
at *
at *
at *
at *
at * {
[cause]: undefined
}
@ -44,6 +47,7 @@ Error: cause that throws
at *
at *
at *
at *
at * {
[cause]: [Getter]
}
@ -53,7 +57,7 @@ RangeError: New Stack Frames
[cause]: FoobarError: Individual message
at *
*[90m at *[39m
*[90m ... 5 lines matching cause stack trace ...*[39m
*[90m ... 6 lines matching cause stack trace ...*[39m
*[90m at *[39m {
status: *[32m'Feeling good'*[39m,
extraProperties: *[32m'Yes!'*[39m,
@ -66,17 +70,18 @@ RangeError: New Stack Frames
*[90m at *[39m
*[90m at *[39m
*[90m at *[39m
*[90m at *[39m
}
}
Error: Stack causes
at *
*[90m at *[39m
*[90m ... 5 lines matching cause stack trace ...*[39m
*[90m ... 6 lines matching cause stack trace ...*[39m
*[90m at *[39m {
[cause]: FoobarError: Individual message
at *
*[90m at *[39m
*[90m ... 5 lines matching cause stack trace ...*[39m
*[90m ... 6 lines matching cause stack trace ...*[39m
*[90m at *[39m {
status: *[32m'Feeling good'*[39m,
extraProperties: *[32m'Yes!'*[39m,
@ -89,6 +94,7 @@ Error: Stack causes
*[90m at *[39m
*[90m at *[39m
*[90m at *[39m
*[90m at *[39m
}
}
RangeError: New Stack Frames
@ -97,12 +103,12 @@ RangeError: New Stack Frames
[cause]: Error: Stack causes
at *
*[90m at *[39m
*[90m ... 5 lines matching cause stack trace ...*[39m
*[90m ... 6 lines matching cause stack trace ...*[39m
*[90m at *[39m {
[cause]: FoobarError: Individual message
at *
*[90m at *[39m
*[90m ... 5 lines matching cause stack trace ...*[39m
*[90m ... 6 lines matching cause stack trace ...*[39m
*[90m at *[39m {
status: *[32m'Feeling good'*[39m,
extraProperties: *[32m'Yes!'*[39m,
@ -115,6 +121,7 @@ RangeError: New Stack Frames
*[90m at *[39m
*[90m at *[39m
*[90m at *[39m
*[90m at *[39m
}
}
}
@ -124,7 +131,7 @@ RangeError: New Stack Frames
[cause]: FoobarError: Individual message
at *
at *
... 5 lines matching cause stack trace ...
... 6 lines matching cause stack trace ...
at * {
status: 'Feeling good',
extraProperties: 'Yes!',
@ -137,17 +144,18 @@ RangeError: New Stack Frames
at *
at *
at *
at *
}
}
Error: Stack causes
at *
at *
... 5 lines matching cause stack trace ...
... 6 lines matching cause stack trace ...
at * {
[cause]: FoobarError: Individual message
at *
at *
... 5 lines matching cause stack trace ...
... 6 lines matching cause stack trace ...
at *
status: 'Feeling good',
extraProperties: 'Yes!',
@ -160,6 +168,7 @@ Error: Stack causes
at *
at *
at *
at *
}
}
RangeError: New Stack Frames
@ -168,12 +177,12 @@ RangeError: New Stack Frames
[cause]: Error: Stack causes
at *
at *
... 5 lines matching cause stack trace ...
... 6 lines matching cause stack trace ...
at * {
[cause]: FoobarError: Individual message
at *
at *
... 5 lines matching cause stack trace ...
... 6 lines matching cause stack trace ...
at * {
status: 'Feeling good',
extraProperties: 'Yes!',
@ -186,6 +195,7 @@ RangeError: New Stack Frames
at *
at *
at *
at *
}
}
}

5
test/message/util_inspect_error.out
View File

@ -9,6 +9,7 @@
at *
at *
at *
at *
nested:
{ err:
Error: foo
@ -21,6 +22,7 @@
at *
at *
at *
at *
{
err: Error: foo
bar
@ -32,6 +34,7 @@
at *
at *
at *
at *
nested: {
err: Error: foo
bar
@ -43,6 +46,7 @@
at *
at *
at *
at *
}
}
{ Error: foo
@ -55,4 +59,5 @@ bar
at *
at *
at *
at *
foo: 'bar' }

7
test/parallel/test-bootstrap-modules.js
View File

@ -98,6 +98,7 @@ expected.beforePreExec = new Set([
'NativeModule internal/modules/package_json_reader',
'Internal Binding module_wrap',
'NativeModule internal/modules/cjs/loader',
'NativeModule diagnostics_channel',
'Internal Binding wasm_web_api',
'NativeModule internal/events/abort_listener',
]);
@ -162,11 +163,11 @@ if (process.features.inspector) {
expected.beforePreExec.add('Internal Binding inspector');
expected.beforePreExec.add('NativeModule internal/util/inspector');
expected.atRunTime.add('NativeModule internal/inspector_async_hook');
}
// This is loaded if the test is run with NODE_V8_COVERAGE.
if (process.env.NODE_V8_COVERAGE) {
// This is loaded if the test is run with NODE_V8_COVERAGE.
if (process.env.NODE_V8_COVERAGE) {
expected.atRunTime.add('Internal Binding profiler');
}
}
const difference = (setA, setB) => {

69
test/parallel/test-diagnostics-channel-module-import-error.js Normal file
View File

@ -0,0 +1,69 @@
'use strict';
const common = require('../common');
const assert = require('assert');
const dc = require('diagnostics_channel');
const trace = dc.tracingChannel('module.import');
const events = [];
let lastEvent;
function track(name) {
return (event) => {
// Verify every event after the first is the same object
if (events.length) {
assert.strictEqual(event, lastEvent);
}
lastEvent = event;
events.push({ name, ...event });
};
}
trace.subscribe({
start: common.mustCall(track('start')),
end: common.mustCall(track('end')),
asyncStart: common.mustCall(track('asyncStart')),
asyncEnd: common.mustCall(track('asyncEnd')),
error: common.mustCall(track('error')),
});
import('does-not-exist').then(
common.mustNotCall(),
common.mustCall((error) => {
let expectedParentURL = module.filename.replaceAll('\\', '/');
expectedParentURL = common.isWindows ?
`file:///${expectedParentURL}` :
`file://${expectedParentURL}`;
// Verify order and contents of each event
assert.deepStrictEqual(events, [
{
name: 'start',
parentURL: expectedParentURL,
url: 'does-not-exist',
},
{
name: 'end',
parentURL: expectedParentURL,
url: 'does-not-exist',
},
{
name: 'error',
parentURL: expectedParentURL,
url: 'does-not-exist',
error,
},
{
name: 'asyncStart',
parentURL: expectedParentURL,
url: 'does-not-exist',
error,
},
{
name: 'asyncEnd',
parentURL: expectedParentURL,
url: 'does-not-exist',
error,
},
]);
})
);

63
test/parallel/test-diagnostics-channel-module-import.js Normal file
View File

@ -0,0 +1,63 @@
'use strict';
const common = require('../common');
const assert = require('assert');
const dc = require('diagnostics_channel');
const trace = dc.tracingChannel('module.import');
const events = [];
let lastEvent;
function track(name) {
return (event) => {
// Verify every event after the first is the same object
if (events.length) {
assert.strictEqual(event, lastEvent);
}
lastEvent = event;
events.push({ name, ...event });
};
}
trace.subscribe({
start: common.mustCall(track('start')),
end: common.mustCall(track('end')),
asyncStart: common.mustCall(track('asyncStart')),
asyncEnd: common.mustCall(track('asyncEnd')),
error: common.mustNotCall(track('error')),
});
import('http').then(
common.mustCall((result) => {
let expectedParentURL = module.filename.replaceAll('\\', '/');
expectedParentURL = common.isWindows ?
`file:///${expectedParentURL}` :
`file://${expectedParentURL}`;
// Verify order and contents of each event
assert.deepStrictEqual(events, [
{
name: 'start',
parentURL: expectedParentURL,
url: 'http',
},
{
name: 'end',
parentURL: expectedParentURL,
url: 'http',
},
{
name: 'asyncStart',
parentURL: expectedParentURL,
url: 'http',
result,
},
{
name: 'asyncEnd',
parentURL: expectedParentURL,
url: 'http',
result,
},
]);
}),
common.mustNotCall(),
);

56
test/parallel/test-diagnostics-channel-module-require-error.js Normal file
View File

@ -0,0 +1,56 @@
'use strict';
const common = require('../common');
const assert = require('assert');
const dc = require('diagnostics_channel');
const trace = dc.tracingChannel('module.require');
const events = [];
let lastEvent;
function track(name) {
return (event) => {
// Verify every event after the first is the same object
if (events.length) {
assert.strictEqual(event, lastEvent);
}
lastEvent = event;
events.push({ name, ...event });
};
}
trace.subscribe({
start: common.mustCall(track('start')),
end: common.mustCall(track('end')),
asyncStart: common.mustNotCall(track('asyncStart')),
asyncEnd: common.mustNotCall(track('asyncEnd')),
error: common.mustCall(track('error')),
});
let error;
try {
require('does-not-exist');
} catch (err) {
error = err;
}
// Verify order and contents of each event
assert.deepStrictEqual(events, [
{
name: 'start',
parentFilename: module.filename,
id: 'does-not-exist',
},
{
name: 'error',
parentFilename: module.filename,
id: 'does-not-exist',
error,
},
{
name: 'end',
parentFilename: module.filename,
id: 'does-not-exist',
error,
},
]);

45
test/parallel/test-diagnostics-channel-module-require.js Normal file
View File

@ -0,0 +1,45 @@
'use strict';
const common = require('../common');
const assert = require('assert');
const dc = require('diagnostics_channel');
const trace = dc.tracingChannel('module.require');
const events = [];
let lastEvent;
function track(name) {
return (event) => {
// Verify every event after the first is the same object
if (events.length) {
assert.strictEqual(event, lastEvent);
}
lastEvent = event;
events.push({ name, ...event });
};
}
trace.subscribe({
start: common.mustCall(track('start')),
end: common.mustCall(track('end')),
asyncStart: common.mustNotCall(track('asyncStart')),
asyncEnd: common.mustNotCall(track('asyncEnd')),
error: common.mustNotCall(track('error')),
});
const result = require('http');
// Verify order and contents of each event
assert.deepStrictEqual(events, [
{
name: 'start',
parentFilename: module.filename,
id: 'http',
},
{
name: 'end',
parentFilename: module.filename,
id: 'http',
result,
},
]);

2
test/parallel/test-domain-set-uncaught-exception-capture-after-load.js
View File

@ -2,6 +2,8 @@
const common = require('../common');
const assert = require('assert');
Error.stackTraceLimit = Infinity;
(function foobar() {
require('domain');
})();

11
test/parallel/test-module-prototype-mutation.js
View File

@ -1,12 +1,21 @@
'use strict';
const common = require('../common');
const fixtures = require('../common/fixtures');
const { Channel } = require('diagnostics_channel');
const assert = require('assert');
Object.defineProperty(Object.prototype, 'name', {
__proto__: null,
get: common.mustNotCall('get %Object.prototype%.name'),
set: common.mustNotCall('set %Object.prototype%.name'),
set: function(v) {
// A diagnostic_channel is created to track module loading
// when using `require` or `import`. This class contains a
// `name` property that would cause a false alert for this
// test case. See Channel.prototype.name.
if (!(this instanceof Channel)) {
common.mustNotCall('set %Object.prototype%.name')(v);
}
},
enumerable: false,
});
Object.defineProperty(Object.prototype, 'main', {

11
test/parallel/test-repl.js
View File

@ -577,11 +577,12 @@ const errorTests = [
/^Uncaught Error: Cannot find module 'internal\/repl'/,
/^Require stack:/,
/^- <repl>/,
/^ {4}at .*/,
/^ {4}at .*/,
/^ {4}at .*/,
/^ {4}at .*/,
/^ {4}at .*/,
/^ {4}at .*/, // at Module._resolveFilename
/^ {4}at .*/, // at Module._load
/^ {4}at .*/, // at TracingChannel.traceSync
/^ {4}at .*/, // at wrapModuleLoad
/^ {4}at .*/, // at Module.require
/^ {4}at .*/, // at require
" code: 'MODULE_NOT_FOUND',",
" requireStack: [ '<repl>' ]",
'}',

1
test/pseudo-tty/console_colors.js
View File

@ -4,6 +4,7 @@ const vm = require('vm');
// Make this test OS-independent by overriding stdio getColorDepth().
process.stdout.getColorDepth = () => 8;
process.stderr.getColorDepth = () => 8;
Error.stackTraceLimit = Infinity;
console.log({ foo: 'bar' });
console.log('%s q', 'string');

11
test/pseudo-tty/console_colors.out
View File

@ -13,6 +13,7 @@ foobar
[90m at *[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m
Error: Should not ever get here.
at Object.<anonymous> [90m(*node_modules*[4m*node_modules*[24m*bar.js:*:*[90m)[39m
@ -22,9 +23,17 @@ Error: Should not ever get here.
[90m at *[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m
at Object.<anonymous> [90m(*console_colors.js:*:*[90m)[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m
Error
at evalmachine.<anonymous>:*:*
@ -37,3 +46,5 @@ Error
[90m at *[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m

3
test/pseudo-tty/test-fatal-error.out
View File

@ -8,7 +8,8 @@ TypeError: foobar
[90m at *(node:internal*loader:*:*)[39m
[90m at *(node:internal*loader:*:*)[39m
[90m at *(node:internal*loader:*:*)[39m
[90m at *(node:internal*loader:*:*)[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m
[90m at *[39m {
bla: [33mtrue[39m

1
test/pseudo-tty/test-trace-sigint.out
View File

@ -8,3 +8,4 @@ KEYBOARD_INTERRUPT: Script execution was interrupted by `SIGINT`
at *
at *
at *
at *