Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ioredis: cannot instrument an ESM-imported ioredis #1692

Closed
synchrone opened this issue Sep 20, 2023 · 5 comments · Fixed by #1694
Closed

ioredis: cannot instrument an ESM-imported ioredis #1692

synchrone opened this issue Sep 20, 2023 · 5 comments · Fixed by #1694
Assignees
Labels
bug Something isn't working pkg:instrumentation-ioredis priority:p1 Bugs which cause problems in end-user applications such as crashes, data inconsistencies

Comments

@synchrone
Copy link

What version of OpenTelemetry are you using?

        "@opentelemetry/auto-instrumentations-node": "0.39.2",
        "@opentelemetry/sdk-node": "0.43.0",
        "@opentelemetry/instrumentation-ioredis": "0.35.1",
        "@opentelemetry/instrumentation": "0.41.2",

What version of Node are you using?

v18.13.0 (18.13.0+dfsg1-1)

What did you do?

create a file test.mjs

import {IORedisInstrumentation} from "@opentelemetry/instrumentation-ioredis";
new IORedisInstrumentation()
import 'ioredis'
setTimeout(() => 0, 1000)

then run:
node --experimental-loader=@opentelemetry/instrumentation/hook.mjs test.mjs

What did you expect to see?

a successfully instrumented ioredis

What did you see instead?

Uncaught TypeError: Cannot read properties of undefined (reading 'sendCommand') instrumentation.js:131

Additional context

when InstrumentationNodeModuleDefinition patch callback runs, it expects require-in-the-middle to provide moduleExports, which is a normal class.
However, in ESM-mode, import-in-the-middle actually provides a Proxy as moduleExports variable, which means moduleExports.prototype is undefined, resulting in an error thrown.

@synchrone synchrone added the bug Something isn't working label Sep 20, 2023
@pichlermarc pichlermarc added priority:p1 Bugs which cause problems in end-user applications such as crashes, data inconsistencies up-for-grabs Good for taking. Extra help will be provided by maintainers labels Sep 20, 2023
@trentm
Copy link
Contributor

trentm commented Sep 20, 2023

I can take a look.

@trentm
Copy link
Contributor

trentm commented Sep 20, 2023

I've added the following to the instrumentation-ioredis/src/instrumentation.ts init() to show a little bit what is going on:

console.log('XXX --- instrumentation-ioredis init()');
console.log('XXX moduleExports: ', moduleExports);
console.log('XXX moduleExports.default: ', moduleExports.default);

First let's reproduce with "test.mjs" (trimmed a bit for brevity):

% node --experimental-loader=@opentelemetry/instrumentation/hook.mjs test.mjs
XXX --- instrumentation-ioredis init()
XXX moduleExports:  [Module: null prototype] {
  AbstractConnector: [class AbstractConnector],
  Redis: [class Redis extends Commander] {
    Cluster: [Getter],
    default: [Getter],
    Redis: [Getter],
    ...
  },
  __esModule: undefined,
  default: [class Redis extends Commander] {
    AbstractConnector: [Getter],
    default: [Getter],
    Redis: [Getter],
    ...
  },
  ...
}
XXX moduleExports.default:  [class Redis extends Commander] {
  AbstractConnector: [Getter],
  Cluster: [Getter],
  Command: [Getter],
  default: [Getter],
  Redis: [Getter],
  ...
}
/Users/trentm/tmp/asdf.20230920T112542/node_modules/@opentelemetry/instrumentation-ioredis/build/src/instrumentation.js:134
                if ((0, instrumentation_1.isWrapped)(moduleExports.prototype.sendCommand)) {
                                                                             ^

TypeError: Cannot read properties of undefined (reading 'sendCommand')
    at InstrumentationNodeModuleDefinition.patch (/Users/trentm/tmp/asdf.20230920T112542/node_modules/@opentelemetry/instrumentation-ioredis/build/src/instrumentation.js:134:78)
    at IORedisInstrumentation._onRequire (/Users/trentm/tmp/asdf.20230920T112542/node_modules/@opentelemetry/instrumentation-ioredis/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:157:39)
    at hookFn (/Users/trentm/tmp/asdf.20230920T112542/node_modules/@opentelemetry/instrumentation-ioredis/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:198:29)
    at callHookFn (/Users/trentm/tmp/asdf.20230920T112542/node_modules/import-in-the-middle/index.js:28:22)
    at Hook._iitmHook (/Users/trentm/tmp/asdf.20230920T112542/node_modules/import-in-the-middle/index.js:76:11)
    at /Users/trentm/tmp/asdf.20230920T112542/node_modules/import-in-the-middle/index.js:17:41
    at Array.forEach (<anonymous>)
    at addHook (/Users/trentm/tmp/asdf.20230920T112542/node_modules/import-in-the-middle/index.js:17:10)
    at new Hook (/Users/trentm/tmp/asdf.20230920T112542/node_modules/import-in-the-middle/index.js:84:3)
    at IORedisInstrumentation.enable (/Users/trentm/tmp/asdf.20230920T112542/node_modules/@opentelemetry/instrumentation-ioredis/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:210:29)

Node.js v18.17.1

Then let's run the equivalent CommonJS version:

const {IORedisInstrumentation} = require("@opentelemetry/instrumentation-ioredis");
new IORedisInstrumentation()
require('ioredis');
setTimeout(() => 0, 1000)
% node test.cjs
XXX --- instrumentation-ioredis init()
XXX moduleExports:  [class Redis extends Commander] {
  AbstractConnector: [Getter],
  Cluster: [Getter],
  Command: [Getter],
  default: [Getter],
  Redis: [Getter],
  ...
}
XXX moduleExports.default:  [class Redis extends Commander] {
  AbstractConnector: [Getter],
  Cluster: [Getter],
  Command: [Getter],
  default: [Getter],
  Redis: [Getter],
  ...
}

The relevant difference between the two is:

// ESM import Module object
XXX moduleExports:  [Module: null prototype] {

// CommonJS top-level export
XXX moduleExports:  [class Redis extends Commander] {

The top-level "thing" from an ESM import, the thing that is passed to the
import-in-the-middle hook, is a Module Namespace Object -- an immutable "exotic" object that holds the named exports. That design is difficult for interoperability with a top-level CommonJS export that is anything but a simple object -- e.g. a class, or a function.

For some interoperability, Node.js' ESM loader adds a <module>.default equal to the CommonJS module.exports:

https://nodejs.org/api/esm.html#commonjs-namespaces

The ECMAScript Module Namespace representation of a CommonJS module is always a namespace with a default export key pointing to the CommonJS module.exports value.

For ioredis, the top-level export is a class object that the current OTel instrumentation is trying to use.
For an ESM import of ioredis, that same class is available at <module>.default.

For a CommonJS import of ioredis, that same class is also available at <moduleExports>.default because ioredis source code is doing this: https://github.com/redis/ioredis/blob/main/lib/index.ts#L1-L3
which is transpiled to:

...
exports = module.exports = require("./Redis").default;
var Redis_1 = require("./Redis");
Object.defineProperty(exports, "default", { enumerable: true, get: function () { return Redis_1.default; } });
...

That means we should be able to change the instrumentation-ioredis to instrument <moduleThing>.default.prototype.command.

Trying that gets us further. More below.

Aside

This "<moduleThing>.default is the same top-level thing for both ESM and CJS" convenience is likely not the case for every module. Instrumentations that treat that top-level <moduleThing> as anything other than a namespace (e.g. as a class that has a .prototype) will probably need to adjust. They should be able to sniff out if it is an ESM Module Namespace Object via (given the @@toStringTag spec requirement at https://tc39.es/ecma262/#sec-module-namespace-objects)

moduleExports[Symbol.toStringTag] === "Module"

The next issue

Making the change to patch moduleExports.default.prototype.* gets use past that issue, but we then hit this.
(Line numbers might be off for you because I have some debug prints in the way.)

% node --experimental-loader=@opentelemetry/instrumentation/hook.mjs test.mjs
/Users/trentm/tmp/asdf.20230920T112542/node_modules/@opentelemetry/instrumentation-ioredis/build/src/instrumentation.js:163
            return this.traceSendCommand(original, moduleVersion);
                        ^

TypeError: this.traceSendCommand is not a function
    at /Users/trentm/tmp/asdf.20230920T112542/node_modules/@opentelemetry/instrumentation-ioredis/build/src/instrumentation.js:163:25
    at wrap (/Users/trentm/tmp/asdf.20230920T112542/node_modules/shimmer/index.js:48:17)
    at InstrumentationBase._wrap (/Users/trentm/tmp/asdf.20230920T112542/node_modules/@opentelemetry/instrumentation-ioredis/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:39:43)
    at InstrumentationNodeModuleDefinition.patch (/Users/trentm/tmp/asdf.20230920T112542/node_modules/@opentelemetry/instrumentation-ioredis/build/src/instrumentation.js:141:22)
    at IORedisInstrumentation._onRequire (/Users/trentm/tmp/asdf.20230920T112542/node_modules/@opentelemetry/instrumentation-ioredis/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:157:39)
    at hookFn (/Users/trentm/tmp/asdf.20230920T112542/node_modules/@opentelemetry/instrumentation-ioredis/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:198:29)
    at callHookFn (/Users/trentm/tmp/asdf.20230920T112542/node_modules/import-in-the-middle/index.js:28:22)
    at Hook._iitmHook (/Users/trentm/tmp/asdf.20230920T112542/node_modules/import-in-the-middle/index.js:76:11)
    at /Users/trentm/tmp/asdf.20230920T112542/node_modules/import-in-the-middle/index.js:17:41
    at Array.forEach (<anonymous>)

Node.js v18.17.1

Things work fine with CJS:

% node test.cjs

I modified "instrumentation-ioredis/build/src/instrumentation.js" to dump that this:

    _patchSendCommand(moduleVersion) {
        console.log('XXX _patchSendCommand: this=', this);
        return (original) => {
            return this.traceSendCommand(original, moduleVersion);
        };
    }

When run via CommonJS it looks like:

XXX _patchSendCommand: this= IORedisInstrumentation {
  instrumentationName: '@opentelemetry/instrumentation-ioredis',
  instrumentationVersion: '0.35.1',
  _wrap: [Function (anonymous)],
  ...
  _modules: [
    InstrumentationNodeModuleDefinition {
      name: 'ioredis',
      supportedVersions: [Array],
      patch: [Function (anonymous)],
      unpatch: [Function (anonymous)],
      files: [],
      moduleVersion: '5.3.2',
      moduleExports: [Function]
    }
  ],
  traceSendCommand: [Function (anonymous)],
  traceConnection: [Function (anonymous)]
}

But when run via ESM it does not have the traceSendCommand and traceConnection properties.

Here is what I believe is happening. First, ESM imports happen before other code is executed, so "test.mjs" is effectively this:

import {IORedisInstrumentation} from "@opentelemetry/instrumentation-ioredis";
import 'ioredis'  // <--- this effectively happens before `new IORedisInstrumentation()`
new IORedisInstrumentation()
setTimeout(() => 0, 1000)

To support this behaviour, import-in-the-middle (IITM) keeps a toHook list of imported modules.
When new IORedisInstrumentation() is called it:

  1. constructs IORedisInstrumentation:
    export class IORedisInstrumentation extends InstrumentationBase<any> {
    constructor(_config: IORedisInstrumentationConfig = {}) {
    super(
    '@opentelemetry/instrumentation-ioredis',
    VERSION,
    Object.assign({}, DEFAULT_CONFIG, _config)
    );
    }
  2. which calls its super class constructor: https://github.com/open-telemetry/opentelemetry-js/blob/1a8652aa5466510d2df2a232a0c8aa78857619c4/experimental/packages/opentelemetry-instrumentation/src/platform/node/instrumentation.ts#L47-L73
  3. which calls this.init() and this.enable(). This creates an IITM Hook. Because the import 'ioredis'; has already been noticed by IITM, it synchronously calls the hookFn, which in this case calls the patch function here:
    (moduleExports, moduleVersion?: string) => {
    diag.debug('Applying patch for ioredis');
    if (isWrapped(moduleExports.prototype.sendCommand)) {
    this._unwrap(moduleExports.prototype, 'sendCommand');
    }
    this._wrap(
    moduleExports.prototype,
    'sendCommand',
    this._patchSendCommand(moduleVersion)
    );
    if (isWrapped(moduleExports.prototype.connect)) {
    this._unwrap(moduleExports.prototype, 'connect');
    }
    this._wrap(
    moduleExports.prototype,
    'connect',
    this._patchConnection()
    );
    return moduleExports;
    },

That should be fine, except I was a little surprised by the resultant JavaScript from the class IORedisInstrumentation TypeScript code. Here is the generated file:
https://gist.github.com/trentm/1fe20356a73e721fb8e1162d6805ead7#file-instrumentation-js-L30-L126
Notice how the traceSendCommand() and traceConnection() properties are added and the end of the constructor, after the super(...) call. That means the synchronous call of the patch function in that super(...) call, by IITM, comes before the class has those methods.

If we change the definition of those to methods not using arrow-functions:

diff --git a/plugins/node/opentelemetry-instrumentation-ioredis/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-ioredis/src/instrumentation.ts
index 94f8b850..50a64993 100644
--- a/plugins/node/opentelemetry-instrumentation-ioredis/src/instrumentation.ts
+++ b/plugins/node/opentelemetry-instrumentation-ioredis/src/instrumentation.ts
@@ -84,17 +84,17 @@ export class IORedisInstrumentation extends InstrumentationBase<any> {
    */
   private _patchSendCommand(moduleVersion?: string) {
     return (original: Function) => {
-      return this.traceSendCommand(original, moduleVersion);
+      return this._traceSendCommand(original, moduleVersion);
     };
   }

   private _patchConnection() {
     return (original: Function) => {
-      return this.traceConnection(original);
+      return this._traceConnection(original);
     };
   }

-  private traceSendCommand = (original: Function, moduleVersion?: string) => {
+  private _traceSendCommand(original: Function, moduleVersion?: string) {
     const instrumentation = this;
     return function (this: RedisInterface, cmd?: IORedisCommand) {
       if (arguments.length < 1 || typeof cmd !== 'object') {
@@ -178,9 +178,9 @@ export class IORedisInstrumentation extends InstrumentationBase<any> {
         throw error;
       }
     };
-  };
+  }

-  private traceConnection = (original: Function) => {
+  private _traceConnection(original: Function) {
     const instrumentation = this;
     return function (this: RedisInterface) {
       const config =
@@ -213,5 +213,5 @@ export class IORedisInstrumentation extends InstrumentationBase<any> {
         throw error;
       }
     };
-  };
+  }
 }

Then things work:

% node --experimental-loader=@opentelemetry/instrumentation/hook.mjs test.mjs
(node:84838) ExperimentalWarning: Custom ESM Loaders is an experimental feature and might change at any time
(Use `node --trace-warnings ...` to show where the warning was created)

I'll work on a PR.

@Flarna
Copy link
Member

Flarna commented Sep 21, 2023

Nice analysis. In special the last part with missing properties remembers me to open-telemetry/opentelemetry-js#1989 and open-telemetry/opentelemetry-js#3837

@trentm
Copy link
Contributor

trentm commented Sep 21, 2023

Thanks for the links, especially the former that links to microsoft/TypeScript#9209 (comment)

@trentm
Copy link
Contributor

trentm commented Sep 21, 2023

Here is a slightly longer test case, that generates some spans to sanity check that ioredis instrumentation is working:

import {IORedisInstrumentation} from "@opentelemetry/instrumentation-ioredis";
import { NodeSDK, tracing, api } from '@opentelemetry/sdk-node';
const { SimpleSpanProcessor, ConsoleSpanExporter } = tracing;
import Redis from 'ioredis';
// diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);

const sdk = new NodeSDK({
    serviceName: 'test-redis-instr',
    spanProcessor: new SimpleSpanProcessor(new ConsoleSpanExporter()),
    instrumentations: [
        new IORedisInstrumentation()
    ]
})
sdk.start();
const tracer = api.trace.getTracer('default');

const redis = new Redis();
await tracer.startActiveSpan('manual-span', async (span) => {
    redis.set('foo', 'bar');
    const val = await redis.get('foo');
    console.log('foo: %s', val);
    span.end()
})
await redis.quit();

When running that I get the expected output.
(Note that my long arg to --experimental-loader is to ensure there is only one @opentelemetry/instrumentation package, and hence one import-in-the-middle, package in play.)

% node --experimental-loader ./../../tm/opentelemetry-js-contrib2/plugins/node/opentelemetry-instrumentation-ioredis/node_modules/@opentelemetry/instrumentation/hook.mjs test.mjs
(node:94013) ExperimentalWarning: Custom ESM Loaders is an experimental feature and might change at any time
(Use `node --trace-warnings ...` to show where the warning was created)
{
  traceId: '9b68860155d239a4ca2ce40972598bdb',
  parentId: '8746370e1c8a1d8f',
  traceState: undefined,
  name: 'set',
  id: 'dda3dacb7d0b7ba5',
  kind: 2,
  timestamp: 1695323765138000,
  duration: 12865.888,
  attributes: {
    'db.system': 'redis',
    'db.statement': 'set foo [1 other arguments]',
    'net.peer.name': 'localhost',
    'net.peer.port': 6379,
    'db.connection_string': 'redis://localhost:6379'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  traceId: '9b68860155d239a4ca2ce40972598bdb',
  parentId: '8746370e1c8a1d8f',
  traceState: undefined,
  name: 'get',
  id: '06b5834cbd18b78d',
  kind: 2,
  timestamp: 1695323765139000,
  duration: 14119.384,
  attributes: {
    'db.system': 'redis',
    'db.statement': 'get foo',
    'net.peer.name': 'localhost',
    'net.peer.port': 6379,
    'db.connection_string': 'redis://localhost:6379'
  },
  status: { code: 0 },
  events: [],
  links: []
}
foo: bar
{
  traceId: '9b68860155d239a4ca2ce40972598bdb',
  parentId: undefined,
  traceState: undefined,
  name: 'manual-span',
  id: '8746370e1c8a1d8f',
  kind: 0,
  timestamp: 1695323765135000,
  duration: 18500.548,
  attributes: {},
  status: { code: 0 },
  events: [],
  links: []
}

trentm added a commit to trentm/opentelemetry-js-contrib that referenced this issue Sep 21, 2023
- With an ESM import the top-level object is a Module Namespace Object
  (https://tc39.es/ecma262/#sec-module-namespace-objects) that has no
  prototype. For compat, Node.js assigns the usual CommonJS
  module.exports to `<module>.default`, so use that when this is
  an ESM module.
- Also, TypeScript translates class properties to assignments in the
  constructor after the super() call. Because super() can call init()
  and enable() synchronously, it calls back into
  'IORedisInstrumentation' before 'traceSendCommand' was defined.
  Defining it as a method fixes that issue.

Fixes: open-telemetry#1692
@pichlermarc pichlermarc removed the up-for-grabs Good for taking. Extra help will be provided by maintainers label Oct 12, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working pkg:instrumentation-ioredis priority:p1 Bugs which cause problems in end-user applications such as crashes, data inconsistencies
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants