open-telemetry / opentelemetry-js-contrib

OpenTelemetry instrumentation for JavaScript modules
https://opentelemetry.io
Apache License 2.0
703 stars 524 forks source link

"format is not a function" error when using mysql2 instrumentation with `kysely` #1511

Open jballentine-sharpen opened 1 year ago

jballentine-sharpen commented 1 year ago

Is your instrumentation request related to a problem? Please describe

Kysely currently breaks when using OpenTelemetry. When I attempt to execute a query, I get an error of TypeError: format is not a function as well as some warnings of Warning: Accessing non-existent property 'format' of module exports inside circular dependency, with the error coming from @opentelemetry/instrumentation-mysql2/src/utils.ts:105:21. and caused by kysely/dist/esm/dialect/mysql/mysql-driver.js:117:33

It appears the mysql instrumentation breaks Kysely functionality. It would be great to be able to use both Kysely and otel without this conflict.

Is it applicable for Node or Browser or both?

Node

Do you expect this instrumentation to be commonly used?

Weekly Downloads: 59,839

What version of instrumentation are you interested in using?

Versions: Latest?

Additional context

I think instrumentation would just work as it uses mysql/pg under the hood, it just needs this conflict to be resolved.

jballentine-sharpen commented 1 year ago

Repo here: https://github.com/kysely-org/kysely

pichlermarc commented 1 year ago

Hi @jballentine-sharpen thanks for reporting this. Looks like this is not an instrumentation-request but a bug report. An instrumentation should not interfere with the library's functionality.

If possible, please provide a minimal reproducer. Before we start working on an issue we need to know exactly what's causing the behavior. Issues usually get fixed way quicker if a reproducer repository is at hand. :slightly_smiling_face:

FYI @haddasbronfman

jballentine-sharpen commented 1 year ago

Thanks for the response.

I unfortunately no longer have time to play around with this anymore and I got rid of the code I had due to me pivoting to using drizzle.

However, it should be very easy to reproduce. It happened to be after simply setting up a really basic select query using the mysql2 information on their docs (I ran into this pretty much right away when trying to use this package).

https://kysely.dev/docs/getting-started?dialect=mysql#dialects

It's really not worth me writing up code since you'd need to modify it to fit your database connection and schema.

If writing up a minimal reproducer is absolutely required, I will try to find some time to do so, but it is not really my top priority at the moment.

Thanks.

github-actions[bot] commented 1 year ago

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

kevinmarks commented 11 months ago

I am seeing this too, Not in kysely but with a straightforward node app writing mysql. Both the Warning: Accessing non-existent property 'format' of module exports inside circular dependency which shows up in this line here

this._patchQuery(moduleExports.format, false) as any https://github.com/open-telemetry/opentelemetry-js-contrib/blob/1c24cfd2e4cbb417a04ce9d6bad047fde76a823b/plugins/node/opentelemetry-instrumentation-mysql2/src/instrumentation.ts#L67

As compiled it looks like:

return [
            new instrumentation_1.InstrumentationNodeModuleDefinition('mysql2', ['>= 1.4.2 < 4.0'], (moduleExports, moduleVersion) => {
                api.diag.debug(`Patching mysql2@${moduleVersion}`);
                const ConnectionPrototype = moduleExports.Connection.prototype;
                api.diag.debug('Patching Connection.prototype.query');
                if ((0, instrumentation_1.isWrapped)(ConnectionPrototype.query)) {
                    this._unwrap(ConnectionPrototype, 'query');
                }
                this._wrap(ConnectionPrototype, 'query', this._patchQuery(moduleExports.format, false));
                if ((0, instrumentation_1.isWrapped)(ConnectionPrototype.execute)) {
                    this._unwrap(ConnectionPrototype, 'execute');
                }
                this._wrap(ConnectionPrototype, 'execute', this._patchQuery(moduleExports.format, true));
                return moduleExports;
            }, (moduleExports) => {
                if (moduleExports === undefined)
                    return;
                const ConnectionPrototype = moduleExports.Connection.prototype;
                this._unwrap(ConnectionPrototype, 'query');
                this._unwrap(ConnectionPrototype, 'execute');
            }),
        ];

and errors when I try to do an INSERT VALUES ? type query passing an array of values to mysql2 like this:

function valuesquery(dbc,query,values){
    return dbc.getConnection()
        .then(conn => {
            const res = conn.query(query,values);
            conn.release();
            return res;
        })
}

As this is preventing my app from writing data while instrumented it's a critical failure

kevinmarks commented 11 months ago

Which of your examples is testing this? The runtime error is here https://github.com/open-telemetry/opentelemetry-js-contrib/blob/1c24cfd2e4cbb417a04ce9d6bad047fde76a823b/plugins/node/opentelemetry-instrumentation-mysql2/src/utils.ts#L105 with format being undefined, it gives the TypeError

NavaceSystem commented 5 months ago

Seeing this too, Knex uses mysql2 under the hood.

I've narrowed it down the the moduleExports.format function being undefined here https://github.com/Aneurysm9/opentelemetry-js-contrib/blob/ff109b77928cc9a139a21c63d6b54399bb017fa4/plugins/node/opentelemetry-instrumentation-mysql2/src/instrumentation.ts#L66.

Inside _patchQuery it tries to use the format to format the query and breaks when it's undefined.

This should be a pretty simple patch no?

constb commented 3 months ago

This issue reproduces in ESM mode on Node.JS 20.x. I stopped inside instrumentation using debugger and what I'm seeing is that moduleExports does not contain format function.

This seems to me like a import-in-the-middle issue. Probably related to the way mysql2 (a common js module) exports format and other similar functions: https://github.com/sidorares/node-mysql2/blob/master/index.js#L49 – all of those functions are absent in moduleExports when instrumentation initializes…

constb commented 3 months ago

So I tried to reproduce this with import-in-the-middle and failed.

When I'm hooking mysql2 with import-in-the-middle (v1.11.0) it actually works as expected, the exports parameter in the hook has all the functions and classes from the package. And format function is present there too. I will try to investigate further to figure out how @opentelemetry/instrumentation manages to loose it and why it's missing in the moduleExports of instrumentation initializer…

luiz-rissardi commented 2 months ago

I was going through the same problem today, a solution I found was to analyze what type of mysql2 I am using, whether it is the normal one or mysql2/promise, I did not get to check completely but I assume that this instrumentation is on top of mysql2/promise, try using mysql2/promise and your problem will be solved and openTelemetry will do the tracing of your application, mysql2 in version ^3.11.0 worked I do not know the others

clifinger commented 1 month ago

I did a "little hack" and it work fine with Kysely, Knex should work also:

Screenshot 2024-09-27 151823 ,

// File: loader.cjs
const { registerInstrumentations } = require("@opentelemetry/instrumentation");
const { HttpInstrumentation } = require("@opentelemetry/instrumentation-http");
const {
    SocketIoInstrumentation,
} = require("@opentelemetry/instrumentation-socket.io");
const { PinoInstrumentation } = require("@opentelemetry/instrumentation-pino");

const {
    MySQL2Instrumentation,
} = require("@opentelemetry/instrumentation-mysql2");
const {
    FastifyInstrumentation,
} = require("@opentelemetry/instrumentation-fastify");

registerInstrumentations({
    instrumentations: [
        new FastifyInstrumentation(),
        new MySQL2Instrumentation(),
        new HttpInstrumentation(),
        new SocketIoInstrumentation(),
        new PinoInstrumentation(),
    ],
});

// load after instrumentation
const mysql = require("mysql2/promise");
const mysqlCommon = require("mysql2");

// Verify if the format function is missing and add it if necessary
if (!mysql.format) {
    mysql.format = mysqlCommon.format;
}

And I required it in my node command (TSX in my case):

tsx watch --require 'dotenv/config' --require './loader.cjs' --require '@opentelemetry/auto-instrumentations-node/register' src/main.ts
tpraxl commented 1 month ago

I set up a simple repo that demonstrates the error:

https://github.com/tpraxl/test-esm-mysql-otel

It is an esm node.js application that inserts a value into a table. It demonstrates that mysql2/promise works (thanks @luiz-rissardi for that useful trail) and that mysql2 does not work.

Maybe this helps tracking the error down.

clifinger commented 1 month ago

@tpraxl as my project is also esm and the format is missing into mysql2 (without promise).

Maybe the responsabilty of format should be handled by @opentelemetry/instrumentation-mysql2 as the output needed is for telemetry.

Because this work in commonjs and esm ( I tested it yesterday)

// load after instrumentation
const mysql = require("mysql2/promise");
const mysqlCommon = require("mysql2");

// Verify if the format function is missing and add it if necessary
if (!mysql.format) {
    mysql.format = mysqlCommon.format;
}
tpraxl commented 1 month ago

@clifinger you could argue that format should be the responsibility of @opentelemetry/instrumentation-mysql2 – in that case, it should depend on sqlstring and use its format function directly.

However, I am wondering what the point would be, because in order to instrument mysql2, we already heavily depend on its correctness and completeness, as far as I get it.

Having no mysql.format function seems to be a bug caused by circular dependencies and the way we patch things here when modules are required.

By removing the circular dependencies in mysql2, this bug vanishes.

smhmayboudi commented 1 month ago

I was going through the same problem today, a solution I found was to analyze what type of mysql2 I am using, whether it is the normal one or mysql2/promise, I did not get to check completely but I assume that this instrumentation is on top of mysql2/promise, try using mysql2/promise and your problem will be solved and openTelemetry will do the tracing of your application, mysql2 in version ^3.11.0 worked I do not know the others

@luiz-rissardi

The solution is not working with kysely. Would you happen to have another solution?

clifinger commented 1 month ago

I did a "little hack" and it work fine with Kysely, Knex should work also:

Screenshot 2024-09-27 151823 ,

// File: loader.cjs
const { registerInstrumentations } = require("@opentelemetry/instrumentation");
const { HttpInstrumentation } = require("@opentelemetry/instrumentation-http");
const {
  SocketIoInstrumentation,
} = require("@opentelemetry/instrumentation-socket.io");
const { PinoInstrumentation } = require("@opentelemetry/instrumentation-pino");

const {
  MySQL2Instrumentation,
} = require("@opentelemetry/instrumentation-mysql2");
const {
  FastifyInstrumentation,
} = require("@opentelemetry/instrumentation-fastify");

registerInstrumentations({
  instrumentations: [
      new FastifyInstrumentation(),
      new MySQL2Instrumentation(),
      new HttpInstrumentation(),
      new SocketIoInstrumentation(),
      new PinoInstrumentation(),
  ],
});

// load after instrumentation
const mysql = require("mysql2/promise");
const mysqlCommon = require("mysql2");

// Verify if the format function is missing and add it if necessary
if (!mysql.format) {
  mysql.format = mysqlCommon.format;
}

And I required it in my node command (TSX in my case):

tsx watch --require 'dotenv/config' --require './loader.cjs' --require '@opentelemetry/auto-instrumentations-node/register' src/main.ts

@luiz-rissardi we use Kysely in our project and this solution work fine for us

luiz-rissardi commented 1 month ago

Eu estava passando pelo problema, uma solução que eu encontrei foi analisar que tipo de mysql2 estou usando, se é o normal ou mysql2/promise, eu não consigo verificar completamente, mas eu assumo que esta instrumentação está no topo do mysql2/promise, tente usar mysql2/promiseprometo e seu problema será resolvido e openTelemetry fará o rastreamento de sua aplicação mysql2 na versão ^3.11.0 função Eu não consigo encontrar os outros

@luiz-rissardi

A solução não está funcionando com kysely. Você tem outra solução?

daria pra testar algumas outras alternativas viáveis sobre esse problema, mas acho que o @clifinger já conseguiu algo semelhante ao que você gostaria, e pra falar a verdade tenho que tirar um tempo extra pra tentar resolver esse "Bug" do open telemetry , thanks for all bros sksksk

clifinger commented 1 month ago

@smhmayboudi See my last answer, it work for us with Kysely ;)

constb commented 1 month ago

@pichlermarc I think I found some kind of reproduction for this bug. It's not entirely an error, but it does produce some similar looking warnings.

package.json:

{
  "name": "otel-mysql2",
  "version": "0.0.1",
  "main": "index.js",
  "type": "module",
  "scripts": {
    "start": "cross-env OTEL_PROPAGATORS=tracecontext OTEL_TRACES_EXPORTER=console OTEL_NODE_RESOURCE_DETECTORS=none node --import ./register.js ./index.js"
  },
  "author": "Konstantin Bryzgalin <constb@outlook.com>",
  "license": "UNLICENSED",
  "description": "",
  "dependencies": {
    "@opentelemetry/instrumentation": "0.53.0",
    "@opentelemetry/instrumentation-mysql2": "0.41.0",
    "@opentelemetry/sdk-node": "0.53.0",
    "cross-env": "7.0.3",
    "mysql2": "3.11.3"
  },
  "volta": {
    "node": "18.20.4"
  }
}

register.js:

import { register } from 'node:module';
import { MySQL2Instrumentation } from '@opentelemetry/instrumentation-mysql2';
import { node, NodeSDK } from '@opentelemetry/sdk-node';

const OPENTELEMETRY_SDK = Symbol('openTelemetrySdk');

register('@opentelemetry/instrumentation/hook.mjs', import.meta.url);

globalThis[OPENTELEMETRY_SDK] = new NodeSDK({
  serviceName: 'test',
  instrumentations: [new MySQL2Instrumentation({ enabled: true })],
});
globalThis[OPENTELEMETRY_SDK].start();

const shutdownFn = async () => globalThis[OPENTELEMETRY_SDK].shutdown().then(() => console.log('shutdown')).catch((error) => console.error(error));
let shutdownStarted = false;
const beforeExitHandler = () => {
  if (shutdownStarted) return;
  shutdownStarted = true;
  void shutdownFn().then(() => process.removeListener('beforeExit', beforeExitHandler));
};
process.on('beforeExit', beforeExitHandler);
const signals = ['SIGHUP', 'SIGINT', 'SIGQUIT', 'SIGILL', 'SIGTRAP', 'SIGABRT', 'SIGBUS', 'SIGFPE', 'SIGSEGV', 'SIGUSR2', 'SIGTERM'];
const signalHandler = (signal) => {
  if (shutdownStarted) return;
  shutdownStarted = true;
  shutdownFn().then(() => {
    signals.forEach((s) => process.removeListener(s, signalHandler));
    process.kill(process.pid, signal);
  });
};
signals.forEach((s) => process.on(s, signalHandler));

index.js:

import { format } from 'mysql2';

console.log(format('select ?', [1]));

produced output:

❯ NODE_OPTIONS=--trace-warnings npm run start

> otel-mysql2@0.0.1 start
> cross-env OTEL_PROPAGATORS=tracecontext OTEL_TRACES_EXPORTER=console OTEL_NODE_RESOURCE_DETECTORS=none node --import ./register.js ./index.js

function
select 1
(node:79032) Warning: Accessing non-existent property 'format' of module exports inside circular dependency
    at emitCircularRequireWarning (node:internal/modules/cjs/loader:883:11)
    at Object.get (node:internal/modules/cjs/loader:899:5)
    at instrumentation_1.InstrumentationNodeModuleDefinition.ConnectionPrototype [as patch] (/Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/@opentelemetry/instrumentation-mysql2/build/src/instrumentation.js:36:89)
    at MySQL2Instrumentation._onRequire (/Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:164:39)
    at onRequire (/Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:225:29)
    at /Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/@opentelemetry/instrumentation/build/src/platform/node/RequireInTheMiddleSingleton.js:67:27
    at Module.patchedRequire (/Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/require-in-the-middle/index.js:310:28)
    at Hook._require.Module.require (/Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/require-in-the-middle/index.js:142:27)
    at require (node:internal/modules/helpers:177:18)
    at Object.<anonymous> (/Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/mysql2/lib/pool.js:4:15)
(node:79032) Warning: Accessing non-existent property 'format' of module exports inside circular dependency
    at emitCircularRequireWarning (node:internal/modules/cjs/loader:883:11)
    at Object.get (node:internal/modules/cjs/loader:899:5)
    at instrumentation_1.InstrumentationNodeModuleDefinition.ConnectionPrototype [as patch] (/Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/@opentelemetry/instrumentation-mysql2/build/src/instrumentation.js:40:91)
    at MySQL2Instrumentation._onRequire (/Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:164:39)
    at onRequire (/Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:225:29)
    at /Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/@opentelemetry/instrumentation/build/src/platform/node/RequireInTheMiddleSingleton.js:67:27
    at Module.patchedRequire (/Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/require-in-the-middle/index.js:310:28)
    at Hook._require.Module.require (/Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/require-in-the-middle/index.js:142:27)
    at require (node:internal/modules/helpers:177:18)
    at Object.<anonymous> (/Users/constb/Code/1win/.tmp/otel-mysql2/node_modules/mysql2/lib/pool.js:4:15)
shutdown

As you can see the format function actually runs and works, but when the script finishes execution it produces a bunch of warnings similar to the ones in topmost message of the thread.

The FIX for the problem is even weirder!

Let's replace first line in register.js with import { createRequire, register } from 'node:module';.

And second, lets add right after SDK start() is called: createRequire(import.meta.url)('mysql2');

And the output is:

❯ NODE_OPTIONS=--trace-warnings npm run start

> otel-mysql2@0.0.1 start
> cross-env OTEL_PROPAGATORS=tracecontext OTEL_TRACES_EXPORTER=console OTEL_NODE_RESOURCE_DETECTORS=none node --import ./register.js ./index.js

select 1
shutdown

Somehow, requiring CommonJS-style a 'mysql2' package after the instrumentation is installed (but before it's ESM-way imported!), completely fixes the problem!

This is the second time I'm seeing that sort of error, actually. Take a look at https://github.com/open-telemetry/opentelemetry-js/issues/5024 and there seems to be a pattern.

tpraxl commented 3 weeks ago

I am currently attempting to merge fixes to mysql2. It will fix the missing format function error by reducing the amount of circular dependencies: https://github.com/sidorares/node-mysql2/pull/3081

I also studied the documentation of opentelemetry once more and found out that I should have started the instrumentation with the additional argument --experimental-loader=@opentelemetry/instrumentation/hook.mjs.

These two fixes allow us to have instrumentation for the callback based variant of mysql2 (promise variant worked before).

I provided a test repo showing all cases and instructions on how to test it with the (not yet merged) fixes to mysql2:

https://github.com/tpraxl/test-esm-mysql-otel