From 4fe6a1820026a26c80943ac3c3bfdc5b41bc3056 Mon Sep 17 00:00:00 2001 From: Durran Jordan Date: Tue, 17 Jan 2023 12:28:56 +0100 Subject: [PATCH 1/7] feat(NODE-4756): ok 1 with write concern failure event changes --- src/cmap/connection.ts | 13 +++-- .../retryable_writes.spec.prose.test.ts | 54 +++++++++++++++++-- 2 files changed, 59 insertions(+), 8 deletions(-) diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 67503091973..6ace4ed6638 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 and 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/test/integration/retryable-writes/retryable_writes.spec.prose.test.ts b/test/integration/retryable-writes/retryable_writes.spec.prose.test.ts index 165945e7605..c50b79d4e86 100644 --- a/test/integration/retryable-writes/retryable_writes.spec.prose.test.ts +++ b/test/integration/retryable-writes/retryable_writes.spec.prose.test.ts @@ -230,11 +230,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 +294,54 @@ 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 () => { + const successListener = event => { + if (event.commandName === 'insert' && event.reply.writeConcernError) { + expect(event.reply.writeConcernError.code).to.equal(91); + } + }; + + const failureListener = event => { + if (event.commandName === 'insert') { + expect.fail('the insert must be retried after the first suceeded event'); + } + }; + + // 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. + client.db('admin').command({ + configureFailPoint: 'failCommand', + mode: { times: 1 }, + data: { + writeConcernError: { + code: 91, + errorLabels: ['RetryableWriteError'] + }, + failCommands: ['insert'] + } + }); + + client.addListener('commandSucceeded', successListener); + client.addListener('commandFailed', failureListener); + + const insertResult = await collection.insertOne({ _id: 1 }).catch(error => error); + + // sinon.restore(); + client.removeListener('commandSucceeded', successListener); + client.removeListener('commandFailed', failureListener); + + expect(insertResult).to.deep.equal({ acknowledged: true, insertedId: 1 }); + } + ); }); }); From 0a9404d6d86c1de5d04cb9097e7d75d6be78d2b4 Mon Sep 17 00:00:00 2001 From: Durran Jordan Date: Tue, 17 Jan 2023 12:58:43 +0100 Subject: [PATCH 2/7] test(NODE-4756): add unified spec tests --- .../monitoring/insertOne.json | 80 +++++++++++++++++++ .../monitoring/insertOne.yml | 38 +++++++++ 2 files changed, 118 insertions(+) diff --git a/test/spec/command-logging-and-monitoring/monitoring/insertOne.json b/test/spec/command-logging-and-monitoring/monitoring/insertOne.json index 6ff732e41be..7609665cdd2 100644 --- a/test/spec/command-logging-and-monitoring/monitoring/insertOne.json +++ b/test/spec/command-logging-and-monitoring/monitoring/insertOne.json @@ -139,6 +139,86 @@ ] } ] + }, + { + "description": "A failed insertOne 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": 3, + "x": 33 + } + }, + "expectError": { + "isClientError": false + } + } + ], + "expectEvents": [ + { + "client": "client", + "events": [ + { + "commandStartedEvent": { + "command": { + "insert": "test", + "documents": [ + { + "_id": 3, + "x": 33 + } + ], + "ordered": true + }, + "commandName": "insert", + "databaseName": "command-monitoring-tests" + } + }, + { + "commandSucceededEvent": { + "reply": { + "ok": 1, + "n": 1, + "writeConcernError": { + "code": 91, + "errorLabels": [ + "RetryableWriteError" + ] + } + }, + "commandName": "insert" + } + } + ] + } + ] } ] } diff --git a/test/spec/command-logging-and-monitoring/monitoring/insertOne.yml b/test/spec/command-logging-and-monitoring/monitoring/insertOne.yml index cd4431295b1..77e0ef7e5ef 100644 --- a/test/spec/command-logging-and-monitoring/monitoring/insertOne.yml +++ b/test/spec/command-logging-and-monitoring/monitoring/insertOne.yml @@ -75,3 +75,41 @@ tests: # so those assertions are not present here. writeErrors: { $$type: array } commandName: insert + + - description: "A failed insertOne 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: 3, x: 33 } + expectError: + isClientError: false + expectEvents: + - client: *client + events: + - commandStartedEvent: + command: + insert: *collectionName + documents: + - { _id: 3, x: 33 } + ordered: true + commandName: insert + databaseName: *databaseName + - commandSucceededEvent: + reply: + ok: 1 + n: 1 + writeConcernError: { code: 91, errorLabels: [ "RetryableWriteError" ] } + commandName: insert \ No newline at end of file From 96c5c2363225f09857264b32246abf428f189cfb Mon Sep 17 00:00:00 2001 From: Durran Jordan Date: Tue, 17 Jan 2023 14:17:58 +0100 Subject: [PATCH 3/7] test: update unified tests --- src/sdam/server.ts | 3 +- .../monitoring/insertOne.json | 80 --------- .../monitoring/insertOne.yml | 38 ----- .../monitoring/writeConcernError.json | 155 ++++++++++++++++++ .../monitoring/writeConcernError.yml | 80 +++++++++ 5 files changed, 237 insertions(+), 119 deletions(-) create mode 100644 test/spec/command-logging-and-monitoring/monitoring/writeConcernError.json create mode 100644 test/spec/command-logging-and-monitoring/monitoring/writeConcernError.yml 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/spec/command-logging-and-monitoring/monitoring/insertOne.json b/test/spec/command-logging-and-monitoring/monitoring/insertOne.json index 7609665cdd2..6ff732e41be 100644 --- a/test/spec/command-logging-and-monitoring/monitoring/insertOne.json +++ b/test/spec/command-logging-and-monitoring/monitoring/insertOne.json @@ -139,86 +139,6 @@ ] } ] - }, - { - "description": "A failed insertOne 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": 3, - "x": 33 - } - }, - "expectError": { - "isClientError": false - } - } - ], - "expectEvents": [ - { - "client": "client", - "events": [ - { - "commandStartedEvent": { - "command": { - "insert": "test", - "documents": [ - { - "_id": 3, - "x": 33 - } - ], - "ordered": true - }, - "commandName": "insert", - "databaseName": "command-monitoring-tests" - } - }, - { - "commandSucceededEvent": { - "reply": { - "ok": 1, - "n": 1, - "writeConcernError": { - "code": 91, - "errorLabels": [ - "RetryableWriteError" - ] - } - }, - "commandName": "insert" - } - } - ] - } - ] } ] } diff --git a/test/spec/command-logging-and-monitoring/monitoring/insertOne.yml b/test/spec/command-logging-and-monitoring/monitoring/insertOne.yml index 77e0ef7e5ef..cd4431295b1 100644 --- a/test/spec/command-logging-and-monitoring/monitoring/insertOne.yml +++ b/test/spec/command-logging-and-monitoring/monitoring/insertOne.yml @@ -75,41 +75,3 @@ tests: # so those assertions are not present here. writeErrors: { $$type: array } commandName: insert - - - description: "A failed insertOne 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: 3, x: 33 } - expectError: - isClientError: false - expectEvents: - - client: *client - events: - - commandStartedEvent: - command: - insert: *collectionName - documents: - - { _id: 3, x: 33 } - ordered: true - commandName: insert - databaseName: *databaseName - - commandSucceededEvent: - reply: - ok: 1 - n: 1 - writeConcernError: { code: 91, errorLabels: [ "RetryableWriteError" ] } - commandName: insert \ No newline at end of file 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 From dcb1f77b0a44c93939bd460dec507c041c202cce Mon Sep 17 00:00:00 2001 From: Durran Jordan Date: Wed, 18 Jan 2023 20:08:06 +0100 Subject: [PATCH 4/7] test: update prose tests to await events --- .../retryable_writes.spec.prose.test.ts | 34 ++++++++----------- 1 file changed, 15 insertions(+), 19 deletions(-) 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 c50b79d4e86..e3b515acbda 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'; @@ -304,22 +306,10 @@ describe('Retryable Writes Spec Prose', () => { 'emits a command succeeded event for write concern errors with ok: 1', { requires: { topology: 'replicaset', mongodb: '>=4.2.9' } }, async () => { - const successListener = event => { - if (event.commandName === 'insert' && event.reply.writeConcernError) { - expect(event.reply.writeConcernError.code).to.equal(91); - } - }; - - const failureListener = event => { - if (event.commandName === 'insert') { - expect.fail('the insert must be retried after the first suceeded event'); - } - }; - // 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. - client.db('admin').command({ + await client.db('admin').command({ configureFailPoint: 'failCommand', mode: { times: 1 }, data: { @@ -331,15 +321,21 @@ describe('Retryable Writes Spec Prose', () => { } }); - client.addListener('commandSucceeded', successListener); - client.addListener('commandFailed', failureListener); + const willBeCommandSucceeded = once(client, 'commandSucceeded').catch(error => error); + const willBeCommandFailed = once(client, 'commandFailed', { + signal: AbortSignal.timeout(1000) + }).catch(error => error); const insertResult = await collection.insertOne({ _id: 1 }).catch(error => error); - // sinon.restore(); - client.removeListener('commandSucceeded', successListener); - client.removeListener('commandFailed', failureListener); - + 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.include('operation was aborted'); expect(insertResult).to.deep.equal({ acknowledged: true, insertedId: 1 }); } ); From ba0b21769418b72ec0d06eaff2266d8edabb36f8 Mon Sep 17 00:00:00 2001 From: Durran Jordan Date: Thu, 19 Jan 2023 11:51:53 +0100 Subject: [PATCH 5/7] test: update to use sleep --- .../retryable_writes.spec.prose.test.ts | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) 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 e3b515acbda..a2b528f969b 100644 --- a/test/integration/retryable-writes/retryable_writes.spec.prose.test.ts +++ b/test/integration/retryable-writes/retryable_writes.spec.prose.test.ts @@ -4,6 +4,8 @@ import { once } from 'node:events'; import { expect } from 'chai'; import * as sinon from 'sinon'; +import { sleep } from '../../tools/utils'; + import { Collection, MongoClient, @@ -322,9 +324,10 @@ describe('Retryable Writes Spec Prose', () => { }); const willBeCommandSucceeded = once(client, 'commandSucceeded').catch(error => error); - const willBeCommandFailed = once(client, 'commandFailed', { - signal: AbortSignal.timeout(1000) - }).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); @@ -335,7 +338,7 @@ describe('Retryable Writes Spec Prose', () => { expect( noCommandFailedEvent.message, 'expected timeout, since no failure event should emit' - ).to.include('operation was aborted'); + ).to.equal('timeout'); expect(insertResult).to.deep.equal({ acknowledged: true, insertedId: 1 }); } ); From dd98b50a4257bbd797b0c17ca89109e5b7d02b11 Mon Sep 17 00:00:00 2001 From: Durran Jordan Date: Thu, 19 Jan 2023 20:45:33 +0100 Subject: [PATCH 6/7] fix: fix lint error --- .../retryable-writes/retryable_writes.spec.prose.test.ts | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) 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 a2b528f969b..4bc11cfbb4e 100644 --- a/test/integration/retryable-writes/retryable_writes.spec.prose.test.ts +++ b/test/integration/retryable-writes/retryable_writes.spec.prose.test.ts @@ -4,8 +4,6 @@ import { once } from 'node:events'; import { expect } from 'chai'; import * as sinon from 'sinon'; -import { sleep } from '../../tools/utils'; - import { Collection, MongoClient, @@ -14,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.', () => { From 0d00e0eae3df57d24b76da3e94cb9003b44d5454 Mon Sep 17 00:00:00 2001 From: Daria Pardue Date: Thu, 19 Jan 2023 17:42:38 -0500 Subject: [PATCH 7/7] Update src/cmap/connection.ts --- src/cmap/connection.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 6ace4ed6638..f2d7fec5fe2 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -681,7 +681,7 @@ function write( operationDescription.started = now(); operationDescription.cb = (err, reply) => { // Command monitoring spec states that if ok is 1, then we must always emit - // a command suceeded event, even if there's and error. Write concern errors + // 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(