debugs

Author: baileympearson

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<Connection> {
+  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();

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<ServerEvents> {
     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);
         }

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' &&

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 @@
       ]
     }
   ]
-}
+}

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) => {

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);
+              }
+            }
+          );
+        }
       }
     });
   }