diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 67503091973..f2d7fec5fe2 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -416,7 +416,7 @@ export class Connection extends TypedEventEmitter { 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); } }; } diff --git a/src/sdam/server.ts b/src/sdam/server.ts index 21dcc23f97d..290cd1b2de5 100644 --- a/src/sdam/server.ts +++ b/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); } diff --git a/test/integration/retryable-writes/retryable_writes.spec.prose.test.ts b/test/integration/retryable-writes/retryable_writes.spec.prose.test.ts index 165945e7605..4bc11cfbb4e 100644 --- a/test/integration/retryable-writes/retryable_writes.spec.prose.test.ts +++ b/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 }); + } + ); }); }); diff --git a/test/spec/command-logging-and-monitoring/monitoring/writeConcernError.json b/test/spec/command-logging-and-monitoring/monitoring/writeConcernError.json new file mode 100644 index 00000000000..cc97450687d --- /dev/null +++ b/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" + } + } + ] + } + ] + } + ] +} diff --git a/test/spec/command-logging-and-monitoring/monitoring/writeConcernError.yml b/test/spec/command-logging-and-monitoring/monitoring/writeConcernError.yml new file mode 100644 index 00000000000..fbaa4a330d5 --- /dev/null +++ b/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