Skip to content

Commit 38fb2e4

Browse files
refactor(NODE-4848): add runtime error handling to logging (#3971)
1 parent 7f97c2a commit 38fb2e4

File tree

4 files changed

+365
-52
lines changed

4 files changed

+365
-52
lines changed

src/mongo_logger.ts

Lines changed: 89 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,4 @@
1-
import type { Writable } from 'stream';
2-
import { inspect } from 'util';
1+
import { inspect, promisify } from 'util';
32

43
import { type Document, EJSON, type EJSONOptions, type ObjectId } from './bson';
54
import type { CommandStartedEvent } from './cmap/command_monitoring_events';
@@ -58,7 +57,7 @@ import type {
5857
ServerSelectionSucceededEvent,
5958
WaitingForSuitableServerEvent
6059
} from './sdam/server_selection_events';
61-
import { HostAddress, parseUnsignedInteger } from './utils';
60+
import { HostAddress, isPromiseLike, parseUnsignedInteger } from './utils';
6261

6362
/** @internal */
6463
export const SeverityLevel = Object.freeze({
@@ -192,16 +191,19 @@ export interface MongoLoggerOptions {
192191
/** Max length of embedded EJSON docs. Setting to 0 disables truncation. Defaults to 1000. */
193192
maxDocumentLength: number;
194193
/** Destination for log messages. */
195-
logDestination: Writable | MongoDBLogWritable;
194+
logDestination: MongoDBLogWritable;
195+
/** For internal check to see if error should stop logging. */
196+
logDestinationIsStdErr: boolean;
196197
}
197198

198199
/**
199200
* Parses a string as one of SeverityLevel
201+
* @internal
200202
*
201203
* @param s - the value to be parsed
202204
* @returns one of SeverityLevel if value can be parsed as such, otherwise null
203205
*/
204-
function parseSeverityFromString(s?: string): SeverityLevel | null {
206+
export function parseSeverityFromString(s?: string): SeverityLevel | null {
205207
const validSeverities: string[] = Object.values(SeverityLevel);
206208
const lowerSeverity = s?.toLowerCase();
207209

@@ -217,10 +219,10 @@ export function createStdioLogger(stream: {
217219
write: NodeJS.WriteStream['write'];
218220
}): MongoDBLogWritable {
219221
return {
220-
write: (log: Log): unknown => {
221-
stream.write(inspect(log, { compact: true, breakLength: Infinity }), 'utf-8');
222+
write: promisify((log: Log, cb: (error?: Error) => void): unknown => {
223+
stream.write(inspect(log, { compact: true, breakLength: Infinity }), 'utf-8', cb);
222224
return;
223-
}
225+
})
224226
};
225227
}
226228

@@ -237,26 +239,26 @@ export function createStdioLogger(stream: {
237239
function resolveLogPath(
238240
{ MONGODB_LOG_PATH }: MongoLoggerEnvOptions,
239241
{ mongodbLogPath }: MongoLoggerMongoClientOptions
240-
): MongoDBLogWritable {
242+
): { mongodbLogPath: MongoDBLogWritable; mongodbLogPathIsStdErr: boolean } {
241243
if (typeof mongodbLogPath === 'string' && /^stderr$/i.test(mongodbLogPath)) {
242-
return createStdioLogger(process.stderr);
244+
return { mongodbLogPath: createStdioLogger(process.stderr), mongodbLogPathIsStdErr: true };
243245
}
244246
if (typeof mongodbLogPath === 'string' && /^stdout$/i.test(mongodbLogPath)) {
245-
return createStdioLogger(process.stdout);
247+
return { mongodbLogPath: createStdioLogger(process.stdout), mongodbLogPathIsStdErr: false };
246248
}
247249

248250
if (typeof mongodbLogPath === 'object' && typeof mongodbLogPath?.write === 'function') {
249-
return mongodbLogPath;
251+
return { mongodbLogPath: mongodbLogPath, mongodbLogPathIsStdErr: false };
250252
}
251253

252254
if (MONGODB_LOG_PATH && /^stderr$/i.test(MONGODB_LOG_PATH)) {
253-
return createStdioLogger(process.stderr);
255+
return { mongodbLogPath: createStdioLogger(process.stderr), mongodbLogPathIsStdErr: true };
254256
}
255257
if (MONGODB_LOG_PATH && /^stdout$/i.test(MONGODB_LOG_PATH)) {
256-
return createStdioLogger(process.stdout);
258+
return { mongodbLogPath: createStdioLogger(process.stdout), mongodbLogPathIsStdErr: false };
257259
}
258260

259-
return createStdioLogger(process.stderr);
261+
return { mongodbLogPath: createStdioLogger(process.stderr), mongodbLogPathIsStdErr: true };
260262
}
261263

262264
function resolveSeverityConfiguration(
@@ -281,7 +283,7 @@ export interface Log extends Record<string, any> {
281283

282284
/** @internal */
283285
export interface MongoDBLogWritable {
284-
write(log: Log): void;
286+
write(log: Log): PromiseLike<unknown> | unknown;
285287
}
286288

287289
function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 {
@@ -415,10 +417,10 @@ export function stringifyWithMaxLen(
415417
): string {
416418
let strToTruncate = '';
417419

418-
if (typeof value === 'function') {
419-
strToTruncate = value.toString();
420-
} else {
421-
strToTruncate = EJSON.stringify(value, options);
420+
try {
421+
strToTruncate = typeof value !== 'function' ? EJSON.stringify(value, options) : value.name;
422+
} catch (e) {
423+
strToTruncate = `Extended JSON serialization failed with: ${e.message}`;
422424
}
423425

424426
return maxDocumentLength !== 0 && strToTruncate.length > maxDocumentLength
@@ -455,15 +457,15 @@ function attachCommandFields(
455457
) {
456458
log.commandName = commandEvent.commandName;
457459
log.requestId = commandEvent.requestId;
458-
log.driverConnectionId = commandEvent?.connectionId;
460+
log.driverConnectionId = commandEvent.connectionId;
459461
const { host, port } = HostAddress.fromString(commandEvent.address).toHostPort();
460462
log.serverHost = host;
461463
log.serverPort = port;
462464
if (commandEvent?.serviceId) {
463465
log.serviceId = commandEvent.serviceId.toHexString();
464466
}
465467
log.databaseName = commandEvent.databaseName;
466-
log.serverConnectionId = commandEvent?.serverConnectionId;
468+
log.serverConnectionId = commandEvent.serverConnectionId;
467469

468470
return log;
469471
}
@@ -497,7 +499,8 @@ function attachServerHeartbeatFields(
497499
return log;
498500
}
499501

500-
function defaultLogTransform(
502+
/** @internal */
503+
export function defaultLogTransform(
501504
logObject: LoggableEvent | Record<string, any>,
502505
maxDocumentLength: number = DEFAULT_MAX_DOCUMENT_LENGTH
503506
): Omit<Log, 's' | 't' | 'c'> {
@@ -509,7 +512,7 @@ function defaultLogTransform(
509512
return log;
510513
case SERVER_SELECTION_FAILED:
511514
log = attachServerSelectionFields(log, logObject, maxDocumentLength);
512-
log.failure = logObject.failure.message;
515+
log.failure = logObject.failure?.message;
513516
return log;
514517
case SERVER_SELECTION_SUCCEEDED:
515518
log = attachServerSelectionFields(log, logObject, maxDocumentLength);
@@ -536,7 +539,7 @@ function defaultLogTransform(
536539
log = attachCommandFields(log, logObject);
537540
log.message = 'Command failed';
538541
log.durationMS = logObject.duration;
539-
log.failure = logObject.failure.message ?? '(redacted)';
542+
log.failure = logObject.failure?.message ?? '(redacted)';
540543
return log;
541544
case CONNECTION_POOL_CREATED:
542545
log = attachConnectionFields(log, logObject);
@@ -562,7 +565,7 @@ function defaultLogTransform(
562565
log = attachConnectionFields(log, logObject);
563566
log.message = 'Connection pool cleared';
564567
if (logObject.serviceId?._bsontype === 'ObjectId') {
565-
log.serviceId = logObject.serviceId.toHexString();
568+
log.serviceId = logObject.serviceId?.toHexString();
566569
}
567570
return log;
568571
case CONNECTION_POOL_CLOSED:
@@ -666,7 +669,7 @@ function defaultLogTransform(
666669
log = attachServerHeartbeatFields(log, logObject);
667670
log.message = 'Server heartbeat failed';
668671
log.durationMS = logObject.duration;
669-
log.failure = logObject.failure.message;
672+
log.failure = logObject.failure?.message;
670673
return log;
671674
case TOPOLOGY_OPENING:
672675
log = attachSDAMFields(log, logObject);
@@ -700,7 +703,9 @@ function defaultLogTransform(
700703
export class MongoLogger {
701704
componentSeverities: Record<MongoLoggableComponent, SeverityLevel>;
702705
maxDocumentLength: number;
703-
logDestination: MongoDBLogWritable | Writable;
706+
logDestination: MongoDBLogWritable;
707+
logDestinationIsStdErr: boolean;
708+
pendingLog: PromiseLike<unknown> | unknown = null;
704709

705710
/**
706711
* This method should be used when logging errors that do not have a public driver API for
@@ -732,12 +737,44 @@ export class MongoLogger {
732737
this.componentSeverities = options.componentSeverities;
733738
this.maxDocumentLength = options.maxDocumentLength;
734739
this.logDestination = options.logDestination;
740+
this.logDestinationIsStdErr = options.logDestinationIsStdErr;
735741
}
736742

737743
willLog(severity: SeverityLevel, component: MongoLoggableComponent): boolean {
738744
return compareSeverity(severity, this.componentSeverities[component]) <= 0;
739745
}
740746

747+
turnOffSeverities() {
748+
for (const key of Object.values(MongoLoggableComponent)) {
749+
this.componentSeverities[key as MongoLoggableComponent] = SeverityLevel.OFF;
750+
}
751+
}
752+
753+
private logWriteFailureHandler(error: Error) {
754+
if (this.logDestinationIsStdErr) {
755+
this.turnOffSeverities();
756+
this.clearPendingLog();
757+
return;
758+
}
759+
this.logDestination = createStdioLogger(process.stderr);
760+
this.logDestinationIsStdErr = true;
761+
this.clearPendingLog();
762+
this.error(MongoLoggableComponent.CLIENT, {
763+
toLog: function () {
764+
return {
765+
message: 'User input for mongodbLogPath is now invalid. Logging is halted.',
766+
error: error.message
767+
};
768+
}
769+
});
770+
this.turnOffSeverities();
771+
this.clearPendingLog();
772+
}
773+
774+
private clearPendingLog() {
775+
this.pendingLog = null;
776+
}
777+
741778
private log(
742779
severity: SeverityLevel,
743780
component: MongoLoggableComponent,
@@ -755,7 +792,25 @@ export class MongoLogger {
755792
logMessage = { ...logMessage, ...defaultLogTransform(message, this.maxDocumentLength) };
756793
}
757794
}
758-
this.logDestination.write(logMessage);
795+
796+
if (isPromiseLike(this.pendingLog)) {
797+
this.pendingLog = this.pendingLog
798+
.then(() => this.logDestination.write(logMessage))
799+
.then(this.clearPendingLog.bind(this), this.logWriteFailureHandler.bind(this));
800+
return;
801+
}
802+
803+
try {
804+
const logResult = this.logDestination.write(logMessage);
805+
if (isPromiseLike(logResult)) {
806+
this.pendingLog = logResult.then(
807+
this.clearPendingLog.bind(this),
808+
this.logWriteFailureHandler.bind(this)
809+
);
810+
}
811+
} catch (error) {
812+
this.logWriteFailureHandler(error);
813+
}
759814
}
760815

761816
/**
@@ -776,10 +831,12 @@ export class MongoLogger {
776831
clientOptions: MongoLoggerMongoClientOptions
777832
): MongoLoggerOptions {
778833
// client options take precedence over env options
834+
const resolvedLogPath = resolveLogPath(envOptions, clientOptions);
779835
const combinedOptions = {
780836
...envOptions,
781837
...clientOptions,
782-
mongodbLogPath: resolveLogPath(envOptions, clientOptions)
838+
mongodbLogPath: resolvedLogPath.mongodbLogPath,
839+
mongodbLogPathIsStdErr: resolvedLogPath.mongodbLogPathIsStdErr
783840
};
784841
const defaultSeverity = resolveSeverityConfiguration(
785842
combinedOptions.mongodbLogComponentSeverities?.default,
@@ -820,7 +877,8 @@ export class MongoLogger {
820877
combinedOptions.mongodbLogMaxDocumentLength ??
821878
parseUnsignedInteger(combinedOptions.MONGODB_LOG_MAX_DOCUMENT_LENGTH) ??
822879
1000,
823-
logDestination: combinedOptions.mongodbLogPath
880+
logDestination: combinedOptions.mongodbLogPath,
881+
logDestinationIsStdErr: combinedOptions.mongodbLogPathIsStdErr
824882
};
825883
}
826884
}

src/sdam/server_selection.ts

Lines changed: 8 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -22,25 +22,26 @@ export type ServerSelector = (
2222
* Returns a server selector that selects for writable servers
2323
*/
2424
export function writableServerSelector(): ServerSelector {
25-
return (
25+
return function writableServer(
2626
topologyDescription: TopologyDescription,
2727
servers: ServerDescription[]
28-
): ServerDescription[] =>
29-
latencyWindowReducer(
28+
): ServerDescription[] {
29+
return latencyWindowReducer(
3030
topologyDescription,
3131
servers.filter((s: ServerDescription) => s.isWritable)
3232
);
33+
};
3334
}
3435

3536
/**
3637
* The purpose of this selector is to select the same server, only
3738
* if it is in a state that it can have commands sent to it.
3839
*/
3940
export function sameServerSelector(description?: ServerDescription): ServerSelector {
40-
return (
41+
return function sameServerSelector(
4142
topologyDescription: TopologyDescription,
4243
servers: ServerDescription[]
43-
): ServerDescription[] => {
44+
): ServerDescription[] {
4445
if (!description) return [];
4546
// Filter the servers to match the provided description only if
4647
// the type is not unknown.
@@ -265,11 +266,11 @@ export function readPreferenceServerSelector(readPreference: ReadPreference): Se
265266
throw new MongoInvalidArgumentError('Invalid read preference specified');
266267
}
267268

268-
return (
269+
return function readPreferenceServers(
269270
topologyDescription: TopologyDescription,
270271
servers: ServerDescription[],
271272
deprioritized: ServerDescription[] = []
272-
): ServerDescription[] => {
273+
): ServerDescription[] {
273274
const commonWireVersion = topologyDescription.commonWireVersion;
274275
if (
275276
commonWireVersion &&

src/utils.ts

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -171,8 +171,13 @@ export function applyRetryableWrites<T extends HasRetryableWrites>(target: T, db
171171
* @param value - An object that could be a promise
172172
* @returns true if the provided value is a Promise
173173
*/
174-
export function isPromiseLike<T = any>(value?: PromiseLike<T> | void): value is Promise<T> {
175-
return !!value && typeof value.then === 'function';
174+
export function isPromiseLike<T = unknown>(value?: unknown): value is PromiseLike<T> {
175+
return (
176+
value != null &&
177+
typeof value === 'object' &&
178+
'then' in value &&
179+
typeof value.then === 'function'
180+
);
176181
}
177182

178183
/**

0 commit comments

Comments
 (0)