From 921778f7c61f74be4eae7d6c4d38bfe8ccd3a3d4 Mon Sep 17 00:00:00 2001 From: bailey Date: Thu, 13 Mar 2025 14:47:24 -0600 Subject: [PATCH 1/3] fix flakiness --- .../client-side-operations-timeout/runCursorCommand.json | 4 ++-- .../client-side-operations-timeout/runCursorCommand.yml | 8 ++++---- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/test/spec/client-side-operations-timeout/runCursorCommand.json b/test/spec/client-side-operations-timeout/runCursorCommand.json index 36f774fb5af..06d43579ac6 100644 --- a/test/spec/client-side-operations-timeout/runCursorCommand.json +++ b/test/spec/client-side-operations-timeout/runCursorCommand.json @@ -149,7 +149,7 @@ "getMore" ], "blockConnection": true, - "blockTimeMS": 60 + "blockTimeMS": 120 } } } @@ -159,7 +159,7 @@ "object": "db", "arguments": { "commandName": "find", - "timeoutMS": 100, + "timeoutMS": 200, "command": { "find": "collection", "batchSize": 2 diff --git a/test/spec/client-side-operations-timeout/runCursorCommand.yml b/test/spec/client-side-operations-timeout/runCursorCommand.yml index 91a18d6dd81..bdecd66f5d2 100644 --- a/test/spec/client-side-operations-timeout/runCursorCommand.yml +++ b/test/spec/client-side-operations-timeout/runCursorCommand.yml @@ -70,7 +70,7 @@ tests: runOnRequirements: - serverless: forbid operations: - # Block find/getMore for 60ms. + # Block find/getMore for 120ms. - name: failPoint object: testRunner arguments: @@ -81,16 +81,16 @@ tests: data: failCommands: [find, getMore] blockConnection: true - blockTimeMS: 60 + blockTimeMS: 120 # Run a find with timeoutMS less than double our failPoint blockTimeMS and # batchSize less than the total document count will cause a find and a - # getMore to be sent. Both will block for 60ms so together they will go + # getMore to be sent. Both will block for 120ms so together they will go # over the timeout. - name: runCursorCommand object: *db arguments: commandName: find - timeoutMS: 100 + timeoutMS: 200 command: { find: *collection, batchSize: 2 } expectError: isTimeoutError: true From 21bdda8cec89789e76516c813a77283af086598e Mon Sep 17 00:00:00 2001 From: bailey Date: Fri, 14 Mar 2025 09:46:42 -0600 Subject: [PATCH 2/3] debugs --- src/cmap/connect.ts | 7 ++++ src/sdam/server.ts | 5 +++ ...lient_side_operations_timeout.spec.test.ts | 26 ++++++++----- .../runCursorCommand.json | 6 +-- test/tools/unified-spec-runner/operations.ts | 16 +++++++- test/tools/unified-spec-runner/runner.ts | 39 +++++++++++-------- 6 files changed, 68 insertions(+), 31 deletions(-) diff --git a/src/cmap/connect.ts b/src/cmap/connect.ts index 394b70689ca..e6dbed04e81 100644 --- a/src/cmap/connect.ts +++ b/src/cmap/connect.ts @@ -35,12 +35,19 @@ import { /** @public */ export type Stream = Socket | TLSSocket; +export const log = (...args) => _log && console.error(...args); +export let _log = false; +export const enable = () => (_log = true); +export const disable = () => (_log = false); + export async function connect(options: ConnectionOptions): Promise { + const start = performance.now(); let connection: Connection | null = null; try { const socket = await makeSocket(options); connection = makeConnection(options, socket); await performInitialHandshake(connection, options); + log('established: ', performance.now() - start); return connection; } catch (error) { connection?.destroy(); diff --git a/src/sdam/server.ts b/src/sdam/server.ts index c6798316974..a2951516f7b 100644 --- a/src/sdam/server.ts +++ b/src/sdam/server.ts @@ -1,5 +1,6 @@ import type { Document } from '../bson'; import { type AutoEncrypter } from '../client-side-encryption/auto_encrypter'; +import { log } from '../cmap/connect'; import { type CommandOptions, Connection } from '../cmap/connection'; import { ConnectionPool, @@ -48,6 +49,7 @@ import { maxWireVersion, type MongoDBNamespace, noop, + now, squashError, supportsRetryableWrites } from '../utils'; @@ -320,7 +322,10 @@ export class Server extends TypedEventEmitter { this.incrementOperationCount(); if (conn == null) { try { + log('starting checkout, ', now()); conn = await this.pool.checkOut(options); + log('checked out', now()); + if (this.loadBalanced && isPinnableCommand(cmd, session)) { session?.pin(conn); } diff --git a/test/integration/client-side-operations-timeout/client_side_operations_timeout.spec.test.ts b/test/integration/client-side-operations-timeout/client_side_operations_timeout.spec.test.ts index a1b0791026d..ec6b59b8168 100644 --- a/test/integration/client-side-operations-timeout/client_side_operations_timeout.spec.test.ts +++ b/test/integration/client-side-operations-timeout/client_side_operations_timeout.spec.test.ts @@ -21,20 +21,26 @@ const skippedTests = { 'timeoutMS is refreshed for getMore if maxAwaitTimeMS is set': 'TODO(DRIVERS-3018)' }; -describe('CSOT spec tests', function () { - const specs = loadSpecTests('client-side-operations-timeout'); - for (const spec of specs) { - for (const test of spec.tests) { - if (skippedSpecs[spec.name] != null) { - test.skipReason = skippedSpecs[spec.name]; - } - if (skippedTests[test.description] != null) { - test.skipReason = skippedTests[test.description]; - } +const specs = loadSpecTests('client-side-operations-timeout'); +for (const spec of specs) { + for (const test of spec.tests) { + if (skippedSpecs[spec.name] != null) { + test.skipReason = skippedSpecs[spec.name]; + } + if (skippedTests[test.description] != null) { + test.skipReason = skippedTests[test.description]; } } +} +describe('CSOT spec tests', function () { runUnifiedSuite(specs, (test, configuration) => { + if ( + test.description !== + 'Non-tailable cursor lifetime remaining timeoutMS applied to getMore if timeoutMode is unset' + ) { + return 'skipped for now'; + } const sessionCSOTTests = ['timeoutMS applied to withTransaction']; if ( configuration.topologyType === 'LoadBalanced' && diff --git a/test/spec/client-side-operations-timeout/runCursorCommand.json b/test/spec/client-side-operations-timeout/runCursorCommand.json index 06d43579ac6..4fe068d3d86 100644 --- a/test/spec/client-side-operations-timeout/runCursorCommand.json +++ b/test/spec/client-side-operations-timeout/runCursorCommand.json @@ -149,7 +149,7 @@ "getMore" ], "blockConnection": true, - "blockTimeMS": 120 + "blockTimeMS": 60 } } } @@ -159,7 +159,7 @@ "object": "db", "arguments": { "commandName": "find", - "timeoutMS": 200, + "timeoutMS": 100, "command": { "find": "collection", "batchSize": 2 @@ -580,4 +580,4 @@ ] } ] -} +} \ No newline at end of file diff --git a/test/tools/unified-spec-runner/operations.ts b/test/tools/unified-spec-runner/operations.ts index f7c34a70239..ac10608968e 100644 --- a/test/tools/unified-spec-runner/operations.ts +++ b/test/tools/unified-spec-runner/operations.ts @@ -6,14 +6,19 @@ import { pipeline } from 'node:stream/promises'; import { AssertionError, expect } from 'chai'; import { + _log, type ChangeStream, Collection, CommandStartedEvent, Db, + disable, type Document, + enable, GridFSBucket, + log, type MongoClient, MongoError, + now, ReadConcern, ReadPreference, SERVER_DESCRIPTION_CHANGED, @@ -821,7 +826,16 @@ operations.set('runCursorCommand', async ({ entities, operation }: OperationFunc if (!Number.isNaN(+opts.maxTimeMS)) cursor.setMaxTimeMS(+opts.maxTimeMS); if (opts.comment !== undefined) cursor.setComment(opts.comment); - return cursor.toArray(); + enable(); + log('starting iteration'); + log(now()); + const result = await cursor.toArray().catch(e => { + log('finished', now()); + disable(); + + throw e; + }); + return result; }); operations.set('createCommandCursor', async ({ entities, operation }: OperationFunctionParams) => { diff --git a/test/tools/unified-spec-runner/runner.ts b/test/tools/unified-spec-runner/runner.ts index 84bea56766a..ea37452f263 100644 --- a/test/tools/unified-spec-runner/runner.ts +++ b/test/tools/unified-spec-runner/runner.ts @@ -319,23 +319,28 @@ export function runUnifiedSuite( for (const unifiedSuite of specTests) { context(String(unifiedSuite.description), function () { for (const [index, test] of unifiedSuite.tests.entries()) { - it(String(test.description === '' ? `Test ${index}` : test.description), async function () { - if (expectRuntimeError) { - const error = await runUnifiedTest(this, unifiedSuite, test, skipFilter).catch( - error => error - ); - expect(error).to.satisfy(value => { - return ( - value instanceof AssertionError || - value instanceof MongoServerError || - value instanceof TypeError || - value instanceof MongoParseError - ); - }); - } else { - await runUnifiedTest(this, unifiedSuite, test, skipFilter); - } - }); + for (let i = 0; i < 1000; ++i) { + it( + String(test.description === '' ? `Test ${index}` : test.description) + i, + async function () { + if (expectRuntimeError) { + const error = await runUnifiedTest(this, unifiedSuite, test, skipFilter).catch( + error => error + ); + expect(error).to.satisfy(value => { + return ( + value instanceof AssertionError || + value instanceof MongoServerError || + value instanceof TypeError || + value instanceof MongoParseError + ); + }); + } else { + await runUnifiedTest(this, unifiedSuite, test, skipFilter); + } + } + ); + } } }); } From 50563279637ed6a96e5e94d720805d9f4244f4f2 Mon Sep 17 00:00:00 2001 From: bailey Date: Fri, 14 Mar 2025 10:39:45 -0600 Subject: [PATCH 3/3] asdf --- .../runCursorCommand.json | 17 ++++++++++++++++- .../runCursorCommand.yml | 17 +++++++++++++---- 2 files changed, 29 insertions(+), 5 deletions(-) diff --git a/test/spec/client-side-operations-timeout/runCursorCommand.json b/test/spec/client-side-operations-timeout/runCursorCommand.json index 4fe068d3d86..64b6a9302ba 100644 --- a/test/spec/client-side-operations-timeout/runCursorCommand.json +++ b/test/spec/client-side-operations-timeout/runCursorCommand.json @@ -133,6 +133,16 @@ } ], "operations": [ + { + "name": "find", + "object": "collection", + "arguments": { + "filter": { + "_id": 0 + } + }, + "expectResult": [] + }, { "name": "failPoint", "object": "testRunner", @@ -174,6 +184,11 @@ { "client": "client", "events": [ + { + "commandStartedEvent": { + "commandName": "find" + } + }, { "commandStartedEvent": { "commandName": "find", @@ -580,4 +595,4 @@ ] } ] -} \ No newline at end of file +} diff --git a/test/spec/client-side-operations-timeout/runCursorCommand.yml b/test/spec/client-side-operations-timeout/runCursorCommand.yml index bdecd66f5d2..3ec0eb3619a 100644 --- a/test/spec/client-side-operations-timeout/runCursorCommand.yml +++ b/test/spec/client-side-operations-timeout/runCursorCommand.yml @@ -70,7 +70,13 @@ tests: runOnRequirements: - serverless: forbid operations: - # Block find/getMore for 120ms. + # pre-populate the pool with a connection + - name: find + object: collection + arguments: + filter: { _id: 0 } + expectResult: [] + # Block find/getMore for 60ms. - name: failPoint object: testRunner arguments: @@ -81,22 +87,25 @@ tests: data: failCommands: [find, getMore] blockConnection: true - blockTimeMS: 120 + blockTimeMS: 60 # Run a find with timeoutMS less than double our failPoint blockTimeMS and # batchSize less than the total document count will cause a find and a - # getMore to be sent. Both will block for 120ms so together they will go + # getMore to be sent. Both will block for 60ms so together they will go # over the timeout. - name: runCursorCommand object: *db arguments: commandName: find - timeoutMS: 200 + timeoutMS: 100 command: { find: *collection, batchSize: 2 } expectError: isTimeoutError: true expectEvents: - client: *client events: + # first find is from the initial find to populate the connection poo + - commandStartedEvent: + commandName: find - commandStartedEvent: commandName: find command: