From 3fc095f2f485860f9ec5135ae11cc7e42fc3895c Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Fri, 19 Jan 2024 13:43:49 -0500 Subject: [PATCH 1/9] all sync error handling done --- src/mongo_logger.ts | 65 ++++++++++++---- test/unit/mongo_logger.test.ts | 138 +++++++++++++++++++++++++++++++++ 2 files changed, 187 insertions(+), 16 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 23f270bd4a3..d17e36b7a5e 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -197,11 +197,12 @@ export interface MongoLoggerOptions { /** * Parses a string as one of SeverityLevel + * @internal * * @param s - the value to be parsed * @returns one of SeverityLevel if value can be parsed as such, otherwise null */ -function parseSeverityFromString(s?: string): SeverityLevel | null { +export function parseSeverityFromString(s?: string): SeverityLevel | null { const validSeverities: string[] = Object.values(SeverityLevel); const lowerSeverity = s?.toLowerCase(); @@ -415,10 +416,15 @@ export function stringifyWithMaxLen( ): string { let strToTruncate = ''; - if (typeof value === 'function') { - strToTruncate = value.toString(); - } else { - strToTruncate = EJSON.stringify(value, options); + try { + strToTruncate = + typeof value !== 'function' + ? EJSON.stringify(value, options) + : value.name !== '' + ? value.name + : 'anonymous function'; + } catch (e) { + return '... ESJON failed : Error ...'; } return maxDocumentLength !== 0 && strToTruncate.length > maxDocumentLength @@ -455,21 +461,21 @@ function attachCommandFields( ) { log.commandName = commandEvent.commandName; log.requestId = commandEvent.requestId; - log.driverConnectionId = commandEvent?.connectionId; - const { host, port } = HostAddress.fromString(commandEvent.address).toHostPort(); + log.driverConnectionId = commandEvent.connectionId; + const { host, port } = HostAddress.fromString(commandEvent.address ?? '').toHostPort(); log.serverHost = host; log.serverPort = port; if (commandEvent?.serviceId) { log.serviceId = commandEvent.serviceId.toHexString(); } log.databaseName = commandEvent.databaseName; - log.serverConnectionId = commandEvent?.serverConnectionId; + log.serverConnectionId = commandEvent.serverConnectionId; return log; } function attachConnectionFields(log: Record, event: any) { - const { host, port } = HostAddress.fromString(event.address).toHostPort(); + const { host, port } = HostAddress.fromString(event.address ?? '').toHostPort(); log.serverHost = host; log.serverPort = port; @@ -491,13 +497,14 @@ function attachServerHeartbeatFields( const { awaited, connectionId } = serverHeartbeatEvent; log.awaited = awaited; log.driverConnectionId = serverHeartbeatEvent.connectionId; - const { host, port } = HostAddress.fromString(connectionId).toHostPort(); + const { host, port } = HostAddress.fromString(connectionId ?? '').toHostPort(); log.serverHost = host; log.serverPort = port; return log; } -function defaultLogTransform( +/** @internal */ +export function defaultLogTransform( logObject: LoggableEvent | Record, maxDocumentLength: number = DEFAULT_MAX_DOCUMENT_LENGTH ): Omit { @@ -509,7 +516,7 @@ function defaultLogTransform( return log; case SERVER_SELECTION_FAILED: log = attachServerSelectionFields(log, logObject, maxDocumentLength); - log.failure = logObject.failure.message; + log.failure = logObject.failure?.message; return log; case SERVER_SELECTION_SUCCEEDED: log = attachServerSelectionFields(log, logObject, maxDocumentLength); @@ -536,7 +543,7 @@ function defaultLogTransform( log = attachCommandFields(log, logObject); log.message = 'Command failed'; log.durationMS = logObject.duration; - log.failure = logObject.failure.message ?? '(redacted)'; + log.failure = logObject.failure?.message ?? '(redacted)'; return log; case CONNECTION_POOL_CREATED: log = attachConnectionFields(log, logObject); @@ -562,7 +569,7 @@ function defaultLogTransform( log = attachConnectionFields(log, logObject); log.message = 'Connection pool cleared'; if (logObject.serviceId?._bsontype === 'ObjectId') { - log.serviceId = logObject.serviceId.toHexString(); + log.serviceId = logObject.serviceId?.toHexString(); } return log; case CONNECTION_POOL_CLOSED: @@ -666,7 +673,7 @@ function defaultLogTransform( log = attachServerHeartbeatFields(log, logObject); log.message = 'Server heartbeat failed'; log.durationMS = logObject.duration; - log.failure = logObject.failure.message; + log.failure = logObject.failure?.message; return log; case TOPOLOGY_OPENING: log = attachSDAMFields(log, logObject); @@ -738,6 +745,28 @@ export class MongoLogger { return compareSeverity(severity, this.componentSeverities[component]) <= 0; } + turnOffSeverities() { + for (const key of Object.keys(MongoLoggableComponent)) { + this.componentSeverities[key as MongoLoggableComponent] = SeverityLevel.OFF; + } + } + + logWriteFailureHandler(errorMessage: string) { + try { + const tempLogDestination = createStdioLogger(process.stderr); + tempLogDestination.write({ + t: new Date(), + c: MongoLoggableComponent.CLIENT, + s: SeverityLevel.ERROR, + message: `User input for mongodbLogPath is now invalid. Now logging to stderr.`, + error: errorMessage + }); + this.logDestination = tempLogDestination; + } catch (e) { + this.turnOffSeverities(); + } + } + private log( severity: SeverityLevel, component: MongoLoggableComponent, @@ -755,7 +784,11 @@ export class MongoLogger { logMessage = { ...logMessage, ...defaultLogTransform(message, this.maxDocumentLength) }; } } - this.logDestination.write(logMessage); + try { + this.logDestination.write(logMessage); + } catch (e) { + this.logWriteFailureHandler(e.message); + } } /** diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 90a36437494..880c5b86d74 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -19,11 +19,14 @@ import { CONNECTION_POOL_CREATED, CONNECTION_POOL_READY, CONNECTION_READY, + createStdioLogger, DEFAULT_MAX_DOCUMENT_LENGTH, + defaultLogTransform, type Log, type MongoDBLogWritable, MongoLogger, type MongoLoggerOptions, + parseSeverityFromString, SeverityLevel, stringifyWithMaxLen } from '../mongodb'; @@ -1227,6 +1230,12 @@ describe('class MongoLogger', function () { }); }); }); + + context('when invalid severity is passed into parseSeverityFromString', function () { + it('should not throw', function () { + expect(parseSeverityFromString('notARealSeverityLevel')).to.equal(null); + }); + }); }); } }); @@ -1276,6 +1285,135 @@ describe('class MongoLogger', function () { }).to.not.throw(); }); }); + + context('EJSON stringify invalid inputs', function () { + const errorInputs = [ + { + name: 'Map with non-string keys', + input: new Map([ + [1, 'one'], + [2, 'two'], + [3, 'three'] + ]) + }, + { + name: 'Object with invalid _bsontype', + input: { _bsontype: 'i will never be a real bson type' } + } + ]; + for (let i = 0; i < errorInputs.length; i++) { + context(`when value is ${errorInputs[i].name}`, function () { + it('should output default error message, with no error thrown', function () { + expect( + stringifyWithMaxLen(errorInputs[i].input, DEFAULT_MAX_DOCUMENT_LENGTH) + ).to.equal('... ESJON failed : Error ...'); + }); + }); + } + }); + + context('when given anonymous function as input', function () { + it('should output default error message', function () { + expect(stringifyWithMaxLen((v: number) => v + 1, DEFAULT_MAX_DOCUMENT_LENGTH)).to.equal( + 'anonymous function' + ); + }); + }); + }); + }); + + describe('defaultLogTransform', function () { + context('when provided a Loggable Event with invalid host-port', function () { + // this is an important case to consider, because in the case of an undefined address, the HostAddress.toString() function will throw + it('should not throw and output empty host string instead', function () { + expect(defaultLogTransform({ name: 'connectionCreated' }).serverHost).to.equal(''); + }); + }); + }); + + describe('log', function () { + context('stream failure handling', function () { + const componentSeverities: MongoLoggerOptions['componentSeverities'] = { + default: 'error' + } as any; + context('when stream is not stderr', function () { + let stderrStub; + + beforeEach(function () { + stderrStub = sinon.stub(process.stderr); + }); + + afterEach(function () { + sinon.restore(); + }); + + context('when stream user defined stream and stream.write throws', function () { + it('should catch error, not crash application, warn user, and start writing to stderr', function () { + const stream = { + write(_log) { + throw Error('This writable always throws'); + } + }; + const logger = new MongoLogger({ + componentSeverities, + maxDocumentLength: 1000, + logDestination: stream + }); + // print random message at the debug level + logger.debug('random message'); + let stderrStubCall = stderrStub.write.getCall(0).args[0]; + stderrStubCall = stderrStubCall.slice(stderrStubCall.search('c:')); + expect(stderrStubCall).to.equal( + `c: 'client', s: 'error', message: 'User input for mongodbLogPath is now invalid. Now logging to stderr.', error: 'This writable always throws' }` + ); + logger.debug('random message 2'); + const stderrStubCall2 = stderrStub.write.getCall(1); + expect(stderrStubCall2).to.not.be.null; + }); + }); + + context('when stream is stdout and stdout.write throws', function () { + it('should catch error, not crash application, warn user, and start writing to stderr', function () { + sinon.stub(process.stdout, 'write').throws(new Error('I am stdout and do not work')); + // print random message at the debug level + const logger = new MongoLogger({ + componentSeverities, + maxDocumentLength: 1000, + logDestination: createStdioLogger(process.stdout) + }); + logger.debug('random message'); + let stderrStubCall = stderrStub.write.getCall(0).args[0]; + stderrStubCall = stderrStubCall.slice(stderrStubCall.search('c:')); + expect(stderrStubCall).to.equal( + `c: 'client', s: 'error', message: 'User input for mongodbLogPath is now invalid. Now logging to stderr.', error: 'I am stdout and do not work' }` + ); + logger.debug('random message 2'); + const stderrStubCall2 = stderrStub.write.getCall(1); + expect(stderrStubCall2).to.not.be.null; + }); + }); + }); + + context('when stream is stderr', function () { + context('when stderr.write throws', function () { + beforeEach(function () { + sinon.stub(process.stderr, 'write').throws(new Error('fake stderr failure')); + }); + afterEach(function () { + sinon.restore(); + }); + + it('should not throw error', function () { + // print random message at the debug level + const logger = new MongoLogger({ + componentSeverities, + maxDocumentLength: 1000, + logDestination: createStdioLogger(process.stderr) + }); + expect(() => logger.debug('random message')).to.not.throw(Error); + }); + }); + }); }); }); }); From 18c1d88b85fa3e1ac66489ec7e0eff81a26e2bca Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Fri, 19 Jan 2024 14:44:33 -0500 Subject: [PATCH 2/9] async error handling done (with exception of stdio logger) --- src/mongo_logger.ts | 34 +++++++++--- test/unit/mongo_logger.test.ts | 96 +++++++++++++++++++++++++++++++--- 2 files changed, 117 insertions(+), 13 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index d17e36b7a5e..656fe8bf0e0 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -58,7 +58,7 @@ import type { ServerSelectionSucceededEvent, WaitingForSuitableServerEvent } from './sdam/server_selection_events'; -import { HostAddress, parseUnsignedInteger } from './utils'; +import { HostAddress, isPromiseLike, parseUnsignedInteger } from './utils'; /** @internal */ export const SeverityLevel = Object.freeze({ @@ -282,7 +282,7 @@ export interface Log extends Record { /** @internal */ export interface MongoDBLogWritable { - write(log: Log): void; + write(log: Log): any; } function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { @@ -708,6 +708,7 @@ export class MongoLogger { componentSeverities: Record; maxDocumentLength: number; logDestination: MongoDBLogWritable | Writable; + pendingLog: any | undefined; /** * This method should be used when logging errors that do not have a public driver API for @@ -739,6 +740,7 @@ export class MongoLogger { this.componentSeverities = options.componentSeverities; this.maxDocumentLength = options.maxDocumentLength; this.logDestination = options.logDestination; + this.pendingLog = undefined; } willLog(severity: SeverityLevel, component: MongoLoggableComponent): boolean { @@ -751,7 +753,7 @@ export class MongoLogger { } } - logWriteFailureHandler(errorMessage: string) { + private logWriteFailureHandler(error: Error) { try { const tempLogDestination = createStdioLogger(process.stderr); tempLogDestination.write({ @@ -759,12 +761,17 @@ export class MongoLogger { c: MongoLoggableComponent.CLIENT, s: SeverityLevel.ERROR, message: `User input for mongodbLogPath is now invalid. Now logging to stderr.`, - error: errorMessage + error: error.message }); this.logDestination = tempLogDestination; } catch (e) { this.turnOffSeverities(); } + this.clearPendingLog(); + } + + private clearPendingLog() { + this.pendingLog = undefined; } private log( @@ -784,10 +791,23 @@ export class MongoLogger { logMessage = { ...logMessage, ...defaultLogTransform(message, this.maxDocumentLength) }; } } + + if (isPromiseLike(this.pendingLog)) { + this.pendingLog = this.pendingLog + .then(() => this.logDestination.write(logMessage)) + .then(this.clearPendingLog.bind(this), this.logWriteFailureHandler.bind(this)); + return; + } + try { - this.logDestination.write(logMessage); - } catch (e) { - this.logWriteFailureHandler(e.message); + const logResult = this.logDestination.write(logMessage); + if (isPromiseLike(logResult)) + this.pendingLog = logResult.then( + this.clearPendingLog.bind(this), + this.logWriteFailureHandler.bind(this) + ); + } catch (error) { + this.logWriteFailureHandler(error); } } diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 880c5b86d74..d29a9be03ba 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -2,6 +2,7 @@ import { EJSON, ObjectId } from 'bson'; import { expect } from 'chai'; import * as sinon from 'sinon'; import { Readable, Writable } from 'stream'; +import { setTimeout } from 'timers'; import { inspect } from 'util'; import { @@ -56,7 +57,7 @@ describe('meta tests for BufferingStream', function () { }); }); -describe('class MongoLogger', function () { +describe('class MongoLogger', async function () { describe('#constructor()', function () { it('assigns each property from the options object onto the logging class', function () { const componentSeverities: MongoLoggerOptions['componentSeverities'] = { @@ -1331,11 +1332,11 @@ describe('class MongoLogger', function () { }); }); - describe('log', function () { - context('stream failure handling', function () { - const componentSeverities: MongoLoggerOptions['componentSeverities'] = { - default: 'error' - } as any; + describe('log', async function () { + const componentSeverities: MongoLoggerOptions['componentSeverities'] = { + default: 'error' + } as any; + describe('sync stream failure handling', function () { context('when stream is not stderr', function () { let stderrStub; @@ -1415,5 +1416,88 @@ describe('class MongoLogger', function () { }); }); }); + describe('async stream failure handling', async function () { + context('when stream is not stderr', function () { + let stderrStub; + + beforeEach(function () { + stderrStub = sinon.stub(process.stderr); + }); + + afterEach(function () { + sinon.restore(); + }); + + context('when stream user defined stream and stream.write throws async', async function () { + it('should catch error, not crash application, warn user, and start writing to stderr', async function () { + const stream = { + async write(_log) { + await new Promise(r => setTimeout(r, 500)); + throw Error('This writable always throws, but only after at least 500ms'); + } + }; + const logger = new MongoLogger({ + componentSeverities, + maxDocumentLength: 1000, + logDestination: stream + }); + // print random message at the debug level + logger.debug('random message'); + + // before timeout resolves, no error + expect(stderrStub.write.getCall(0)).to.be.null; + + // manually wait for timeout to end + await new Promise(r => setTimeout(r, 600)); + + // stderr now contains the error message + let stderrStubCall = stderrStub.write.getCall(0).args[0]; + stderrStubCall = stderrStubCall.slice(stderrStubCall.search('c:')); + expect(stderrStubCall).to.equal( + `c: 'client', s: 'error', message: 'User input for mongodbLogPath is now invalid. Now logging to stderr.', error: 'This writable always throws, but only after at least 500ms' }` + ); + + logger.debug('random message 2'); + const stderrStubCall2 = stderrStub.write.getCall(1); + expect(stderrStubCall2).to.not.be.null; + }); + }); + }); + }); + context('when async stream has multiple logs with different timeouts', async function () { + it('should preserve their order', async function () { + const stream = { + buffer: [], + async write(log) { + if (log.c === 'longer timeout') { + await new Promise(r => setTimeout(r, 2000)); + } else if (log.c === 'shorter timeout') { + await new Promise(r => setTimeout(r, 500)); + } + this.buffer.push(log.c); + } + }; + const logger = new MongoLogger({ + componentSeverities, + maxDocumentLength: 1000, + logDestination: stream + }); + + logger.debug('longer timeout'); + logger.debug('shorter timeout'); + logger.debug('no timeout'); + + expect(stream.buffer.length).to.equal(0); + + await new Promise(r => setTimeout(r, 2100)); + expect(stream.buffer.length).to.equal(1); + expect(stream.buffer[0]).to.equal('longer timeout'); + + await new Promise(r => setTimeout(r, 600)); + expect(stream.buffer.length).to.equal(3); + expect(stream.buffer[1]).to.equal('shorter timeout'); + expect(stream.buffer[2]).to.equal('no timeout'); + }); + }); }); }); From af8183ca3df8909c611ba6fc49c2fc400e10b443 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Fri, 19 Jan 2024 16:59:01 -0500 Subject: [PATCH 3/9] Primary PR requested changes --- src/mongo_logger.ts | 48 +++++++++++++++++++--------------- test/unit/mongo_logger.test.ts | 33 +++++++++++------------ 2 files changed, 42 insertions(+), 39 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 656fe8bf0e0..dd4a732ba85 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -44,6 +44,7 @@ import { TOPOLOGY_OPENING, WAITING_FOR_SUITABLE_SERVER } from './constants'; +import { MongoError } from './error'; import type { ServerClosedEvent, ServerOpeningEvent, @@ -214,14 +215,16 @@ export function parseSeverityFromString(s?: string): SeverityLevel | null { } /** @internal */ -export function createStdioLogger(stream: { - write: NodeJS.WriteStream['write']; -}): MongoDBLogWritable { +export function createStdioLogger( + stream: { write: NodeJS.WriteStream['write'] }, + streamName: 'stderr' | 'stdout' +): MongoDBLogWritable { return { write: (log: Log): unknown => { stream.write(inspect(log, { compact: true, breakLength: Infinity }), 'utf-8'); return; - } + }, + streamName: streamName }; } @@ -240,10 +243,10 @@ function resolveLogPath( { mongodbLogPath }: MongoLoggerMongoClientOptions ): MongoDBLogWritable { if (typeof mongodbLogPath === 'string' && /^stderr$/i.test(mongodbLogPath)) { - return createStdioLogger(process.stderr); + return createStdioLogger(process.stderr, 'stderr'); } if (typeof mongodbLogPath === 'string' && /^stdout$/i.test(mongodbLogPath)) { - return createStdioLogger(process.stdout); + return createStdioLogger(process.stdout, 'stdout'); } if (typeof mongodbLogPath === 'object' && typeof mongodbLogPath?.write === 'function') { @@ -251,13 +254,13 @@ function resolveLogPath( } if (MONGODB_LOG_PATH && /^stderr$/i.test(MONGODB_LOG_PATH)) { - return createStdioLogger(process.stderr); + return createStdioLogger(process.stderr, 'stderr'); } if (MONGODB_LOG_PATH && /^stdout$/i.test(MONGODB_LOG_PATH)) { - return createStdioLogger(process.stdout); + return createStdioLogger(process.stdout, 'stdout'); } - return createStdioLogger(process.stderr); + return createStdioLogger(process.stderr, 'stderr'); } function resolveSeverityConfiguration( @@ -282,7 +285,8 @@ export interface Log extends Record { /** @internal */ export interface MongoDBLogWritable { - write(log: Log): any; + write(log: Log): PromiseLike | any; + streamName?: string; } function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { @@ -424,7 +428,7 @@ export function stringifyWithMaxLen( ? value.name : 'anonymous function'; } catch (e) { - return '... ESJON failed : Error ...'; + strToTruncate = `... ESJON failed : Error ${e.message}`; } return maxDocumentLength !== 0 && strToTruncate.length > maxDocumentLength @@ -708,7 +712,7 @@ export class MongoLogger { componentSeverities: Record; maxDocumentLength: number; logDestination: MongoDBLogWritable | Writable; - pendingLog: any | undefined; + pendingLog: PromiseLike | undefined = undefined; /** * This method should be used when logging errors that do not have a public driver API for @@ -740,7 +744,6 @@ export class MongoLogger { this.componentSeverities = options.componentSeverities; this.maxDocumentLength = options.maxDocumentLength; this.logDestination = options.logDestination; - this.pendingLog = undefined; } willLog(severity: SeverityLevel, component: MongoLoggableComponent): boolean { @@ -755,15 +758,18 @@ export class MongoLogger { private logWriteFailureHandler(error: Error) { try { - const tempLogDestination = createStdioLogger(process.stderr); - tempLogDestination.write({ - t: new Date(), - c: MongoLoggableComponent.CLIENT, - s: SeverityLevel.ERROR, - message: `User input for mongodbLogPath is now invalid. Now logging to stderr.`, - error: error.message + if ((this.logDestination as any)?.streamName === 'stderr') { + throw MongoError; + } + this.logDestination = createStdioLogger(process.stderr, 'stderr'); + this.error(MongoLoggableComponent.CLIENT, { + toLog: function () { + return { + message: 'User input for mongodbLogPath is now invalid. Now logging to stderr.', + error: error.message + }; + } }); - this.logDestination = tempLogDestination; } catch (e) { this.turnOffSeverities(); } diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index d29a9be03ba..da167046088 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -2,7 +2,6 @@ import { EJSON, ObjectId } from 'bson'; import { expect } from 'chai'; import * as sinon from 'sinon'; import { Readable, Writable } from 'stream'; -import { setTimeout } from 'timers'; import { inspect } from 'util'; import { @@ -31,6 +30,7 @@ import { SeverityLevel, stringifyWithMaxLen } from '../mongodb'; +import { sleep } from '../tools/utils'; class BufferingStream extends Writable { buffer: any[] = []; @@ -1302,12 +1302,12 @@ describe('class MongoLogger', async function () { input: { _bsontype: 'i will never be a real bson type' } } ]; - for (let i = 0; i < errorInputs.length; i++) { - context(`when value is ${errorInputs[i].name}`, function () { + for (const errorInput of errorInputs) { + context(`when value is ${errorInput.name}`, function () { it('should output default error message, with no error thrown', function () { - expect( - stringifyWithMaxLen(errorInputs[i].input, DEFAULT_MAX_DOCUMENT_LENGTH) - ).to.equal('... ESJON failed : Error ...'); + expect(stringifyWithMaxLen(errorInput.input, 25)).to.equal( + '... ESJON failed : Error ...' + ); }); }); } @@ -1380,7 +1380,7 @@ describe('class MongoLogger', async function () { const logger = new MongoLogger({ componentSeverities, maxDocumentLength: 1000, - logDestination: createStdioLogger(process.stdout) + logDestination: createStdioLogger(process.stdout, 'stdout') }); logger.debug('random message'); let stderrStubCall = stderrStub.write.getCall(0).args[0]; @@ -1432,7 +1432,7 @@ describe('class MongoLogger', async function () { it('should catch error, not crash application, warn user, and start writing to stderr', async function () { const stream = { async write(_log) { - await new Promise(r => setTimeout(r, 500)); + await sleep(500); throw Error('This writable always throws, but only after at least 500ms'); } }; @@ -1448,7 +1448,7 @@ describe('class MongoLogger', async function () { expect(stderrStub.write.getCall(0)).to.be.null; // manually wait for timeout to end - await new Promise(r => setTimeout(r, 600)); + await sleep(600); // stderr now contains the error message let stderrStubCall = stderrStub.write.getCall(0).args[0]; @@ -1470,9 +1470,9 @@ describe('class MongoLogger', async function () { buffer: [], async write(log) { if (log.c === 'longer timeout') { - await new Promise(r => setTimeout(r, 2000)); + await sleep(2000); } else if (log.c === 'shorter timeout') { - await new Promise(r => setTimeout(r, 500)); + await sleep(500); } this.buffer.push(log.c); } @@ -1489,14 +1489,11 @@ describe('class MongoLogger', async function () { expect(stream.buffer.length).to.equal(0); - await new Promise(r => setTimeout(r, 2100)); - expect(stream.buffer.length).to.equal(1); - expect(stream.buffer[0]).to.equal('longer timeout'); + await sleep(2100); + expect(stream.buffer).to.deep.equal(['longer timeout']); - await new Promise(r => setTimeout(r, 600)); - expect(stream.buffer.length).to.equal(3); - expect(stream.buffer[1]).to.equal('shorter timeout'); - expect(stream.buffer[2]).to.equal('no timeout'); + await sleep(600); + expect(stream.buffer).to.deep.equal(['longer timeout', 'shorter timeout', 'no timeout']); }); }); }); From 2c3b18addbac500cbafbff694e26d798030aa994 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Mon, 22 Jan 2024 10:05:01 -0500 Subject: [PATCH 4/9] added unknown to pending log types --- src/mongo_logger.ts | 8 +-- src/utils.ts | 5 +- test/unit/mongo_logger.test.ts | 89 ++++++++++++++++++---------------- 3 files changed, 55 insertions(+), 47 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index dd4a732ba85..239e4877116 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -712,7 +712,7 @@ export class MongoLogger { componentSeverities: Record; maxDocumentLength: number; logDestination: MongoDBLogWritable | Writable; - pendingLog: PromiseLike | undefined = undefined; + pendingLog: PromiseLike | unknown = null; /** * This method should be used when logging errors that do not have a public driver API for @@ -762,6 +762,7 @@ export class MongoLogger { throw MongoError; } this.logDestination = createStdioLogger(process.stderr, 'stderr'); + this.clearPendingLog(); this.error(MongoLoggableComponent.CLIENT, { toLog: function () { return { @@ -777,7 +778,7 @@ export class MongoLogger { } private clearPendingLog() { - this.pendingLog = undefined; + this.pendingLog = null; } private log( @@ -807,11 +808,12 @@ export class MongoLogger { try { const logResult = this.logDestination.write(logMessage); - if (isPromiseLike(logResult)) + if (isPromiseLike(logResult)) { this.pendingLog = logResult.then( this.clearPendingLog.bind(this), this.logWriteFailureHandler.bind(this) ); + } } catch (error) { this.logWriteFailureHandler(error); } diff --git a/src/utils.ts b/src/utils.ts index 25a1cc422c4..20393b48025 100644 --- a/src/utils.ts +++ b/src/utils.ts @@ -171,7 +171,10 @@ export function applyRetryableWrites(target: T, db * @param value - An object that could be a promise * @returns true if the provided value is a Promise */ -export function isPromiseLike(value?: PromiseLike | void): value is Promise { +export function isPromiseLike( + value?: PromiseLike | void | unknown +): value is Promise { + // @ts-expect-error since value exists, value.then check is valid ts return !!value && typeof value.then === 'function'; } diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index da167046088..49c25c460c9 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -1348,7 +1348,7 @@ describe('class MongoLogger', async function () { sinon.restore(); }); - context('when stream user defined stream and stream.write throws', function () { + context('when stream is user defined and stream.write throws', function () { it('should catch error, not crash application, warn user, and start writing to stderr', function () { const stream = { write(_log) { @@ -1372,48 +1372,6 @@ describe('class MongoLogger', async function () { expect(stderrStubCall2).to.not.be.null; }); }); - - context('when stream is stdout and stdout.write throws', function () { - it('should catch error, not crash application, warn user, and start writing to stderr', function () { - sinon.stub(process.stdout, 'write').throws(new Error('I am stdout and do not work')); - // print random message at the debug level - const logger = new MongoLogger({ - componentSeverities, - maxDocumentLength: 1000, - logDestination: createStdioLogger(process.stdout, 'stdout') - }); - logger.debug('random message'); - let stderrStubCall = stderrStub.write.getCall(0).args[0]; - stderrStubCall = stderrStubCall.slice(stderrStubCall.search('c:')); - expect(stderrStubCall).to.equal( - `c: 'client', s: 'error', message: 'User input for mongodbLogPath is now invalid. Now logging to stderr.', error: 'I am stdout and do not work' }` - ); - logger.debug('random message 2'); - const stderrStubCall2 = stderrStub.write.getCall(1); - expect(stderrStubCall2).to.not.be.null; - }); - }); - }); - - context('when stream is stderr', function () { - context('when stderr.write throws', function () { - beforeEach(function () { - sinon.stub(process.stderr, 'write').throws(new Error('fake stderr failure')); - }); - afterEach(function () { - sinon.restore(); - }); - - it('should not throw error', function () { - // print random message at the debug level - const logger = new MongoLogger({ - componentSeverities, - maxDocumentLength: 1000, - logDestination: createStdioLogger(process.stderr) - }); - expect(() => logger.debug('random message')).to.not.throw(Error); - }); - }); }); }); describe('async stream failure handling', async function () { @@ -1462,6 +1420,51 @@ describe('class MongoLogger', async function () { expect(stderrStubCall2).to.not.be.null; }); }); + + context('when stream is stdout and stdout.write throws', async function () { + it('should catch error, not crash application, warn user, and start writing to stderr', async function () { + sinon.stub(process.stdout, 'write').throws(new Error('I am stdout and do not work')); + // print random message at the debug level + const logger = new MongoLogger({ + componentSeverities, + maxDocumentLength: 1000, + logDestination: createStdioLogger(process.stdout, 'stdout') + }); + logger.debug('random message'); + // manually wait for promise to resolve (takes extra time with promisify) + await sleep(600); + let stderrStubCall = stderrStub.write.getCall(0).args[0]; + stderrStubCall = stderrStubCall.slice(stderrStubCall.search('c:')); + expect(stderrStubCall).to.equal( + `c: 'client', s: 'error', message: 'User input for mongodbLogPath is now invalid. Now logging to stderr.', error: 'I am stdout and do not work' }` + ); + logger.debug('random message 2'); + const stderrStubCall2 = stderrStub.write.getCall(1); + expect(stderrStubCall2).to.not.be.null; + }); + }); + }); + + context('when stream is stderr', function () { + context('when stderr.write throws', function () { + beforeEach(function () { + sinon.stub(process.stderr, 'write').throws(new Error('fake stderr failure')); + }); + afterEach(function () { + sinon.restore(); + }); + + it('should not throw error and turn off severities', function () { + // print random message at the debug level + const logger = new MongoLogger({ + componentSeverities, + maxDocumentLength: 1000, + logDestination: createStdioLogger(process.stderr, 'stderr') + }); + expect(() => logger.debug('random message')).to.not.throw(Error); + expect(Object.keys(logger.componentSeverities).every(key => key === SeverityLevel.OFF)); + }); + }); }); }); context('when async stream has multiple logs with different timeouts', async function () { From 8a0b25d5e4b2e8206f826b7cc2e955cb79123357 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Mon, 22 Jan 2024 16:36:36 -0500 Subject: [PATCH 5/9] PR requested changes 2 --- src/mongo_logger.ts | 51 +++++++++++++++++++--------------- src/utils.ts | 12 ++++---- test/unit/mongo_logger.test.ts | 48 +++++++++++++++++++++----------- 3 files changed, 67 insertions(+), 44 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 239e4877116..b5a4dbec94c 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -1,4 +1,3 @@ -import type { Writable } from 'stream'; import { inspect } from 'util'; import { type Document, EJSON, type EJSONOptions, type ObjectId } from './bson'; @@ -44,7 +43,6 @@ import { TOPOLOGY_OPENING, WAITING_FOR_SUITABLE_SERVER } from './constants'; -import { MongoError } from './error'; import type { ServerClosedEvent, ServerOpeningEvent, @@ -193,7 +191,9 @@ export interface MongoLoggerOptions { /** Max length of embedded EJSON docs. Setting to 0 disables truncation. Defaults to 1000. */ maxDocumentLength: number; /** Destination for log messages. */ - logDestination: Writable | MongoDBLogWritable; + logDestination: MongoDBLogWritable; + /** For internal check to see if error should stop logging. */ + logDestinationIsStdErr: boolean; } /** @@ -215,16 +215,14 @@ export function parseSeverityFromString(s?: string): SeverityLevel | null { } /** @internal */ -export function createStdioLogger( - stream: { write: NodeJS.WriteStream['write'] }, - streamName: 'stderr' | 'stdout' -): MongoDBLogWritable { +export function createStdioLogger(stream: { + write: NodeJS.WriteStream['write']; +}): MongoDBLogWritable { return { write: (log: Log): unknown => { stream.write(inspect(log, { compact: true, breakLength: Infinity }), 'utf-8'); return; - }, - streamName: streamName + } }; } @@ -241,26 +239,26 @@ export function createStdioLogger( function resolveLogPath( { MONGODB_LOG_PATH }: MongoLoggerEnvOptions, { mongodbLogPath }: MongoLoggerMongoClientOptions -): MongoDBLogWritable { +): { mongodbLogPath: MongoDBLogWritable; mongodbLogPathIsStdErr: boolean } { if (typeof mongodbLogPath === 'string' && /^stderr$/i.test(mongodbLogPath)) { - return createStdioLogger(process.stderr, 'stderr'); + return { mongodbLogPath: createStdioLogger(process.stderr), mongodbLogPathIsStdErr: true }; } if (typeof mongodbLogPath === 'string' && /^stdout$/i.test(mongodbLogPath)) { - return createStdioLogger(process.stdout, 'stdout'); + return { mongodbLogPath: createStdioLogger(process.stdout), mongodbLogPathIsStdErr: false }; } if (typeof mongodbLogPath === 'object' && typeof mongodbLogPath?.write === 'function') { - return mongodbLogPath; + return { mongodbLogPath: mongodbLogPath, mongodbLogPathIsStdErr: false }; } if (MONGODB_LOG_PATH && /^stderr$/i.test(MONGODB_LOG_PATH)) { - return createStdioLogger(process.stderr, 'stderr'); + return { mongodbLogPath: createStdioLogger(process.stderr), mongodbLogPathIsStdErr: true }; } if (MONGODB_LOG_PATH && /^stdout$/i.test(MONGODB_LOG_PATH)) { - return createStdioLogger(process.stdout, 'stdout'); + return { mongodbLogPath: createStdioLogger(process.stdout), mongodbLogPathIsStdErr: false }; } - return createStdioLogger(process.stderr, 'stderr'); + return { mongodbLogPath: createStdioLogger(process.stderr), mongodbLogPathIsStdErr: true }; } function resolveSeverityConfiguration( @@ -286,7 +284,6 @@ export interface Log extends Record { /** @internal */ export interface MongoDBLogWritable { write(log: Log): PromiseLike | any; - streamName?: string; } function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { @@ -711,7 +708,8 @@ export function defaultLogTransform( export class MongoLogger { componentSeverities: Record; maxDocumentLength: number; - logDestination: MongoDBLogWritable | Writable; + logDestination: MongoDBLogWritable; + logDestinationIsStdErr: boolean; pendingLog: PromiseLike | unknown = null; /** @@ -744,6 +742,7 @@ export class MongoLogger { this.componentSeverities = options.componentSeverities; this.maxDocumentLength = options.maxDocumentLength; this.logDestination = options.logDestination; + this.logDestinationIsStdErr = options.logDestinationIsStdErr; } willLog(severity: SeverityLevel, component: MongoLoggableComponent): boolean { @@ -758,10 +757,13 @@ export class MongoLogger { private logWriteFailureHandler(error: Error) { try { - if ((this.logDestination as any)?.streamName === 'stderr') { - throw MongoError; + if (this.logDestinationIsStdErr) { + this.turnOffSeverities(); + this.clearPendingLog(); + return; } - this.logDestination = createStdioLogger(process.stderr, 'stderr'); + this.logDestination = createStdioLogger(process.stderr); + this.logDestinationIsStdErr = true; this.clearPendingLog(); this.error(MongoLoggableComponent.CLIENT, { toLog: function () { @@ -837,10 +839,12 @@ export class MongoLogger { clientOptions: MongoLoggerMongoClientOptions ): MongoLoggerOptions { // client options take precedence over env options + const resolvedLogPath = resolveLogPath(envOptions, clientOptions); const combinedOptions = { ...envOptions, ...clientOptions, - mongodbLogPath: resolveLogPath(envOptions, clientOptions) + mongodbLogPath: resolvedLogPath.mongodbLogPath, + mongodbLogPathIsStdErr: resolvedLogPath.mongodbLogPathIsStdErr }; const defaultSeverity = resolveSeverityConfiguration( combinedOptions.mongodbLogComponentSeverities?.default, @@ -881,7 +885,8 @@ export class MongoLogger { combinedOptions.mongodbLogMaxDocumentLength ?? parseUnsignedInteger(combinedOptions.MONGODB_LOG_MAX_DOCUMENT_LENGTH) ?? 1000, - logDestination: combinedOptions.mongodbLogPath + logDestination: combinedOptions.mongodbLogPath, + logDestinationIsStdErr: combinedOptions.mongodbLogPathIsStdErr }; } } diff --git a/src/utils.ts b/src/utils.ts index 20393b48025..0e352cb555c 100644 --- a/src/utils.ts +++ b/src/utils.ts @@ -171,11 +171,13 @@ export function applyRetryableWrites(target: T, db * @param value - An object that could be a promise * @returns true if the provided value is a Promise */ -export function isPromiseLike( - value?: PromiseLike | void | unknown -): value is Promise { - // @ts-expect-error since value exists, value.then check is valid ts - return !!value && typeof value.then === 'function'; +export function isPromiseLike(value?: unknown): value is Promise { + return ( + value != null && + typeof value === 'object' && + 'then' in value && + typeof value.then === 'function' + ); } /** diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 49c25c460c9..9ca92833784 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -67,7 +67,8 @@ describe('class MongoLogger', async function () { const logger = new MongoLogger({ componentSeverities, maxDocumentLength: 10, - logDestination: stream + logDestination: stream, + logDestinationIsStdErr: false }); expect(logger).to.have.property('componentSeverities', componentSeverities); @@ -85,7 +86,8 @@ describe('class MongoLogger', async function () { } as { buffer: any[]; write: (log: Log) => void }; const logger = new MongoLogger({ componentSeverities: { command: 'error' } as any, - logDestination + logDestination, + logDestinationIsStdErr: false } as any); logger.error('command', 'Hello world!'); @@ -105,7 +107,8 @@ describe('class MongoLogger', async function () { const logger = new MongoLogger({ componentSeverities: { command: 'error' } as any, - logDestination + logDestination, + logDestinationIsStdErr: false } as any); logger.error('command', 'Hello world!'); @@ -648,7 +651,8 @@ describe('class MongoLogger', async function () { componentSeverities: { topology: 'off' } as any, - logDestination: stream + logDestination: stream, + logDestinationIsStdErr: false } as any); logger[severityLevel]('topology', 'message'); @@ -662,7 +666,8 @@ describe('class MongoLogger', async function () { componentSeverities: { command: severityLevel } as any, - logDestination: stream + logDestination: stream, + logDestinationIsStdErr: false } as any); for (let i = index + 1; i < severities.length; i++) { @@ -681,7 +686,8 @@ describe('class MongoLogger', async function () { componentSeverities: { command: severityLevel } as any, - logDestination: stream + logDestination: stream, + logDestinationIsStdErr: false } as any); // Calls all severity logging methods with a level less than or equal to what severityLevel @@ -706,7 +712,8 @@ describe('class MongoLogger', async function () { const stream = new BufferingStream(); const logger = new MongoLogger({ componentSeverities: { command: severityLevel } as any, - logDestination: stream + logDestination: stream, + logDestinationIsStdErr: false } as any); logger[severityLevel]('command', obj); @@ -722,7 +729,8 @@ describe('class MongoLogger', async function () { const stream = new BufferingStream(); const logger = new MongoLogger({ componentSeverities: { command: severityLevel } as any, - logDestination: stream + logDestination: stream, + logDestinationIsStdErr: false } as any); logger[severityLevel]('command', obj); @@ -742,7 +750,8 @@ describe('class MongoLogger', async function () { const stream = new BufferingStream(); const logger = new MongoLogger({ componentSeverities: { command: severityLevel } as any, - logDestination: stream + logDestination: stream, + logDestinationIsStdErr: false } as any); logger[severityLevel]('command', obj); @@ -760,7 +769,8 @@ describe('class MongoLogger', async function () { const stream = new BufferingStream(); const logger = new MongoLogger({ componentSeverities: { command: severityLevel } as any, - logDestination: stream + logDestination: stream, + logDestinationIsStdErr: false } as any); logger[severityLevel]('command', message); @@ -780,7 +790,8 @@ describe('class MongoLogger', async function () { command: 'trace', connection: 'trace' } as any, - logDestination: stream + logDestination: stream, + logDestinationIsStdErr: false } as any); }); @@ -1358,7 +1369,8 @@ describe('class MongoLogger', async function () { const logger = new MongoLogger({ componentSeverities, maxDocumentLength: 1000, - logDestination: stream + logDestination: stream, + logDestinationIsStdErr: false }); // print random message at the debug level logger.debug('random message'); @@ -1397,7 +1409,8 @@ describe('class MongoLogger', async function () { const logger = new MongoLogger({ componentSeverities, maxDocumentLength: 1000, - logDestination: stream + logDestination: stream, + logDestinationIsStdErr: false }); // print random message at the debug level logger.debug('random message'); @@ -1428,7 +1441,8 @@ describe('class MongoLogger', async function () { const logger = new MongoLogger({ componentSeverities, maxDocumentLength: 1000, - logDestination: createStdioLogger(process.stdout, 'stdout') + logDestination: createStdioLogger(process.stdout), + logDestinationIsStdErr: false }); logger.debug('random message'); // manually wait for promise to resolve (takes extra time with promisify) @@ -1459,7 +1473,8 @@ describe('class MongoLogger', async function () { const logger = new MongoLogger({ componentSeverities, maxDocumentLength: 1000, - logDestination: createStdioLogger(process.stderr, 'stderr') + logDestination: createStdioLogger(process.stderr), + logDestinationIsStdErr: true }); expect(() => logger.debug('random message')).to.not.throw(Error); expect(Object.keys(logger.componentSeverities).every(key => key === SeverityLevel.OFF)); @@ -1483,7 +1498,8 @@ describe('class MongoLogger', async function () { const logger = new MongoLogger({ componentSeverities, maxDocumentLength: 1000, - logDestination: stream + logDestination: stream, + logDestinationIsStdErr: false }); logger.debug('longer timeout'); From 566dd00fb7ab107d710cf99f74e4c071651b4aed Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Tue, 23 Jan 2024 14:29:29 -0500 Subject: [PATCH 6/9] PR requested changes 3 --- src/mongo_logger.ts | 45 +++++++++++++--------------- test/unit/mongo_logger.test.ts | 54 +++++++++++++++++++++------------- 2 files changed, 55 insertions(+), 44 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index b5a4dbec94c..a18aed40afd 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -1,4 +1,4 @@ -import { inspect } from 'util'; +import { inspect, promisify } from 'util'; import { type Document, EJSON, type EJSONOptions, type ObjectId } from './bson'; import type { CommandStartedEvent } from './cmap/command_monitoring_events'; @@ -219,10 +219,10 @@ export function createStdioLogger(stream: { write: NodeJS.WriteStream['write']; }): MongoDBLogWritable { return { - write: (log: Log): unknown => { - stream.write(inspect(log, { compact: true, breakLength: Infinity }), 'utf-8'); + write: promisify((log: Log, cb: () => void): unknown => { + stream.write(inspect(log, { compact: true, breakLength: Infinity }), 'utf-8', cb); return; - } + }) }; } @@ -283,7 +283,7 @@ export interface Log extends Record { /** @internal */ export interface MongoDBLogWritable { - write(log: Log): PromiseLike | any; + write(log: Log): PromiseLike | unknown; } function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { @@ -750,32 +750,29 @@ export class MongoLogger { } turnOffSeverities() { - for (const key of Object.keys(MongoLoggableComponent)) { + for (const key of Object.values(MongoLoggableComponent)) { this.componentSeverities[key as MongoLoggableComponent] = SeverityLevel.OFF; } } private logWriteFailureHandler(error: Error) { - try { - if (this.logDestinationIsStdErr) { - this.turnOffSeverities(); - this.clearPendingLog(); - return; - } - this.logDestination = createStdioLogger(process.stderr); - this.logDestinationIsStdErr = true; - this.clearPendingLog(); - this.error(MongoLoggableComponent.CLIENT, { - toLog: function () { - return { - message: 'User input for mongodbLogPath is now invalid. Now logging to stderr.', - error: error.message - }; - } - }); - } catch (e) { + if (this.logDestinationIsStdErr) { this.turnOffSeverities(); + this.clearPendingLog(); + return; } + this.logDestination = createStdioLogger(process.stderr); + this.logDestinationIsStdErr = true; + this.clearPendingLog(); + this.error(MongoLoggableComponent.CLIENT, { + toLog: function () { + return { + message: 'User input for mongodbLogPath is now invalid. Logging is halted.', + error: error.message + }; + } + }); + this.turnOffSeverities(); this.clearPendingLog(); } diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 9ca92833784..09f84ace2ad 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -1345,7 +1345,11 @@ describe('class MongoLogger', async function () { describe('log', async function () { const componentSeverities: MongoLoggerOptions['componentSeverities'] = { - default: 'error' + command: 'trace', + topology: 'trace', + serverSelection: 'trace', + connection: 'trace', + client: 'trace' } as any; describe('sync stream failure handling', function () { context('when stream is not stderr', function () { @@ -1373,15 +1377,18 @@ describe('class MongoLogger', async function () { logDestinationIsStdErr: false }); // print random message at the debug level - logger.debug('random message'); + logger.debug('client', 'random message'); let stderrStubCall = stderrStub.write.getCall(0).args[0]; stderrStubCall = stderrStubCall.slice(stderrStubCall.search('c:')); expect(stderrStubCall).to.equal( - `c: 'client', s: 'error', message: 'User input for mongodbLogPath is now invalid. Now logging to stderr.', error: 'This writable always throws' }` + `c: 'client', s: 'error', message: 'User input for mongodbLogPath is now invalid. Logging is halted.', error: 'This writable always throws' }` ); - logger.debug('random message 2'); + + // logging is halted + logger.debug('client', 'random message 2'); const stderrStubCall2 = stderrStub.write.getCall(1); - expect(stderrStubCall2).to.not.be.null; + expect(stderrStubCall2).to.be.null; + expect(Object.keys(logger.componentSeverities).every(key => key === SeverityLevel.OFF)); }); }); }); @@ -1413,7 +1420,7 @@ describe('class MongoLogger', async function () { logDestinationIsStdErr: false }); // print random message at the debug level - logger.debug('random message'); + logger.debug('client', 'random message'); // before timeout resolves, no error expect(stderrStub.write.getCall(0)).to.be.null; @@ -1425,12 +1432,14 @@ describe('class MongoLogger', async function () { let stderrStubCall = stderrStub.write.getCall(0).args[0]; stderrStubCall = stderrStubCall.slice(stderrStubCall.search('c:')); expect(stderrStubCall).to.equal( - `c: 'client', s: 'error', message: 'User input for mongodbLogPath is now invalid. Now logging to stderr.', error: 'This writable always throws, but only after at least 500ms' }` + `c: 'client', s: 'error', message: 'User input for mongodbLogPath is now invalid. Logging is halted.', error: 'This writable always throws, but only after at least 500ms' }` ); - logger.debug('random message 2'); + // no more logging in the future + logger.debug('client', 'random message 2'); const stderrStubCall2 = stderrStub.write.getCall(1); - expect(stderrStubCall2).to.not.be.null; + expect(stderrStubCall2).to.be.null; + expect(Object.keys(logger.componentSeverities).every(key => key === SeverityLevel.OFF)); }); }); @@ -1444,17 +1453,22 @@ describe('class MongoLogger', async function () { logDestination: createStdioLogger(process.stdout), logDestinationIsStdErr: false }); - logger.debug('random message'); + logger.debug('client', 'random message'); + // manually wait for promise to resolve (takes extra time with promisify) await sleep(600); + let stderrStubCall = stderrStub.write.getCall(0).args[0]; stderrStubCall = stderrStubCall.slice(stderrStubCall.search('c:')); expect(stderrStubCall).to.equal( - `c: 'client', s: 'error', message: 'User input for mongodbLogPath is now invalid. Now logging to stderr.', error: 'I am stdout and do not work' }` + `c: 'client', s: 'error', message: 'User input for mongodbLogPath is now invalid. Logging is halted.', error: 'I am stdout and do not work' }` ); - logger.debug('random message 2'); + + // logging is halted + logger.debug('client', 'random message 2'); const stderrStubCall2 = stderrStub.write.getCall(1); - expect(stderrStubCall2).to.not.be.null; + expect(stderrStubCall2).to.be.null; + expect(Object.keys(logger.componentSeverities).every(key => key === SeverityLevel.OFF)); }); }); }); @@ -1476,7 +1490,7 @@ describe('class MongoLogger', async function () { logDestination: createStdioLogger(process.stderr), logDestinationIsStdErr: true }); - expect(() => logger.debug('random message')).to.not.throw(Error); + expect(() => logger.debug('client', 'random message')).to.not.throw(Error); expect(Object.keys(logger.componentSeverities).every(key => key === SeverityLevel.OFF)); }); }); @@ -1487,12 +1501,12 @@ describe('class MongoLogger', async function () { const stream = { buffer: [], async write(log) { - if (log.c === 'longer timeout') { + if (log.message === 'longer timeout') { await sleep(2000); - } else if (log.c === 'shorter timeout') { + } else if (log.message === 'shorter timeout') { await sleep(500); } - this.buffer.push(log.c); + this.buffer.push(log.message); } }; const logger = new MongoLogger({ @@ -1502,9 +1516,9 @@ describe('class MongoLogger', async function () { logDestinationIsStdErr: false }); - logger.debug('longer timeout'); - logger.debug('shorter timeout'); - logger.debug('no timeout'); + logger.debug('client', 'longer timeout'); + logger.debug('client', 'shorter timeout'); + logger.debug('client', 'no timeout'); expect(stream.buffer.length).to.equal(0); From d7856774d53de6b429c18f2936001576b70a2ad1 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Tue, 23 Jan 2024 14:51:21 -0500 Subject: [PATCH 7/9] PR requested changes 3 (remaining changes) --- src/mongo_logger.ts | 12 +++++------- test/unit/mongo_logger.test.ts | 12 +----------- 2 files changed, 6 insertions(+), 18 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index a18aed40afd..8c4b0b284fa 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -421,11 +421,9 @@ export function stringifyWithMaxLen( strToTruncate = typeof value !== 'function' ? EJSON.stringify(value, options) - : value.name !== '' - ? value.name - : 'anonymous function'; + : 'ReadPreference function'; } catch (e) { - strToTruncate = `... ESJON failed : Error ${e.message}`; + strToTruncate = `Extended JSON serialization failed with: ${e.message}`; } return maxDocumentLength !== 0 && strToTruncate.length > maxDocumentLength @@ -463,7 +461,7 @@ function attachCommandFields( log.commandName = commandEvent.commandName; log.requestId = commandEvent.requestId; log.driverConnectionId = commandEvent.connectionId; - const { host, port } = HostAddress.fromString(commandEvent.address ?? '').toHostPort(); + const { host, port } = HostAddress.fromString(commandEvent.address).toHostPort(); log.serverHost = host; log.serverPort = port; if (commandEvent?.serviceId) { @@ -476,7 +474,7 @@ function attachCommandFields( } function attachConnectionFields(log: Record, event: any) { - const { host, port } = HostAddress.fromString(event.address ?? '').toHostPort(); + const { host, port } = HostAddress.fromString(event.address).toHostPort(); log.serverHost = host; log.serverPort = port; @@ -498,7 +496,7 @@ function attachServerHeartbeatFields( const { awaited, connectionId } = serverHeartbeatEvent; log.awaited = awaited; log.driverConnectionId = serverHeartbeatEvent.connectionId; - const { host, port } = HostAddress.fromString(connectionId ?? '').toHostPort(); + const { host, port } = HostAddress.fromString(connectionId).toHostPort(); log.serverHost = host; log.serverPort = port; return log; diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 09f84ace2ad..aea9d8706f6 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -21,7 +21,6 @@ import { CONNECTION_READY, createStdioLogger, DEFAULT_MAX_DOCUMENT_LENGTH, - defaultLogTransform, type Log, type MongoDBLogWritable, MongoLogger, @@ -57,7 +56,7 @@ describe('meta tests for BufferingStream', function () { }); }); -describe('class MongoLogger', async function () { +describe.only('class MongoLogger', async function () { describe('#constructor()', function () { it('assigns each property from the options object onto the logging class', function () { const componentSeverities: MongoLoggerOptions['componentSeverities'] = { @@ -1334,15 +1333,6 @@ describe('class MongoLogger', async function () { }); }); - describe('defaultLogTransform', function () { - context('when provided a Loggable Event with invalid host-port', function () { - // this is an important case to consider, because in the case of an undefined address, the HostAddress.toString() function will throw - it('should not throw and output empty host string instead', function () { - expect(defaultLogTransform({ name: 'connectionCreated' }).serverHost).to.equal(''); - }); - }); - }); - describe('log', async function () { const componentSeverities: MongoLoggerOptions['componentSeverities'] = { command: 'trace', From 68ffd886e91cf3661c4d307d16ba11e37584d068 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Tue, 23 Jan 2024 16:17:28 -0500 Subject: [PATCH 8/9] PR requested changes 4 --- src/mongo_logger.ts | 7 ++----- src/sdam/server_selection.ts | 15 +++++++------- src/utils.ts | 2 +- test/unit/mongo_logger.test.ts | 37 ++++++++++++++++++++-------------- 4 files changed, 33 insertions(+), 28 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 8c4b0b284fa..390179bf4da 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -219,7 +219,7 @@ export function createStdioLogger(stream: { write: NodeJS.WriteStream['write']; }): MongoDBLogWritable { return { - write: promisify((log: Log, cb: () => void): unknown => { + write: promisify((log: Log, cb: (error?: Error) => void): unknown => { stream.write(inspect(log, { compact: true, breakLength: Infinity }), 'utf-8', cb); return; }) @@ -418,10 +418,7 @@ export function stringifyWithMaxLen( let strToTruncate = ''; try { - strToTruncate = - typeof value !== 'function' - ? EJSON.stringify(value, options) - : 'ReadPreference function'; + strToTruncate = typeof value !== 'function' ? EJSON.stringify(value, options) : value.name; } catch (e) { strToTruncate = `Extended JSON serialization failed with: ${e.message}`; } diff --git a/src/sdam/server_selection.ts b/src/sdam/server_selection.ts index 2ffae442415..8c92f08b625 100644 --- a/src/sdam/server_selection.ts +++ b/src/sdam/server_selection.ts @@ -22,14 +22,15 @@ export type ServerSelector = ( * Returns a server selector that selects for writable servers */ export function writableServerSelector(): ServerSelector { - return ( + return function writableServer( topologyDescription: TopologyDescription, servers: ServerDescription[] - ): ServerDescription[] => - latencyWindowReducer( + ): ServerDescription[] { + return latencyWindowReducer( topologyDescription, servers.filter((s: ServerDescription) => s.isWritable) ); + }; } /** @@ -37,10 +38,10 @@ export function writableServerSelector(): ServerSelector { * if it is in a state that it can have commands sent to it. */ export function sameServerSelector(description?: ServerDescription): ServerSelector { - return ( + return function sameServerSelector( topologyDescription: TopologyDescription, servers: ServerDescription[] - ): ServerDescription[] => { + ): ServerDescription[] { if (!description) return []; // Filter the servers to match the provided description only if // the type is not unknown. @@ -265,11 +266,11 @@ export function readPreferenceServerSelector(readPreference: ReadPreference): Se throw new MongoInvalidArgumentError('Invalid read preference specified'); } - return ( + return function readPreferenceServers( topologyDescription: TopologyDescription, servers: ServerDescription[], deprioritized: ServerDescription[] = [] - ): ServerDescription[] => { + ): ServerDescription[] { const commonWireVersion = topologyDescription.commonWireVersion; if ( commonWireVersion && diff --git a/src/utils.ts b/src/utils.ts index 0e352cb555c..d511d6f1a55 100644 --- a/src/utils.ts +++ b/src/utils.ts @@ -171,7 +171,7 @@ export function applyRetryableWrites(target: T, db * @param value - An object that could be a promise * @returns true if the provided value is a Promise */ -export function isPromiseLike(value?: unknown): value is Promise { +export function isPromiseLike(value?: unknown): value is PromiseLike { return ( value != null && typeof value === 'object' && diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index aea9d8706f6..7a6e1b2da9b 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -56,7 +56,7 @@ describe('meta tests for BufferingStream', function () { }); }); -describe.only('class MongoLogger', async function () { +describe('class MongoLogger', async function () { describe('#constructor()', function () { it('assigns each property from the options object onto the logging class', function () { const componentSeverities: MongoLoggerOptions['componentSeverities'] = { @@ -1315,32 +1315,39 @@ describe.only('class MongoLogger', async function () { for (const errorInput of errorInputs) { context(`when value is ${errorInput.name}`, function () { it('should output default error message, with no error thrown', function () { - expect(stringifyWithMaxLen(errorInput.input, 25)).to.equal( - '... ESJON failed : Error ...' + expect(stringifyWithMaxLen(errorInput.input, 40)).to.equal( + 'Extended JSON serialization failed with:...' ); }); }); } }); - context('when given anonymous function as input', function () { - it('should output default error message', function () { - expect(stringifyWithMaxLen((v: number) => v + 1, DEFAULT_MAX_DOCUMENT_LENGTH)).to.equal( - 'anonymous function' - ); + context('when given function as input', function () { + it('should output function.name', function () { + expect( + stringifyWithMaxLen(function randomFunc() { + return 1; + }, DEFAULT_MAX_DOCUMENT_LENGTH) + ).to.equal('randomFunc'); }); }); }); }); describe('log', async function () { - const componentSeverities: MongoLoggerOptions['componentSeverities'] = { - command: 'trace', - topology: 'trace', - serverSelection: 'trace', - connection: 'trace', - client: 'trace' - } as any; + let componentSeverities: MongoLoggerOptions['componentSeverities']; + + beforeEach(function () { + componentSeverities = { + command: 'trace', + topology: 'trace', + serverSelection: 'trace', + connection: 'trace', + client: 'trace' + } as any; + }); + describe('sync stream failure handling', function () { context('when stream is not stderr', function () { let stderrStub; From d9eb4e8615625dc3c5936e0f1c604514cc834bd0 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Wed, 24 Jan 2024 11:27:03 -0500 Subject: [PATCH 9/9] Anna's suggested change to isPromiseLike --- src/utils.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/utils.ts b/src/utils.ts index d511d6f1a55..677c681396e 100644 --- a/src/utils.ts +++ b/src/utils.ts @@ -171,7 +171,7 @@ export function applyRetryableWrites(target: T, db * @param value - An object that could be a promise * @returns true if the provided value is a Promise */ -export function isPromiseLike(value?: unknown): value is PromiseLike { +export function isPromiseLike(value?: unknown): value is PromiseLike { return ( value != null && typeof value === 'object' &&