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

Co-authored-by: Neal Beeken <neal.beeken@mongodb.com>

src/cmap/connection_pool.ts

@@ -27,7 +27,7 @@ import {
 import { CancellationToken, TypedEventEmitter } from '../mongo_types';
 import type { Server } from '../sdam/server';
 import { Timeout, TimeoutError } from '../timeout';
-import { type Callback, List, makeCounter, promiseWithResolvers } from '../utils';
+import { type Callback, List, makeCounter, now, promiseWithResolvers } from '../utils';
 import { connect } from './connect';
 import { Connection, type ConnectionEvents, type ConnectionOptions } from './connection';
 import {
@@ -104,6 +104,7 @@ export interface WaitQueueMember {
   reject: (err: AnyError) => void;
   timeout: Timeout;
   [kCancelled]?: boolean;
+  checkoutTime: number;
 }
 
 /** @internal */
@@ -355,6 +356,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
    * explicitly destroyed by the new owner.
    */
   async checkOut(): Promise<Connection> {
+    const checkoutTime = now();
     this.emitAndLog(
       ConnectionPool.CONNECTION_CHECK_OUT_STARTED,
       new ConnectionCheckOutStartedEvent(this)
@@ -369,7 +371,8 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
     const waitQueueMember: WaitQueueMember = {
       resolve,
       reject,
-      timeout
+      timeout,
+      checkoutTime
     };
 
     this[kWaitQueue].push(waitQueueMember);
@@ -385,7 +388,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
 
         this.emitAndLog(
           ConnectionPool.CONNECTION_CHECK_OUT_FAILED,
-          new ConnectionCheckOutFailedEvent(this, 'timeout')
+          new ConnectionCheckOutFailedEvent(this, 'timeout', waitQueueMember.checkoutTime)
         );
         const timeoutError = new WaitQueueTimeoutError(
           this.loadBalanced
@@ -629,6 +632,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 = now();
     this.emitAndLog(
       ConnectionPool.CONNECTION_CREATED,
       new ConnectionCreatedEvent(this, { id: connectOptions.id })
@@ -670,7 +674,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]--;
@@ -759,7 +763,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
         const error = this.closed ? new PoolClosedError(this) : new PoolClearedError(this);
         this.emitAndLog(
           ConnectionPool.CONNECTION_CHECK_OUT_FAILED,
-          new ConnectionCheckOutFailedEvent(this, reason, error)
+          new ConnectionCheckOutFailedEvent(this, reason, waitQueueMember.checkoutTime, error)
         );
         waitQueueMember.timeout.clear();
         this[kWaitQueue].shift();
@@ -780,7 +784,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
         this[kCheckedOut].add(connection);
         this.emitAndLog(
           ConnectionPool.CONNECTION_CHECKED_OUT,
-          new ConnectionCheckedOutEvent(this, connection)
+          new ConnectionCheckedOutEvent(this, connection, waitQueueMember.checkoutTime)
         );
         waitQueueMember.timeout.clear();
 
@@ -809,14 +813,19 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
             this.emitAndLog(
               ConnectionPool.CONNECTION_CHECK_OUT_FAILED,
               // TODO(NODE-5192): Remove this cast
-              new ConnectionCheckOutFailedEvent(this, 'connectionError', err as MongoError)
+              new ConnectionCheckOutFailedEvent(
+                this,
+                'connectionError',
+                waitQueueMember.checkoutTime,
+                err as MongoError
+              )
             );
             waitQueueMember.reject(err);
           } else if (connection) {
             this[kCheckedOut].add(connection);
             this.emitAndLog(
               ConnectionPool.CONNECTION_CHECKED_OUT,
-              new ConnectionCheckedOutEvent(this, connection)
+              new ConnectionCheckedOutEvent(this, connection, waitQueueMember.checkoutTime)
             );
             waitQueueMember.resolve(connection);
           }

src/cmap/connection_pool_events.ts

@@ -13,6 +13,7 @@ import {
   CONNECTION_READY
 } from '../constants';
 import type { MongoError } from '../error';
+import { now } from '../utils';
 import type { Connection } from './connection';
 import type { ConnectionPool, ConnectionPoolOptions } from './connection_pool';
 
@@ -126,12 +127,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 = now() - connectionCreatedEventTime;
     this.connectionId = connection.id;
   }
 }
@@ -194,14 +208,23 @@ 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 check out.
+   */
+  durationMS: number;
 
   /** @internal */
   constructor(
     pool: ConnectionPool,
     reason: 'poolClosed' | 'timeout' | 'connectionError',
+    checkoutTime: number,
     error?: MongoError
   ) {
     super(pool);
+    this.durationMS = now() - checkoutTime;
     this.reason = reason;
     this.error = error;
   }
@@ -217,10 +240,19 @@ 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.
+   *
+   */
+  durationMS: number;
 
   /** @internal */
-  constructor(pool: ConnectionPool, connection: Connection) {
+  constructor(pool: ConnectionPool, connection: Connection, checkoutTime: number) {
     super(pool);
+    this.durationMS = now() - checkoutTime;
     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"