diff --git a/.tav.yml b/.tav.yml index 2554fe6a097..e80e83f327b 100644 --- a/.tav.yml +++ b/.tav.yml @@ -144,22 +144,22 @@ mongodb-core: mongodb-3: name: mongodb versions: '>=3.3 <4' - commands: node test/instrumentation/modules/mongodb.test.js + commands: node test/instrumentation/modules/mongodb/mongodb.test.js mongodb-4: name: mongodb versions: '>=4 <5' node: '>=12.9.0' - commands: node test/instrumentation/modules/mongodb.test.js + commands: node test/instrumentation/modules/mongodb/mongodb.test.js mongodb-5: name: mongodb versions: '>=5 <6' node: '>=14.20.1' - commands: node test/instrumentation/modules/mongodb.test.js + commands: node test/instrumentation/modules/mongodb/mongodb.test.js mongodb: name: mongodb versions: '>=6 <7' node: '>=15.0.0' - commands: node test/instrumentation/modules/mongodb.test.js + commands: node test/instrumentation/modules/mongodb/mongodb.test.js # Bluebird is effectively deprecated (https://github.com/petkaantonov/bluebird#%EF%B8%8Fnote%EF%B8%8F). # Testing the full set of supported bluebird releases (`>=2 <4`) is currently diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc index 2a6d5f15730..f1159ecfd04 100644 --- a/CHANGELOG.asciidoc +++ b/CHANGELOG.asciidoc @@ -56,6 +56,10 @@ See the <> guide. [float] ===== Bug fixes +* Fix `mongodb` instrumentation to avoid loosing context when multiple cursors + are running concurrently. ({issues}3161[#3161]) + + [float] ===== Chores diff --git a/lib/instrumentation/index.js b/lib/instrumentation/index.js index 518668efb38..85151e1f8e8 100644 --- a/lib/instrumentation/index.js +++ b/lib/instrumentation/index.js @@ -92,6 +92,10 @@ var MODULE_PATCHERS = [ { modPath: 'mimic-response' }, { modPath: 'mongodb-core' }, { modPath: 'mongodb' }, + { + modPath: 'mongodb/lib/cmap/connection_pool.js', + patcher: './modules/mongodb/lib/cmap/connection_pool.js', + }, { modPath: 'mysql' }, { modPath: 'mysql2' }, { modPath: 'next' }, diff --git a/lib/instrumentation/modules/mongodb/lib/cmap/connection_pool.js b/lib/instrumentation/modules/mongodb/lib/cmap/connection_pool.js new file mode 100644 index 00000000000..d4e6d8ccfc6 --- /dev/null +++ b/lib/instrumentation/modules/mongodb/lib/cmap/connection_pool.js @@ -0,0 +1,39 @@ +/* + * Copyright Elasticsearch B.V. and other contributors where applicable. + * Licensed under the BSD 2-Clause License; you may not use this file except in + * compliance with the BSD 2-Clause License. + */ + +'use strict'; + +const { AsyncResource } = require('async_hooks'); + +const semver = require('semver'); + +module.exports = (mod, agent, { version, enabled }) => { + if (!enabled) return mod; + if (!semver.satisfies(version, '>=3.3 <7.0')) { + agent.logger.debug( + 'mongodb version %s not instrumented (mongodb <3.3 is instrumented via mongodb-core)', + version, + ); + return mod; + } + + if (mod.ConnectionPool) { + class ConnectionPoolTraced extends mod.ConnectionPool { + checkOut(callback) { + return super.checkOut(AsyncResource.bind(callback)); + } + } + + Object.defineProperty(mod, 'ConnectionPool', { + enumerable: true, + get: function () { + return ConnectionPoolTraced; + }, + }); + + return mod; + } +}; diff --git a/test/_is_mongodb_incompat.js b/test/_is_mongodb_incompat.js index 4a9f1ab9642..6f547b9f74f 100644 --- a/test/_is_mongodb_incompat.js +++ b/test/_is_mongodb_incompat.js @@ -7,6 +7,7 @@ 'use strict'; var semver = require('semver'); +const { safeGetPackageVersion } = require('./_utils'); /** * Return whether the current 'mongodb' version is incompatible with the @@ -26,7 +27,7 @@ var semver = require('semver'); */ function isMongodbIncompat() { const nodeVer = process.version; - const mongodbVer = require('mongodb/package.json').version; + const mongodbVer = safeGetPackageVersion('mongodb'); const msg = `mongodb@${mongodbVer} is incompatible with node@${nodeVer}`; if (semver.satisfies(mongodbVer, '4.x')) { diff --git a/test/instrumentation/modules/mongodb.test.js b/test/instrumentation/modules/mongodb.test.js deleted file mode 100644 index 4d130db4541..00000000000 --- a/test/instrumentation/modules/mongodb.test.js +++ /dev/null @@ -1,371 +0,0 @@ -/* - * Copyright Elasticsearch B.V. and other contributors where applicable. - * Licensed under the BSD 2-Clause License; you may not use this file except in - * compliance with the BSD 2-Clause License. - */ - -'use strict'; - -if (process.env.GITHUB_ACTIONS === 'true' && process.platform === 'win32') { - console.log('# SKIP: GH Actions do not support docker services on Windows'); - process.exit(0); -} - -const agent = require('../../..').start({ - serviceName: 'test-mongodb', - captureExceptions: false, - metricsInterval: 0, - centralConfig: false, - cloudProvider: 'none', - spanCompressionEnabled: false, -}); - -const isMongodbIncompat = require('../../_is_mongodb_incompat')(); -if (isMongodbIncompat) { - console.log(`# SKIP ${isMongodbIncompat}`); - process.exit(); -} - -const { promisify } = require('util'); - -const MongoClient = require('mongodb').MongoClient; -const semver = require('semver'); -const test = require('tape'); - -const mockClient = require('../../_mock_http_client'); -const mockClientStates = require('../../_mock_http_client_states'); - -const mongodbSupportsCallbacks = semver.satisfies( - require('mongodb/package.json').version, - '<5', -); -const host = process.env.MONGODB_HOST || 'localhost'; -const url = `mongodb://${host}:27017`; - -test( - 'new MongoClient(url); client.connect(callback)', - { skip: !mongodbSupportsCallbacks }, - 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)', - { skip: !mongodbSupportsCallbacks }, - 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)', - { skip: !mongodbSupportsCallbacks }, - 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) { - // 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._apmClient._writes; - const trans = data.transactions[0]; - t.equal(trans.name, 't0', 'transaction.name'); - t.equal( - trans.span_count.started, - 1, - 'transaction.span_count.started (no duplicate started spans)', - ); - 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'); - }); - await client.close(); - t.end(); -}); - -test('ensure run context', async function (t) { - resetAgent(5, function noop() {}); - - 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. - const promises = []; - promises.push( - collection.findOne({ a: 1 }).catch((err) => { - t.error(err, 'no findOne error'); - }), - ); - agent.startSpan('manual').end(); - 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) { - t.error(err, 'no error from agent.flush()'); - const data = agent._apmClient._writes; - const trans = data.transactions[0]; - t.equal(trans.name, 't0', 'transaction.name'); - t.equal( - trans.span_count.started, - 4, - 'transaction.span_count.started (no duplicate started spans)', - ); - 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', async function (t) { - resetAgentStates( - [ - makeSpanTest(t, 'elasticapm.test.insert', 'insert'), - makeSpanTest(t, 'elasticapm.test.update', 'update'), - makeSpanTest(t, 'elasticapm.test.delete', 'delete'), - makeSpanTest(t, 'elasticapm.test.find', 'find'), - makeTransactionTest(t), - ], - function () { - t.end(); - }, - ); - - const client = await new MongoClient(url, { - // These two options are to avoid deprecation warnings from some versions - // of mongodb@3. - useUnifiedTopology: true, - useNewUrlParser: true, - }).connect(); - - agent.startTransaction('foo', 'bar'); - - const db = client.db('elasticapm'); - const collection = db.collection('test'); - let results; - let count; - - results = await collection.insertMany([{ a: 1 }, { a: 2 }, { a: 3 }], { - w: 1, - }); - count = getInsertedCountFromResults(results); - t.strictEqual(count, 3, 'inserted three records'); - - // If records have been inserted, they should be cleaned up - t.on('end', async () => { - await collection.deleteMany({}, { w: 1 }); - client.close(); - }); - - results = await collection.updateOne({ a: 1 }, { $set: { b: 1 } }, { w: 1 }); - count = getMatchedCountFromResults(results); - t.strictEqual(count, 1, 'updated one record'); - - results = await collection.deleteOne({ a: 1 }, { w: 1 }); - count = getDeletedCountFromResults(results); - t.strictEqual(count, 1, 'deleted one record'); - - const cursor = collection.find({}); - let doc = await cursor.next(); - t.strictEqual(doc.a, 2, 'found record #2'); - - doc = await cursor.next(); - t.strictEqual(doc.a, 3, 'found record #3'); - - agent.endTransaction(); - agent.flush(); -}); - -function makeTransactionTest(t) { - return { - find(type) { - return type === 'transaction'; - }, - test(trans) { - t.strictEqual(trans.name, 'foo', 'transaction name is "foo"'); - t.strictEqual(trans.type, 'bar', 'transaction type is "bar"'); - t.strictEqual(trans.result, 'success', 'transaction result is "success"'); - }, - }; -} - -function makeSpanTest(t, name, action) { - return { - find(type, span) { - return type === 'span' && span.name === name; - }, - test(span) { - t.ok(span, 'found valid span'); - t.strictEqual(span.name, name, 'span.name'); - t.strictEqual(span.type, 'db', 'span.type'); - t.strictEqual(span.subtype, 'mongodb', 'span.subtype'); - t.strictEqual(span.action, action, 'span.action'); - - t.deepEqual( - span.context.db, - { type: 'mongodb', instance: 'elasticapm' }, - 'span.context.db', - ); - t.deepEqual( - span.context.service.target, - { type: 'mongodb', name: 'elasticapm' }, - 'span.context.service.target', - ); - - // We can't easily assert destination.address because mongodb >3.5.0 - // returns a resolved IP for the given connection hostname. In our CI - // setup, the host is set to "mongodb" which is a Docker container with - // some IP. We could `dns.resolve4()` here, but that's overkill I think. - t.ok( - span.context.destination.address, - 'context.destination.address is defined', - ); - t.deepEqual( - span.context.destination, - { - address: span.context.destination.address, - port: 27017, - service: { type: '', name: '', resource: 'mongodb/elasticapm' }, - }, - 'span.context.destination', - ); - }, - }; -} - -// MongoDB changed the structure of their results objects -// between version 3 and version 4 -function getInsertedCountFromResults(results) { - return results.result ? results.result.n : results.insertedCount; -} - -function getMatchedCountFromResults(results) { - return results.result ? results.result.n : results.matchedCount; -} - -function getDeletedCountFromResults(results) { - return results.result ? results.result.n : results.deletedCount; -} - -function resetAgentStates(expectations, cb) { - agent._instrumentation.testReset(); - agent._apmClient = mockClientStates(expectations, cb); - agent.captureError = function (err) { - throw err; - }; -} - -function resetAgent(numExpected, cb) { - agent._instrumentation.testReset(); - agent._apmClient = mockClient(numExpected, cb); - agent.captureError = function (err) { - throw err; - }; -} diff --git a/test/instrumentation/modules/mongodb/fixtures/use-mongodb-async-context.js b/test/instrumentation/modules/mongodb/fixtures/use-mongodb-async-context.js new file mode 100644 index 00000000000..1e8664623ea --- /dev/null +++ b/test/instrumentation/modules/mongodb/fixtures/use-mongodb-async-context.js @@ -0,0 +1,89 @@ +/* + * Copyright Elasticsearch B.V. and other contributors where applicable. + * Licensed under the BSD 2-Clause License; you may not use this file except in + * compliance with the BSD 2-Clause License. + */ + +'use strict'; + +const apm = require('../../../../..').start({ + serviceName: 'use-mongodb-async-context', + captureExceptions: false, + centralConfig: false, + metricsInterval: 0, + cloudProvider: 'none', + stackTraceLimit: 4, // get it smaller for reviewing output + logLevel: 'info', + spanCompressionEnabled: false, +}); +const http = require('http'); +const MongoClient = require('mongodb').MongoClient; + +// ---- support functions +/** + * + * @param {import('mongodb').MongoClient} mongodbClient + * @param {{ port: number }} options + */ +async function useMongodbAsyncContext(options) { + const { port } = options; + const serverUrl = `http://localhost:${port}`; + + const reqs = new Array(50).fill(serverUrl).map((url) => { + return new Promise((resolve, reject) => { + http.request(url).on('response', resolve).on('error', reject).end(); + }); + }); + + // Wait for all request to finish and make sure APM Server + // receives all spans + await Promise.all(reqs); + await apm.flush(); +} + +// ---- mainline + +async function main() { + const host = process.env.TEST_HOST || '127.0.0.1'; + const port = process.env.TEST_PORT || '27017'; + const db = process.env.TEST_DB || 'elasticapm'; + const col = process.env.TEST_COLLECTION || 'test'; + const url = `mongodb://${host}:${port}`; + + const mongodbClient = await MongoClient.connect(url); + const server = http.createServer(function (req, res) { + req.resume(); + req.on('end', function () { + mongodbClient + .db(db) + .collection(col) + .find() + .toArray() + .then(JSON.stringify) + .then(function (body) { + res.writeHead(200, { + server: 'trace-mongodb-cats-server', + 'content-type': 'text/plain', + 'content-length': Buffer.byteLength(body), + }); + res.end(body); + }); + }); + }); + server.listen(); + + useMongodbAsyncContext(server.address()).then( + function () { + server.close(); + mongodbClient.close(); + }, + function (err) { + apm.logger.error(err, 'useMongodbAsyncContext rejected'); + server.close(); + mongodbClient.close(); + process.exitCode = 1; + }, + ); +} + +main(); diff --git a/test/instrumentation/modules/mongodb/fixtures/use-mongodb-connect.js b/test/instrumentation/modules/mongodb/fixtures/use-mongodb-connect.js new file mode 100644 index 00000000000..2ca772e5cee --- /dev/null +++ b/test/instrumentation/modules/mongodb/fixtures/use-mongodb-connect.js @@ -0,0 +1,144 @@ +/* + * Copyright Elasticsearch B.V. and other contributors where applicable. + * Licensed under the BSD 2-Clause License; you may not use this file except in + * compliance with the BSD 2-Clause License. + */ + +'use strict'; + +const apm = require('../../../../..').start({ + serviceName: 'use-mongodb-connect', + captureExceptions: false, + centralConfig: false, + metricsInterval: 0, + cloudProvider: 'none', + stackTraceLimit: 4, // get it smaller for reviewing output + logLevel: 'info', + spanCompressionEnabled: false, +}); + +const MongoClient = require('mongodb').MongoClient; + +// ---- support functions +/** + * + * @param {import('mongodb').MongoClient} mongodbClient + * @param {Record} options + */ +async function useMongodbConnect(options) { + const { url, db, col, useCallbacks } = options; + const log = apm.logger.child({ + 'event.module': 'app', + url, + database: db, + collection: col, + useCallbacks, + }); + + /** @type {import('mongodb').MongoClient} */ + let client; + + // Test connections using callbacks + if (useCallbacks) { + // 'new MongoClient(url); client.connect(callback)', + client = new MongoClient(url); + await new Promise((resolve, reject) => { + client.connect(function (err) { + log.info({ err }, 'new MongoClient(url); client.connect(callback)'); + if (err) { + reject(err); + } else { + client + .db(db) + .collection(col) + .findOne({ a: 1 }, function (err) { + log.info({ err }, 'findOne'); + err ? reject(err) : resolve(); + }); + } + }); + }); + await client.close(); + log.info({}, 'closed'); + + // 'new MongoClient(url, {...}); client.connect(callback)', + client = new MongoClient(url, { + useUnifiedTopology: true, + useNewUrlParser: true, + }); + await new Promise((resolve, reject) => { + client.connect(function (err) { + log.info( + { err }, + 'new MongoClient(url, {...}); client.connect(callback)', + ); + if (err) { + reject(err); + } else { + client + .db(db) + .collection(col) + .findOne({ a: 1 }, function (err) { + log.info({ err }, 'findOne'); + err ? reject(err) : resolve(); + }); + } + }); + }); + await client.close(); + log.info({}, 'closed'); + + // 'MongoClient.connect(url, callback)', + await new Promise((resolve, reject) => { + MongoClient.connect(url, function (err, res) { + client = res; + log.info({ err }, 'MongoClient.connect(url, callback)'); + if (err) { + reject(err); + } else { + client + .db(db) + .collection(col) + .findOne({ a: 1 }, function (err) { + log.info({ err }, 'findOne'); + err ? reject(err) : resolve(); + }); + } + }); + }); + await client.close(); + log.info({}, 'closed'); + } + + // 'await MongoClient.connect(url)' + client = await MongoClient.connect(url); + await client.db(db).collection(col).findOne({ a: 1 }); + await client.close(); +} + +// ---- mainline + +async function main() { + const host = process.env.TEST_HOST || '127.0.0.1'; + const port = process.env.TEST_PORT || '27017'; + const db = process.env.TEST_DB || 'elasticapm'; + const col = process.env.TEST_COLLECTION || 'test'; + const url = `mongodb://${host}:${port}`; + const useCallbacks = process.env.TEST_USE_CALLBACKS === 'true'; + + const tx = apm.startTransaction('manual'); + useMongodbConnect({ url, db, col, useCallbacks }).then( + function () { + tx.end(); + process.exitCode = 0; + }, + function (err) { + apm.logger.error(err, 'useMongodbConnect rejected'); + tx.setOutcome('failure'); + tx.end(); + process.exitCode = 1; + }, + ); +} + +main(); diff --git a/test/instrumentation/modules/mongodb/fixtures/use-mongodb.js b/test/instrumentation/modules/mongodb/fixtures/use-mongodb.js new file mode 100644 index 00000000000..4ef19b1c7f2 --- /dev/null +++ b/test/instrumentation/modules/mongodb/fixtures/use-mongodb.js @@ -0,0 +1,243 @@ +/* + * Copyright Elasticsearch B.V. and other contributors where applicable. + * Licensed under the BSD 2-Clause License; you may not use this file except in + * compliance with the BSD 2-Clause License. + */ + +'use strict'; + +const apm = require('../../../../..').start({ + serviceName: 'use-mongodb', + captureExceptions: false, + centralConfig: false, + metricsInterval: 0, + cloudProvider: 'none', + stackTraceLimit: 4, // get it smaller for reviewing output + logLevel: 'info', + spanCompressionEnabled: false, +}); +const assert = require('assert'); + +const MongoClient = require('mongodb').MongoClient; + +// ---- support functions +/** + * + * @param {import('mongodb').MongoClient} mongodbClient + * @param {Record} options + */ +async function useMongodb(mongodbClient, options) { + const { url, db, col, useCallbacks } = options; + const log = apm.logger.child({ + 'event.module': 'app', + url, + database: db, + collection: col, + useCallbacks, + }); + + // All versions return a promise for `connect` method and + // different types of connection are tested in a separate file + await mongodbClient.connect(); + assert( + apm.currentSpan === null, + 'Mongodb span (or its HTTP span) should not be currentSpan after awaiting the task', + ); + log.info({}, 'connect'); + + const database = mongodbClient.db(db); + const collection = database.collection(col); + let data; + + // https://mongodb.github.io/node-mongodb-native/4.7/classes/Collection.html#insertMany + data = await collection.insertMany([{ a: 1 }, { a: 2 }, { a: 3 }], { + w: 1, + }); + assert( + apm.currentSpan === null, + 'Mongodb span (or its HTTP span) should not be currentSpan after awaiting the task', + ); + log.info({ data }, 'insertMany with promise'); + + if (useCallbacks) { + data = await new Promise((resolve, reject) => { + collection.insertMany( + [{ a: 4 }, { a: 5 }, { a: 6 }], + { w: 1 }, + function (err, res) { + if (err) { + reject(err); + } else { + resolve(res); + } + }, + ); + }); + assert( + apm.currentSpan === null, + 'Mongodb span (or its HTTP span) should not be currentSpan after awaiting the task', + ); + log.info({ data }, 'insertMany with callback'); + } + + // https://mongodb.github.io/node-mongodb-native/4.7/classes/Collection.html#findOne + data = await collection.findOne({ a: 1 }); + assert( + apm.currentSpan === null, + 'Mongodb span (or its HTTP span) should not be currentSpan after awaiting the task', + ); + log.info({ data }, 'findOne with promises'); + + // 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. + const queries = [{ a: 1 }, { b: 2 }, { c: 3 }]; + await Promise.all(queries.map((q) => collection.findOne(q))); + + if (useCallbacks) { + data = await new Promise((resolve, reject) => { + collection.findOne({ a: 4 }, function (err, res) { + if (err) { + reject(err); + } else { + resolve(res); + } + }); + }); + assert( + apm.currentSpan === null, + 'Mongodb span (or its HTTP span) should not be currentSpan after awaiting the task', + ); + log.info({ data }, 'findOne with callback'); + } + + // https://mongodb.github.io/node-mongodb-native/4.7/classes/Collection.html#update + data = await collection.updateOne({ a: 1 }, { $set: { b: 1 } }, { w: 1 }); + assert( + apm.currentSpan === null, + 'Mongodb span (or its HTTP span) should not be currentSpan after awaiting the task', + ); + log.info({ data }, 'updateOne with promises'); + + if (useCallbacks) { + data = await new Promise((resolve, reject) => { + collection.updateOne( + { a: 4 }, + { $set: { b: 4 } }, + { w: 1 }, + function (err, res) { + if (err) { + reject(err); + } else { + resolve(res); + } + }, + ); + }); + assert( + apm.currentSpan === null, + 'Mongodb span (or its HTTP span) should not be currentSpan after awaiting the task', + ); + log.info({ data }, 'updateOne with callback'); + } + + // https://mongodb.github.io/node-mongodb-native/4.7/classes/Collection.html#deleteOne + data = await collection.deleteOne({ a: 1 }, { w: 1 }); + assert( + apm.currentSpan === null, + 'Mongodb span (or its HTTP span) should not be currentSpan after awaiting the task', + ); + log.info({ data }, 'deleteOne with promises'); + + if (useCallbacks) { + data = await new Promise((resolve, reject) => { + collection.deleteOne({ a: 4 }, { w: 1 }, function (err, res) { + if (err) { + reject(err); + } else { + resolve(res); + } + }); + }); + assert( + apm.currentSpan === null, + 'Mongodb span (or its HTTP span) should not be currentSpan after awaiting the task', + ); + log.info({ data }, 'deleteOne with callback'); + } + + const cursor = collection.find({}); + data = await cursor.next(); + assert(data.a === 2, 'found record #2'); + log.info({ data }, 'cursor.next()'); + + data = await cursor.next(); + assert(data.a === 3, 'found record #3'); + log.info({ data }, 'cursor.next()'); + + if (useCallbacks) { + data = await cursor.next(); + assert(data.a === 5, 'found record #5'); + log.info({ data }, 'cursor.next()'); + + data = await cursor.next(); + assert(data.a === 6, 'found record #6'); + log.info({ data }, 'cursor.next()'); + } + + // https://mongodb.github.io/node-mongodb-native/4.7/classes/Collection.html#deleteMany + data = await collection.deleteMany({ a: { $lte: 3 } }, { w: 1 }); + assert( + apm.currentSpan === null, + 'Mongodb span (or its HTTP span) should not be currentSpan after awaiting the task', + ); + log.info({ data }, 'deleteMany with promises'); + + if (useCallbacks) { + data = await new Promise((resolve, reject) => { + collection.deleteMany({ a: { $gte: 4 } }, { w: 1 }, function (err, res) { + if (err) { + reject(err); + } else { + resolve(res); + } + }); + }); + assert( + apm.currentSpan === null, + 'Mongodb span (or its HTTP span) should not be currentSpan after awaiting the task', + ); + log.info({ data }, 'deleteMany with callback'); + } +} + +// ---- mainline + +async function main() { + const host = process.env.TEST_HOST || '127.0.0.1'; + const port = process.env.TEST_PORT || '27017'; + const db = process.env.TEST_DB || 'elasticapm'; + const col = process.env.TEST_COLLECTION || 'test'; + const url = `mongodb://${host}:${port}`; + const useCallbacks = process.env.TEST_USE_CALLBACKS === 'true'; + + const mongodbClient = new MongoClient(url); + + const tx = apm.startTransaction('manual'); + useMongodb(mongodbClient, { url, db, col, useCallbacks }).then( + function () { + tx.end(); + mongodbClient.close(); + process.exitCode = 0; + }, + function (err) { + apm.logger.error(err, 'useMongodb rejected'); + tx.setOutcome('failure'); + tx.end(); + mongodbClient.close(); + process.exitCode = 1; + }, + ); +} + +main(); diff --git a/test/instrumentation/modules/mongodb/mongodb.test.js b/test/instrumentation/modules/mongodb/mongodb.test.js new file mode 100644 index 00000000000..7ef781d76e3 --- /dev/null +++ b/test/instrumentation/modules/mongodb/mongodb.test.js @@ -0,0 +1,517 @@ +/* + * Copyright Elasticsearch B.V. and other contributors where applicable. + * Licensed under the BSD 2-Clause License; you may not use this file except in + * compliance with the BSD 2-Clause License. + */ + +'use strict'; + +// Tests of the instrumentation for `mongodb` module. +// +// They have been split into 3 sections: +// - Test of normal usage of the module with prmises and callback APIs +// - Test of the connection API to ensure the client returnes is properly instrumented +// - Test of cursors working concurrently to check if spans are attached to +// the right transaction. + +if (process.env.GITHUB_ACTIONS === 'true' && process.platform === 'win32') { + console.log('# SKIP: GH Actions do not support docker services on Windows'); + process.exit(0); +} + +const isMongodbIncompat = require('../../../_is_mongodb_incompat')(); +if (isMongodbIncompat) { + console.log(`# SKIP ${isMongodbIncompat}`); + process.exit(); +} + +const test = require('tape'); +const semver = require('semver'); + +const { validateSpan } = require('../../../_validate_schema'); +const { + runTestFixtures, + safeGetPackageVersion, + sortApmEvents, +} = require('../../../_utils'); + +const MONGODB_VERSION = safeGetPackageVersion('mongodb'); +// Setting `localhost` will set `span.context.destination.address` to [::1] sometimes +const TEST_HOST = '127.0.0.1'; +const TEST_PORT = '27017'; +const TEST_DB = 'elasticapm'; +const TEST_COLLECTION = 'test'; +const TEST_USE_CALLBACKS = semver.satisfies(MONGODB_VERSION, '<5'); + +/** @type {import('../../../_utils').TestFixture[]} */ +const testFixtures = [ + { + name: 'mongodb usage scenario', + script: 'fixtures/use-mongodb.js', + cwd: __dirname, + timeout: 20000, // sanity guard on the test hanging + maxBuffer: 10 * 1024 * 1024, // This is big, but I don't ever want this to be a failure reason. + env: { + TEST_HOST, + TEST_PORT, + TEST_DB, + TEST_COLLECTION, + TEST_USE_CALLBACKS: String(TEST_USE_CALLBACKS), + }, + verbose: true, + checkApmServer: (t, apmServer) => { + t.ok(apmServer.events[0].metadata, 'metadata'); + const events = sortApmEvents(apmServer.events); + + // First the transaction. + t.ok(events[0].transaction, 'got the transaction'); + const tx = events.shift().transaction; + + // Compare some common fields across all spans. + // ignore http/external spans + const spans = events + .filter((e) => e.span && e.span.type !== 'external') + .map((e) => e.span); + spans.forEach((s) => { + const errs = validateSpan(s); + t.equal(errs, null, 'span is valid (per apm-server intake schema)'); + }); + t.equal( + spans.filter((s) => s.trace_id === tx.trace_id).length, + spans.length, + 'all spans have the same trace_id', + ); + t.equal( + spans.filter((s) => s.transaction_id === tx.id).length, + spans.length, + 'all spans have the same transaction_id', + ); + t.equal( + spans.filter((s) => s.sync === false).length, + spans.length, + 'all spans have sync=false', + ); + t.equal( + spans.filter((s) => s.sample_rate === 1).length, + spans.length, + 'all spans have sample_rate=1', + ); + + spans.forEach((s) => { + // Remove variable and common fields to facilitate t.deepEqual below. + delete s.id; + delete s.transaction_id; + delete s.parent_id; + delete s.trace_id; + delete s.timestamp; + delete s.duration; + delete s.sync; + delete s.sample_rate; + }); + + // Work through each of the pipeline functions (insertMany, findOne, ...) in the script: + const insertManySpan = { + name: 'elasticapm.test.insert', + type: 'db', + subtype: 'mongodb', + action: 'insert', + context: { + service: { + target: { + type: 'mongodb', + name: TEST_DB, + }, + }, + destination: { + address: TEST_HOST, + port: Number(TEST_PORT), + service: { + type: '', + name: '', + resource: `mongodb/${TEST_DB}`, + }, + }, + db: { + type: 'mongodb', + instance: TEST_DB, + }, + }, + outcome: 'success', + }; + t.deepEqual( + spans.shift(), + insertManySpan, + 'insertMany produced expected span', + ); + + if (TEST_USE_CALLBACKS) { + t.deepEqual( + spans.shift(), + insertManySpan, + 'insertMany with callback produced expected span', + ); + } + + const findOneSpan = { + name: 'elasticapm.test.find', + type: 'db', + subtype: 'mongodb', + action: 'find', + context: { + service: { + target: { + type: 'mongodb', + name: TEST_DB, + }, + }, + destination: { + address: TEST_HOST, + port: Number(TEST_PORT), + service: { + type: '', + name: '', + resource: `mongodb/${TEST_DB}`, + }, + }, + db: { + type: 'mongodb', + instance: TEST_DB, + }, + }, + outcome: 'success', + }; + t.deepEqual(spans.shift(), findOneSpan, 'findOne produced expected span'); + + t.deepEqual(spans.shift(), findOneSpan, 'findOne 1st concurrent call'); + t.deepEqual(spans.shift(), findOneSpan, 'findOne 2nd concurrent call'); + t.deepEqual(spans.shift(), findOneSpan, 'findOne 3rd concurrent call'); + + if (TEST_USE_CALLBACKS) { + t.deepEqual( + spans.shift(), + findOneSpan, + 'findOne with callback produced expected span', + ); + } + + const updateOneSpan = { + name: 'elasticapm.test.update', + type: 'db', + subtype: 'mongodb', + action: 'update', + context: { + service: { + target: { + type: 'mongodb', + name: TEST_DB, + }, + }, + destination: { + address: TEST_HOST, + port: Number(TEST_PORT), + service: { + type: '', + name: '', + resource: `mongodb/${TEST_DB}`, + }, + }, + db: { + type: 'mongodb', + instance: TEST_DB, + }, + }, + outcome: 'success', + }; + t.deepEqual( + spans.shift(), + updateOneSpan, + 'updateOne produced expected span', + ); + + if (TEST_USE_CALLBACKS) { + t.deepEqual( + spans.shift(), + updateOneSpan, + 'updateOne with callbacks produced expected span', + ); + } + + const deleteOneSpan = { + name: 'elasticapm.test.delete', + type: 'db', + subtype: 'mongodb', + action: 'delete', + context: { + service: { + target: { + type: 'mongodb', + name: TEST_DB, + }, + }, + destination: { + address: TEST_HOST, + port: Number(TEST_PORT), + service: { + type: '', + name: '', + resource: `mongodb/${TEST_DB}`, + }, + }, + db: { + type: 'mongodb', + instance: TEST_DB, + }, + }, + outcome: 'success', + }; + t.deepEqual( + spans.shift(), + deleteOneSpan, + 'deleteOne produced expected span', + ); + + if (TEST_USE_CALLBACKS) { + t.deepEqual( + spans.shift(), + deleteOneSpan, + 'deleteOne with callbacks produced expected span', + ); + } + + t.deepEqual( + spans.shift(), + { + name: 'elasticapm.test.find', + type: 'db', + subtype: 'mongodb', + action: 'find', + context: { + service: { + target: { + type: 'mongodb', + name: TEST_DB, + }, + }, + destination: { + address: TEST_HOST, + port: Number(TEST_PORT), + service: { + type: '', + name: '', + resource: `mongodb/${TEST_DB}`, + }, + }, + db: { + type: 'mongodb', + instance: TEST_DB, + }, + }, + outcome: 'success', + }, + 'find produced expected span', + ); + + const deleteManySpan = { + name: 'elasticapm.test.delete', + type: 'db', + subtype: 'mongodb', + action: 'delete', + context: { + service: { + target: { + type: 'mongodb', + name: TEST_DB, + }, + }, + destination: { + address: TEST_HOST, + port: Number(TEST_PORT), + service: { + type: '', + name: '', + resource: `mongodb/${TEST_DB}`, + }, + }, + db: { + type: 'mongodb', + instance: TEST_DB, + }, + }, + outcome: 'success', + }; + t.deepEqual( + spans.shift(), + deleteManySpan, + 'deleteMany produced expected span', + ); + + if (TEST_USE_CALLBACKS) { + t.deepEqual( + spans.shift(), + deleteManySpan, + 'deleteMany with callbacks produced expected span', + ); + } + + t.equal( + spans.length, + 0, + `all spans accounted for, remaining spans: ${JSON.stringify(spans)}`, + ); + }, + }, + { + name: 'mongodb variations of connection', + script: 'fixtures/use-mongodb-connect.js', + cwd: __dirname, + timeout: 20000, // sanity guard on the test hanging + maxBuffer: 10 * 1024 * 1024, // This is big, but I don't ever want this to be a failure reason. + env: { + TEST_HOST, + TEST_PORT, + TEST_DB, + TEST_COLLECTION, + TEST_USE_CALLBACKS: String(TEST_USE_CALLBACKS), + }, + verbose: false, + checkApmServer: (t, apmServer) => { + t.ok(apmServer.events[0].metadata, 'metadata'); + const events = sortApmEvents(apmServer.events); + + const tx = events.shift().transaction; + t.ok(tx, 'got the transaction'); + + const spans = events + .filter((e) => e.span && e.span.type !== 'external') + .map((e) => e.span); + + spans.forEach((s) => { + // Remove variable and common fields to facilitate t.deepEqual below. + delete s.id; + delete s.transaction_id; + delete s.parent_id; + delete s.trace_id; + delete s.timestamp; + delete s.duration; + delete s.sync; + delete s.sample_rate; + }); + + const connectionsMade = TEST_USE_CALLBACKS ? 4 : 1; + + for (let i = 0; i < connectionsMade; i++) { + t.deepEqual( + spans.shift(), + { + name: 'elasticapm.test.find', + type: 'db', + subtype: 'mongodb', + action: 'find', + context: { + service: { + target: { + type: 'mongodb', + name: TEST_DB, + }, + }, + destination: { + address: TEST_HOST, + port: Number(TEST_PORT), + service: { + type: '', + name: '', + resource: `mongodb/${TEST_DB}`, + }, + }, + db: { + type: 'mongodb', + instance: TEST_DB, + }, + }, + outcome: 'success', + }, + 'findOne produced expected span', + ); + + t.deepEqual( + spans.shift(), + { + name: 'admin.$cmd.endSessions', + type: 'db', + subtype: 'mongodb', + action: 'endSessions', + context: { + service: { + target: { + type: 'mongodb', + name: 'admin', + }, + }, + destination: { + address: TEST_HOST, + port: Number(TEST_PORT), + service: { + type: '', + name: '', + resource: 'mongodb/admin', + }, + }, + db: { + type: 'mongodb', + instance: 'admin', + }, + }, + outcome: 'success', + }, + 'close produced expected span', + ); + } + + t.equal(spans.length, 0, 'all spans accounted for'); + }, + }, + { + name: 'mongodb concurrency and async context', + script: 'fixtures/use-mongodb-async-context.js', + cwd: __dirname, + timeout: 20000, // sanity guard on the test hanging + maxBuffer: 10 * 1024 * 1024, // This is big, but I don't ever want this to be a failure reason. + env: { + TEST_HOST, + TEST_PORT, + TEST_DB, + TEST_COLLECTION, + }, + verbose: false, + checkApmServer: (t, apmServer) => { + t.ok(apmServer.events[0].metadata, 'metadata'); + const events = sortApmEvents(apmServer.events); + + const transactions = events + .filter((e) => e.transaction) + .map((e) => e.transaction); + + const spans = events + .filter((e) => e.span && e.span.type !== 'external') + .map((e) => e.span); + + while (transactions.length) { + const tx = transactions.shift(); + const idx = spans.findIndex((s) => s.parent_id === tx.id); + + t.ok(idx !== -1, 'transaction has a child span'); + + const [span] = spans.splice(idx, 1); + + t.equal(span.name, 'elasticapm.test.find', 'span.name'); + } + + t.equal(spans.length, 0, 'all spans accounted for'); + }, + }, +]; + +test('mongodb fixtures', (suite) => { + runTestFixtures(suite, testFixtures); + suite.end(); +});