feat(NODE-4720): Add log messages to CMAP spec

src/cmap/connection_pool.ts

@@ -252,7 +252,9 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
     this[kProcessingWaitQueue] = false;
 
     process.nextTick(() => {
-      this.emit(ConnectionPool.CONNECTION_POOL_CREATED, new ConnectionPoolCreatedEvent(this));
+      const connectionPoolCreatedEvent = new ConnectionPoolCreatedEvent(this);
+      this.emit(ConnectionPool.CONNECTION_POOL_CREATED, connectionPoolCreatedEvent);
+      this.client.mongoLogger.debug('connection', connectionPoolCreatedEvent);
     });
   }
 
@@ -322,6 +324,9 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
     return this[kCheckedOut];
   }
 
+  get client() {
+    return this[kServer].s.topology.client;
+  }
   /**
    * Get the metrics information for the pool when a wait queue timeout occurs.
    */
@@ -337,7 +342,9 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
       return;
     }
     this[kPoolState] = PoolState.ready;
-    this.emit(ConnectionPool.CONNECTION_POOL_READY, new ConnectionPoolReadyEvent(this));
+    const connectionPoolReadyEvent = new ConnectionPoolReadyEvent(this);
+    this.emit(ConnectionPool.CONNECTION_POOL_READY, connectionPoolReadyEvent);
+    this.client.mongoLogger.debug('connection', connectionPoolReadyEvent);
     clearTimeout(this[kMinPoolSizeTimer]);
     this.ensureMinPoolSize();
   }
@@ -348,10 +355,9 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
    * explicitly destroyed by the new owner.
    */
   checkOut(callback: Callback<Connection>): void {
-    this.emit(
-      ConnectionPool.CONNECTION_CHECK_OUT_STARTED,
-      new ConnectionCheckOutStartedEvent(this)
-    );
+    const connectionCheckOutStartedEvent = new ConnectionCheckOutStartedEvent(this);
+    this.emit(ConnectionPool.CONNECTION_CHECK_OUT_STARTED, connectionCheckOutStartedEvent);
+    this.client.mongoLogger.debug('connection', connectionCheckOutStartedEvent);
 
     const waitQueueMember: WaitQueueMember = { callback };
     const waitQueueTimeoutMS = this.options.waitQueueTimeoutMS;
@@ -360,10 +366,9 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
         waitQueueMember[kCancelled] = true;
         waitQueueMember.timer = undefined;
 
-        this.emit(
-          ConnectionPool.CONNECTION_CHECK_OUT_FAILED,
-          new ConnectionCheckOutFailedEvent(this, 'timeout')
-        );
+        const connectionCheckOutFailedEvent = new ConnectionCheckOutFailedEvent(this, 'timeout');
+        this.emit(ConnectionPool.CONNECTION_CHECK_OUT_FAILED, connectionCheckOutFailedEvent);
+        this.client.mongoLogger.debug('connection', connectionCheckOutFailedEvent);
         waitQueueMember.callback(
           new WaitQueueTimeoutError(
             this.loadBalanced
@@ -398,7 +403,9 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
     }
 
     this[kCheckedOut].delete(connection);
-    this.emit(ConnectionPool.CONNECTION_CHECKED_IN, new ConnectionCheckedInEvent(this, connection));
+    const connectionCheckedInEvent = new ConnectionCheckedInEvent(this, connection);
+    this.emit(ConnectionPool.CONNECTION_CHECKED_IN, connectionCheckedInEvent);
+    this.client.mongoLogger.debug('connection', connectionCheckedInEvent);
 
     if (willDestroy) {
       const reason = connection.closed ? 'error' : poolClosed ? 'poolClosed' : 'stale';
@@ -437,10 +444,9 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
         // Increment the generation for the service id.
         this.serviceGenerations.set(sid, generation + 1);
       }
-      this.emit(
-        ConnectionPool.CONNECTION_POOL_CLEARED,
-        new ConnectionPoolClearedEvent(this, { serviceId })
-      );
+      const connectionPoolClearedEvent = new ConnectionPoolClearedEvent(this, { serviceId });
+      this.emit(ConnectionPool.CONNECTION_POOL_CLEARED, connectionPoolClearedEvent);
+      this.client.mongoLogger.debug('connection', connectionPoolClearedEvent);
       return;
     }
     // handle non load-balanced case
@@ -452,10 +458,11 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
 
     this.clearMinPoolSizeTimer();
     if (!alreadyPaused) {
-      this.emit(
-        ConnectionPool.CONNECTION_POOL_CLEARED,
-        new ConnectionPoolClearedEvent(this, { interruptInUseConnections })
-      );
+      const connectionPoolClearedEvent = new ConnectionPoolClearedEvent(this, {
+        interruptInUseConnections
+      });
+      this.emit(ConnectionPool.CONNECTION_POOL_CLEARED, connectionPoolClearedEvent);
+      this.client.mongoLogger.debug('connection', connectionPoolClearedEvent);
     }
 
     if (interruptInUseConnections) {
@@ -509,15 +516,16 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
     eachAsync<Connection>(
       this[kConnections].toArray(),
       (conn, cb) => {
-        this.emit(
-          ConnectionPool.CONNECTION_CLOSED,
-          new ConnectionClosedEvent(this, conn, 'poolClosed')
-        );
+        const connectionClosedEvent = new ConnectionClosedEvent(this, conn, 'poolClosed');
+        this.emit(ConnectionPool.CONNECTION_CLOSED, connectionClosedEvent);
+        this.client.mongoLogger.debug('connection', connectionClosedEvent);
         conn.destroy({ force: !!options.force }, cb);
       },
       err => {
         this[kConnections].clear();
-        this.emit(ConnectionPool.CONNECTION_POOL_CLOSED, new ConnectionPoolClosedEvent(this));
+        const poolClosedEvent = new ConnectionPoolClosedEvent(this);
+        this.emit(ConnectionPool.CONNECTION_POOL_CLOSED, poolClosedEvent);
+        this.client.mongoLogger.debug('connection', poolClosedEvent);
         callback(err);
       }
     );
@@ -645,10 +653,9 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
     connection: Connection,
     reason: 'error' | 'idle' | 'stale' | 'poolClosed'
   ) {
-    this.emit(
-      ConnectionPool.CONNECTION_CLOSED,
-      new ConnectionClosedEvent(this, connection, reason)
-    );
+    const connectionClosedEvent = new ConnectionClosedEvent(this, connection, reason);
+    this.emit(ConnectionPool.CONNECTION_CLOSED, connectionClosedEvent);
+    this.client.mongoLogger.debug('connection', connectionClosedEvent);
     // destroy the connection
     process.nextTick(() => connection.destroy({ force: false }));
   }
@@ -694,24 +701,22 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
 
     this[kPending]++;
     // This is our version of a "virtual" no-I/O connection as the spec requires
-    this.emit(
-      ConnectionPool.CONNECTION_CREATED,
-      new ConnectionCreatedEvent(this, { id: connectOptions.id })
-    );
+    const connectionCreatedEvent = new ConnectionCreatedEvent(this, { id: connectOptions.id });
+    this.emit(ConnectionPool.CONNECTION_CREATED, connectionCreatedEvent);
+    this.client.mongoLogger.debug('connection', connectionCreatedEvent);
 
     connect(connectOptions, (err, connection) => {
       if (err || !connection) {
         this[kPending]--;
-        this.emit(
-          ConnectionPool.CONNECTION_CLOSED,
-          new ConnectionClosedEvent(
-            this,
-            { id: connectOptions.id, serviceId: undefined },
-            'error',
-            // TODO(NODE-5192): Remove this cast
-            err as MongoError
-          )
+        const connectionClosedEvent = new ConnectionClosedEvent(
+          this,
+          { id: connectOptions.id, serviceId: undefined },
+          'error',
+          // TODO(NODE-5192): Remove this cast
+          err as MongoError
         );
+        this.emit(ConnectionPool.CONNECTION_CLOSED, connectionClosedEvent);
+        this.client.mongoLogger.debug('connection', connectionClosedEvent);
         if (err instanceof MongoNetworkError || err instanceof MongoServerError) {
           err.connectionGeneration = connectOptions.generation;
         }
@@ -729,7 +734,12 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
 
       // forward all events from the connection to the pool
       for (const event of [...APM_EVENTS, Connection.CLUSTER_TIME_RECEIVED]) {
-        connection.on(event, (e: any) => this.emit(event, e));
+        connection.on(event, (e: any) => {
+          this.emit(event, e);
+          if (event !== Connection.CLUSTER_TIME_RECEIVED) {
+            this.client.mongoLogger.debug('command', event);
+          }
+        });
       }
 
       if (this.loadBalanced) {
@@ -750,7 +760,9 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
       }
 
       connection.markAvailable();
-      this.emit(ConnectionPool.CONNECTION_READY, new ConnectionReadyEvent(this, connection));
+      const connectionReadyEvent = new ConnectionReadyEvent(this, connection);
+      this.emit(ConnectionPool.CONNECTION_READY, connectionReadyEvent);
+      this.client.mongoLogger.debug('connection', connectionReadyEvent);
 
       this[kPending]--;
       callback(undefined, connection);
@@ -819,10 +831,13 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
       if (this[kPoolState] !== PoolState.ready) {
         const reason = this.closed ? 'poolClosed' : 'connectionError';
         const error = this.closed ? new PoolClosedError(this) : new PoolClearedError(this);
-        this.emit(
-          ConnectionPool.CONNECTION_CHECK_OUT_FAILED,
-          new ConnectionCheckOutFailedEvent(this, reason, error)
+        const connectionCheckOutFailedEvent = new ConnectionCheckOutFailedEvent(
+          this,
+          reason,
+          error
         );
+        this.emit(ConnectionPool.CONNECTION_CHECK_OUT_FAILED, connectionCheckOutFailedEvent);
+        this.client.mongoLogger.debug('connection', connectionCheckOutFailedEvent);
         if (waitQueueMember.timer) {
           clearTimeout(waitQueueMember.timer);
         }
@@ -842,10 +857,9 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
 
       if (!this.destroyConnectionIfPerished(connection)) {
         this[kCheckedOut].add(connection);
-        this.emit(
-          ConnectionPool.CONNECTION_CHECKED_OUT,
-          new ConnectionCheckedOutEvent(this, connection)
-        );
+        const connectionCheckedOutEvent = new ConnectionCheckedOutEvent(this, connection);
+        this.emit(ConnectionPool.CONNECTION_CHECKED_OUT, connectionCheckedOutEvent);
+        this.client.mongoLogger.debug('connection', connectionCheckedOutEvent);
         if (waitQueueMember.timer) {
           clearTimeout(waitQueueMember.timer);
         }
@@ -872,17 +886,19 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
           }
         } else {
           if (err) {
-            this.emit(
-              ConnectionPool.CONNECTION_CHECK_OUT_FAILED,
-              // TODO(NODE-5192): Remove this cast
-              new ConnectionCheckOutFailedEvent(this, 'connectionError', err as MongoError)
+            // TODO(NODE-5192): Remove this cast
+            const connectionCheckOutFailedEvent = new ConnectionCheckOutFailedEvent(
+              this,
+              'connectionError',
+              err as MongoError
             );
+            this.emit(ConnectionPool.CONNECTION_CHECK_OUT_FAILED, connectionCheckOutFailedEvent);
+            this.client.mongoLogger.debug('connection', connectionCheckOutFailedEvent);
           } else if (connection) {
             this[kCheckedOut].add(connection);
-            this.emit(
-              ConnectionPool.CONNECTION_CHECKED_OUT,
-              new ConnectionCheckedOutEvent(this, connection)
-            );
+            const connectionCheckedOutEvent = new ConnectionCheckedOutEvent(this, connection);
+            this.emit(ConnectionPool.CONNECTION_CHECKED_OUT, connectionCheckedOutEvent);
+            this.client.mongoLogger.debug('connection', connectionCheckedOutEvent);
           }
 
           if (waitQueueMember.timer) {

test/integration/connection-monitoring-and-pooling/connection_monitoring_and_pooling.spec.test.ts

@@ -1,5 +1,6 @@
 import { loadSpecTests } from '../../spec';
 import { CmapTest, runCmapTestSuite, SkipDescription } from '../../tools/cmap_spec_runner';
+import { runUnifiedSuite } from '../../tools/unified-spec-runner/runner';
 
 // These tests rely on a simple "pool.clear()" command, which is not sufficient
 // to properly clear the pool in LB mode, since it requires a serviceId to be passed in
@@ -28,15 +29,15 @@ const INTERRUPT_IN_USE_SKIPPED_TESTS: SkipDescription[] = [
   },
   {
     description:
-      'Pool clear SHOULD schedule the next background thread run immediately (interruptInUseConnections: false)',
+      'Pool clear SHOULD schedule the next background thread run immediately (interruptInUseConnections = false)',
     skipIfCondition: 'always',
     skipReason:
       'NodeJS does not have a background thread responsible for managing connections, and so already checked in connections are not pruned when in-use connections are interrupted.'
   }
 ];
 
-describe('Connection Monitoring and Pooling Spec Tests (Integration)', function () {
-  const tests: CmapTest[] = loadSpecTests('connection-monitoring-and-pooling');
+describe('Connection Monitoring and Pooling Spec Tests (Integration) - cmap-format', function () {
+  const tests: CmapTest[] = loadSpecTests('connection-monitoring-and-pooling', 'cmap-format');
 
   runCmapTestSuite(tests, {
     testsToSkip: LB_SKIP_TESTS.concat(
@@ -52,3 +53,19 @@ describe('Connection Monitoring and Pooling Spec Tests (Integration)', function
     )
   });
 });
+
+describe('Connection Monitoring and Pooling Spec Tests (Integration) - logging', function () {
+  const tests = loadSpecTests('connection-monitoring-and-pooling', 'logging');
+
+  runUnifiedSuite(tests, (test: { description: string }) => {
+    if (
+      [
+        'waitQueueMultiple should be included in connection pool created message when specified',
+        'waitQueueSize should be included in connection pool created message when specified'
+      ].includes(test.description)
+    ) {
+      return 'not applicable: waitQueueSize not supported';
+    }
+    return false;
+  });
+});

test/spec/connection-monitoring-and-pooling/pool-clear-interrupt-immediately.json → test/spec/connection-monitoring-and-pooling/cmap-format/pool-clear-interrupt-immediately.json

@@ -24,7 +24,7 @@
       "name": "waitForEvent",
       "event": "ConnectionPoolCleared",
       "count": 1,
-      "timeout": 1000      
+      "timeout": 1000
     },
     {
       "name": "waitForEvent",

test/spec/connection-monitoring-and-pooling/pool-clear-interrupting-pending-connections.json → test/spec/connection-monitoring-and-pooling/cmap-format/pool-clear-interrupting-pending-connections.json

@@ -56,7 +56,7 @@
     },
     {
       "type": "ConnectionCreated"
-    },    
+    },
     {
       "type": "ConnectionPoolCleared",
       "interruptInUseConnections": true

test/spec/connection-monitoring-and-pooling/pool-clear-schedule-run-interruptInUseConnections-false.json → test/spec/connection-monitoring-and-pooling/cmap-format/pool-clear-schedule-run-interruptInUseConnections-false.json

@@ -1,7 +1,7 @@
 {
   "version": 1,
   "style": "unit",
-  "description": "Pool clear SHOULD schedule the next background thread run immediately (interruptInUseConnections: false)",
+  "description": "Pool clear SHOULD schedule the next background thread run immediately (interruptInUseConnections = false)",
   "poolOptions": {
     "backgroundThreadIntervalMS": 10000
   },
@@ -28,7 +28,7 @@
       "name": "waitForEvent",
       "event": "ConnectionPoolCleared",
       "count": 1,
-      "timeout": 1000      
+      "timeout": 1000
     },
     {
       "name": "waitForEvent",

test/spec/connection-monitoring-and-pooling/pool-clear-schedule-run-interruptInUseConnections-false.yml → test/spec/connection-monitoring-and-pooling/cmap-format/pool-clear-schedule-run-interruptInUseConnections-false.yml

@@ -1,6 +1,6 @@
 version: 1
 style: unit
-description: Pool clear SHOULD schedule the next background thread run immediately (interruptInUseConnections: false)
+description: Pool clear SHOULD schedule the next background thread run immediately (interruptInUseConnections = false)
 poolOptions:
   # ensure it's not involved by default
   backgroundThreadIntervalMS: 10000