VM ESM with dynamic imports resolves promises before linking is complete

[SimenB]

• Version: v14.1.0
• Platform: Darwin Simens-MacBook-Pro.local 18.7.0 Darwin Kernel Version 18.7.0: Mon Feb 10 21:08:45 PST 2020; root:xnu-4903.278.28~1/RELEASE_X86_64 x86_64
• Subsystem: VM, ESM

What steps will reproduce the bug?

See https://github.com/SimenB/node-vm-esm-promise-awaiting

Run node --experimental-vm-modules index.js to reproduce.

How often does it reproduce? Is there a required condition?

Almost every time. There seems to be some race condition in there. I've added a manual timeout in there - tweak its numbers to see different behavior. In the code the timeout is 1 second and then one of the tests fail almost every time. Increasing the timeoyt will often make both tests fail

What is the expected behavior?

All linking and execution should happen before the promises resolve.

What do you see instead?

The promises resolve, so the internal state of completed is set to true, which later throws.

Additional information

The reproduction is adapted from a bug report to Jest (jestjs/jest#9430 (comment)), so apologies if it looks a little wonky. I've tried to emulate sorta what happens under the hood in Jest down to solely node core modules.

Note that I might very well have gotten some semantics wrong in the dynamic linking, so please tell me if I'm doing something really dumb in the reproduction (except having no module cache at all) - I've probably made the same mistake in Jest's implementation. Main difference is that the calls will linger - In jest these would all be inside test() calls or some such that we execute later. I don't think it impacts the reproduction much though - the promises resolve seconds before linking complete, so I don't think it's necessarily tied to dangling promises. I might very well be wrong though.

For some extra context if it's helpful, here's Jest's implementation: https://github.com/facebook/jest/blob/7a3c9977847cc9fafed6f6662289f3c35e44e0c6/packages/jest-runtime/src/index.ts#L323-L456

It's spread a bit around, but those are the essential bits where we use the VM APIs.

[GeoffreyBooth]

cc @devsnek

[devsnek]

The example given looks sufficiently contrived/broken (multiple linker functions, multiple calls to evaluate, etc) that I am not convinced there is a bug with node at this point. If a simpler reproduction can be provided I will gladly take a look.

[SimenB]

That doesn't bode well for my current implementation in Jest then as I have pretty much the same approach there 😅 I can remove the evaluate call in the linker, but not the link call, then it fails with Module status must not be unlinked or linking. There's no example in the docs using importModuleDynamically, so I might very well be using it wrong. Am I not supposed to reuse a linker function as callback for importModuleDynamically?

[devsnek]

@SimenB here's an example loader that might help:

'use strict';

const { SourceTextModule } = require('vm');
const path = require('path');
const fs = require('fs');

const cache = new Map();
function load(specifier, referrer) {
  const filename = path.resolve(path.dirname(referrer.identifier), specifier);
  if (cache.has(filename)) {
    return cache.get(filename);
  }
  const source = fs.readFileSync(filename, 'utf8');
  const m = new SourceTextModule(source, {
    identifier: filename,
    importModuleDynamically: entry,
  });
  cache.set(filename, m);
  return m;
}

async function entry(specifier, referrer) {
  const m = load(specifier, referrer);
  if (m.status === 'unlinked') {
    await m.link(load);
  }
  if (m.status === 'linked') {
    await m.evaluate();
  }
  return m;
}

entry('./a.mjs', { identifier: process.cwd() + '/[node]' });

While you can evaluate and link each layer of the graph manually, it is much simpler to just call link and evaluate at the top. The m.status checks are needed in case the static entry is dynamically imported.

[SimenB]

Thanks @devsnek, that's cleaner indeed! And it does fix the error in my original reproduction as well. However, making the same change in Jest doesn't fix the issue there.

I've now spent some more time on it, and I'm now able to see the same error I can see in Jest - which is that it seems like the linking tries to link modules from different contexts, or something? I've changed the repo in the OP to have a fake super-dumb test framework and added a "teardown" when a test complete (setting completed to true). I'm seeing the error about 1 in 10 times, while in Jest it's reproducible 100% of the time, but hopefully it's enough. I moved the entry and load functions inside the runTest function to easily have separate caches and contexts per test, but it should be an easy refactor to just pass those as arguments and keep them at the top level.

Example of the error.

$ node --experimental-vm-modules index.js
(node:9917) ExperimentalWarning: VM Modules is an experimental feature. This feature could change at any time
(Use `node --trace-warnings ...` to show where the warning was created)
Map(1) { 'goodbye' => 'success!' }
Trying to load /Users/simen/repos/jest-esm-dynamic-import-error/lib/hello.js from test ./__tests__/goodbye.test.js
Map(1) {
  'hello' => Error: test has already completed
      at TestRuntime.load (/Users/simen/repos/jest-esm-dynamic-import-error/index.js:46:19)
      at async TestRuntime.entry (/Users/simen/repos/jest-esm-dynamic-import-error/index.js:22:19)
      at async importModuleDynamicallyWrapper (internal/vm/module.js:422:15)
      at async echo (/Users/simen/repos/jest-esm-dynamic-import-error/lib/index.js:2:29)
      at async /Users/simen/repos/jest-esm-dynamic-import-error/__tests__/hello.test.js:4:18
      at async TestRuntime.globalThis.runTests [as framework] (/Users/simen/repos/jest-esm-dynamic-import-error/testFramework.js:12:13)
      at async TestRuntime.runTest (/Users/simen/repos/jest-esm-dynamic-import-error/index.js:71:25)
      at async runTest (/Users/simen/repos/jest-esm-dynamic-import-error/index.js:83:21)
      at async Promise.all (index 0)
}
test run complete!

I'm really not sure what the bug is, but there are 3 things wrong with the behavior that I can see

1. We seem to be running goodbye.test.js, which has already completed
2. That test is trying to load hello.js, which it should never do
3. The stack trace shows hello.test.js:4:18 which is unexpected, as that's not the test we're running.

EDIT: Just pushed another commit which removed the timeout stuff I added, and the test now fails almost every time I run it
EDIT2: Pushed yet another commit to bring it even closer to Jest - a runtime class which holds the state instead of closures

[devsnek]

@SimenB you have a TOCTOU here because of the async file op: https://github.com/SimenB/node-vm-esm-promise-awaiting/blob/d7e5baf9927e5400432575ae8de55253c24a7e78/index.js#L39-L57

[targos]

Is this still an issue?

[SimenB]

Yes, but I believe #36351 might be the underlying reason. Not 100% sure - would be interesting to attempt to reproduce this after that issue is fixed. I haven't found the time to dig into this yet, but I'm hopeful I'll find the time in the not too distant future (I assume a bunch of modules will start to be ESM only once Node 10 is EOL, at which point good support in Jest will be very much needed)

[SimenB]

I updated the repo now so it still works on newer versions of Node (the TLA PR removed the result from evaluate so had to move things around a bit).

---

@devsnek I don't quite understand why the TOCTOU concern you mention is an issue. hello should never access goodbye (and vice versa), so it's not like a cache miss and a subsequent "duplicate" module should mess with anything, is it?

I tried adding a super simple mutex, but that is never triggered (i.e. the same module is not loaded more than once in the same "test run"). You can remove the module cache (or throw on module cache hits) and we still get the same error. One "test" never accesses the same module twice, so the cache shouldn't matter. Both tests access the same module, but they should be independent since they're evaluated in different contexts.

---

I agree removing the async readFile (e.g. replacing it with a readFileSync) fixes the error in the reproduction, but seeing as module resolution can be async I'm not sure how that's the underlying issue? Could you perhaps show me how you'd structure async access to the "same module" (i.e. same identifier and content, but different instances of SourceTextModule and using different contexts) in parallel?

It looks to me like there's some sort of unwanted cached module somewhere, so the wrong thing runs, do you think it might be the same issue as #36351?

[devsnek]

@SimenB the issue is this:

async function load() {
  1. if cache has entry, return cached entry
  2. let new entry be await foo
  3. insert new entry into cache
  4. return new entry
}

// invoking it:
load() // cache miss, new await happens (waiting at step 2)
load() // cache miss, the other one is still waiting at step 2, new await happens

[SimenB]

Right, but in this case 1. never hits - the same module is never loaded twice (from the same test). So I don't think that's an issue in practice?

But I see you're saying step 2 is the issue, so maybe the cache part doesn't affect things. But does that mean we cannot run importModuleDynamically in parallel? I.e. we need some mutex/lock in there. There is only one import() call per test, so even that shouldn't be an issue I think, unless we cannot run importModuleDynamically in parallel within the same node process at all? That would seem like a bad limitation, so I assume I'm still missing something 😅