Skip to content

Commit

Permalink
fix: set outcome for mongodb spans (#3695)
Browse files Browse the repository at this point in the history
  • Loading branch information
@david-luna
david-luna authored Oct 30, 2023
1 parent a61142f commit bb65827
Show file tree
Hide file tree
Showing 4 changed files with 103 additions and 14 deletions.
2 changes: 2 additions & 0 deletions CHANGELOG.asciidoc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -61,6 +61,8 @@ See the <<upgrade-to-v4>> guide.
* Fix `mongodb` instrumentation to avoid loosing context when multiple cursors
are running concurrently. ({issues}3161[#3161])
* Set `mongodb` span's outcome according to the result of the command being traced.
({pull}3695[#3695])
[float]
===== Chores
Expand Down
68 changes: 54 additions & 14 deletions lib/instrumentation/modules/mongodb.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@

const semver = require('semver');

const { OUTCOME_SUCCESS, OUTCOME_FAILURE } = require('../../constants');
const { getDBDestination } = require('../context');
const shimmer = require('../shimmer');
const kListenersAdded = Symbol('kListenersAdded');
Expand All @@ -32,8 +33,8 @@ module.exports = (mongodb, agent, { version, enabled }) => {
if (mongodb.instrument) {
const listener = mongodb.instrument();
listener.on('started', onStart);
listener.on('succeeded', onEnd);
listener.on('failed', onEnd);
listener.on('succeeded', onSuccess);
listener.on('failed', onFailure);
} else if (mongodb.MongoClient) {
// mongodb 4.0+ removed the instrument() method in favor of
// listeners on the instantiated client objects. There are two mechanisms
Expand All @@ -51,8 +52,8 @@ module.exports = (mongodb, agent, { version, enabled }) => {
}
super(...args);
this.on('commandStarted', onStart);
this.on('commandSucceeded', onEnd);
this.on('commandFailed', onEnd);
this.on('commandSucceeded', onSuccess);
this.on('commandFailed', onFailure);
this[kListenersAdded] = true;
}
}
Expand Down Expand Up @@ -102,8 +103,8 @@ module.exports = (mongodb, agent, { version, enabled }) => {
} else {
if (!client[kListenersAdded]) {
client.on('commandStarted', onStart);
client.on('commandSucceeded', onEnd);
client.on('commandFailed', onEnd);
client.on('commandSucceeded', onSuccess);
client.on('commandFailed', onFailure);
client[kListenersAdded] = true;
}
callback(err, client);
Expand All @@ -115,8 +116,8 @@ module.exports = (mongodb, agent, { version, enabled }) => {
p.then((client) => {
if (!client[kListenersAdded]) {
client.on('commandStarted', onStart);
client.on('commandSucceeded', onEnd);
client.on('commandFailed', onEnd);
client.on('commandSucceeded', onSuccess);
client.on('commandFailed', onFailure);
client[kListenersAdded] = true;
}
});
Expand All @@ -127,17 +128,15 @@ module.exports = (mongodb, agent, { version, enabled }) => {

function onStart(event) {
// `event` is a `CommandStartedEvent`
// https://github.com/mongodb/specifications/blob/master/source/command-monitoring/command-monitoring.rst#api
// E.g. with mongodb@3.6.3:
// https://github.com/mongodb/specifications/blob/master/source/command-logging-and-monitoring/command-logging-and-monitoring.rst#command-started-message
// E.g. with mongodb@6.2.0:
// CommandStartedEvent {
// address: '127.0.0.1:27017',
// connectionId: 1,
// connectionId: '127.0.0.1:27017',
// requestId: 1,
// databaseName: 'test',
// commandName: 'insert',
// command:
// { ... } }

const name = [
event.databaseName,
collectionFor(event),
Expand Down Expand Up @@ -174,10 +173,51 @@ module.exports = (mongodb, agent, { version, enabled }) => {
}
}

function onEnd(event) {
function onSuccess(event) {
// `event` is a `CommandSucceededEvent`
// https://github.com/mongodb/specifications/blob/master/source/command-logging-and-monitoring/command-logging-and-monitoring.rst#command-succeeded-message
// E.g. with [email protected]:
// CommandSucceededEvent {
// connectionId: '127.0.0.1:27017',
// requestId: 1,
// duration: 1,
// reply: { ... }
// }
if (!activeSpans.has(event.requestId)) return;

const span = activeSpans.get(event.requestId);
activeSpans.delete(event.requestId);

// From [email protected] and up some commands like `deleteOne` may contain
// error data inside the `reply` property. It makes sense to capture it.
const writeErrors = event?.reply?.writeErrors;

if (writeErrors && writeErrors.length) {
agent.captureError(writeErrors[0].errmsg, {
skipOutcome: true,
parent: span,
});
}
span.setOutcome(OUTCOME_SUCCESS);
span.end(span._timer.start / 1000 + event.duration);
}

function onFailure(event) {
// `event` is a `CommandFailedEvent`
// https://github.com/mongodb/specifications/blob/master/source/command-logging-and-monitoring/command-logging-and-monitoring.rst#command-failed-message
// E.g. with [email protected]:
// CommandFailedEvent {
// connectionId: '127.0.0.1:27017',
// requestId: 6,
// commandName: "find",
// duration: 1,
// "failure": { ... }
// }
if (!activeSpans.has(event.requestId)) return;

const span = activeSpans.get(event.requestId);
activeSpans.delete(event.requestId);
span.setOutcome(OUTCOME_FAILURE);
span.end(span._timer.start / 1000 + event.duration);
}

Expand Down
14 changes: 14 additions & 0 deletions test/instrumentation/modules/mongodb/fixtures/use-mongodb.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -94,6 +94,13 @@ async function useMongodb(mongodbClient, options) {
const queries = [{ a: 1 }, { b: 2 }, { c: 3 }];
await Promise.all(queries.map((q) => collection.findOne(q)));

// Force an error to check the span outcome
try {
await collection.findOne({ a: 1 }, { hint: 'foo' });
} catch (err) {
log.info({ err }, 'error in .findOne() with bogus "hint"');
}

if (useCallbacks) {
data = await new Promise((resolve, reject) => {
collection.findOne({ a: 4 }, function (err, res) {
Expand Down Expand Up @@ -149,6 +156,13 @@ async function useMongodb(mongodbClient, options) {
);
log.info({ data }, 'deleteOne with promises');

// Force an error to check the span outcome
try {
await collection.deleteOne({ a: 1 }, { hint: 'foo' });
} catch (err) {
log.info({ err }, 'error in .deleteOne() with bogus "hint"');
}

if (useCallbacks) {
data = await new Promise((resolve, reject) => {
collection.deleteOne({ a: 4 }, { w: 1 }, function (err, res) {
Expand Down
33 changes: 33 additions & 0 deletions test/instrumentation/modules/mongodb/mongodb.test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,12 @@ const TEST_DB = 'elasticapm';
const TEST_COLLECTION = 'test';
const TEST_USE_CALLBACKS = semver.satisfies(MONGODB_VERSION, '<5');

// From [email protected] and up CommandSuccessEvents may contain errors
const MONGODB_SUCCESS_WITH_ERRORS = semver.satisfies(
MONGODB_VERSION,
'>=3.6.0',
);

/** @type {import('../../../_utils').TestFixture[]} */
const testFixtures = [
{
Expand All @@ -66,6 +72,7 @@ const testFixtures = [
// First the transaction.
t.ok(events[0].transaction, 'got the transaction');
const tx = events.shift().transaction;
const errors = events.filter((e) => e.error).map((e) => e.error);

// Compare some common fields across all spans.
// ignore http/external spans
Expand Down Expand Up @@ -97,6 +104,7 @@ const testFixtures = [
'all spans have sample_rate=1',
);

const failingSpanId = spans[TEST_USE_CALLBACKS ? 11 : 8].id; // index of `.deleteOne` with bogus "hint"
spans.forEach((s) => {
// Remove variable and common fields to facilitate t.deepEqual below.
delete s.id;
Expand Down Expand Up @@ -194,6 +202,12 @@ const testFixtures = [
t.deepEqual(spans.shift(), findOneSpan, 'findOne 2nd concurrent call');
t.deepEqual(spans.shift(), findOneSpan, 'findOne 3rd concurrent call');

t.deepEqual(
spans.shift(),
{ ...findOneSpan, outcome: 'failure' },
'findOne with bogus "hint" produced expected span',
);

if (TEST_USE_CALLBACKS) {
t.deepEqual(
spans.shift(),
Expand Down Expand Up @@ -278,6 +292,25 @@ const testFixtures = [
'deleteOne produced expected span',
);

// Delete command errors are not faling
// - Promise API does not reject
// - callback API does not return an error param
// - CommandSucceededvent is fired (althoug it contains error data)
t.deepEqual(
spans.shift(),
deleteOneSpan,
'deleteOne with bogus "hint" produced expected span',
);

if (MONGODB_SUCCESS_WITH_ERRORS) {
t.equal(errors.length, 1, 'got 1 error');
t.equal(
errors[0].parent_id,
failingSpanId,
'error is a child of the failing span from deleteOne with bogus "hint"',
);
}

if (TEST_USE_CALLBACKS) {
t.deepEqual(
spans.shift(),
Expand Down

0 comments on commit bb65827

Please sign in to comment.