diff --git a/src/cmap/connection_pool.ts b/src/cmap/connection_pool.ts index f91e1361f6..2a66c9244f 100644 --- a/src/cmap/connection_pool.ts +++ b/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 { * explicitly destroyed by the new owner. */ async checkOut(): Promise { + const checkoutTime = now(); this.emitAndLog( ConnectionPool.CONNECTION_CHECK_OUT_STARTED, new ConnectionCheckOutStartedEvent(this) @@ -369,7 +371,8 @@ export class ConnectionPool extends TypedEventEmitter { const waitQueueMember: WaitQueueMember = { resolve, reject, - timeout + timeout, + checkoutTime }; this[kWaitQueue].push(waitQueueMember); @@ -385,7 +388,7 @@ export class ConnectionPool extends TypedEventEmitter { 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 { 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 { 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 { 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 { 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 { 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); } diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index 379bc2d521..5b8c4093cf 100644 --- a/src/cmap/connection_pool_events.ts +++ b/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 | ''; + /** + * 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 | ''; /** @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; } } diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 2310ce8448..abac20d846 100644 --- a/src/mongo_logger.ts +++ b/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); diff --git a/test/integration/connection-monitoring-and-pooling/unified-cmap-node-specs/connection-logging.json b/test/integration/connection-monitoring-and-pooling/unified-cmap-node-specs/connection-logging.json index bda7186886..26900e3745 100644 --- a/test/integration/connection-monitoring-and-pooling/unified-cmap-node-specs/connection-logging.json +++ b/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 diff --git a/test/integration/retryable-writes/retryable_writes.spec.test.ts b/test/integration/retryable-writes/retryable_writes.spec.test.ts index a8e1412584..0ba83bcdb9 100644 --- a/test/integration/retryable-writes/retryable_writes.spec.test.ts +++ b/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)); diff --git a/test/spec/connection-monitoring-and-pooling/logging/connection-logging.json b/test/spec/connection-monitoring-and-pooling/logging/connection-logging.json index b3d48f56b7..72103b3cab 100644 --- a/test/spec/connection-monitoring-and-pooling/logging/connection-logging.json +++ b/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" + ] } } } diff --git a/test/spec/connection-monitoring-and-pooling/logging/connection-logging.yml b/test/spec/connection-monitoring-and-pooling/logging/connection-logging.yml index 1134c34b42..49868a062e 100644 --- a/test/spec/connection-monitoring-and-pooling/logging/connection-logging.yml +++ b/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] } diff --git a/test/spec/connection-monitoring-and-pooling/logging/connection-pool-options.json b/test/spec/connection-monitoring-and-pooling/logging/connection-pool-options.json index aff88f5bfd..7055a54869 100644 --- a/test/spec/connection-monitoring-and-pooling/logging/connection-pool-options.json +++ b/test/spec/connection-monitoring-and-pooling/logging/connection-pool-options.json @@ -128,6 +128,13 @@ "int", "long" ] + }, + "durationMS": { + "$$type": [ + "double", + "int", + "long" + ] } } } diff --git a/test/spec/connection-monitoring-and-pooling/logging/connection-pool-options.yml b/test/spec/connection-monitoring-and-pooling/logging/connection-pool-options.yml index 5fa7ac2297..790dab6fed 100644 --- a/test/spec/connection-monitoring-and-pooling/logging/connection-pool-options.yml +++ b/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"