From 075103032ec0d57a599f263a59aced0ebb9157bf Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Mon, 22 Jan 2024 14:49:31 -0500 Subject: [PATCH 1/2] Feature flagging done Sinon stub issue with testing, almost ready for review added test, ready for review Removed extranous changes from other PR lint fix made all mongoLogger accesses in topology.ts be conditional --- src/mongo_logger.ts | 2 +- src/sdam/topology.ts | 179 +++++++++++++++--------- test/unit/sdam/server_selection.test.ts | 42 +++++- 3 files changed, 158 insertions(+), 65 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 27fcbf8d308..58e9290c514 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -222,7 +222,7 @@ export function createStdioLogger(stream: { write: promisify((log: Log, cb: (error?: Error) => void): unknown => { stream.write(inspect(log, { compact: true, breakLength: Infinity }), 'utf-8', cb); return; - }) + } }; } diff --git a/src/sdam/topology.ts b/src/sdam/topology.ts index 2526aad535b..28bddbd2c9b 100644 --- a/src/sdam/topology.ts +++ b/src/sdam/topology.ts @@ -31,7 +31,7 @@ import { MongoTopologyClosedError } from '../error'; import type { MongoClient, ServerApi } from '../mongo_client'; -import { MongoLoggableComponent, type MongoLogger } from '../mongo_logger'; +import { MongoLoggableComponent, type MongoLogger, SeverityLevel } from '../mongo_logger'; import { TypedEventEmitter } from '../mongo_types'; import { ReadPreference, type ReadPreferenceLike } from '../read_preference'; import type { ClientSession } from '../sessions'; @@ -568,25 +568,36 @@ export class Topology extends TypedEventEmitter { } options = { serverSelectionTimeoutMS: this.s.serverSelectionTimeoutMS, ...options }; - this.client.mongoLogger?.debug( - MongoLoggableComponent.SERVER_SELECTION, - new ServerSelectionStartedEvent(selector, this.description, options.operationName) - ); + if ( + this.client.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.SERVER_SELECTION) + ) { + this.client.mongoLogger?.debug( + MongoLoggableComponent.SERVER_SELECTION, + new ServerSelectionStartedEvent(selector, this.description, options.operationName) + ); + } const isSharded = this.description.type === TopologyType.Sharded; const session = options.session; const transaction = session && session.transaction; if (isSharded && transaction && transaction.server) { - this.client.mongoLogger?.debug( - MongoLoggableComponent.SERVER_SELECTION, - new ServerSelectionSucceededEvent( - selector, - this.description, - transaction.server.pool.address, - options.operationName + if ( + this.client.mongoLogger?.willLog( + SeverityLevel.DEBUG, + MongoLoggableComponent.SERVER_SELECTION ) - ); + ) { + this.client.mongoLogger?.debug( + MongoLoggableComponent.SERVER_SELECTION, + new ServerSelectionSucceededEvent( + selector, + this.description, + transaction.server.pool.address, + options.operationName + ) + ); + } callback(undefined, transaction.server); return; } @@ -611,15 +622,22 @@ export class Topology extends TypedEventEmitter { `Server selection timed out after ${options.serverSelectionTimeoutMS} ms`, this.description ); - this.client.mongoLogger?.debug( - MongoLoggableComponent.SERVER_SELECTION, - new ServerSelectionFailedEvent( - selector, - this.description, - timeoutError, - options.operationName + if ( + this.client.mongoLogger?.willLog( + SeverityLevel.DEBUG, + MongoLoggableComponent.SERVER_SELECTION ) - ); + ) { + this.client.mongoLogger?.debug( + MongoLoggableComponent.SERVER_SELECTION, + new ServerSelectionFailedEvent( + selector, + this.description, + timeoutError, + options.operationName + ) + ); + } waitQueueMember.callback(timeoutError); }); @@ -896,15 +914,22 @@ function drainWaitQueue(queue: List, err?: MongoDriverEr if (!waitQueueMember[kCancelled]) { if (err) { - waitQueueMember.mongoLogger?.debug( - MongoLoggableComponent.SERVER_SELECTION, - new ServerSelectionFailedEvent( - waitQueueMember.serverSelector, - waitQueueMember.topologyDescription, - err, - waitQueueMember.operationName + if ( + waitQueueMember.mongoLogger?.willLog( + SeverityLevel.DEBUG, + MongoLoggableComponent.SERVER_SELECTION ) - ); + ) { + waitQueueMember.mongoLogger?.debug( + MongoLoggableComponent.SERVER_SELECTION, + new ServerSelectionFailedEvent( + waitQueueMember.serverSelector, + waitQueueMember.topologyDescription, + err, + waitQueueMember.operationName + ) + ); + } } waitQueueMember.callback(err); } @@ -943,15 +968,22 @@ function processWaitQueue(topology: Topology) { : serverDescriptions; } catch (e) { waitQueueMember.timeoutController.clear(); - topology.client.mongoLogger?.debug( - MongoLoggableComponent.SERVER_SELECTION, - new ServerSelectionFailedEvent( - waitQueueMember.serverSelector, - topology.description, - e, - waitQueueMember.operationName + if ( + topology.client.mongoLogger?.willLog( + SeverityLevel.DEBUG, + MongoLoggableComponent.SERVER_SELECTION ) - ); + ) { + topology.client.mongoLogger?.debug( + MongoLoggableComponent.SERVER_SELECTION, + new ServerSelectionFailedEvent( + waitQueueMember.serverSelector, + topology.description, + e, + waitQueueMember.operationName + ) + ); + } waitQueueMember.callback(e); continue; } @@ -959,17 +991,24 @@ function processWaitQueue(topology: Topology) { let selectedServer: Server | undefined; if (selectedDescriptions.length === 0) { if (!waitQueueMember.waitingLogged) { - topology.client.mongoLogger?.info( - MongoLoggableComponent.SERVER_SELECTION, - new WaitingForSuitableServerEvent( - waitQueueMember.serverSelector, - topology.description, - topology.s.serverSelectionTimeoutMS !== 0 - ? topology.s.serverSelectionTimeoutMS - (now() - waitQueueMember.startTime) - : -1, - waitQueueMember.operationName + if ( + topology.client.mongoLogger?.willLog( + SeverityLevel.INFORMATIONAL, + MongoLoggableComponent.SERVER_SELECTION ) - ); + ) { + topology.client.mongoLogger?.info( + MongoLoggableComponent.SERVER_SELECTION, + new WaitingForSuitableServerEvent( + waitQueueMember.serverSelector, + topology.description, + topology.s.serverSelectionTimeoutMS !== 0 + ? topology.s.serverSelectionTimeoutMS - (now() - waitQueueMember.startTime) + : -1, + waitQueueMember.operationName + ) + ); + } waitQueueMember.waitingLogged = true; } topology[kWaitQueue].push(waitQueueMember); @@ -992,15 +1031,22 @@ function processWaitQueue(topology: Topology) { 'server selection returned a server description but the server was not found in the topology', topology.description ); - topology.client.mongoLogger?.debug( - MongoLoggableComponent.SERVER_SELECTION, - new ServerSelectionFailedEvent( - waitQueueMember.serverSelector, - topology.description, - error, - waitQueueMember.operationName + if ( + topology.client.mongoLogger?.willLog( + SeverityLevel.DEBUG, + MongoLoggableComponent.SERVER_SELECTION ) - ); + ) { + topology.client.mongoLogger?.debug( + MongoLoggableComponent.SERVER_SELECTION, + new ServerSelectionFailedEvent( + waitQueueMember.serverSelector, + topology.description, + error, + waitQueueMember.operationName + ) + ); + } waitQueueMember.callback(error); return; } @@ -1011,15 +1057,22 @@ function processWaitQueue(topology: Topology) { waitQueueMember.timeoutController.clear(); - topology.client.mongoLogger?.debug( - MongoLoggableComponent.SERVER_SELECTION, - new ServerSelectionSucceededEvent( - waitQueueMember.serverSelector, - waitQueueMember.topologyDescription, - selectedServer.pool.address, - waitQueueMember.operationName + if ( + topology.client.mongoLogger?.willLog( + SeverityLevel.DEBUG, + MongoLoggableComponent.SERVER_SELECTION ) - ); + ) { + topology.client.mongoLogger?.debug( + MongoLoggableComponent.SERVER_SELECTION, + new ServerSelectionSucceededEvent( + waitQueueMember.serverSelector, + waitQueueMember.topologyDescription, + selectedServer.pool.address, + waitQueueMember.operationName + ) + ); + } waitQueueMember.callback(undefined, selectedServer); } diff --git a/test/unit/sdam/server_selection.test.ts b/test/unit/sdam/server_selection.test.ts index 925d40eef07..c26f3b96510 100644 --- a/test/unit/sdam/server_selection.test.ts +++ b/test/unit/sdam/server_selection.test.ts @@ -3,17 +3,21 @@ import * as sinon from 'sinon'; import { MIN_SECONDARY_WRITE_WIRE_VERSION, + MongoLogger, ObjectId, ReadPreference, readPreferenceServerSelector, sameServerSelector, secondaryWritableServerSelector, ServerDescription, + ServerSelectionEvent, TopologyDescription, TopologyType } from '../../mongodb'; +import * as mock from '../../tools/mongodb-mock/index'; +import { topologyWithPlaceholderClient } from '../../tools/utils'; -describe('server selection', function () { +describe('server selection', async function () { const primary = new ServerDescription('127.0.0.1:27017', { setName: 'test', isWritablePrimary: true, @@ -605,4 +609,40 @@ describe('server selection', function () { }); }); }); + + describe('server selection logging feature flagging', async function () { + const topologyDescription = sinon.stub(); + + let mockServer; + let topology; + + beforeEach(async () => { + mockServer = await mock.createServer(); + topology = topologyWithPlaceholderClient(mockServer.hostAddress(), {}); + }); + + afterEach(async () => { + await mock.cleanup(); + }); + + context('when willLog returns false', function () { + const original = Object.getPrototypeOf(ServerSelectionEvent); + let serverSelectionEventStub; + beforeEach(async () => { + sinon.stub(MongoLogger.prototype, 'willLog').callsFake((_v, _w) => false); + serverSelectionEventStub = sinon.stub(); + Object.setPrototypeOf(ServerSelectionEvent, serverSelectionEventStub); + }); + + afterEach(async () => { + sinon.restore(); + Object.setPrototypeOf(ServerSelectionEvent, original); + }); + + it('should not create server selection event instances', function () { + topology?.selectServer(topologyDescription, { operationName: 'test' }, v => v); + expect(serverSelectionEventStub.getCall(0)).to.be.null; + }); + }); + }); }); From 19cf05e9564605e8faa83c0f1ecead71676ad94f Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Mon, 12 Feb 2024 11:05:05 -0500 Subject: [PATCH 2/2] fix misc rebase issues --- src/mongo_logger.ts | 2 +- src/sdam/topology.ts | 30 +++++++++++++++--------------- 2 files changed, 16 insertions(+), 16 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 58e9290c514..27fcbf8d308 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -222,7 +222,7 @@ export function createStdioLogger(stream: { write: promisify((log: Log, cb: (error?: Error) => void): unknown => { stream.write(inspect(log, { compact: true, breakLength: Infinity }), 'utf-8', cb); return; - } + }) }; } diff --git a/src/sdam/topology.ts b/src/sdam/topology.ts index 28bddbd2c9b..4bf816f2380 100644 --- a/src/sdam/topology.ts +++ b/src/sdam/topology.ts @@ -569,7 +569,7 @@ export class Topology extends TypedEventEmitter { options = { serverSelectionTimeoutMS: this.s.serverSelectionTimeoutMS, ...options }; if ( - this.client.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.SERVER_SELECTION) + this.client.mongoLogger?.willLog(MongoLoggableComponent.SERVER_SELECTION, SeverityLevel.DEBUG) ) { this.client.mongoLogger?.debug( MongoLoggableComponent.SERVER_SELECTION, @@ -584,8 +584,8 @@ export class Topology extends TypedEventEmitter { if (isSharded && transaction && transaction.server) { if ( this.client.mongoLogger?.willLog( - SeverityLevel.DEBUG, - MongoLoggableComponent.SERVER_SELECTION + MongoLoggableComponent.SERVER_SELECTION, + SeverityLevel.DEBUG ) ) { this.client.mongoLogger?.debug( @@ -624,8 +624,8 @@ export class Topology extends TypedEventEmitter { ); if ( this.client.mongoLogger?.willLog( - SeverityLevel.DEBUG, - MongoLoggableComponent.SERVER_SELECTION + MongoLoggableComponent.SERVER_SELECTION, + SeverityLevel.DEBUG ) ) { this.client.mongoLogger?.debug( @@ -916,8 +916,8 @@ function drainWaitQueue(queue: List, err?: MongoDriverEr if (err) { if ( waitQueueMember.mongoLogger?.willLog( - SeverityLevel.DEBUG, - MongoLoggableComponent.SERVER_SELECTION + MongoLoggableComponent.SERVER_SELECTION, + SeverityLevel.DEBUG ) ) { waitQueueMember.mongoLogger?.debug( @@ -970,8 +970,8 @@ function processWaitQueue(topology: Topology) { waitQueueMember.timeoutController.clear(); if ( topology.client.mongoLogger?.willLog( - SeverityLevel.DEBUG, - MongoLoggableComponent.SERVER_SELECTION + MongoLoggableComponent.SERVER_SELECTION, + SeverityLevel.DEBUG ) ) { topology.client.mongoLogger?.debug( @@ -993,8 +993,8 @@ function processWaitQueue(topology: Topology) { if (!waitQueueMember.waitingLogged) { if ( topology.client.mongoLogger?.willLog( - SeverityLevel.INFORMATIONAL, - MongoLoggableComponent.SERVER_SELECTION + MongoLoggableComponent.SERVER_SELECTION, + SeverityLevel.INFORMATIONAL ) ) { topology.client.mongoLogger?.info( @@ -1033,8 +1033,8 @@ function processWaitQueue(topology: Topology) { ); if ( topology.client.mongoLogger?.willLog( - SeverityLevel.DEBUG, - MongoLoggableComponent.SERVER_SELECTION + MongoLoggableComponent.SERVER_SELECTION, + SeverityLevel.DEBUG ) ) { topology.client.mongoLogger?.debug( @@ -1059,8 +1059,8 @@ function processWaitQueue(topology: Topology) { if ( topology.client.mongoLogger?.willLog( - SeverityLevel.DEBUG, - MongoLoggableComponent.SERVER_SELECTION + MongoLoggableComponent.SERVER_SELECTION, + SeverityLevel.DEBUG ) ) { topology.client.mongoLogger?.debug(