Skip to content

Commit

Permalink
fix(NODE-5818): Add feature flagging to server selection logging (#3974)
Browse files Browse the repository at this point in the history 
Co-authored-by: Durran Jordan <durran@gmail.com>
  • Loading branch information
@aditi-khare-mongoDB @durran
aditi-khare-mongoDB and durran authored Feb 15, 2024
1 parent ecfc615 commit 55203ef
Show file tree
Hide file tree
Showing 2 changed files with 157 additions and 64 deletions.
179 changes: 116 additions & 63 deletions src/sdam/topology.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand Down Expand Up @@ -568,25 +568,36 @@ export class Topology extends TypedEventEmitter<TopologyEvents> {
}

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(MongoLoggableComponent.SERVER_SELECTION, SeverityLevel.DEBUG)
) {
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(
MongoLoggableComponent.SERVER_SELECTION,
SeverityLevel.DEBUG
)
);
) {
this.client.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionSucceededEvent(
selector,
this.description,
transaction.server.pool.address,
options.operationName
)
);
}
callback(undefined, transaction.server);
return;
}
Expand All @@ -611,15 +622,22 @@ export class Topology extends TypedEventEmitter<TopologyEvents> {
`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(
MongoLoggableComponent.SERVER_SELECTION,
SeverityLevel.DEBUG
)
);
) {
this.client.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionFailedEvent(
selector,
this.description,
timeoutError,
options.operationName
)
);
}
waitQueueMember.callback(timeoutError);
});

Expand Down Expand Up @@ -896,15 +914,22 @@ function drainWaitQueue(queue: List<ServerSelectionRequest>, 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(
MongoLoggableComponent.SERVER_SELECTION,
SeverityLevel.DEBUG
)
);
) {
waitQueueMember.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionFailedEvent(
waitQueueMember.serverSelector,
waitQueueMember.topologyDescription,
err,
waitQueueMember.operationName
)
);
}
}
waitQueueMember.callback(err);
}
Expand Down Expand Up @@ -943,33 +968,47 @@ 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(
MongoLoggableComponent.SERVER_SELECTION,
SeverityLevel.DEBUG
)
);
) {
topology.client.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionFailedEvent(
waitQueueMember.serverSelector,
topology.description,
e,
waitQueueMember.operationName
)
);
}
waitQueueMember.callback(e);
continue;
}

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(
MongoLoggableComponent.SERVER_SELECTION,
SeverityLevel.INFORMATIONAL
)
);
) {
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);
Expand All @@ -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(
MongoLoggableComponent.SERVER_SELECTION,
SeverityLevel.DEBUG
)
);
) {
topology.client.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionFailedEvent(
waitQueueMember.serverSelector,
topology.description,
error,
waitQueueMember.operationName
)
);
}
waitQueueMember.callback(error);
return;
}
Expand All @@ -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(
MongoLoggableComponent.SERVER_SELECTION,
SeverityLevel.DEBUG
)
);
) {
topology.client.mongoLogger?.debug(
MongoLoggableComponent.SERVER_SELECTION,
new ServerSelectionSucceededEvent(
waitQueueMember.serverSelector,
waitQueueMember.topologyDescription,
selectedServer.pool.address,
waitQueueMember.operationName
)
);
}
waitQueueMember.callback(undefined, selectedServer);
}

Expand Down
42 changes: 41 additions & 1 deletion test/unit/sdam/server_selection.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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;
});
});
});
});

0 comments on commit 55203ef

Please sign in to comment.