bug: mongodb instrumentation breaks for node v14

[david-luna]

What version of OpenTelemetry are you using?

"@opentelemetry/instrumentation-mongodb": "0.37.1",

What version of Node are you using?

v14.21

What did you do?

checkout the main branch and install then

cd plugins/node/opentelemetry-instrumentation-mongodb
nvm use v14.21.3
npm i mongodb@^5.0.0
RUN_MONGODB_TESTS=true npm run test-v5

What did you expect to see?

Tests ran correctly with the following output (attached from a run with node v18)

> @opentelemetry/instrumentation-mongodb@0.37.1 test-v5
> nyc ts-mocha -p tsconfig.json --require '@opentelemetry/contrib-test-utils' 'test/mongodb-v4-v5.metrics.test.ts' 'test/**/mongodb-v5.test.ts'



  MongoDBInstrumentation-Metrics
    ✓ Should add connection usage metrics (100ms)
    ✓ Should add disconnection usage metrics (212ms)

  MongoDBInstrumentation-Tracing-v5
    Instrumenting query operations
      ✓ should create a child span for insert
      ✓ should create a child span for update
      ✓ should create a child span for remove
    Instrumenting cursor operations
      ✓ should create a child span for find
      ✓ should create a child span for cursor operations
      ✓ should create child spans for concurrent cursor operations
    Instrumenting command operations
      ✓ should create a child span for create index
    when using enhanced database reporting without db statementSerializer
      ✓ should properly collect db statement (hide attribute values)
    when specifying a dbStatementSerializer configuration
      with a valid function
        ✓ should properly collect db statement
      with an invalid function
        ✓ should not do any harm when throwing an exception
    when specifying a responseHook configuration
      with a valid function
        ✓ should attach response hook data to the resulting span for insert function
        ✓ should attach response hook data to the resulting span for find function
      with an invalid function
        ✓ should not do any harm when throwing an exception
    Mixed operations with callback
      ✓ should create a span for find after callback insert
    Removing Instrumentation
      ✓ should unpatch plugin
      ✓ should not create a child span for query
      ✓ should not create a child span for cursor
      ✓ should not create a child span for command


  20 passing (464ms)

--------------------|---------|----------|---------|---------|-------------------------
File                | % Stmts | % Branch | % Funcs | % Lines | Uncovered Line #s
--------------------|---------|----------|---------|---------|-------------------------
All files           |   55.36 |    32.27 |    74.6 |   56.53 |
 instrumentation.ts |   53.42 |    31.01 |   73.77 |   54.61 | ...-700,734,767-788,896
 internal-types.ts  |     100 |      100 |     100 |     100 |
 types.ts           |     100 |      100 |     100 |     100 |
--------------------|---------|----------|---------|---------|-------------------------

What did you see instead?

Tests failing with this output and process didn't exit

> @opentelemetry/instrumentation-mongodb@0.37.1 test-v5 /Users/david/Documents/repos/otel/opentelemetry-js-contrib/plugins/node/opentelemetry-instrumentation-mongodb
> nyc ts-mocha -p tsconfig.json --require '@opentelemetry/contrib-test-utils' 'test/mongodb-v4-v5.metrics.test.ts' 'test/**/mongodb-v5.test.ts'



  MongoDBInstrumentation-Tracing-v5
    Instrumenting cursor operations
(node:41656) UnhandledPromiseRejectionWarning: TypeError: Converting circular structure to JSON
    --> starting at object with constructor 'Connection'
    |     property 'authContext' -> object with constructor 'AuthContext'
    --- property 'connection' closes the circle
    at JSON.stringify (<anonymous>)
    at /Users/david/Documents/repos/otel/opentelemetry-js-contrib/plugins/node/opentelemetry-instrumentation-mongodb/node_modules/mocha/lib/runnable.js:409:64
    at /Users/david/Documents/repos/otel/opentelemetry-js-contrib/plugins/node/opentelemetry-instrumentation-mongodb/test/mongodb-v5.test.ts:281:11
    at processTicksAndRejections (internal/process/task_queues.js:95:5)
(Use `node --trace-warnings ...` to show where the warning was created)
(node:41656) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
(node:41656) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
      1) should create child spans for concurrent cursor operations
      2) "after each" hook for "should create child spans for concurrent cursor operations"


  0 passing (2s)
  2 failing

  1) MongoDBInstrumentation-Tracing-v5
       Instrumenting cursor operations
         should create child spans for concurrent cursor operations:
     Error: Timeout of 2000ms exceeded. For async tests and hooks, ensure "done()" is called; if returning a Promise, ensure it resolves. (/Users/david/Documents/repos/otel/opentelemetry-js-contrib/plugins/node/opentelemetry-instrumentation-mongodb/test/mongodb-v5.test.ts)
      at listOnTimeout (internal/timers.js:557:17)
      at processTimers (internal/timers.js:500:7)

  2) MongoDBInstrumentation-Tracing-v5
       "after each" hook for "should create child spans for concurrent cursor operations":
     Error: the object {
  "_events": {
    "clusterTimeReceived": [Function]
    "commandFailed": [Function]
    "commandStarted": [Function]
    "commandSucceeded": [Function]
  }
  "_eventsCount": 4
  "_maxListeners": [undefined]
  "address": "127.0.0.1:27017"
  "authContext": {
    "connection": [Circular]
    "credentials": [undefined]
    "options": {
      "autoEncrypter": [undefined]
      "cancellationToken": {
        "_events": {}
        "_eventsCount": 0
        "_maxListeners": Infinity
      }
      "compressors": [
        "none"
      ]
      "connectTimeoutMS": 30000
      "connectionType": {
        "CLOSE": "close"
        "CLUSTER_TIME_RECEIVED": "clusterTimeReceived"
        "COMMAND_FAILED": "commandFailed"
        "COMMAND_STARTED": "commandStarted"
        "COMMAND_SUCCEEDED": "commandSucceeded"
        "MESSAGE": "message"
        "PINNED": "pinned"
        "UNPINNED": "unpinned"
      }
      "dbName": "opentelemetry-tests-traces"
      "directConnection": false
      "driverInfo": {}
      "enableUtf8Validation": true
      "forceServerObjectId": false
      "generation": 0
      "heartbeatFrequencyMS": 10000
      "hostAddress": {
        "host": "127.0.0.1"
        "isIPv6": false
        "port": 27017
        "socketPath": [undefined]
      }
      "hosts": [
        {
          "host": "127.0.0.1"
          "isIPv6": false
          "port": 27017
          "socketPath": [undefined]
        }
      ]
      "id": 5
      "keepAlive": true
      "keepAliveInitialDelay": 120000
      "loadBalanced": false
      "localThresholdMS": 15
      "maxConnecting": 2
      "maxIdleTimeMS": 0
      "maxPoolSize": 100
      "metadata": {
        "driver": {
          "name": "nodejs"
          "version": "5.9.1"
        }
        "os": {
          "architecture": "arm64"
          "name": "darwin"
          "type": "Darwin"
          "version": "22.6.0"
        }
        "platform": "Node.js v14.21.3, LE"
      }
      "minHeartbeatFrequencyMS": 500
      "minPoolSize": 0
      "minPoolSizeCheckFrequencyMS": 100
      "mongoLoggerOptions": {
        "componentSeverities": {
          "command": "off"
          "connection": "off"
          "default": "off"
          "serverSelection": "off"
          "topology": "off"
        }
        "logDestination": {
          "write": [Function]
        }
        "maxDocumentLength": 1000
      }
      "monitorCommands": false
      "noDelay": true
      "pkFactory": {
        "createPk": [Function]
      }
      "raw": false
      "readPreference": {
        "hedge": [undefined]
        "maxStalenessSeconds": [undefined]
        "minWireVersion": [undefined]
        "mode": "primary"
        "tags": [undefined]
      }
      "retryReads": true
      "retryWrites": true
      "serverSelectionTimeoutMS": 1000
      "socketTimeoutMS": 0
      "srvMaxHosts": 0
      "srvServiceName": "mongodb"
      "userSpecifiedAuthSource": false
      "userSpecifiedReplicaSet": false
      "waitQueueTimeoutMS": 0
      "zlibCompressionLevel": 0
    }
    "reauthenticating": false
  }
  "closed": false
  "commandAsync": [Function]
  "helloOk": true
  "id": 5
  "lastHelloMS": 2
  "monitorCommands": false
  "serverApi": [undefined]
  "socketTimeoutMS": 0
} was thrown, throw an Error :)
      at processTicksAndRejections (internal/process/task_queues.js:95:5)



^C----------|---------|----------|---------|---------|-------------------
File      | % Stmts | % Branch | % Funcs | % Lines | Uncovered Line #s
----------|---------|----------|---------|---------|-------------------
All files |       0 |        0 |       0 |       0 |
----------|---------|----------|---------|---------|-------------------

Additional context

There is a previous PR which introduced a patch to handle properly concurrent queries without loosing the context. The PR makes use of AsynResource.bind API which turns out it behaves differently from v17.8 and up. Previous versions mix the params in a way that mongodb callbacks receive the result as 1st param (which is expected to be an error param) and triggers a failure.

Other agents like DD and Elastic have used a polyfill to have same behaviour in AsynResource.bind

https://github.com/elastic/apm-agent-nodejs/pull/3692/files#diff-009816e1fad4583e0fb0de567eef5f23fd783b6c78aa56785459438c9db9cde8

[david-luna]

I was wondering why the TAV passed
https://github.com/open-telemetry/opentelemetry-js-contrib/actions/runs/6512867260/job/17691364774

I think it's because it doesn't set the env var RUN_MONGODB_TESTS so it skips all tests :(

[trentm]

Discussed in the SIG today and for now let's put the AsyncResource.bind polyfill in a file in the mongodb instrumentation package. It can have a comment that if any other instrumentation needs to use it, we could discuss moving the polyfill to the 'instrumentation' or a new 'instrumentation-helpers' package.

[Flarna]

why is AsyncResource.bind() used here instead ContextManager.bind() like in a lot other cases?
Besides the node version topic AsyncResource is a "global" thing (effects all users of async_hooks/AsyncLocalStore) not just the Otel instrumentation.

[david-luna]

Hi @Flarna

I've missed that option. Thanks for pointing it out :)

We could move then to contextManager.bind(). Is this also going to handle the different behaviour between node versions?

[Flarna]

Is this also going to handle the different behaviour between node versions?

It's not delegating to AsyncResource.bind() therefore the corresponding node.js change is not applicable.

[trentm]

The main argument for using AsyncResource.bind() is that it fixes the context issue in the same way as it would (hopefully) eventually be done in the mongodb client library itself, as part of this PR: mongodb/node-mongodb-native#3871
(That PR doesn't currently do an AsyncResource.bind() polyfill. With the latest mongodb major version having a min-support Node.js at version 16, I don't think the polyfill is required.)

The AsyncResource.bind() usage does fix the context loss for other async_hooks users, if any. However, granted that using ContextManager.bind() does keep the change limited to OTel, which might be more appropriate. I don't have a strong opinion on that.

[Flarna]

I think AsyncResource.bind() is the right thing to do for the actual library. But an instrumentation should avoid to create global side effects - even if the side effect looks "global correct" here. It might impact e.g. other APM tools monitoring the same process next to OTel. Instrumentation shouldn't do bug fixing.

Besides that instrumentations should be not bound to AsyncResource/AsyncHooks as there might be other context managers used in the final application.

But I agree that this is more a matter of taste. APM without AsyncResource/AsyncHooks/AsyncLocalStore is unrealistic as of now and the global side effect mentioned above is very unlikely problematic for anyone.

There might come the time where AsyncResource/AsyncLocalStore is superseded by AsyncContext. If instrumentations only use ContextManager it's just a new ContextManager which is needed. Otherwise more changes might be needed (incl. version checks spread across the codebase).