feat(NODE-5459): add durations to connection pool events

src/cmap/connection_pool.ts

@@ -162,6 +162,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
   [kWaitQueue]: List<WaitQueueMember>;
   [kMetrics]: ConnectionPoolMetrics;
   [kProcessingWaitQueue]: boolean;
+  checkOutTime: undefined | number;
 
   /**
    * Emitted when the connection pool is created.
@@ -355,6 +356,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
    * explicitly destroyed by the new owner.
    */
   async checkOut(): Promise<Connection> {
+    this.checkOutTime = Date.now();
     this.emitAndLog(
       ConnectionPool.CONNECTION_CHECK_OUT_STARTED,
       new ConnectionCheckOutStartedEvent(this)
@@ -629,6 +631,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
 
     this[kPending]++;
     // This is our version of a "virtual" no-I/O connection as the spec requires
+    const connectionCreatedTime = Date.now();
     this.emitAndLog(
       ConnectionPool.CONNECTION_CREATED,
       new ConnectionCreatedEvent(this, { id: connectOptions.id })
@@ -670,7 +673,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
         connection.markAvailable();
         this.emitAndLog(
           ConnectionPool.CONNECTION_READY,
-          new ConnectionReadyEvent(this, connection)
+          new ConnectionReadyEvent(this, connection, connectionCreatedTime)
         );
 
         this[kPending]--;

src/cmap/connection_pool_events.ts

@@ -126,12 +126,25 @@ export class ConnectionCreatedEvent extends ConnectionPoolMonitoringEvent {
 export class ConnectionReadyEvent extends ConnectionPoolMonitoringEvent {
   /** The id of the connection */
   connectionId: number | '<monitor>';
+  /**
+   * The time it took to establish the connection.
+   * In accordance with the definition of establishment of a connection
+   * specified by `ConnectionPoolOptions.maxConnecting`,
+   * it is the time elapsed between emitting a `ConnectionCreatedEvent`
+   * and emitting this event as part of the same checking out.
+   *
+   * Naturally, when establishing a connection is part of checking out,
+   * this duration is not greater than
+   * `ConnectionCheckedOutEvent.duration`.
+   */
+  durationMS: number;
   /** @internal */
   name = CONNECTION_READY;
 
   /** @internal */
-  constructor(pool: ConnectionPool, connection: Connection) {
+  constructor(pool: ConnectionPool, connection: Connection, connectionCreatedEventTime: number) {
     super(pool);
+    this.durationMS = Date.now() - connectionCreatedEventTime;
     this.connectionId = connection.id;
   }
 }
@@ -194,6 +207,20 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent
   error?: MongoError;
   /** @internal */
   name = CONNECTION_CHECK_OUT_FAILED;
+  /**
+   * The time it took to check out the connection.
+   * More specifically, the time elapsed between
+   * emitting a `ConnectionCheckOutStartedEvent`
+   * and emitting this event as part of the same checking out.
+   *
+   * Naturally, if a new connection was not created (`ConnectionCreatedEvent`)
+   * and established (`ConnectionReadyEvent`) as part of checking out,
+   * this duration is usually
+   * not greater than `ConnectionPoolOptions.waitQueueTimeoutMS`,
+   * but MAY occasionally be greater than that,
+   * because a driver does not provide hard real-time guarantees.
+   */
+  durationMS: number;
 
   /** @internal */
   constructor(
@@ -202,6 +229,7 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent
     error?: MongoError
   ) {
     super(pool);
+    this.durationMS = Date.now() - (pool.checkOutTime ?? 0);
     this.reason = reason;
     this.error = error;
   }
@@ -217,10 +245,25 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent {
   connectionId: number | '<monitor>';
   /** @internal */
   name = CONNECTION_CHECKED_OUT;
+  /**
+   * The time it took to check out the connection.
+   * More specifically, the time elapsed between
+   * emitting a `ConnectionCheckOutStartedEvent`
+   * and emitting this event as part of the same checking out.
+   *
+   * Naturally, if a new connection was not created (`ConnectionCreatedEvent`)
+   * and established (`ConnectionReadyEvent`) as part of checking out,
+   * this duration is usually
+   * not greater than `ConnectionPoolOptions.waitQueueTimeoutMS`,
+   * but MAY occasionally be greater than that,
+   * because a driver does not provide hard real-time guarantees.
+   */
+  durationMS: number;
 
   /** @internal */
   constructor(pool: ConnectionPool, connection: Connection) {
     super(pool);
+    this.durationMS = Date.now() - (pool.checkOutTime ?? 0);
     this.connectionId = connection.id;
   }
 }

src/mongo_logger.ts

@@ -604,6 +604,7 @@ export function defaultLogTransform(
       log = attachConnectionFields(log, logObject);
       log.message = 'Connection ready';
       log.driverConnectionId = logObject.connectionId;
+      log.durationMS = logObject.durationMS;
       return log;
     case CONNECTION_CLOSED:
       log = attachConnectionFields(log, logObject);
@@ -653,11 +654,13 @@ export function defaultLogTransform(
         default:
           log.reason = `Unknown close reason: ${logObject.reason}`;
       }
+      log.durationMS = logObject.durationMS;
       return log;
     case CONNECTION_CHECKED_OUT:
       log = attachConnectionFields(log, logObject);
       log.message = 'Connection checked out';
       log.driverConnectionId = logObject.connectionId;
+      log.durationMS = logObject.durationMS;
       return log;
     case CONNECTION_CHECKED_IN:
       log = attachConnectionFields(log, logObject);

test/integration/connection-monitoring-and-pooling/unified-cmap-node-specs/connection-logging.json

@@ -191,6 +191,13 @@
                     "long"
                   ]
                 },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
+                },
                 "reason": "An error occurred while trying to establish a new connection",
                 "error": {
                   "$$exists": true

test/integration/retryable-writes/retryable_writes.spec.test.ts

@@ -63,7 +63,6 @@ describe('Legacy Retryable Writes Specs', function () {
         await ctx.client.close();
         ctx = {}; // reset context
       });
-
       for (const spec of suite.tests) {
         // Step 2: Run the test
         const mochaTest = it(spec.description, async () => await executeScenarioTest(spec, ctx));

test/spec/connection-monitoring-and-pooling/logging/connection-logging.json

@@ -140,6 +140,13 @@
                     "int",
                     "long"
                   ]
+                },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
                 }
               }
             },
@@ -162,6 +169,13 @@
                     "int",
                     "long"
                   ]
+                },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
                 }
               }
             },
@@ -222,6 +236,13 @@
                     "int",
                     "long"
                   ]
+                },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
                 }
               }
             },
@@ -484,6 +505,13 @@
                 "reason": "An error occurred while trying to establish a new connection",
                 "error": {
                   "$$exists": true
+                },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
                 }
               }
             }

test/spec/connection-monitoring-and-pooling/logging/connection-logging.yml

@@ -66,6 +66,7 @@ tests:
               driverConnectionId: { $$type: [int, long] }
               serverHost: { $$type: string }
               serverPort: { $$type: [int, long] }
+              durationMS: { $$type: [double, int, long] }
 
           - level: debug
             component: connection
@@ -74,6 +75,7 @@ tests:
               driverConnectionId: { $$type: [int, long] }
               serverHost: { $$type: string }
               serverPort: { $$type: [int, long] }
+              durationMS: { $$type: [double, int, long] }
 
           - level: debug
             component: connection
@@ -98,6 +100,7 @@ tests:
               driverConnectionId: { $$type: [int, long] }
               serverHost: { $$type: string }
               serverPort: { $$type: [int, long] }
+              durationMS: { $$type: [double, int, long] }
 
           - level: debug
             component: connection
@@ -218,3 +221,4 @@ tests:
               serverPort: { $$type: [int, long] }
               reason: "An error occurred while trying to establish a new connection"
               error: { $$exists: true }
+              durationMS: { $$type: [double, int, long] }

test/spec/connection-monitoring-and-pooling/logging/connection-pool-options.json

@@ -128,6 +128,13 @@
                     "int",
                     "long"
                   ]
+                },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
                 }
               }
             }

test/spec/connection-monitoring-and-pooling/logging/connection-pool-options.yml

@@ -71,6 +71,7 @@ tests:
               driverConnectionId: { $$type: [int, long] }
               serverHost: { $$type: string }
               serverPort: { $$type: [int, long] }
+              durationMS: { $$type: [double, int, long] }
 
   # Drivers who have not done DRIVERS-1943 will need to skip this test.
   - description: "maxConnecting should be included in connection pool created message when specified"