feat(NODE-4756)!: ok 1 with write concern failure event changes (#3525)

Author: durran

src/cmap/connection.ts

@@ -416,7 +416,7 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
 
       if (operationDescription.command) {
         if (document.writeConcernError) {
-          callback(new MongoWriteConcernError(document.writeConcernError, document));
+          callback(new MongoWriteConcernError(document.writeConcernError, document), document);
           return;
         }
 
@@ -680,7 +680,10 @@ function write(
 
     operationDescription.started = now();
     operationDescription.cb = (err, reply) => {
-      if (err) {
+      // Command monitoring spec states that if ok is 1, then we must always emit
+      // a command suceeded event, even if there's an error. Write concern errors
+      // will have an ok: 1 in their reply.
+      if (err && reply?.ok !== 1) {
         conn.emit(
           Connection.COMMAND_FAILED,
           new CommandFailedEvent(conn, command, err, operationDescription.started)
@@ -700,7 +703,11 @@ function write(
       }
 
       if (typeof callback === 'function') {
-        callback(err, reply);
+        // Since we're passing through the reply with the write concern error now, we
+        // need it not to be provided to the original callback in this case so
+        // retryability does not get tricked into thinking the command actually
+        // succeeded.
+        callback(err, err instanceof MongoWriteConcernError ? undefined : reply);
       }
     };
   }

src/sdam/server.ts

@@ -500,7 +500,8 @@ function makeOperationHandler(
 ): Callback {
   const session = options?.session;
   return function handleOperationResult(error, result) {
-    if (result != null) {
+    // We should not swallow an error if it is present.
+    if (error == null && result != null) {
       return callback(undefined, result);
     }
 

test/integration/retryable-writes/retryable_writes.spec.prose.test.ts

@@ -1,4 +1,6 @@
 /* eslint-disable @typescript-eslint/no-non-null-assertion */
+import { once } from 'node:events';
+
 import { expect } from 'chai';
 import * as sinon from 'sinon';
 
@@ -10,6 +12,7 @@ import {
   MongoWriteConcernError,
   Server
 } from '../../mongodb';
+import { sleep } from '../../tools/utils';
 
 describe('Retryable Writes Spec Prose', () => {
   describe('1. Test that retryable writes raise an exception when using the MMAPv1 storage engine.', () => {
@@ -230,11 +233,6 @@ describe('Retryable Writes Spec Prose', () => {
     });
 
     /**
-     * **NOTE:** Node emits a command failed event for writeConcern errors, making the commandSucceeded part of this test inconsistent see (DRIVERS-2468).
-     * Second our event emitters are called synchronously but operations are asynchronous, we don't have a way to make sure a fail point is set before a retry
-     * is attempted, if the server allowed us to specify an ordered list of fail points this would be possible, alas we can use sinon. Sinon will set an error
-     * to be thrown on the first and second call to Server.command(), this should enter the retry logic for the second error thrown.
-     *
      * This test MUST be implemented by any driver that implements the Command Monitoring specification,
      * only run against replica sets as mongos does not propagate the NoWritesPerformed label to the drivers.
      * Additionally, this test requires drivers to set a fail point after an insertOne operation but before the subsequent retry.
@@ -299,5 +297,49 @@ describe('Retryable Writes Spec Prose', () => {
         expect(insertResult).to.have.property('code', 91);
       }
     );
+
+    // This is an extra test that is a complimentary test to prose test #3. We basically want to
+    // test that in the case of a write concern error with ok: 1 in the response, that
+    // a command succeeded event is emitted but that the driver still treats it as a failure
+    // and retries. So for the success, we check the error code if exists, and since the retry
+    // must succeed, we fail if any command failed event occurs on insert.
+    it(
+      'emits a command succeeded event for write concern errors with ok: 1',
+      { requires: { topology: 'replicaset', mongodb: '>=4.2.9' } },
+      async () => {
+        // Generate a write concern error to assert that we get a command
+        // suceeded event but the operation will retry because it was an
+        // actual write concern error.
+        await client.db('admin').command({
+          configureFailPoint: 'failCommand',
+          mode: { times: 1 },
+          data: {
+            writeConcernError: {
+              code: 91,
+              errorLabels: ['RetryableWriteError']
+            },
+            failCommands: ['insert']
+          }
+        });
+
+        const willBeCommandSucceeded = once(client, 'commandSucceeded').catch(error => error);
+        const willBeCommandFailed = Promise.race([
+          once(client, 'commandFailed'),
+          sleep(1000).then(() => Promise.reject(new Error('timeout')))
+        ]).catch(error => error);
+
+        const insertResult = await collection.insertOne({ _id: 1 }).catch(error => error);
+
+        const [commandSucceeded] = await willBeCommandSucceeded;
+        expect(commandSucceeded.commandName).to.equal('insert');
+        expect(commandSucceeded.reply).to.have.nested.property('writeConcernError.code', 91);
+        const noCommandFailedEvent = await willBeCommandFailed;
+        expect(
+          noCommandFailedEvent.message,
+          'expected timeout, since no failure event should emit'
+        ).to.equal('timeout');
+        expect(insertResult).to.deep.equal({ acknowledged: true, insertedId: 1 });
+      }
+    );
   });
 });

test/spec/command-logging-and-monitoring/monitoring/writeConcernError.json

@@ -0,0 +1,155 @@
+{
+  "description": "writeConcernError",
+  "schemaVersion": "1.13",
+  "runOnRequirements": [
+    {
+      "minServerVersion": "4.1.0",
+      "topologies": [
+        "replicaset"
+      ],
+      "serverless": "forbid"
+    }
+  ],
+  "createEntities": [
+    {
+      "client": {
+        "id": "client",
+        "observeEvents": [
+          "commandStartedEvent",
+          "commandSucceededEvent",
+          "commandFailedEvent"
+        ]
+      }
+    },
+    {
+      "database": {
+        "id": "database",
+        "client": "client",
+        "databaseName": "command-monitoring-tests"
+      }
+    },
+    {
+      "collection": {
+        "id": "collection",
+        "database": "database",
+        "collectionName": "test"
+      }
+    }
+  ],
+  "initialData": [
+    {
+      "collectionName": "test",
+      "databaseName": "command-monitoring-tests",
+      "documents": [
+        {
+          "_id": 1,
+          "x": 11
+        }
+      ]
+    }
+  ],
+  "tests": [
+    {
+      "description": "A retryable write with write concern errors publishes success event",
+      "operations": [
+        {
+          "name": "failPoint",
+          "object": "testRunner",
+          "arguments": {
+            "client": "client",
+            "failPoint": {
+              "configureFailPoint": "failCommand",
+              "mode": {
+                "times": 1
+              },
+              "data": {
+                "failCommands": [
+                  "insert"
+                ],
+                "writeConcernError": {
+                  "code": 91,
+                  "errorLabels": [
+                    "RetryableWriteError"
+                  ]
+                }
+              }
+            }
+          }
+        },
+        {
+          "name": "insertOne",
+          "object": "collection",
+          "arguments": {
+            "document": {
+              "_id": 2,
+              "x": 22
+            }
+          }
+        }
+      ],
+      "expectEvents": [
+        {
+          "client": "client",
+          "events": [
+            {
+              "commandStartedEvent": {
+                "command": {
+                  "insert": "test",
+                  "documents": [
+                    {
+                      "_id": 2,
+                      "x": 22
+                    }
+                  ],
+                  "ordered": true
+                },
+                "commandName": "insert",
+                "databaseName": "command-monitoring-tests"
+              }
+            },
+            {
+              "commandSucceededEvent": {
+                "reply": {
+                  "ok": 1,
+                  "n": 1,
+                  "writeConcernError": {
+                    "code": 91,
+                    "errorLabels": [
+                      "RetryableWriteError"
+                    ]
+                  }
+                },
+                "commandName": "insert"
+              }
+            },
+            {
+              "commandStartedEvent": {
+                "command": {
+                  "insert": "test",
+                  "documents": [
+                    {
+                      "_id": 2,
+                      "x": 22
+                    }
+                  ],
+                  "ordered": true
+                },
+                "commandName": "insert",
+                "databaseName": "command-monitoring-tests"
+              }
+            },
+            {
+              "commandSucceededEvent": {
+                "reply": {
+                  "ok": 1,
+                  "n": 1
+                },
+                "commandName": "insert"
+              }
+            }
+          ]
+        }
+      ]
+    }
+  ]
+}

test/spec/command-logging-and-monitoring/monitoring/writeConcernError.yml

@@ -0,0 +1,80 @@
+description: "writeConcernError"
+schemaVersion: "1.13"
+runOnRequirements:
+  -
+    minServerVersion: 4.1.0
+    topologies:
+      - replicaset
+    serverless: "forbid"
+
+createEntities:
+  - client:
+      id: &client client
+      observeEvents:
+        - commandStartedEvent
+        - commandSucceededEvent
+        - commandFailedEvent
+  - database:
+      id: &database database
+      client: *client
+      databaseName: &databaseName command-monitoring-tests
+  - collection:
+      id: &collection collection
+      database: *database
+      collectionName: &collectionName test
+
+initialData:
+  - collectionName: *collectionName
+    databaseName: *databaseName
+    documents:
+      - { _id: 1, x: 11 }
+
+tests:
+  - description: "A retryable write with write concern errors publishes success event"
+    operations:
+      - name: failPoint
+        object: testRunner
+        arguments:
+          client: *client
+          failPoint:
+            configureFailPoint: failCommand
+            mode: { times: 1 }
+            data:
+              failCommands: [ insert ]
+              writeConcernError:
+                code: 91 # ShutdownInProgress
+                errorLabels: [RetryableWriteError]
+      - name: insertOne
+        object: *collection
+        arguments:
+          document: { _id: 2, x: 22 }
+    expectEvents:
+      - client: *client
+        events:
+          - commandStartedEvent:
+              command:
+                insert: *collectionName
+                documents:
+                  - { _id: 2, x: 22 }
+                ordered: true
+              commandName: insert
+              databaseName: *databaseName
+          - commandSucceededEvent:
+              reply:
+                ok: 1
+                n: 1
+                writeConcernError: { code: 91, errorLabels: [ "RetryableWriteError" ] }
+              commandName: insert
+          - commandStartedEvent:
+              command:
+                insert: *collectionName
+                documents:
+                  - { _id: 2, x: 22 }
+                ordered: true
+              commandName: insert
+              databaseName: *databaseName
+          - commandSucceededEvent:
+              reply:
+                ok: 1
+                n: 1
+              commandName: insert