lib: add diagnostics_channel events to module loading

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

Co-Authored-By: Stephen Belanger <admin@stephenbelanger.com>

doc/api/diagnostics_channel.md

@@ -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`

lib/diagnostics_channel.js

@@ -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])) {

lib/internal/modules/cjs/loader.js

@@ -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);
   }

lib/internal/modules/esm/loader.js

@@ -43,6 +43,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
  */
@@ -211,10 +214,17 @@ class ModuleLoader {
       return compileSourceTextModule(url, source, this);
     };
     const { ModuleJob } = require('internal/modules/esm/module_job');
-    const job = new ModuleJob(
-      this, url, undefined, evalInstance, false, false);
-    this.loadCache.set(url, undefined, job);
-    const { module } = await job.run(isEntryPoint);
+    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) {
-    const moduleJob = await this.getModuleJob(specifier, parentURL, importAttributes);
-    const { module } = await moduleJob.run(isEntryPoint);
-    return module.getNamespace();
+    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,
+    });
   }
 
   /**

test/fixtures/console/console.snapshot

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

test/fixtures/errors/force_colors.snapshot

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

test/fixtures/errors/promise_unhandled_warn_with_error.snapshot

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

test/fixtures/errors/unhandled_promise_trace_warnings.snapshot

@@ -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 *

test/message/assert_throws_stack.out

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

test/message/internal_assert.out

@@ -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'
 }

test/message/internal_assert_fail.out

@@ -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'
 }

test/message/util-inspect-error-cause.out

@@ -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 *
     }
   }
 }