@opentelemetry/instrumentation _onRequire does not receive the actual import name

[gajus]

What happened?

I've been debugging for days why tracing does not work as expected.

I've realized that some auto instrumentations are never actually applied.

After a lot of digging, I've landed on issue being that the module name is never matched in the _onRequire function.

opentelemetry-js/experimental/packages/opentelemetry-instrumentation/src/platform/node/instrumentation.ts

Lines 173 to 219 in 43e598e

	private _onRequire<T>(
	module: InstrumentationModuleDefinition<T>,
	exports: T,
	name: string,
	baseDir?: string | void
	): T {
	if (!baseDir) {
	if (typeof module.patch === 'function') {
	module.moduleExports = exports;
	if (this._enabled) {
	return module.patch(exports);
	}
	}
	return exports;
	}
	const version = this._extractPackageVersion(baseDir);
	module.moduleVersion = version;
	if (module.name === name) {
	// main module
	if (
	isSupported(module.supportedVersions, version, module.includePrerelease)
	) {
	if (typeof module.patch === 'function') {
	module.moduleExports = exports;
	if (this._enabled) {
	return module.patch(exports, module.moduleVersion);
	}
	}
	}
	return exports;
	}
	// internal file
	const files = module.files ?? [];
	const supportedFileInstrumentations = files
	.filter(f => f.name === name)
	.filter(f =>
	isSupported(f.supportedVersions, version, module.includePrerelease)
	);
	return supportedFileInstrumentations.reduce<T>((patchedExports, file) => {
	file.moduleExports = patchedExports;
	if (this._enabled) {
	return file.patch(patchedExports, module.moduleVersion);
	}
	return patchedExports;
	}, exports);
	}

If I add a console.log here:

console.log('>>> require', module.name, name);

The only things printed are:

>>> require fastify fastify/lib/logger.js
>>> require fastify fastify/lib/schemas.js
>>> require fastify fastify/lib/error-serializer.js
>>> require fastify fastify/lib/error-handler.js
>>> require fastify fastify/lib/reply.js
>>> require fastify fastify/lib/request.js
>>> require fastify fastify/lib/context.js
>>> require fastify fastify/lib/httpMethods.js
>>> require fastify fastify/lib/decorate.js
>>> require fastify fastify/lib/contentTypeParser.js
>>> require fastify fastify/lib/schema-controller.js
>>> require fastify fastify/lib/pluginUtils.js
>>> require fastify fastify/lib/reqIdGenFactory.js
>>> require fastify fastify/lib/headRoute.js
>>> require fastify fastify/lib/route.js
>>> require fastify fastify/lib/fourOhFour.js
>>> require fastify fastify/lib/configValidator.js
>>> require fastify fastify/lib/initialConfigValidation.js
>>> require fastify fastify/lib/pluginOverride.js
>>> require fastify fastify/lib/noop-set.js

Meanwhile, in our codebase we import it as:

import createFastify, { type FastifyRequest } from 'fastify';

It appears that the require path gets translated somehow before it can be matched.

This means that getNodeAutoInstrumentations never applies the Fastify instrumentation.

Interestingly, not all imports are affected...

graphql ✅

...
>>> require graphql graphql/utilities/index.js
>>> require graphql graphql

@grpc/grpc-js ✅

>>> require @grpc/grpc-js @grpc/grpc-js/package.json
>>> require @grpc/grpc-js @grpc/grpc-js

but these are the exceptions, most never resolve to the actual module name. ioredis is another example:

>>> require ioredis ioredis/built/SubscriptionSet.js
>>> require ioredis ioredis/built/DataHandler.js
>>> require ioredis ioredis/built/redis/event_handler.js
>>> require ioredis ioredis/built/redis/RedisOptions.js
>>> require ioredis ioredis/built/Redis.js

I am able to replicate this with as little code as:

import { getNodeAutoInstrumentations } from '@opentelemetry/auto-instrumentations-node';

(async () => {
  getNodeAutoInstrumentations();

  await import('fastify');
})();

$ node src/bin/server.mjs
>>> require fastify fastify/package.json
>>> require fastify fastify/lib/symbols.js
>>> require fastify fastify/lib/warnings.js
>>> require fastify fastify/lib/errors.js
>>> require fastify fastify/lib/hooks.js
>>> require fastify fastify/lib/server.js
>>> require fastify fastify/lib/validation.js
>>> require fastify fastify/lib/wrapThenable.js
>>> require fastify fastify/lib/handleRequest.js
>>> require pino pino/package.json
>>> require pino pino/lib/caller.js
>>> require pino pino/lib/symbols.js
>>> require pino pino/lib/redaction.js
>>> require pino pino/lib/time.js
>>> require pino pino/lib/transport.js
>>> require pino pino/lib/tools.js
>>> require pino pino/lib/levels.js
>>> require pino pino/lib/meta.js
>>> require pino pino/lib/proto.js
>>> require pino pino/lib/multistream.js
>>> require pino pino ✅
>>> require fastify fastify/lib/logger.js
>>> require fastify fastify/lib/schemas.js
>>> require fastify fastify/lib/error-serializer.js
>>> require fastify fastify/lib/error-handler.js
>>> require fastify fastify/lib/reply.js
>>> require fastify fastify/lib/request.js
>>> require fastify fastify/lib/context.js
>>> require fastify fastify/lib/httpMethods.js
>>> require fastify fastify/lib/decorate.js
>>> require fastify fastify/lib/contentTypeParser.js
>>> require fastify fastify/lib/schema-controller.js
>>> require fastify fastify/lib/pluginUtils.js
>>> require fastify fastify/lib/reqIdGenFactory.js
>>> require fastify fastify/lib/headRoute.js
>>> require fastify fastify/lib/route.js
>>> require fastify fastify/lib/fourOhFour.js
>>> require fastify fastify/lib/configValidator.js
>>> require fastify fastify/lib/initialConfigValidation.js
>>> require fastify fastify/lib/pluginOverride.js
>>> require fastify fastify/lib/noop-set.js

If I update the file server.cjs, then it works as expected:

$ const { getNodeAutoInstrumentations } = require('@opentelemetry/auto-instrumentations-node');

(async () => {
  getNodeAutoInstrumentations();

  require('fastify');
})();

$ at 16:33:26 ❯ node server.cjs
name http http
name fastify fastify/lib/symbols.js
name fastify fastify/package.json
name https https
name dns dns
name fastify fastify/lib/warnings.js
name fastify fastify/lib/errors.js
name fastify fastify/lib/hooks.js
name fastify fastify/lib/server.js
name fastify fastify/lib/validation.js
name fastify fastify/lib/wrapThenable.js
name fastify fastify/lib/handleRequest.js
name pino pino/lib/caller.js
name pino pino/package.json
name pino pino/lib/symbols.js
name pino pino/lib/redaction.js
name pino pino/lib/time.js
name fs fs
name pino pino/lib/transport.js
name pino pino/lib/tools.js
name pino pino/lib/levels.js
name pino pino/lib/meta.js
name pino pino/lib/proto.js
name pino pino/lib/multistream.js
name pino pino
name fastify fastify/lib/logger.js
name fastify fastify/lib/schemas.js
name fastify fastify/lib/error-serializer.js
name fastify fastify/lib/error-handler.js
name fastify fastify/lib/reply.js
name fastify fastify/lib/request.js
name fastify fastify/lib/context.js
name fastify fastify/lib/httpMethods.js
name fastify fastify/lib/decorate.js
name fastify fastify/lib/contentTypeParser.js
name fastify fastify/lib/schema-controller.js
name fastify fastify/lib/pluginUtils.js
name fastify fastify/lib/reqIdGenFactory.js
name fastify fastify/lib/headRoute.js
name fastify fastify/lib/route.js
name fastify fastify/lib/fourOhFour.js
name fastify fastify/lib/configValidator.js
name fastify fastify/lib/initialConfigValidation.js
name fastify fastify/lib/pluginOverride.js
name fastify fastify/lib/noop-set.js
name fastify fastify

Obviously, that's not an option.

[Flarna]

if you use node in ESM mode it's needed to specify a loader, see here.
This is still experimental and likely dependent on the node.js version so no guarantee that it works.

But not using this ESM hook in an ESM app is for sure a reason that it can't work.

[gajus]

Unfortunately, the underlying library that supports it does not appear to quite work

nodejs/import-in-the-middle#58

[dyladan]

I added the dependencies label here because this bug appears to be in IITM which we really can't anything about until it is fixed there.

[dargmuesli]

The IITM bug appears to be fixed by now 💡