Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

fix(NODE-5818): Add feature flagging to server selection logging #3974

Merged
merged 3 commits into from
Feb 15, 2024
Merged

fix(NODE-5818): Add feature flagging to server selection logging #3974

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
0751030
Feature flagging done
aditi-khare-mongoDB Jan 22, 2024
19cf05e
fix misc rebase issues
aditi-khare-mongoDB Feb 12, 2024
e55eac1
Merge branch 'main' into NODE-5818/server-selection-regression
durran Feb 15, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
179 changes: 116 additions & 63 deletions src/sdam/topology.ts
View file
Open in desktop
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)
) {
alenakhineika marked this conversation as resolved.
Show resolved Hide resolved
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
Open in desktop
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;
});
});
});
});