mongodb instrumentation should set `span.outcome` and `captureError()` on `commandFailed`

[trentm]

From #3168 (comment)

About span outcome - the same onEnd event handler is in use for commandSucceeded and commandFailed events:

          client.on('commandSucceeded', onEnd)
          client.on('commandFailed', onEnd)

And it's possible to set outcome by checking event.failure like:

  function onEnd (event) {
    if (!activeSpans.has(event.requestId)) return
    const span = activeSpans.get(event.requestId)
    activeSpans.delete(event.requestId)
    span.setOutcome(event.failure ? 'failure' : 'success')
    span.end((span._timer.start / 1000) + event.duration)
  }

Doc: v4.0 v5.0

This diff to "examples/trace-mongodb.js" shows a way to get a commandFailed event -- a bogus "hint" to a .deleteOne() call (https://www.mongodb.com/docs/manual/reference/method/db.collection.deleteOne/#std-label-ex-deleteOne-hint),

diff --git a/examples/trace-mongodb.js b/examples/trace-mongodb.js
index 2f4f8992..733d8241 100755
--- a/examples/trace-mongodb.js
+++ b/examples/trace-mongodb.js
@@ -42,6 +42,12 @@ async function main () {
     ])
     console.log('insertMany:', res)

+    try {
+      await coll.deleteOne({ item: 'ham' }, { hint: 'foo' })
+    } catch (err) {
+      console.log('error in .deleteOne() with bogus "hint":', err)
+    }
+
     res = await coll.findOne({ item: 'eggs' })
     console.log('findOne eggs:', res)

Running that:

% node examples/trace-mongodb.js
insertMany: {
  acknowledged: true,
  insertedCount: 3,
  insertedIds: {
    '0': new ObjectId("6400e8780cc1a4a785975123"),
    '1': new ObjectId("6400e8780cc1a4a785975124"),
    '2': new ObjectId("6400e8780cc1a4a785975125")
  }
}
error in .deleteOne() with bogus "hint": MongoServerError: error processing query: ns=example-trace-mongodb.breakfastTree: item $eq "ham"
Sort: {}
Proj: {}
 planner returned error :: caused by :: hint provided does not correspond to an existing index
    at /Users/trentm/el/apm-agent-nodejs/node_modules/mongodb/lib/operations/delete.js:60:33
    at /Users/trentm/el/apm-agent-nodejs/node_modules/mongodb/lib/cmap/connection_pool.js:327:25
    at /Users/trentm/el/apm-agent-nodejs/node_modules/mongodb/lib/sdam/server.js:207:17
    at handleOperationResult (/Users/trentm/el/apm-agent-nodejs/node_modules/mongodb/lib/sdam/server.js:323:20)
    at operationDescription.cb (/Users/trentm/el/apm-agent-nodejs/node_modules/mongodb/lib/cmap/connection.js:475:17)
    at Connection.onMessage (/Users/trentm/el/apm-agent-nodejs/node_modules/mongodb/lib/cmap/connection.js:213:9)
    at MessageStream.<anonymous> (/Users/trentm/el/apm-agent-nodejs/node_modules/mongodb/lib/cmap/connection.js:59:60)
    at MessageStream.emit (node:events:513:28)
    at processIncomingData (/Users/trentm/el/apm-agent-nodejs/node_modules/mongodb/lib/cmap/message_stream.js:124:16)
    at MessageStream._write (/Users/trentm/el/apm-agent-nodejs/node_modules/mongodb/lib/cmap/message_stream.js:33:9)
    at writeOrBuffer (node:internal/streams/writable:391:12)
    at _write (node:internal/streams/writable:332:10)
    at MessageStream.Writable.write (node:internal/streams/writable:336:10)
    at Socket.ondata (node:internal/streams/readable:754:22)
    at Socket.emit (node:events:513:28)
    at addChunk (node:internal/streams/readable:315:12)
    at readableAddChunk (node:internal/streams/readable:289:9)
    at Socket.Readable.push (node:internal/streams/readable:228:10)
    at TCP.onStreamRead (node:internal/stream_base_commons:190:23)
    at TCP.callbackTrampoline (node:internal/async_hooks:130:17) {
  index: 0,
  code: 2,
  [Symbol(errorLabels)]: Set(0) {}
}
findOne eggs: { _id: new ObjectId("6400e8780cc1a4a785975125"), item: 'eggs', n: 2 }
findOne eggs: null

results in a trace like this:

    trace b1f040
    `- transaction d40217 "t1" (65.025ms, outcome=unknown)
       `- span ad7344 "example-trace-mongodb.breakfast.insert" (3ms, mongodb, sync)
       `- span c4139c "example-trace-mongodb.breakfast.delete" (1ms, mongodb)   <--- this span
       `- span 325a5b "example-trace-mongodb.breakfast.find" (2ms, mongodb)
       `- span 7ee1b0 "example-trace-mongodb.breakfast.delete" (1ms, mongodb)
       `- span 1342ae "example-trace-mongodb.breakfast.find" (1ms, mongodb)
       `- span b7aec1 "admin.$cmd.endSessions" (0ms, mongodb, sync)

The span marked "this span" should have outcome=failure and should have captured an error event.

[trentm]

Note to self: I'm moving on for now, but here is a partial start at a test case for this:

diff --git a/test/instrumentation/modules/mongodb.test.js b/test/instrumentation/modules/mongodb.test.js
index 1ff48f11..f50a69ca 100644
--- a/test/instrumentation/modules/mongodb.test.js
+++ b/test/instrumentation/modules/mongodb.test.js
@@ -140,8 +140,9 @@ test('await MongoClient.connect(url)', async function (t) {
   t.end()
 })

-test('ensure run context', async function (t) {
-  resetAgent(5, function noop () {})
+// XXX
+test.only('ensure run context', async function (t) {
+  resetAgent(6, function noop () {})

   const client = await MongoClient.connect(url)
   agent.startTransaction('t0')
@@ -157,12 +158,15 @@ test('ensure run context', async function (t) {
   agent.startSpan('manual').end()
   promises.push(collection.findOne({ b: 2 }))
   promises.push(collection.findOne({ c: 3 }))
-  await Promise.all(promises)
+  promises.push(collection.findOne(42))
+  // XXX node 12.9.0
+  await Promise.allSettled(promises)

   agent.endTransaction()
   await promisify(agent.flush.bind(agent))().then(function (err) {
     t.error(err, 'no error from agent.flush()')
     const data = agent._transport._writes
+    console.log('XXX data:'); console.dir(data, { depth: 5 })
     t.equal(data.transactions[0].name, 't0', 'transaction.name')
     t.equal(data.spans.length, 4)
     data.spans.forEach(s => {

The collection.findOne(42) needs to be changed to the .deleteOne(..., <bogus hint option>) case -- or some other case that results in a commandFailed.

[david-luna]

It seems the error is returned in a commandSucceeded event. I've added a log in the onEnd function

   function onEnd(event) {
+    console.log(JSON.stringify(event, null, 2));
     if (!activeSpans.has(event.requestId)) return;

Running ./examples/trace-mongodb.js I get this log from the failed delete

{
  "name": "commandSucceeded",
  "address": "[::1]:27017",
  "connectionId": 1,
  "requestId": 4,
  "commandName": "delete",
  "duration": 1,
  "reply": {
    "n": 0,
    "writeErrors": [
      {
        "index": 0,
        "code": 2,
        "errmsg": "error processing query: ns=example-trace-mongodb.breakfastTree: item $eq \"ham\"\nSort: {}\nProj: {}\n planner returned error :: caused by :: hint provided does not correspond to an existing index"
      }
    ],
    "ok": 1
  }
}

Some highlights:

• name is commandSucceeded so I guess commandFailed should be for transport errors
• reply.ok is 1 nomatter if the command failed so is not useful
• writeErrors prop appears in this error and not in the succedded commands, but maybe the prop is different for queries

[david-luna]

Could reproduce a commandFailed adding a bogus hint in .findOne() the snippet

await coll.findOne({ bogus: 'value' }, { hint: 'foo' });

Produces the following event

{
  "name": "commandFailed",
  "address": "[::1]:27017",
  "connectionId": 1,
  "requestId": 8,
  "commandName": "find",
  "duration": 0,
  "failure": {
    "ok": 0,
    "code": 2,
    "codeName": "BadValue"
  }
}

[trentm]

It seems the error is returned in a commandSucceeded event.

What about the commandFailed event? Are we calling onEnd twice?

Or what "the error" do you mean here? Is this a different failure case than the commandFailed adding a bogus hint in .findOne() the snippet case?

[trentm]

I dug in a little more and noticed this:
https://github.com/mongodb/node-mongodb-native/blob/f495abb0e25755e867b311a19c8cd35a4c606aa4/src/cmap/connection.ts#L710-L712

The behaviour change to emit CommandSucceededEvent even when there is sometimes an error (a "write concern error") was made here: mongodb/node-mongodb-native#3525
The best description I've seen of the MongoDB drivers spec change for this is in the "Summary" here: https://jira.mongodb.org/browse/DRIVERS-2468

The command monitoring spec defines a successful command as one with an ok:1 reply and a failed command as one with an ok:0 reply. However, it seems that at least the Node driver decides whether to emit a command succeeded or failed event based on whether or not an error is going to be thrown rather than the "ok" value.

While this seems reasonable, that logic is problematic because server replies can have ok:1 and a writeConcernError. In these cases, based on the definition of "success" in the command monitoring spec, we should emit a CommandSucceededEvent but also throw an error.

My opinion: I don't think we should second guess the monitoring events from the MongoDB client. I think the "outcome" should be "success" for commandSucceeded and "failure" for commandFailed. I think we should apm.captureError the event.failure for a commandFailed event.

Code-wise, I think it would be cleaner to separate out the onEnd event handler to two separate functions: one each for commandSucceeded and commandFailed. Then each can have a more well-defined type on the event field: https://github.com/mongodb/node-mongodb-native/blob/f495abb0e25755e867b311a19c8cd35a4c606aa4/src/cmap/command_monitoring_events.ts#L63-L127

---

Repeating that second MongoDB issue sentence from above:

While this seems reasonable, that logic is problematic because server replies can have ok:1 and a writeConcernError. In these cases, based on the definition of "success" in the command monitoring spec, we should emit a CommandSucceededEvent but also throw an error.

Longer term, it might be helpful/interesting to change our wrapping of mongodb so we could capture that error in the we should emit a CommandSucceededEvent but also throw an error. case. In this case we would have a mongodb Span with outcome=success but with a child APM error object.