From 16087c9fc00fa8a4a9cc3e30ee1697bee998d4fc Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Wed, 8 Dec 2021 16:27:42 -0800 Subject: [PATCH 1/7] y u no TAV test mongodb? --- .ci/.jenkins_tav.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.ci/.jenkins_tav.yml b/.ci/.jenkins_tav.yml index 7f5c42cdbb6..a81ccfd9cb2 100644 --- a/.ci/.jenkins_tav.yml +++ b/.ci/.jenkins_tav.yml @@ -23,6 +23,7 @@ TAV: - koa-router - memcached - mimic-response + - mongodb - mongodb-core - mysql - mysql2 From d8cc666bcf4970c6b703cc5ac3ecad713cd05d08 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Thu, 9 Dec 2021 11:24:52 -0800 Subject: [PATCH 2/7] see if this fixes the only-in-Jenkins TAV failure -- running test "node test/instrumentation/modules/mongodb.test.js" with mongodb /app/node_modules/mongodb/lib/utils.js:698 throw error; ^ TypeError: Cannot read property 'db' of undefined at server.connect (/app/test/instrumentation/modules/mongodb.test.js:49:24) at /app/node_modules/mongodb/lib/utils.js:695:9 at err (/app/node_modules/mongodb/lib/mongo_client.js:285:23) at connectCallback (/app/node_modules/mongodb/lib/operations/connect.js:367:5) at topology.connect.err (/app/node_modules/mongodb/lib/operations/connect.js:554:14) ... --- .tav.yml | 12 ++++++++++-- test/instrumentation/modules/mongodb.test.js | 11 +++++------ 2 files changed, 15 insertions(+), 8 deletions(-) diff --git a/.tav.yml b/.tav.yml index 9d4070cad7d..63e66bcdfe5 100644 --- a/.tav.yml +++ b/.tav.yml @@ -92,9 +92,17 @@ pg-new-node: mongodb-core: versions: '>=1.2.19 <4' commands: node test/instrumentation/modules/mongodb-core.test.js -mongodb: - versions: '>=3.3' + +mongodb-3: + name: mongodb + versions: '>=3.3 <4' + commands: node test/instrumentation/modules/mongodb.test.js +mongodb-4: + name: mongodb + versions: '>=4 <5' + node: '>=12' commands: node test/instrumentation/modules/mongodb.test.js + bluebird: versions: '>=2 <4' commands: diff --git a/test/instrumentation/modules/mongodb.test.js b/test/instrumentation/modules/mongodb.test.js index d62a7a46125..d7a9436934a 100644 --- a/test/instrumentation/modules/mongodb.test.js +++ b/test/instrumentation/modules/mongodb.test.js @@ -34,19 +34,18 @@ test('instrument simple command', function (t) { t.end() }) - const server = new MongoClient(url, { + const client = new MongoClient(url, { useUnifiedTopology: true, useNewUrlParser: true }) agent.startTransaction('foo', 'bar') - // test example lifted from https://github.com/christkv/mongodb-core/blob/2.0/README.md#connecting-to-mongodb - server.connect((err, _server) => { + client.connect((err) => { t.error(err, 'no connect error') - t.ok(_server, 'got a valid server connection') + t.ok(client, 'got a valid client connection') - const db = _server.db('elasticapm') + const db = client.db('elasticapm') const collection = db.collection('test') collection.insertMany([{ a: 1 }, { a: 2 }, { a: 3 }], { w: 1 }, function (err, results) { @@ -57,7 +56,7 @@ test('instrument simple command', function (t) { // If records have been inserted, they should be cleaned up t.on('end', () => { collection.deleteMany({}, { w: 1 }, function () { - _server.close() + client.close() }) }) From fedefb3d96c01eb191e131050c884f30987c761d Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Thu, 9 Dec 2021 12:09:35 -0800 Subject: [PATCH 3/7] ensure mongodb server container is started when running 'mongodb' TAV tests --- .ci/scripts/test.sh | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.ci/scripts/test.sh b/.ci/scripts/test.sh index cd085188ea2..2d90947be87 100755 --- a/.ci/scripts/test.sh +++ b/.ci/scripts/test.sh @@ -195,7 +195,7 @@ elif [[ -n "${TAV_MODULE}" ]]; then tedious) DOCKER_COMPOSE_FILE=docker-compose-mssql.yml ;; - mongodb-core) + mongodb|mongodb-core) DOCKER_COMPOSE_FILE=docker-compose-mongodb.yml ;; pg|knex) From c7707f38917cec223672c036617517590e5fc29e Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Thu, 9 Dec 2021 16:04:38 -0800 Subject: [PATCH 4/7] a few 'mongodb' instrumentation fixes - ensure a mongodb span is not accidentally a child of an inflight mongodb span - Fix an issue where instrumentation of `new MongoClient(url)` would fail because the internal handling of `arguments` would add `arguments[1]` but arguments.length stayed at 1. Fix by first changing to an Array. - Fix instrument of a connection made using the MongoClient.connect static method. https://github.com/elastic/apm-agent-nodejs/issues/2467 --- examples/trace-mongodb.js | 80 ++++++++++ lib/instrumentation/modules/mongodb.js | 69 +++++++-- package.json | 2 +- test/instrumentation/modules/mongodb.test.js | 145 ++++++++++++++++++- 4 files changed, 280 insertions(+), 16 deletions(-) create mode 100755 examples/trace-mongodb.js diff --git a/examples/trace-mongodb.js b/examples/trace-mongodb.js new file mode 100755 index 00000000000..734ad08fd32 --- /dev/null +++ b/examples/trace-mongodb.js @@ -0,0 +1,80 @@ +// A small example showing Elastic APM tracing the 'mongodb' package. +// +// This assumes a MongoDB server running on localhost. You can use: +// npm run docker:start mongodb +// to start a MongoDB docker container. Then `npm run docker:stop` to stop it. + +const apm = require('../').start({ // elastic-apm-node + serviceName: 'example-trace-mongodb', + logUncaughtExceptions: true +}) + +const MongoClient = require('mongodb').MongoClient + +const DB_NAME = 'example-trace-mongodb' +const url = 'mongodb://localhost:27017' + +async function usingPromises () { + // For tracing spans to be created, there must be an active transaction. + // Typically, a transaction is automatically started for incoming HTTP + // requests to a Node.js server. However, because this script is not running + // an HTTP server, we manually start a transaction. More details at: + // https://www.elastic.co/guide/en/apm/agent/nodejs/current/custom-transactions.html + const t1 = apm.startTransaction('t1') + + const client = new MongoClient(url) + try { + await client.connect() + + const database = client.db(DB_NAME) + const coll = database.collection('breakfast') + + let res = await coll.insertMany([ + { item: 'spam', n: 0 }, + { item: 'ham', n: 1 }, + { item: 'eggs', n: 2 } + ]) + console.log('insertMany:', res) + + res = await coll.findOne({ item: 'eggs' }) + console.log('findOne eggs:', res) + + coll.findOne({ item: 'ham' }, function (err, res) { + console.log('findOne ham: err=%s res=%s', err && err.message, res) + }) + + await coll.deleteMany({}) + + res = await coll.findOne({ item: 'eggs' }) + console.log('findOne eggs:', res) + } finally { + await client.close() + t1.end() + } +} + +function usingCallbacks () { + const t2 = apm.startTransaction('t2-callback-style') + + MongoClient.connect(url, function (err, client) { + console.log('connect: err=%s', err && err.message) + if (err) { + throw err + } + + const db = client.db(DB_NAME) + const coll = db.collection('breakfast') + coll.insertMany([ + { item: 'spam', n: 0 }, + { item: 'ham', n: 1 }, + { item: 'eggs', n: 2 } + ], { w: 1 }, function (err, res) { + console.log('insertMany: err=%s res=%s', err && err.message, res) + t2.end() + client.close() + }) + }) +} + +usingPromises() + .finally(usingCallbacks) diff --git a/lib/instrumentation/modules/mongodb.js b/lib/instrumentation/modules/mongodb.js index 17f734d66d4..b3aa31187ab 100644 --- a/lib/instrumentation/modules/mongodb.js +++ b/lib/instrumentation/modules/mongodb.js @@ -1,7 +1,9 @@ 'use strict' const semver = require('semver') + const { getDBDestination } = require('../context') +const shimmer = require('../shimmer') // Match expected `:`, e.g. "mongo:27017", "::1:27017", // "127.0.0.1:27017". @@ -14,25 +16,30 @@ module.exports = (mongodb, agent, { version, enabled }) => { return mongodb } + const ins = agent._instrumentation + const activeSpans = new Map() if (mongodb.instrument) { const listener = mongodb.instrument() - listener.on('started', onStart) listener.on('succeeded', onEnd) listener.on('failed', onEnd) } else if (mongodb.MongoClient) { // mongodb 4.0+ removed the instrument() method in favor of - // listeners on the instantiated client objects. - class MongoClient extends mongodb.MongoClient { + // listeners on the instantiated client objects. There are two mechanisms + // to get a client: + // 1. const client = new mongodb.MongoClient(...) + // 2. const client = await MongoClient.connect(...) + class MongoClientTraced extends mongodb.MongoClient { constructor () { - // The `command*` events are only sent if `monitorCommands: true`. - if (!arguments[1]) { - arguments[1] = { monitorCommands: true } - } else if (arguments[1].monitorCommands !== true) { - arguments[1] = Object.assign({}, arguments[1], { monitorCommands: true }) + // The `command*` events are only emitted if `options.monitorCommands: true`. + const args = Array.prototype.slice.call(arguments) + if (!args[1]) { + args[1] = { monitorCommands: true } + } else if (args[1].monitorCommands !== true) { + args[1] = Object.assign({}, args[1], { monitorCommands: true }) } - super(...arguments) + super(...args) this.on('commandStarted', onStart) this.on('commandSucceeded', onEnd) this.on('commandFailed', onEnd) @@ -44,13 +51,53 @@ module.exports = (mongodb, agent, { version, enabled }) => { { enumerable: true, get: function () { - return MongoClient + return MongoClientTraced } } ) + shimmer.wrap(mongodb.MongoClient, 'connect', wrapConnect) + } else { + agent.logger.warn('could not instrument mongodb@%s', version) } return mongodb + // Wrap the MongoClient.connect(url, options?, callback?) static method. + // It calls back with `function (err, client)` or returns a Promise that + // resolves to the client. + // https://github.com/mongodb/node-mongodb-native/blob/v4.2.1/src/mongo_client.ts#L503-L511 + function wrapConnect (origConnect) { + return function wrappedConnect (url, options, callback) { + if (typeof options === 'function') { + callback = options + options = {} + } + options = options || {} + if (!options.monitorCommands) { + options.monitorCommands = true + } + if (typeof callback === 'function') { + return origConnect.call(this, url, options, function wrappedCallback (err, client) { + if (err) { + callback(err) + } else { + client.on('commandStarted', onStart) + client.on('commandSucceeded', onEnd) + client.on('commandFailed', onEnd) + callback(err, client) + } + }) + } else { + const p = origConnect.call(this, url, options, callback) + p.then(client => { + client.on('commandStarted', onStart) + client.on('commandSucceeded', onEnd) + client.on('commandFailed', onEnd) + }) + return p + } + } + } + function onStart (event) { // `event` is a `CommandStartedEvent` // https://github.com/mongodb/specifications/blob/master/source/command-monitoring/command-monitoring.rst#api @@ -70,7 +117,7 @@ module.exports = (mongodb, agent, { version, enabled }) => { event.commandName ].join('.') - const span = agent.startSpan(name, 'db', 'mongodb', 'query') + const span = ins.createSpan(name, 'db', 'mongodb', 'query') if (span) { activeSpans.set(event.requestId, span) diff --git a/package.json b/package.json index 266644b247b..a2ddcba129d 100644 --- a/package.json +++ b/package.json @@ -163,7 +163,7 @@ "mimic-response": "^2.1.0", "mkdirp": "^0.5.1", "module-details-from-path": "^1.0.3", - "mongodb": "^4.1.0", + "mongodb": "^4.2.1", "mongodb-core": "^3.2.7", "mysql": "^2.18.1", "mysql2": "^2.1.0", diff --git a/test/instrumentation/modules/mongodb.test.js b/test/instrumentation/modules/mongodb.test.js index d7a9436934a..6def54ae68f 100644 --- a/test/instrumentation/modules/mongodb.test.js +++ b/test/instrumentation/modules/mongodb.test.js @@ -18,13 +18,142 @@ if (semver.gte(mongodbVersion, '4.0.0') && semver.lt(process.version, '12.0.0')) const MongoClient = require('mongodb').MongoClient const test = require('tape') -const mockClient = require('../../_mock_http_client_states') +const mockClient = require('../../_mock_http_client') +const mockClientStates = require('../../_mock_http_client_states') const host = process.env.MONGODB_HOST || 'localhost' const url = `mongodb://${host}:27017` +test('new MongoClient(url); client.connect(callback)', function (t) { + resetAgent(2, function (data) { + t.equal(data.transactions[0].name, 't0', 'transaction.name') + t.equal(data.spans.length, 1) + t.equal(data.spans[0].name, 'elasticapm.test.find', 'span.name') + t.equal(data.spans[0].subtype, 'mongodb', 'span.subtype') + t.equal(data.spans[0].parent_id, data.transactions[0].id, 'span.parent_id') + t.end() + }) + // Explicitly test with no second argument to `new MongoClient(...)`, because + // that was broken at one point. + const client = new MongoClient(url) + agent.startTransaction('t0') + client.connect(err => { + t.error(err, 'no connect error') + client + .db('elasticapm') + .collection('test') + .findOne({ a: 1 }, function (err, res) { + t.error(err, 'no findOne error') + agent.endTransaction() + agent.flush() + client.close() + }) + }) +}) + +test('new MongoClient(url, {...}); client.connect(callback)', function (t) { + resetAgent(2, function (data) { + t.equal(data.transactions[0].name, 't0', 'transaction.name') + t.equal(data.spans.length, 1) + t.equal(data.spans[0].name, 'elasticapm.test.find', 'span.name') + t.equal(data.spans[0].subtype, 'mongodb', 'span.subtype') + t.equal(data.spans[0].parent_id, data.transactions[0].id, 'span.parent_id') + t.end() + }) + const client = new MongoClient(url, { + useUnifiedTopology: true, + useNewUrlParser: true + }) + agent.startTransaction('t0') + client.connect(err => { + t.error(err, 'no connect error') + client + .db('elasticapm') + .collection('test') + .findOne({ a: 1 }, function (err, res) { + t.error(err, 'no findOne error') + agent.endTransaction() + agent.flush() + client.close() + }) + }) +}) + +test('MongoClient.connect(url, callback)', function (t) { + resetAgent(2, function (data) { + t.equal(data.transactions[0].name, 't0', 'transaction.name') + t.equal(data.spans.length, 1) + t.equal(data.spans[0].name, 'elasticapm.test.find', 'span.name') + t.equal(data.spans[0].subtype, 'mongodb', 'span.subtype') + t.equal(data.spans[0].parent_id, data.transactions[0].id, 'span.parent_id') + t.end() + }) + agent.startTransaction('t0') + MongoClient.connect(url, function (err, client) { + t.error(err, 'no connect error') + t.ok(client, 'got a connected client') + client + .db('elasticapm') + .collection('test') + .findOne({ a: 1 }, function (err, res) { + t.error(err, 'no findOne error') + agent.endTransaction() + agent.flush() + client.close() + }) + }) +}) + +test('await MongoClient.connect(url)', async function (t) { + resetAgent(2, function (data) { + t.equal(data.transactions[0].name, 't0', 'transaction.name') + t.equal(data.spans.length, 1) + t.equal(data.spans[0].name, 'elasticapm.test.find', 'span.name') + t.equal(data.spans[0].subtype, 'mongodb', 'span.subtype') + t.equal(data.spans[0].parent_id, data.transactions[0].id, 'span.parent_id') + t.end() + }) + const client = await MongoClient.connect(url) + agent.startTransaction('t0') + await client.db('elasticapm').collection('test').findOne({ a: 1 }) + agent.endTransaction() + agent.flush() + client.close() +}) + +test('ensure run context', async function (t) { + resetAgent(5, function (data) { + t.equal(data.transactions[0].name, 't0', 'transaction.name') + t.equal(data.spans.length, 4) + data.spans.forEach(s => { + t.equal(s.parent_id, data.transactions[0].id, + `span ${s.type}.${s.subtype} "${s.name}" is a child of the transaction`) + }) + t.end() + }) + const client = await MongoClient.connect(url) + agent.startTransaction('t0') + const collection = client.db('elasticapm').collection('test') + + // There was a time when the spans created for Mongo client commands, while + // one command was already inflight, would be a child of the inflight span. + // That would be wrong. They should all be a direct child of the transaction. + collection.findOne({ a: 1 }, function (err, _res) { + t.error(err, 'no findOne error') + }) + agent.startSpan('manual').end() + collection.findOne({ b: 2 }, function (err, _res) { + t.error(err, 'no findOne error') + }) + await collection.findOne({ c: 3 }) + + agent.endTransaction() + agent.flush() + client.close() +}) + test('instrument simple command', function (t) { - resetAgent([ + resetAgentStates([ makeSpanTest(t, 'elasticapm.test.insert'), makeSpanTest(t, 'elasticapm.test.update'), makeSpanTest(t, 'elasticapm.test.delete'), @@ -35,6 +164,8 @@ test('instrument simple command', function (t) { }) const client = new MongoClient(url, { + // These two options are to avoid deprecation warnings from some versions + // of mongodb@3. useUnifiedTopology: true, useNewUrlParser: true }) @@ -147,8 +278,14 @@ function getDeletedCountFromResults (results) { return results.result ? results.result.n : results.deletedCount } -function resetAgent (expectations, cb) { +function resetAgentStates (expectations, cb) { + agent._instrumentation.testReset() + agent._transport = mockClientStates(expectations, cb) + agent.captureError = function (err) { throw err } +} + +function resetAgent (numExpected, cb) { agent._instrumentation.testReset() - agent._transport = mockClient(expectations, cb) + agent._transport = mockClient(numExpected, cb) agent.captureError = function (err) { throw err } } From ce7814d1e5d1d0edd41d6d77eedfbdd6b98d70a5 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Tue, 4 Jan 2022 13:16:52 -0800 Subject: [PATCH 5/7] fix '.end() already called' errors when running in (slow) Jenkins The issue was that `tape` will automatically `t.end()` an *async* test case tape.test('my test case', async function () { ... }) when the returned Promise resolves. This can happen before the `resetAgent` callback has been called. --- test/instrumentation/modules/mongodb.test.js | 52 +++++++++++++------- 1 file changed, 33 insertions(+), 19 deletions(-) diff --git a/test/instrumentation/modules/mongodb.test.js b/test/instrumentation/modules/mongodb.test.js index 6def54ae68f..f8e2c60c4dd 100644 --- a/test/instrumentation/modules/mongodb.test.js +++ b/test/instrumentation/modules/mongodb.test.js @@ -8,6 +8,8 @@ const agent = require('../../..').start({ cloudProvider: 'none' }) +const { promisify } = require('util') + // As of mongodb@4 only supports node >=v12. const mongodbVersion = require('../../../node_modules/mongodb/package.json').version const semver = require('semver') @@ -105,32 +107,34 @@ test('MongoClient.connect(url, callback)', function (t) { }) test('await MongoClient.connect(url)', async function (t) { - resetAgent(2, function (data) { + // When using an `async function ...`, tape will automatically t.end() when + // the function promise resolves. That means we cannot use the + // `resetAgent(..., callback)` technique because `callback` may be called + // *after* the test async function resolves. Instead we make a Promise for + // `agent.flush(cb)`, do all assertions when that is complete, and await that. + resetAgent(2, function noop () {}) + + const client = await MongoClient.connect(url) + agent.startTransaction('t0') + await client.db('elasticapm').collection('test').findOne({ a: 1 }) + agent.endTransaction() + + await promisify(agent.flush.bind(agent))().then(function (err) { + t.error(err, 'no error from agent.flush()') + const data = agent._transport._writes t.equal(data.transactions[0].name, 't0', 'transaction.name') t.equal(data.spans.length, 1) t.equal(data.spans[0].name, 'elasticapm.test.find', 'span.name') t.equal(data.spans[0].subtype, 'mongodb', 'span.subtype') t.equal(data.spans[0].parent_id, data.transactions[0].id, 'span.parent_id') - t.end() }) - const client = await MongoClient.connect(url) - agent.startTransaction('t0') - await client.db('elasticapm').collection('test').findOne({ a: 1 }) - agent.endTransaction() - agent.flush() - client.close() + await client.close() + t.end() }) test('ensure run context', async function (t) { - resetAgent(5, function (data) { - t.equal(data.transactions[0].name, 't0', 'transaction.name') - t.equal(data.spans.length, 4) - data.spans.forEach(s => { - t.equal(s.parent_id, data.transactions[0].id, - `span ${s.type}.${s.subtype} "${s.name}" is a child of the transaction`) - }) - t.end() - }) + resetAgent(5, function noop () {}) + const client = await MongoClient.connect(url) agent.startTransaction('t0') const collection = client.db('elasticapm').collection('test') @@ -148,8 +152,18 @@ test('ensure run context', async function (t) { await collection.findOne({ c: 3 }) agent.endTransaction() - agent.flush() - client.close() + await promisify(agent.flush.bind(agent))().then(function (err) { + t.error(err, 'no error from agent.flush()') + const data = agent._transport._writes + t.equal(data.transactions[0].name, 't0', 'transaction.name') + t.equal(data.spans.length, 4) + data.spans.forEach(s => { + t.equal(s.parent_id, data.transactions[0].id, + `span ${s.type}.${s.subtype} "${s.name}" is a child of the transaction`) + }) + }) + await client.close() + t.end() }) test('instrument simple command', function (t) { From 814d2c4afbfffe82a79ea4538b70da80de11c1b3 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Tue, 4 Jan 2022 15:16:16 -0800 Subject: [PATCH 6/7] Ensure that all mongo queries in this test case complete before flushing --- test/instrumentation/modules/mongodb.test.js | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/test/instrumentation/modules/mongodb.test.js b/test/instrumentation/modules/mongodb.test.js index f8e2c60c4dd..349f60b0698 100644 --- a/test/instrumentation/modules/mongodb.test.js +++ b/test/instrumentation/modules/mongodb.test.js @@ -142,14 +142,14 @@ test('ensure run context', async function (t) { // There was a time when the spans created for Mongo client commands, while // one command was already inflight, would be a child of the inflight span. // That would be wrong. They should all be a direct child of the transaction. - collection.findOne({ a: 1 }, function (err, _res) { + const promises = [] + promises.push(collection.findOne({ a: 1 }).catch(err => { t.error(err, 'no findOne error') - }) + })) agent.startSpan('manual').end() - collection.findOne({ b: 2 }, function (err, _res) { - t.error(err, 'no findOne error') - }) - await collection.findOne({ c: 3 }) + promises.push(collection.findOne({ b: 2 })) + promises.push(collection.findOne({ c: 3 })) + await Promise.all(promises) agent.endTransaction() await promisify(agent.flush.bind(agent))().then(function (err) { From d91c22a97f5ceb2bf465ac37f590480ad00d8390 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Thu, 6 Jan 2022 08:36:59 -0800 Subject: [PATCH 7/7] changelog entry --- CHANGELOG.asciidoc | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc index 818bfdf3f26..eb0a4f5acb3 100644 --- a/CHANGELOG.asciidoc +++ b/CHANGELOG.asciidoc @@ -52,6 +52,8 @@ Notes: * Fixes for run context handling for 'pg' instrumentation. ({issues}2430[#2430]) +* Fixes for run context handling for 'mongodb' instrumentation. ({issues}2512[#2512]) + [[release-notes-3.26.0]] ==== 3.26.0 2021/12/07