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 36f774fb5af..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", diff --git a/test/spec/client-side-operations-timeout/runCursorCommand.yml b/test/spec/client-side-operations-timeout/runCursorCommand.yml index 91a18d6dd81..3ec0eb3619a 100644 --- a/test/spec/client-side-operations-timeout/runCursorCommand.yml +++ b/test/spec/client-side-operations-timeout/runCursorCommand.yml @@ -70,6 +70,12 @@ tests: runOnRequirements: - serverless: forbid operations: + # 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 @@ -97,6 +103,9 @@ tests: expectEvents: - client: *client events: + # first find is from the initial find to populate the connection poo + - commandStartedEvent: + commandName: find - commandStartedEvent: commandName: find command: 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); + } + } + ); + } } }); }