From a3c6eb98b1ad05cac60b6e8afe39e5b93bc2480c Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Mon, 1 Jul 2024 10:11:19 -0400 Subject: [PATCH 1/9] feat(NODE-5459): add durations to connection pool events --- src/cmap/connection.ts | 2 + src/cmap/connection_pool.ts | 3 +- src/cmap/connection_pool_events.ts | 45 ++++++++++++++++++- ...ection_monitoring_and_pooling.spec.test.ts | 4 +- 4 files changed, 50 insertions(+), 4 deletions(-) diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 1e4afc7f387..8a2efd4ac02 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -191,6 +191,7 @@ export class Connection extends TypedEventEmitter { private lastUseTime: number; private clusterTime: Document | null = null; + private error: Error | null = null; private dataEvents: AsyncGenerator | null = null; @@ -229,6 +230,7 @@ export class Connection extends TypedEventEmitter { this.description = new StreamDescription(this.address, options); this.generation = options.generation; this.lastUseTime = now(); + this.connectionCreatedEventTime = null; this.messageStream = this.socket .on('error', this.onError.bind(this)) diff --git a/src/cmap/connection_pool.ts b/src/cmap/connection_pool.ts index f91e1361f65..04fac90923d 100644 --- a/src/cmap/connection_pool.ts +++ b/src/cmap/connection_pool.ts @@ -629,6 +629,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 = Date.now(); this.emitAndLog( ConnectionPool.CONNECTION_CREATED, new ConnectionCreatedEvent(this, { id: connectOptions.id }) @@ -670,7 +671,7 @@ export class ConnectionPool extends TypedEventEmitter { connection.markAvailable(); this.emitAndLog( ConnectionPool.CONNECTION_READY, - new ConnectionReadyEvent(this, connection) + new ConnectionReadyEvent(this, connection, connectionCreatedTime) ); this[kPending]--; diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index 379bc2d5217..097ea266bc7 100644 --- a/src/cmap/connection_pool_events.ts +++ b/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 | ''; + /** + * 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 = this.durationMS = Date.now() - (connection.connectionCreatedEventTime ?? Date.now()); this.reason = reason; this.error = error; } @@ -217,10 +245,25 @@ 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. + * + * 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 = 0; this.connectionId = connection.id; } } diff --git a/test/integration/connection-monitoring-and-pooling/connection_monitoring_and_pooling.spec.test.ts b/test/integration/connection-monitoring-and-pooling/connection_monitoring_and_pooling.spec.test.ts index d869d05746c..d6a91f4aa21 100644 --- a/test/integration/connection-monitoring-and-pooling/connection_monitoring_and_pooling.spec.test.ts +++ b/test/integration/connection-monitoring-and-pooling/connection_monitoring_and_pooling.spec.test.ts @@ -39,7 +39,7 @@ const INTERRUPT_IN_USE_SKIPPED_TESTS: SkipDescription[] = [ } ]; -describe('Connection Monitoring and Pooling Spec Tests (Integration) - cmap-format', function () { +describe.only('Connection Monitoring and Pooling Spec Tests (Integration) - cmap-format', function () { const tests: CmapTest[] = loadSpecTests('connection-monitoring-and-pooling', 'cmap-format'); runCmapTestSuite(tests, { @@ -57,7 +57,7 @@ describe('Connection Monitoring and Pooling Spec Tests (Integration) - cmap-form }); }); -describe('Connection Monitoring and Pooling Spec Tests (Integration) - logging', function () { +describe.only('Connection Monitoring and Pooling Spec Tests (Integration) - logging', function () { const tests = loadSpecTests('connection-monitoring-and-pooling', 'logging'); runUnifiedSuite(tests, test => { From 920e72e50143e58e8f6cc469b959672c3634a5a8 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Mon, 1 Jul 2024 10:41:37 -0400 Subject: [PATCH 2/9] added durations to checkOut events --- src/cmap/connection.ts | 2 -- src/cmap/connection_pool.ts | 2 ++ src/cmap/connection_pool_events.ts | 4 ++-- .../connection_monitoring_and_pooling.spec.test.ts | 4 ++-- 4 files changed, 6 insertions(+), 6 deletions(-) diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 8a2efd4ac02..1e4afc7f387 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -191,7 +191,6 @@ export class Connection extends TypedEventEmitter { private lastUseTime: number; private clusterTime: Document | null = null; - private error: Error | null = null; private dataEvents: AsyncGenerator | null = null; @@ -230,7 +229,6 @@ export class Connection extends TypedEventEmitter { this.description = new StreamDescription(this.address, options); this.generation = options.generation; this.lastUseTime = now(); - this.connectionCreatedEventTime = null; this.messageStream = this.socket .on('error', this.onError.bind(this)) diff --git a/src/cmap/connection_pool.ts b/src/cmap/connection_pool.ts index 04fac90923d..2debf9b4740 100644 --- a/src/cmap/connection_pool.ts +++ b/src/cmap/connection_pool.ts @@ -162,6 +162,7 @@ export class ConnectionPool extends TypedEventEmitter { [kWaitQueue]: List; [kMetrics]: ConnectionPoolMetrics; [kProcessingWaitQueue]: boolean; + checkOutTime: undefined | number; /** * Emitted when the connection pool is created. @@ -355,6 +356,7 @@ export class ConnectionPool extends TypedEventEmitter { * explicitly destroyed by the new owner. */ async checkOut(): Promise { + this.checkOutTime = Date.now(); this.emitAndLog( ConnectionPool.CONNECTION_CHECK_OUT_STARTED, new ConnectionCheckOutStartedEvent(this) diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index 097ea266bc7..bca300beff9 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -229,7 +229,7 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent error?: MongoError ) { super(pool); - this.durationMS = this.durationMS = Date.now() - (connection.connectionCreatedEventTime ?? Date.now()); + this.durationMS = Date.now() - (pool.checkOutTime ?? 0); this.reason = reason; this.error = error; } @@ -263,7 +263,7 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { /** @internal */ constructor(pool: ConnectionPool, connection: Connection) { super(pool); - this.durationMS = 0; + this.durationMS = Date.now() - (pool.checkOutTime ?? 0); this.connectionId = connection.id; } } diff --git a/test/integration/connection-monitoring-and-pooling/connection_monitoring_and_pooling.spec.test.ts b/test/integration/connection-monitoring-and-pooling/connection_monitoring_and_pooling.spec.test.ts index d6a91f4aa21..d869d05746c 100644 --- a/test/integration/connection-monitoring-and-pooling/connection_monitoring_and_pooling.spec.test.ts +++ b/test/integration/connection-monitoring-and-pooling/connection_monitoring_and_pooling.spec.test.ts @@ -39,7 +39,7 @@ const INTERRUPT_IN_USE_SKIPPED_TESTS: SkipDescription[] = [ } ]; -describe.only('Connection Monitoring and Pooling Spec Tests (Integration) - cmap-format', function () { +describe('Connection Monitoring and Pooling Spec Tests (Integration) - cmap-format', function () { const tests: CmapTest[] = loadSpecTests('connection-monitoring-and-pooling', 'cmap-format'); runCmapTestSuite(tests, { @@ -57,7 +57,7 @@ describe.only('Connection Monitoring and Pooling Spec Tests (Integration) - cmap }); }); -describe.only('Connection Monitoring and Pooling Spec Tests (Integration) - logging', function () { +describe('Connection Monitoring and Pooling Spec Tests (Integration) - logging', function () { const tests = loadSpecTests('connection-monitoring-and-pooling', 'logging'); runUnifiedSuite(tests, test => { From b7f0ee89d763381536af7dfa3a7a0a5cd3db5c89 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Mon, 1 Jul 2024 15:52:46 -0400 Subject: [PATCH 3/9] add to defaultLogTransform --- src/mongo_logger.ts | 3 ++ .../connection-logging.json | 7 +++++ .../logging/connection-logging.json | 28 +++++++++++++++++++ .../logging/connection-logging.yml | 4 +++ .../logging/connection-pool-options.json | 7 +++++ .../logging/connection-pool-options.yml | 1 + 6 files changed, 50 insertions(+) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 2310ce8448b..edbc1ac33e0 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); @@ -649,6 +650,7 @@ export function defaultLogTransform( if (logObject.error) { log.error = logObject.error; } + log.durationMS = logObject.durationMS; break; default: log.reason = `Unknown close reason: ${logObject.reason}`; @@ -658,6 +660,7 @@ export function defaultLogTransform( 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 bda71868869..e0ff51bf209 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 @@ -110,6 +110,13 @@ "int", "long" ] + }, + "durationMS": { + "$$type": [ + "double", + "int", + "long" + ] } } }, 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 b3d48f56b7c..72103b3cabd 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 1134c34b42a..49868a062ec 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 aff88f5bfd2..7055a54869e 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 5fa7ac2297c..790dab6feda 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" From 98cf7b0fa949a2db3da09c976b75b2c0aa993c7a Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Mon, 1 Jul 2024 17:32:27 -0400 Subject: [PATCH 4/9] remove extraneous newline --- test/integration/retryable-writes/retryable_writes.spec.test.ts | 1 - 1 file changed, 1 deletion(-) diff --git a/test/integration/retryable-writes/retryable_writes.spec.test.ts b/test/integration/retryable-writes/retryable_writes.spec.test.ts index a8e14125844..0ba83bcdb9e 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)); From 29408b490c105f9b993175f90283b8561378c42c Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Tue, 2 Jul 2024 16:23:05 -0400 Subject: [PATCH 5/9] fix test --- src/mongo_logger.ts | 2 +- .../connection-logging.json | 14 +++++++------- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index edbc1ac33e0..abac20d8464 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -650,11 +650,11 @@ export function defaultLogTransform( if (logObject.error) { log.error = logObject.error; } - log.durationMS = logObject.durationMS; break; default: log.reason = `Unknown close reason: ${logObject.reason}`; } + log.durationMS = logObject.durationMS; return log; case CONNECTION_CHECKED_OUT: 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 e0ff51bf209..26900e37458 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 @@ -110,13 +110,6 @@ "int", "long" ] - }, - "durationMS": { - "$$type": [ - "double", - "int", - "long" - ] } } }, @@ -198,6 +191,13 @@ "long" ] }, + "durationMS": { + "$$type": [ + "double", + "int", + "long" + ] + }, "reason": "An error occurred while trying to establish a new connection", "error": { "$$exists": true From 5f51f6a58a68e18a3c36d0f83eb0eaf874eb2d18 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Wed, 3 Jul 2024 13:15:59 -0400 Subject: [PATCH 6/9] shorten comments --- src/cmap/connection_pool_events.ts | 12 ------------ 1 file changed, 12 deletions(-) diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index bca300beff9..a6ce8dcc6bf 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -213,12 +213,6 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent * 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; @@ -251,12 +245,6 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { * 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; From 53c783f30b2a3296691d6b6ee84ca5bb8c5cb781 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Wed, 3 Jul 2024 15:25:58 -0400 Subject: [PATCH 7/9] moved checkout time logic to waitQueueMember --- src/cmap/connection_pool.ts | 22 ++++++++++++++-------- src/cmap/connection_pool_events.ts | 7 ++++--- 2 files changed, 18 insertions(+), 11 deletions(-) diff --git a/src/cmap/connection_pool.ts b/src/cmap/connection_pool.ts index 2debf9b4740..5b4b5c7f042 100644 --- a/src/cmap/connection_pool.ts +++ b/src/cmap/connection_pool.ts @@ -104,6 +104,7 @@ export interface WaitQueueMember { reject: (err: AnyError) => void; timeout: Timeout; [kCancelled]?: boolean; + checkoutTime: number; } /** @internal */ @@ -162,7 +163,6 @@ export class ConnectionPool extends TypedEventEmitter { [kWaitQueue]: List; [kMetrics]: ConnectionPoolMetrics; [kProcessingWaitQueue]: boolean; - checkOutTime: undefined | number; /** * Emitted when the connection pool is created. @@ -356,7 +356,7 @@ export class ConnectionPool extends TypedEventEmitter { * explicitly destroyed by the new owner. */ async checkOut(): Promise { - this.checkOutTime = Date.now(); + const checkoutTime = Date.now(); this.emitAndLog( ConnectionPool.CONNECTION_CHECK_OUT_STARTED, new ConnectionCheckOutStartedEvent(this) @@ -371,7 +371,8 @@ export class ConnectionPool extends TypedEventEmitter { const waitQueueMember: WaitQueueMember = { resolve, reject, - timeout + timeout, + checkoutTime }; this[kWaitQueue].push(waitQueueMember); @@ -387,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 @@ -762,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(); @@ -783,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(); @@ -812,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 a6ce8dcc6bf..aa23475dcdc 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -220,10 +220,11 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent constructor( pool: ConnectionPool, reason: 'poolClosed' | 'timeout' | 'connectionError', + checkoutTime: number, error?: MongoError ) { super(pool); - this.durationMS = Date.now() - (pool.checkOutTime ?? 0); + this.durationMS = Date.now() - checkoutTime; this.reason = reason; this.error = error; } @@ -249,9 +250,9 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { durationMS: number; /** @internal */ - constructor(pool: ConnectionPool, connection: Connection) { + constructor(pool: ConnectionPool, connection: Connection, checkoutTime: number) { super(pool); - this.durationMS = Date.now() - (pool.checkOutTime ?? 0); + this.durationMS = Date.now() - checkoutTime; this.connectionId = connection.id; } } From 2e19a25adf780b3ccab260be6dcb283a52e2089f Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Mon, 8 Jul 2024 18:14:19 -0400 Subject: [PATCH 8/9] requested changes 2 --- src/cmap/connection_pool.ts | 6 +++--- src/cmap/connection_pool_events.ts | 7 ++++--- 2 files changed, 7 insertions(+), 6 deletions(-) diff --git a/src/cmap/connection_pool.ts b/src/cmap/connection_pool.ts index 5b4b5c7f042..2a66c9244f9 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 { @@ -356,7 +356,7 @@ export class ConnectionPool extends TypedEventEmitter { * explicitly destroyed by the new owner. */ async checkOut(): Promise { - const checkoutTime = Date.now(); + const checkoutTime = now(); this.emitAndLog( ConnectionPool.CONNECTION_CHECK_OUT_STARTED, new ConnectionCheckOutStartedEvent(this) @@ -632,7 +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 = Date.now(); + const connectionCreatedTime = now(); this.emitAndLog( ConnectionPool.CONNECTION_CREATED, new ConnectionCreatedEvent(this, { id: connectOptions.id }) diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index aa23475dcdc..d34a14f978e 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'; @@ -144,7 +145,7 @@ export class ConnectionReadyEvent extends ConnectionPoolMonitoringEvent { /** @internal */ constructor(pool: ConnectionPool, connection: Connection, connectionCreatedEventTime: number) { super(pool); - this.durationMS = Date.now() - connectionCreatedEventTime; + this.durationMS = now() - connectionCreatedEventTime; this.connectionId = connection.id; } } @@ -224,7 +225,7 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent error?: MongoError ) { super(pool); - this.durationMS = Date.now() - checkoutTime; + this.durationMS = now() - checkoutTime; this.reason = reason; this.error = error; } @@ -252,7 +253,7 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { /** @internal */ constructor(pool: ConnectionPool, connection: Connection, checkoutTime: number) { super(pool); - this.durationMS = Date.now() - checkoutTime; + this.durationMS = now() - checkoutTime; this.connectionId = connection.id; } } From a98c29f7c316b53101c0ca09a70b96af9cca951a Mon Sep 17 00:00:00 2001 From: Aditi Khare <106987683+aditi-khare-mongoDB@users.noreply.github.com> Date: Tue, 9 Jul 2024 14:56:08 -0400 Subject: [PATCH 9/9] Update src/cmap/connection_pool_events.ts Co-authored-by: Neal Beeken --- src/cmap/connection_pool_events.ts | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index d34a14f978e..5b8c4093cf5 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -212,8 +212,7 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent * 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. - * + * and emitting this event as part of the same check out. */ durationMS: number;