fix(opentelemetry-instrumentation): improve _warnOnPreloadedModules function not to show warning logs when the module is not marked as loaded

[rlj1202]

Which problem is this PR solving?

On ESM environment where ECMAScript module and CommonJS modules coexist, unnecessary module preload warning logs appear.

How Has This Been Tested?

Example:

graph TD;
    main.mjs-->a.mjs;
    main.mjs-->b.cjs;
    main.mjs-->d.mjs;
    main.mjs-->e.cjs;
    b.cjs-->c.cjs;
    e.cjs-->f.cjs;

Loading

1. main.mjs visited, b.cjs and e.cjs appear in the require.cache as loaded = false
2. a.mjs visited and loaded
3. b.cjs visited, c.cjs appears in the require.cache as loaded = false
4. c.cjs visited and loaded
5. b.cjs loaded
6. d.mjs visited and loaded
7. e.cjs visited, f.cjs appears in the require.cache as loaded = false
8. f.cjs visited and loaded
9. e.cjs loaded
10. main.mjs loaded

~/projects/stackblitz-starters-oejjyprq
❯ npm start

> start
> node main.mjs

/home/projects/stackblitz-starters-oejjyprq/a.mjs
/home/projects/stackblitz-starters-oejjyprq/c.cjs [
  [ '/home/projects/stackblitz-starters-oejjyprq/b.cjs', false ],
  [ '/home/projects/stackblitz-starters-oejjyprq/e.cjs', false ],
  [ '/home/projects/stackblitz-starters-oejjyprq/c.cjs', false ]
]
/home/projects/stackblitz-starters-oejjyprq/b.cjs [
  [ '/home/projects/stackblitz-starters-oejjyprq/b.cjs', false ],
  [ '/home/projects/stackblitz-starters-oejjyprq/e.cjs', false ],
  [ '/home/projects/stackblitz-starters-oejjyprq/c.cjs', true ]
]
/home/projects/stackblitz-starters-oejjyprq/d.mjs
/home/projects/stackblitz-starters-oejjyprq/f.cjs [
  [ '/home/projects/stackblitz-starters-oejjyprq/b.cjs', true ],
  [ '/home/projects/stackblitz-starters-oejjyprq/e.cjs', false ],
  [ '/home/projects/stackblitz-starters-oejjyprq/c.cjs', true ],
  [ '/home/projects/stackblitz-starters-oejjyprq/f.cjs', false ]
]
/home/projects/stackblitz-starters-oejjyprq/e.cjs [
  [ '/home/projects/stackblitz-starters-oejjyprq/b.cjs', true ],
  [ '/home/projects/stackblitz-starters-oejjyprq/e.cjs', false ],
  [ '/home/projects/stackblitz-starters-oejjyprq/c.cjs', true ],
  [ '/home/projects/stackblitz-starters-oejjyprq/f.cjs', true ]
]

• https://stackblitz.com/edit/stackblitz-starters-oejjyprq?file=package.json
• https://marian-caikovski.medium.com/execution-order-of-javascript-modules-ddaca4561220

So to warn preloaded modules properly in ESM environment, Module.loaded property should be considered.

Checklist:

• Followed the style guidelines of this project
• Unit tests have been added (N/A)
• Documentation has been updated (N/A)

[linux-foundation-easycla]

The committers listed above are authorized under a signed CLA.

• ✅ login: trentm / name: Trent Mick (0079b38, 89dc33b)

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 95.70%. Comparing base (f122107) to head (89dc33b).
⚠️ Report is 1 commits behind head on main.

Additional details and impacted files

@@           Coverage Diff           @@
##             main    #6095   +/-   ##
=======================================
  Coverage   95.70%   95.70%           
=======================================
  Files         364      364           
  Lines       11774    11774           
  Branches     2747     2747           
=======================================
  Hits        11268    11268           
  Misses        506      506           

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
• 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

[trentm]

@rlj1202 I can see how this seems correct. Did you run into a specific example with real modules where you hit this? I quickly tried to come up with a reproduction case of _warnOnPreloadedModules warning with real Instrumentations, but I couldn't'.

[rlj1202]

@rlj1202 I can see how this seems correct. Did you run into a specific example with real modules where you hit this? I quickly tried to come up with a reproduction case of _warnOnPreloadedModules warning with real Instrumentations, but I couldn't'.

Yes! I will make a simple working example using real instrumentations with NestJS and share it within a week.

[rlj1202]

https://stackblitz.com/edit/nestjs-typescript-starter-xtzvpxev?file=src%2Fmain.ts

This is a minimal real-world instrumentation example with Nest.js. If you run this using pnpm start:dev, you will face this warning message:

@opentelemetry/instrumentation-nestjs-core Module @nestjs/core has been loaded before @opentelemetry/instrumentation-nestjs-core so it might not work, please initialize it before requiring @nestjs/core

But instrumentation has no problem. You can see the result from the console logs printed by ConsoleSpanExporter.

In this example, I triggered the instrumentation code by importing instrument.ts file in the main.ts entry file like this.

import './instrument.js';

// ...

However, if you inject instrumentation code like this as described in official documents:

npx tsx --import ./src/instrument.ts ./src/main.ts

You can never see the warning message as before, and this is an expected result. (You need a different running environment than stackblitz)

[trentm]

Thanks for the repro.

Interesting. Here is what I roughly think is happening. dist/main.js looks like this:

import './instrument.js';
import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module.js';
async function main() {
    const app = await NestFactory.create(AppModule);
    await app.listen(3000);
}
void main();
//# sourceMappingURL=main.js.map

This file is ESM. @nestjs/core is CommonJS.
I think during the linking phase of ESM loading, the Node.js ESM loader is putting a placeholder entry in require.cache when it sees the import { NestFactory } from '@nestjs/core'; line and knows that is a CommonJS module. The cache entry looks like this:

name=@nestjs/core

resolvedModule=/Users/trentm/Downloads/nestjs-typescript-starter-xtzvpxev/node_modules/.pnpm/@nestjs+core@11.1.14_@nestjs+common@11.1.14_reflect-metadata@0.2.2_rxjs@7.8.2__@nestjs+_f69fdd95a248b4f2ef2d319b42c2302d/node_modules/@nestjs/core/index.js 

cache entry={
  id: '/Users/trentm/Downloads/nestjs-typescript-starter-xtzvpxev/node_modules/.pnpm/@nestjs+core@11.1.14_@nestjs+common@11.1.14_reflect-metadata@0.2.2_rxjs@7.8.2__@nestjs+_f69fdd95a248b4f2ef2d319b42c2302d/node_modules/@nestjs/core/index.js',
  path: '/Users/trentm/Downloads/nestjs-typescript-starter-xtzvpxev/node_modules/.pnpm/@nestjs+core@11.1.14_@nestjs+common@11.1.14_reflect-metadata@0.2.2_rxjs@7.8.2__@nestjs+_f69fdd95a248b4f2ef2d319b42c2302d/node_modules/@nestjs/core',
  exports: {},
  filename: '/Users/trentm/Downloads/nestjs-typescript-starter-xtzvpxev/node_modules/.pnpm/@nestjs+core@11.1.14_@nestjs+common@11.1.14_reflect-metadata@0.2.2_rxjs@7.8.2__@nestjs+_f69fdd95a248b4f2ef2d319b42c2302d/node_modules/@nestjs/core/index.js',
  loaded: false,
  children: [],
  paths: [Array],
  Symbol(kIsCachedByESMLoader): true
}

Notice that Symbol(kIsCachedByESMLoader): true entry that gave me the hint.

Then @opentelemetry/instrumentation-nestjs-core is fully loaded, then immediately after, @nestjs/core is loaded.

So, I agree with the decision to only emit this "Module [name] has been loaded before ..." warning if loaded: true in the cache.

[trentm]

LGTM, with a nit: let's call it a fix (not a "chore" in the "Features" changelog section).

[otelbot]

Thank you for your contribution @rlj1202! 🎉 We would like to hear from you about your experience contributing to OpenTelemetry by taking a few minutes to fill out this survey.