module: improve error message from asynchronicity in require(esm)

- Improve the error message that shows up when there is a race
  from doing require(esm) and import(esm) at the same time.
- Improve error message of ERR_REQUIRE_ASYNC_MODULE by showing
  parent and target file names, if available.

Drive-by: split the require(tla) tests since we are modifying
the tests already.

Author: joyeecheung

lib/internal/errors.js

@@ -1656,9 +1656,18 @@ E('ERR_QUIC_ENDPOINT_CLOSED', 'QUIC endpoint closed: %s (%d)', Error);
 E('ERR_QUIC_OPEN_STREAM_FAILED', 'Failed to open QUIC stream', Error);
 E('ERR_QUIC_TRANSPORT_ERROR', 'A QUIC transport error occurred. %d [%s]', Error);
 E('ERR_QUIC_VERSION_NEGOTIATION_ERROR', 'The QUIC session requires version negotiation', Error);
-E('ERR_REQUIRE_ASYNC_MODULE', 'require() cannot be used on an ESM ' +
+E('ERR_REQUIRE_ASYNC_MODULE', function(filename, parentFilename) {
+  let message = 'require() cannot be used on an ESM ' +
   'graph with top-level await. Use import() instead. To see where the' +
-  ' top-level await comes from, use --experimental-print-required-tla.', Error);
+  ' top-level await comes from, use --experimental-print-required-tla.';
+  if (parentFilename) {
+    message += `\n  From ${parentFilename} `;
+  }
+  if (filename) {
+    message += `\n  Requiring ${filename} `;
+  }
+  return message;
+}, Error);
 E('ERR_REQUIRE_CYCLE_MODULE', '%s', Error);
 E('ERR_REQUIRE_ESM',
   function(filename, hasEsmSyntax, parentPath = null, packageJsonPath = null) {

lib/internal/modules/esm/loader.js

@@ -338,20 +338,37 @@ class ModuleLoader {
     //    TODO(joyeecheung): ensure that imported synchronous graphs are evaluated
     //    synchronously so that any previously imported synchronous graph is already
     //    evaluated at this point.
+    // TODO(joyeecheung): add something similar to CJS loader's requireStack to help
+    // debugging the the problematic links in the graph for import.
     if (job !== undefined) {
       mod[kRequiredModuleSymbol] = job.module;
+      const parentFilename = urlToFilename(parent?.filename);
+      // TODO(node:55782): this race may stop to happen when the ESM resolution and loading become synchronous.
+      if (!job.module) {
+        let message = `Cannot require() ES Module ${filename} because it is not yet fully loaded. `;
+        message += 'This may be caused by a race condition if the module is simultaneously dynamically ';
+        message += 'import()-ed via Promise.all(). Try await-ing the import() sequentially in a loop instead.';
+        if (parentFilename) {
+          message += ` (from ${parentFilename})`;
+        }
+        assert(job.module, message);
+      }
       if (job.module.async) {
-        throw new ERR_REQUIRE_ASYNC_MODULE();
+        throw new ERR_REQUIRE_ASYNC_MODULE(filename, parentFilename);
       }
+      // job.module may be undefined if it's asynchronously loaded. Which means
+      // there is likely a cycle.
       if (job.module.getStatus() !== kEvaluated) {
-        const parentFilename = urlToFilename(parent?.filename);
         let message = `Cannot require() ES Module ${filename} in a cycle.`;
         if (parentFilename) {
           message += ` (from ${parentFilename})`;
         }
+        message += 'A cycle involving require(esm) is disallowed to maintain ';
+        message += 'invariants madated by the ECMAScript specification';
+        message += 'Try making at least part of the dependency in the graph lazily loaded.';
         throw new ERR_REQUIRE_CYCLE_MODULE(message);
       }
-      return { wrap: job.module, namespace: job.module.getNamespaceSync() };
+      return { wrap: job.module, namespace: job.module.getNamespaceSync(filename, parentFilename) };
     }
     // TODO(joyeecheung): refactor this so that we pre-parse in C++ and hit the
     // cache here, or use a carrier object to carry the compiled module script
@@ -363,7 +380,7 @@ class ModuleLoader {
     job = new ModuleJobSync(this, url, kEmptyObject, wrap, isMain, inspectBrk);
     this.loadCache.set(url, kImplicitTypeAttribute, job);
     mod[kRequiredModuleSymbol] = job.module;
-    return { wrap: job.module, namespace: job.runSync().namespace };
+    return { wrap: job.module, namespace: job.runSync(parent).namespace };
   }
 
   /**

lib/internal/modules/esm/module_job.js

@@ -36,6 +36,7 @@ const assert = require('internal/assert');
 const resolvedPromise = PromiseResolve();
 const {
   setHasStartedUserESMExecution,
+  urlToFilename,
 } = require('internal/modules/helpers');
 const { getOptionValue } = require('internal/options');
 const noop = FunctionPrototype;
@@ -380,7 +381,7 @@ class ModuleJobSync extends ModuleJobBase {
                 `Status = ${status}`);
   }
 
-  runSync() {
+  runSync(parent) {
     // TODO(joyeecheung): add the error decoration logic from the async instantiate.
     this.module.async = this.module.instantiateSync();
     // If --experimental-print-required-tla is true, proceeds to evaluation even
@@ -389,11 +390,13 @@ class ModuleJobSync extends ModuleJobBase {
     // TODO(joyeecheung): track the asynchroniticy using v8::Module::HasTopLevelAwait()
     // and we'll be able to throw right after compilation of the modules, using acron
     // to find and print the TLA.
+    const parentFilename = urlToFilename(parent?.filename);
+    const filename = urlToFilename(this.url);
     if (this.module.async && !getOptionValue('--experimental-print-required-tla')) {
-      throw new ERR_REQUIRE_ASYNC_MODULE();
+      throw new ERR_REQUIRE_ASYNC_MODULE(filename, parentFilename);
     }
     setHasStartedUserESMExecution();
-    const namespace = this.module.evaluateSync();
+    const namespace = this.module.evaluateSync(filename, parentFilename);
     return { __proto__: null, module: this.module, namespace };
   }
 }

src/module_wrap.cc

@@ -710,7 +710,7 @@ void ModuleWrap::EvaluateSync(const FunctionCallbackInfo<Value>& args) {
         FPrintF(stderr, "%s\n", reason);
       }
     }
-    THROW_ERR_REQUIRE_ASYNC_MODULE(env);
+    THROW_ERR_REQUIRE_ASYNC_MODULE(env, args[0], args[1]);
     return;
   }
 
@@ -740,7 +740,7 @@ void ModuleWrap::GetNamespaceSync(const FunctionCallbackInfo<Value>& args) {
   }
 
   if (module->IsGraphAsync()) {
-    return THROW_ERR_REQUIRE_ASYNC_MODULE(realm->env());
+    return THROW_ERR_REQUIRE_ASYNC_MODULE(realm->env(), args[0], args[1]);
   }
   Local<Value> result = module->GetModuleNamespace();
   args.GetReturnValue().Set(result);

src/node_errors.h

@@ -205,10 +205,6 @@ ERRORS_WITH_CODE(V)
     "creating Workers")                                                        \
   V(ERR_NON_CONTEXT_AWARE_DISABLED,                                            \
     "Loading non context-aware native addons has been disabled")               \
-  V(ERR_REQUIRE_ASYNC_MODULE,                                                  \
-    "require() cannot be used on an ESM graph with top-level await. Use "      \
-    "import() instead. To see where the top-level await comes from, use "      \
-    "--experimental-print-required-tla.")                                      \
   V(ERR_SCRIPT_EXECUTION_INTERRUPTED,                                          \
     "Script execution was interrupted by `SIGINT`")                            \
   V(ERR_TLS_PSK_SET_IDENTITY_HINT_FAILED, "Failed to set PSK identity hint")   \
@@ -238,6 +234,28 @@ inline void THROW_ERR_SCRIPT_EXECUTION_TIMEOUT(Environment* env,
   THROW_ERR_SCRIPT_EXECUTION_TIMEOUT(env, message.str().c_str());
 }
 
+inline void THROW_ERR_REQUIRE_ASYNC_MODULE(
+    Environment* env,
+    v8::Local<v8::Value> filename,
+    v8::Local<v8::Value> parent_filename) {
+  static constexpr const char* prefix =
+      "require() cannot be used on an ESM graph with top-level await. Use "
+      "import() instead. To see where the top-level await comes from, use "
+      "--experimental-print-required-tla.";
+  std::string message = prefix;
+  if (!parent_filename.IsEmpty() && parent_filename->IsString()) {
+    Utf8Value utf8(env->isolate(), parent_filename);
+    message += "\n  From ";
+    message += utf8.out();
+  }
+  if (!filename.IsEmpty() && filename->IsString()) {
+    Utf8Value utf8(env->isolate(), filename);
+    message += "\n  Requiring ";
+    message += +utf8.out();
+  }
+  THROW_ERR_REQUIRE_ASYNC_MODULE(env, message.c_str());
+}
+
 inline v8::Local<v8::Object> ERR_BUFFER_TOO_LARGE(v8::Isolate* isolate) {
   char message[128];
   snprintf(message,

test/common/index.js

@@ -855,6 +855,17 @@ function expectRequiredModule(mod, expectation, checkESModule = true) {
   assert.deepStrictEqual(clone, { ...expectation });
 }
 
+function expectRequiredTLAError(err) {
+  const message = /require\(\) cannot be used on an ESM graph with top-level await/;
+  if (typeof err === 'string') {
+    assert.match(err, /ERR_REQUIRE_ASYNC_MODULE/);
+    assert.match(err, message);
+  } else {
+    assert.strictEqual(err.code, 'ERR_REQUIRE_ASYNC_MODULE');
+    assert.match(err.message, message);
+  }
+}
+
 const common = {
   allowGlobals,
   buildType,
@@ -864,6 +875,7 @@ const common = {
   escapePOSIXShell,
   expectsError,
   expectRequiredModule,
+  expectRequiredTLAError,
   expectWarning,
   getArrayBufferViews,
   getBufferSources,

test/es-module/test-require-module-tla-execution.js

@@ -0,0 +1,26 @@
+'use strict';
+
+// Tests that require(esm) with top-level-await throws before execution starts
+// if --experimental-print-required-tla is not enabled.
+
+const common = require('../common');
+const assert = require('assert');
+const { spawnSyncAndExit } = require('../common/child_process');
+const fixtures = require('../common/fixtures');
+
+{
+  spawnSyncAndExit(process.execPath, [
+    fixtures.path('es-modules/tla/require-execution.js'),
+  ], {
+    signal: null,
+    status: 1,
+    stderr(output) {
+      assert.doesNotMatch(output, /I am executed/);
+      common.expectRequiredTLAError(output);
+      assert.match(output, /From .*require-execution\.js/);
+      assert.match(output, /Requiring .*execution\.mjs/);
+      return true;
+    },
+    stdout: ''
+  });
+}

test/es-module/test-require-module-tla-nested.js

@@ -0,0 +1,15 @@
+'use strict';
+
+// Tests that require(esm) throws for top-level-await in inner graphs.
+
+const common = require('../common');
+const assert = require('assert');
+
+assert.throws(() => {
+  require('../fixtures/es-modules/tla/parent.mjs');
+}, (err) => {
+  common.expectRequiredTLAError(err);
+  assert.match(err.message, /From .*test-require-module-tla-nested\.js/);
+  assert.match(err.message, /Requiring .*parent\.mjs/);
+  return true;
+});

test/es-module/test-require-module-tla-print-execution.js

@@ -0,0 +1,29 @@
+'use strict';
+
+// Tests that require(esm) with top-level-await throws after execution
+// if --experimental-print-required-tla is enabled.
+
+const common = require('../common');
+const assert = require('assert');
+const { spawnSyncAndExit } = require('../common/child_process');
+const fixtures = require('../common/fixtures');
+
+{
+  spawnSyncAndExit(process.execPath, [
+    '--experimental-print-required-tla',
+    fixtures.path('es-modules/tla/require-execution.js'),
+  ], {
+    signal: null,
+    status: 1,
+    stderr(output) {
+      assert.match(output, /I am executed/);
+      common.expectRequiredTLAError(output);
+      assert.match(output, /Error: unexpected top-level await at.*execution\.mjs:3/);
+      assert.match(output, /await Promise\.resolve\('hi'\)/);
+      assert.match(output, /From .*require-execution\.js/);
+      assert.match(output, /Requiring .*execution\.mjs/);
+      return true;
+    },
+    stdout: ''
+  });
+}

test/es-module/test-require-module-tla-rejected.js

@@ -0,0 +1,15 @@
+'use strict';
+
+// Tests that require(esm) throws for rejected top-level await.
+
+const common = require('../common');
+const assert = require('assert');
+
+assert.throws(() => {
+  require('../fixtures/es-modules/tla/rejected.mjs');
+}, (err) => {
+  common.expectRequiredTLAError(err);
+  assert.match(err.message, /From .*test-require-module-tla-rejected\.js/);
+  assert.match(err.message, /Requiring .*rejected\.mjs/);
+  return true;
+});