chore: add TAV tests for mongoose #3408

david-luna · 2023-06-07T13:19:15Z

Description

Adding a new test for mongoose package and update tav.yml file accordingly. With this new test were going to check the switch from mongodb-core to mongodb as dependency doesn't affect the instrumentation and also we will have checks on the versions we claim to support in the docs.

Refs: #3161

Checklist

david-luna · 2023-06-07T14:43:36Z

/test tav mongoose

david-luna · 2023-06-07T15:01:51Z

It seems TAV tests did not run after my command. Running it locally it errors with node v18 and mongoose v6.11.1. Logs attached

-- installing ["[email protected]"]
-- running test "node test/instrumentation/modules/mongoose.test.js" with mongoose
(node:44099) [MONGOOSE] DeprecationWarning: Mongoose: the `strictQuery` option will be switched back to `false` by default in Mongoose 7. Use `mongoose.set('strictQuery', false);` if you want to prepare for this change. Or use `mongoose.set('strictQuery', true);` to suppress this warning.
(Use `node --trace-deprecation ...` to show where the warning was created)
/Users/david/Documents/repos/el/apm-agent-nodejs/test/instrumentation/modules/mongoose.test.js:65
    t.equal(data.transactions[0].name, 't0', 'transaction.name')
                                 ^

TypeError: Cannot read properties of undefined (reading 'name')
    at /Users/david/Documents/repos/el/apm-agent-nodejs/test/instrumentation/modules/mongoose.test.js:65:34
    at Object._write (/Users/david/Documents/repos/el/apm-agent-nodejs/test/_mock_http_client.js:46:50)
    at Object.sendSpan (/Users/david/Documents/repos/el/apm-agent-nodejs/test/_mock_http_client.js:50:12)
    at /Users/david/Documents/repos/el/apm-agent-nodejs/lib/instrumentation/index.js:481:28
    at done (/Users/david/Documents/repos/el/apm-agent-nodejs/lib/instrumentation/span.js:486:5)
    at process.processTicksAndRejections (node:internal/process/task_queues:77:11)

Node.js v18.16.0
-- detected failing command, flushing stdout...
{"log.level":"info","@timestamp":"2023-06-07T14:58:28.710Z","log":{"logger":"elastic-apm-node"},"agentVersion":"3.46.0","env":{"pid":44099,"proctitle":"node","os":"darwin 22.5.0","arch":"arm64","host":"Davids-MBP.home","timezone":"UTC+0200","runtime":"Node.js v18.16.0"},"config":{"serviceName":{"source":"start","value":"test-mongoose","commonName":"service_name"},"serviceVersion":{"source":"default","value":"3.46.0","commonName":"service_version"},"serverUrl":{"source":"default","value":"http://127.0.0.1:8200/","commonName":"server_url"},"logLevel":{"source":"default","value":"info","commonName":"log_level"},"captureExceptions":{"source":"start","value":false},"metricsInterval":{"source":"start","value":0},"centralConfig":{"source":"start","value":false},"cloudProvider":{"source":"start","value":"none"},"spanCompressionEnabled":{"source":"start","value":false}},"activationMethod":"require","ecs":{"version":"1.6.0"},"message":"Elastic APM Node.js Agent v3.46.0"}
TAP version 13
# Mongoose simple test
{
  length: 5,
  spans: [
    {
      id: 'aad5c2c75e9724ba',
      transaction_id: '47ecfc0a87e486a1',
      parent_id: '47ecfc0a87e486a1',
      trace_id: 'f837ca3124e7028ebe3e5db769514b4a',
      name: 'elasticapm.tests.create',
      type: 'db',
      subtype: 'mongodb',
      action: 'create',
      timestamp: 1686149908941532,
      duration: 1,
      context: [Object],
      stacktrace: undefined,
      sync: true,
      outcome: 'success',
      sample_rate: 1
    },
    {
      id: '693fc795e32a51b3',
      transaction_id: '47ecfc0a87e486a1',
      parent_id: '47ecfc0a87e486a1',
      trace_id: 'f837ca3124e7028ebe3e5db769514b4a',
      name: 'elasticapm.tests.insert',
      type: 'db',
      subtype: 'mongodb',
      action: 'insert',
      timestamp: 1686149908942156,
      duration: 2,
      context: [Object],
      stacktrace: undefined,
      sync: true,
      outcome: 'success',
      sample_rate: 1
    },
    {
      id: '6e9fdb846c175d2f',
      transaction_id: '47ecfc0a87e486a1',
      parent_id: '47ecfc0a87e486a1',
      trace_id: 'f837ca3124e7028ebe3e5db769514b4a',
      name: 'elasticapm.tests.find',
      type: 'db',
      subtype: 'mongodb',
      action: 'find',
      timestamp: 1686149908946070,
      duration: 1,
      context: [Object],
      stacktrace: undefined,
      sync: false,
      outcome: 'success',
      sample_rate: 1
    },
    {
      id: '3d627a4699414f3b',
      transaction_id: '47ecfc0a87e486a1',
      parent_id: '47ecfc0a87e486a1',
      trace_id: 'f837ca3124e7028ebe3e5db769514b4a',
      name: 'elasticapm.tests.delete',
      type: 'db',
      subtype: 'mongodb',
      action: 'delete',
      timestamp: 1686149908948012,
      duration: 0,
      context: [Object],
      stacktrace: undefined,
      sync: false,
      outcome: 'success',
      sample_rate: 1
    },
    {
      id: '23ba0c8a6089f5c2',
      transaction_id: '47ecfc0a87e486a1',
      parent_id: '47ecfc0a87e486a1',
      trace_id: 'f837ca3124e7028ebe3e5db769514b4a',
      name: 'admin.$cmd.endSessions',
      type: 'db',
      subtype: 'mongodb',
      action: 'endSessions',
      timestamp: 1686149908949448,
      duration: 0,
      context: [Object],
      stacktrace: undefined,
      sync: true,
      outcome: 'success',
      sample_rate: 1
    }
  ],
  transactions: [],
  errors: [],
  metricsets: []
}

-- fatal: Test exited with code 1

trentm

This looks good, but you say that TAV tests are still failing? I assume you want to dig into those before merging, right?

.tav.yml

trentm · 2023-06-07T19:11:35Z

test/instrumentation/modules/mongoose.test.js

+
+test('Mongoose simple test', async function (t) {
+  resetAgent(5, function (data) {
+    console.log(data)


Debugging code to remove eventually?

test/instrumentation/modules/mongoose.test.js

trentm

/test tav mongoose

trentm · 2023-06-07T19:17:28Z

It seems TAV tests did not run after my command.

The difference with mine at #3408 (review) is the /test tav ... comment needs to be on a review comment, because it triggers on pull_request_review:

apm-agent-nodejs/.github/workflows/tav-command.yml

Line 4 in a3b9a60

pull_request_review:

(Also we'd had a case where tav-command did not run this past week because of permissions issues. However, it seems to be working this time, so I'm not sure what is/was going on with permissions. /cc @cachedout My tav-command attempt worked on this PR this time.)

trentm

/test tav mongoose

trentm · 2023-06-07T19:24:12Z

Running it locally it errors with node v18 and mongoose v6.11.1.

Likewise for node v16 and mongoose v6.11.1.

trentm · 2023-06-07T20:32:23Z

Looking at the latest TAV errors (from https://github.com/elastic/apm-agent-nodejs/actions/runs/5203925913?pr=3408), two suggestions:

Sometimes the issue is that you get an addition (5th) span, and because of the resetAgent(5, cb) usage, the cb() is called before the transaction event is actually sent. This is a common problem with resetAgent(NUM, cb) usage and I've tended to avoid it. The easiest option -- if it works with timing -- is to use resetAgent(cb) which just waits a few hundred ms and then returns all events. A better option -- but doesn't need to be done here -- is to use the pattern of some test files that use a MockApmServer, explicitly apm.flush() when done doing the mongoose client calls, then check the resulting events.
I noticed that at least one of the events was name: 'admin.$cmd.command',. The existing "mongodb-core.test.js" refers to spans like this. I don't know the conditions for getting these. That test just ignores those spans in its asserts. You could perhaps do the same.

…ub.com:elastic/apm-agent-nodejs into dluna/3161-mongoose-spans-in-wrong-transaction

david-luna · 2023-06-08T12:15:21Z

Sometimes the issue is that you get an addition (5th) span, and because of the resetAgent(5, cb) usage, the cb() is called before the transaction event is actually sent. This is a common problem with resetAgent(NUM, cb) usage and I've tended to avoid it. The easiest option -- if it works with timing -- is to use resetAgent(cb) which just waits a few hundred ms and then returns all events. A better option -- but doesn't need to be done here -- is to use the pattern of some test files that use a MockApmServer, explicitly apm.flush() when done doing the mongoose client calls, then check the resulting events.

This change is introduced in [email protected] and I was thinking to have separate tests but with this approach it will be simpler. Thanks!

I noticed that at least one of the events was name: 'admin.$cmd.command',. The existing "mongodb-core.test.js" refers to spans like this. I don't know the conditions for getting these. That test just ignores those spans in its asserts. You could perhaps do the same.

By looking at the shape of the command it seems an internal operation to close the session with the DB. Its always present but I prefer to do like the test in mongodb-core

CommandStartedEvent {
  address: '::1:27017',
  connectionId: 2,
  serviceId: undefined,
  requestId: 8,
  databaseName: 'admin',
  commandName: 'endSessions',
  command: { endSessions: [ [Object] ], '$db': 'admin' }
}

trentm · 2023-06-08T15:42:14Z

.ci/tav.json

@@ -23,6 +23,7 @@
    "memcached",
    "mongodb",
    "mongodb-core",
+    "mongoose",


THis puts us at 34 * 7 = 238 combinations, so still under the 256 GH actions jobs limit. All good.

package.json

trentm · 2023-06-08T15:45:27Z

test/instrumentation/modules/mongoose.test.js

+  await mongoose.disconnect()
+  trans.end()
+
+  await promisify(agent.flush.bind(agent))().then(function (err) {


Actually, I believe you can just await agent.flush().

you're right. removing promisify

trentm · 2023-06-08T15:47:17Z

test/instrumentation/modules/mongoose.test.js

+    t.ok(subtypeOk, 'spans subtype')
+
+    // TODO: there seems to be situations where create is sent after insert, seems to be internal to the pacakge
+    // narrowed the problem to v6. v5 and v7 have the spans in order always


I'm fine with having the test just assert that all the spans are there and not requiring the order to be as expected... with a comment here saying why.

I thought so since the order is internal to mongoose package but it's alway nice to have a second opinion :)

trentm · 2023-06-08T15:48:03Z

test/instrumentation/modules/mongoose.test.js

+      // we normalize it
+      t.equal(spans[2].name.replace('.remove', '.delete'), 'elasticapm.tests.delete', 'span.name')
+    } else {
+      t.equal(spans[0].name, 'elasticapm.tests.create', 'span.name')


Do we know the versions for which we expect the create span?

I did some checks and seems that v6.0.6 introduced that command

trentm · 2023-06-08T15:48:27Z

test/instrumentation/modules/mongoose.test.js

+    // TODO: there seems to be situations where create is sent after insert, seems to be internal to the pacakge
+    // narrowed the problem to v6. v5 and v7 have the spans in order always
+    console.log(data.spans)
+    if (spans.length < 5) {


Perhaps it would be clearer to explicitly mention and filter out the admin.* spans.

trentm · 2023-06-08T15:51:18Z

It looks like all the tests with contextManager=patch are failing. That is not too surprising. We can just skip tests in that case (https://github.com/elastic/apm-agent-nodejs/blob/main/test/instrumentation/modules/@aws-sdk/client-s3.test.js#L14-L17 is an example of doing this) and perhaps add a short mention in supported-technologies.asciidoc that mongoose isn't supported with the deprecated contextManager=patch setting.

trentm

/test tav mongoose

trentm · 2023-06-08T16:35:20Z

dev-utils/gen-notice.sh

Now that mongoose is in devDeps, I think the change in this file can be dropped as well.

david-luna · 2023-06-09T18:20:38Z

It looks like all the tests with contextManager=patch are failing. That is not too surprising. We can just skip tests in that case (https://github.com/elastic/apm-agent-nodejs/blob/main/test/instrumentation/modules/@aws-sdk/client-s3.test.js#L14-L17 is an example of doing this) and perhaps add a short mention in supported-technologies.asciidoc that mongoose isn't supported with the deprecated contextManager=patch setting.

Thanks for the example. Although were not instrumenting mongoose directly do you think it's possible show a warning in this situation?

david-luna · 2023-06-09T19:02:16Z

TAV tests reveal there is an error instrumenting mongoose on a certain combination of versions

mongoose <5.7.0
nodejs <=10

Here's the test output

> [email protected] test:tav /Users/david/Documents/repos/el/apm-agent-nodejs
> (cd test/opentelemetry-metrics/fixtures && tav --quiet) && (cd test/opentelemetry-bridge && tav --quiet) && (cd test/instrumentation/modules/next/a-nextjs-app && tav --quiet) && tav --quiet

-- ok
-- ok
-- ok
-- required packages ["[email protected]"]
-- installing ["[email protected]"]
-- running test "node test/instrumentation/modules/mongoose.test.js" with mongoose
-- required packages ["[email protected]"]
-- installing ["[email protected]"]
-- running test "node test/instrumentation/modules/mongoose.test.js" with mongoose
(node:82390) DeprecationWarning: current URL string parser is deprecated, and will be removed in a future version. To use the new parser, pass option { useNewUrlParser: true } to MongoClient.connect.
-- detected failing command, flushing stdout...
{"log.level":"info","@timestamp":"2023-06-09T18:30:17.582Z","log":{"logger":"elastic-apm-node"},"agentVersion":"3.46.0","env":{"pid":82390,"proctitle":"node","os":"darwin 22.5.0","arch":"x64","host":"Davids-MBP.home","timezone":"UTC+0200","runtime":"Node.js v10.24.1"},"config":{"serviceName":{"source":"start","value":"test-mongoose","commonName":"service_name"},"serviceVersion":{"source":"default","value":"3.46.0","commonName":"service_version"},"serverUrl":{"source":"default","value":"http://127.0.0.1:8200/","commonName":"server_url"},"logLevel":{"source":"default","value":"info","commonName":"log_level"},"captureExceptions":{"source":"start","value":false},"metricsInterval":{"source":"start","value":0},"centralConfig":{"source":"start","value":false},"cloudProvider":{"source":"start","value":"none"},"spanCompressionEnabled":{"source":"start","value":false}},"activationMethod":"require","ecs":{"version":"1.6.0"},"message":"Elastic APM Node.js Agent v3.46.0"}
TAP version 13
# Mongoose simple test
ok 1 no error from agent.flush()
ok 2 transaction.name
ok 3 spans parent_id
ok 4 spans subtype
ok 5 insert span present
ok 6 find span present
not ok 7 delete span present
  ---
    operator: ok
    expected: true
    actual:   false
    at: <anonymous> (/Users/david/Documents/repos/el/apm-agent-nodejs/test/instrumentation/modules/mongoose.test.js:97:7)
    stack: |-
      Error: delete span present
          at Test.assert [as _assert] (/Users/david/Documents/repos/el/apm-agent-nodejs/node_modules/tape/lib/test.js:312:48)
          at Test.bound [as _assert] (/Users/david/Documents/repos/el/apm-agent-nodejs/node_modules/tape/lib/test.js:95:17)
          at Test.assert (/Users/david/Documents/repos/el/apm-agent-nodejs/node_modules/tape/lib/test.js:431:7)
          at Test.bound [as ok] (/Users/david/Documents/repos/el/apm-agent-nodejs/node_modules/tape/lib/test.js:95:17)
          at /Users/david/Documents/repos/el/apm-agent-nodejs/test/instrumentation/modules/mongoose.test.js:97:7
          at process._tickCallback (internal/process/next_tick.js:68:7)
  ...

1..7
# tests 7
# pass  6
# fail  1

A bit of debugging reveals the remove query is intercepted by the agent but there is no parent transaction. Latest in mongoose@^5.6.0 is 5.6.13 released in 2019-09-06. We should consider to not give support to such old versions

trentm · 2023-06-09T19:13:26Z

A bit of debugging reveals the remove query is intercepted by the agent but there is no parent transaction. Latest in mongoose@^5.6.0

This does not explain #3161 then right? That user said they are using "mongoose": "^6.9.1"

We should consider to not give support to such old versions

I agree that we do not need to spend time debugging such an old version.

trentm · 2023-06-09T19:16:33Z

Although were not instrumenting mongoose directly do you think it's possible show a warning in this situation?

I think that would require either instrumenting mongoose (too much added code just for this warning) or putting the warning in the mongodb instrumentation (if that is appropriate).

trentm · 2023-06-09T19:18:16Z

test/instrumentation/modules/mongoose.test.js

+  await mongoose.disconnect()
+  trans.end()
+
+  await agent.flush.bind(agent)().then(function (err) {


This could be:

await agent.flush() // ... then dedent the following code that was in the `.then(...)` callback.

david-luna · 2023-09-22T14:51:26Z

@trentm these tests were made to catch the problem defined in #3161 and we already discovered is an issue in `mongodb. I'm inclined to close this PR. WDYT?

trentm · 2023-09-22T17:08:16Z

I'm inclined to close this PR. WDYT?

Fine with me.

It would be nice to have a separate commit that:

updates the supported mongoose versions in "supported-technologies.asciidoc", and
perhaps keep the examples/trace-mongoose.js that was written

david-luna · 2023-09-29T20:14:13Z

It would be nice to have a separate commit that:

updates the supported mongoose versions in "supported-technologies.asciidoc", and

perhaps keep the examples/trace-mongoose.js that was written

Commit in #3653

david-luna added 3 commits June 2, 2023 11:58

chore: add mongoose samples

72584ad

Merge branch 'main' into dluna/3161-mongoose-spans-in-wrong-transaction

5c82542

chore: add TAV tests for mongoose

a69ad83

github-actions bot added the agent-nodejs Make available for APM Agents project planning. label Jun 7, 2023

david-luna added 5 commits June 7, 2023 15:28

chore: update comments

8d53c5f

chore: update docs

1a20122

chore: removed test file

815e9aa

chore: fix lint

6108ce5

chore: add guards for incompatible versions of node

039fa70

david-luna marked this pull request as ready for review June 7, 2023 14:45

david-luna requested a review from trentm June 7, 2023 14:45

trentm reviewed Jun 7, 2023

View reviewed changes

need to start mongodb service for mongoose tests

fe66297

trentm reviewed Jun 7, 2023

View reviewed changes

david-luna added 2 commits June 8, 2023 13:49

chore: split tests

cc68cdf

Merge branch 'dluna/3161-mongoose-spans-in-wrong-transaction' of gith…

bbe1f49

…ub.com:elastic/apm-agent-nodejs into dluna/3161-mongoose-spans-in-wrong-transaction

chore: simplify test

b0f1f33

trentm requested changes Jun 8, 2023

View reviewed changes

trentm reviewed Jun 8, 2023

View reviewed changes

david-luna added 2 commits June 8, 2023 18:11

chore: remove mongoose from dependencies

a13283c

chore: add mongoose as devDependency

31f645c

trentm reviewed Jun 8, 2023

View reviewed changes

dev-utils/gen-notice.sh Outdated

Copy link

Member

trentm Jun 8, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Now that mongoose is in devDeps, I think the change in this file can be dropped as well.

david-luna added 4 commits June 8, 2023 20:04

chore: simplify test

91cc1b7

chore: simplify test

10d397b

chore: removed deps

df9e7f5

chore: do not test with context manager = patch

899c7d0

trentm reviewed Jun 9, 2023

View reviewed changes

Merge branch 'main' into dluna/3161-mongoose-spans-in-wrong-transaction

f393366

david-luna mentioned this pull request Sep 29, 2023

docs: update supported technologies and add an example for mongoose #3653

Merged

6 tasks

david-luna closed this Sep 29, 2023

david-luna deleted the dluna/3161-mongoose-spans-in-wrong-transaction branch September 29, 2023 20:14

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

chore: add TAV tests for mongoose #3408

chore: add TAV tests for mongoose #3408

david-luna commented Jun 7, 2023 •

edited by trentm

Loading

david-luna commented Jun 7, 2023

david-luna commented Jun 7, 2023

trentm left a comment

trentm Jun 7, 2023

david-luna Jun 8, 2023

trentm left a comment

trentm commented Jun 7, 2023

trentm left a comment

trentm commented Jun 7, 2023

trentm commented Jun 7, 2023

david-luna commented Jun 8, 2023

trentm Jun 8, 2023

trentm Jun 8, 2023

david-luna Jun 9, 2023

trentm Jun 8, 2023

david-luna Jun 8, 2023

trentm Jun 8, 2023

david-luna Jun 8, 2023

trentm Jun 8, 2023

trentm commented Jun 8, 2023

trentm left a comment

trentm Jun 8, 2023

david-luna commented Jun 9, 2023

david-luna commented Jun 9, 2023

trentm commented Jun 9, 2023

trentm commented Jun 9, 2023

trentm Jun 9, 2023

david-luna commented Sep 22, 2023

trentm commented Sep 22, 2023

david-luna commented Sep 29, 2023

chore: add TAV tests for mongoose #3408

chore: add TAV tests for mongoose #3408

Conversation

david-luna commented Jun 7, 2023 • edited by trentm Loading

Description

Checklist

david-luna commented Jun 7, 2023

david-luna commented Jun 7, 2023

trentm left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

trentm left a comment

Choose a reason for hiding this comment

trentm commented Jun 7, 2023

trentm left a comment

Choose a reason for hiding this comment

trentm commented Jun 7, 2023

trentm commented Jun 7, 2023

david-luna commented Jun 8, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

trentm commented Jun 8, 2023

trentm left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

david-luna commented Jun 9, 2023

david-luna commented Jun 9, 2023

trentm commented Jun 9, 2023

trentm commented Jun 9, 2023

Choose a reason for hiding this comment

david-luna commented Sep 22, 2023

trentm commented Sep 22, 2023

david-luna commented Sep 29, 2023

david-luna commented Jun 7, 2023 •

edited by trentm

Loading