From a8d42adb3beccefaaea00adc1ecf932f0c65a34d Mon Sep 17 00:00:00 2001 From: Warren James Date: Mon, 27 Mar 2023 14:39:48 -0400 Subject: [PATCH 01/39] refactor(NODE-4813): WIP --- src/mongo_logger.ts | 186 +++++++++++++++++++++++++++++---- test/unit/mongo_logger.test.ts | 15 +++ 2 files changed, 181 insertions(+), 20 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 6c55d16f89..99cef27648 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -1,5 +1,20 @@ +import { Document, EJSON } from 'bson'; import { Writable } from 'stream'; +import { + CommandFailedEvent, + CommandStartedEvent, + CommandSucceededEvent +} from './cmap/command_monitoring_events'; +import { + ConnectionClosedEvent, + ConnectionCreatedEvent, + ConnectionPoolClearedEvent, + ConnectionPoolClosedEvent, + ConnectionPoolCreatedEvent, + ConnectionPoolReadyEvent, + ConnectionReadyEvent +} from './cmap/connection_pool_events'; import { parseUnsignedInteger } from './utils'; /** @internal */ @@ -91,7 +106,7 @@ 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; + logDestination: MongoDBLogWritable; } /** @@ -143,11 +158,84 @@ function resolveLogPath( return process.stderr; } +export interface Log extends Record { + s: SeverityLevel; + t: Date; + c: MongoLoggableComponent; + message?: string; +} + +export interface MongoDBLogWritable { + write(log: Log): unknown; +} + +function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { + const s0Num = SeverityLevelMap.get(s0) as number; + const s1Num = SeverityLevelMap.get(s1) as number; + + return s0Num < s1Num ? -1 : s0Num > s1Num ? 1 : 0; +} + +type LogTransform = (message: Record) => Record; + +const DEFAULT_LOG_TRANSFORM = (message: Record): Record => { + const commandCommonFields = ( + message: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent + ) => { + return { + commandName: message.commandName, + requestId: message.requestId, + driverConnectionId: message.connectionId, + serverHost: message.address, + serverPort: message.address, + serviceId: message.serviceId + }; + }; + const maybeTruncate = (doc: Document, len: number): string => { + const rv = EJSON.stringify(doc); + return rv.length > len ? rv.slice(0, len) + '...' : rv; + }; + + if (message instanceof CommandStartedEvent) { + return { + ...commandCommonFields(message), + message: 'Command started', + command: maybeTruncate(message.command, 1000), + databaseName: message.databaseName + }; + } else if (message instanceof CommandSucceededEvent) { + return { + ...commandCommonFields(message), + message: 'Command succeeded', + durationMS: message.duration, + reply: maybeTruncate(message.reply as Document, 1000) + }; + } else if (message instanceof CommandFailedEvent) { + return { + ...commandCommonFields(message), + message: 'Command failed', + durationMS: message.duration, + failure: message.failure + }; + } else if (message instanceof ConnectionReadyEvent) { + } else if (message instanceof ConnectionClosedEvent) { + } else if (message instanceof ConnectionCreatedEvent) { + } else if (message instanceof ConnectionPoolReadyEvent) { + } else if (message instanceof ConnectionPoolClosedEvent) { + } else if (message instanceof ConnectionPoolClearedEvent) { + } else if (message instanceof ConnectionPoolCreatedEvent) { + } else { + return message; + } + + return {}; +}; + /** @internal */ export class MongoLogger { componentSeverities: Record; maxDocumentLength: number; - logDestination: Writable; + logDestination: MongoDBLogWritable; constructor(options: MongoLoggerOptions) { this.componentSeverities = options.componentSeverities; @@ -155,25 +243,83 @@ export class MongoLogger { this.logDestination = options.logDestination; } - /* eslint-disable @typescript-eslint/no-unused-vars */ - /* eslint-disable @typescript-eslint/no-empty-function */ - emergency(component: any, message: any): void {} - - alert(component: any, message: any): void {} - - critical(component: any, message: any): void {} - - error(component: any, message: any): void {} - - warn(component: any, message: any): void {} - - notice(component: any, message: any): void {} - - info(component: any, message: any): void {} - - debug(component: any, message: any): void {} + emergency( + component: MongoLoggableComponent, + message: Record | string, + transform?: LogTransform + ): void { + this.log(component, 'emergency', message, transform); + } + alert( + component: MongoLoggableComponent, + message: Record | string, + transform?: LogTransform + ): void { + this.log(component, 'alert', message, transform); + } + critical( + component: MongoLoggableComponent, + message: Record | string, + transform: LogTransform = DEFAULT_LOG_TRANSFORM + ): void { + this.log(component, 'critical', message, transform); + } + error( + component: MongoLoggableComponent, + message: Record | string, + transform?: LogTransform + ): void { + this.log(component, 'error', message, transform); + } + warn( + component: MongoLoggableComponent, + message: Record | string, + transform?: LogTransform + ): void { + this.log(component, 'warn', message, transform); + } + info( + component: MongoLoggableComponent, + message: Record | string, + transform?: LogTransform + ): void { + this.log(component, 'info', message, transform); + } + debug( + component: MongoLoggableComponent, + message: Record | string, + transform?: LogTransform + ): void { + this.log(component, 'debug', message, transform); + } + trace( + component: MongoLoggableComponent, + message: Record | string, + transform?: LogTransform + ): void { + this.log(component, 'trace', message, transform); + } - trace(component: any, message: any): void {} + private log( + component: MongoLoggableComponent, + severity: SeverityLevel, + message: Record | string, + transform?: LogTransform + ): void { + if (compareSeverity(severity, this.componentSeverities[component]) <= 0) { + let logMessage: Log = { t: new Date(), c: component, s: severity }; + if (typeof message === 'string') { + logMessage.message = message; + } else { + if (transform) { + logMessage = { ...logMessage, ...transform(message) }; + } else { + logMessage = { ...logMessage, ...message }; + } + } + this.logDestination.write(logMessage); + } + } /** * Merges options set through environment variables and the MongoClient, preferring environment diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 8bf97cd80b..34b1bc2ddf 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -386,6 +386,12 @@ describe('class MongoLogger', function () { } } }); + context('when mongodbLogPath is an object that implements MongoDBLogWritable', function () { + it('successfully writes logs to the MongoDBLogWritable'); + }); + context('when mongodbLogPath implements nodejs:stream.Writable', function () { + it('successfully writes logs to the Writable'); + }); }); context( @@ -519,6 +525,15 @@ describe('class MongoLogger', function () { logger[severityLevel]('topology', 'message'); expect(stream.buffer).to.have.lengthOf(0); }); + + context('when the log severity is lower than what was configured', function () { + it('does not call Loggable.toLog'); + it('does not write to logDestination'); + }); + context('when log severity is equal to or greater than what was configured', function () { + it('successfully writes to a newly created Writable'); + it('successfully writes to a previously used Writable'); + }); }); } }); From e0b1db249db31fbca7334d5ab0f84353aa986b1f Mon Sep 17 00:00:00 2001 From: Warren James Date: Wed, 29 Mar 2023 14:36:42 -0400 Subject: [PATCH 02/39] refactor(NODE-4813): start first draft of logger implementation --- src/mongo_logger.ts | 311 ++++++++++++++++++++++++++++---------------- 1 file changed, 202 insertions(+), 109 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 99cef27648..ece6987379 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -1,4 +1,4 @@ -import { Document, EJSON } from 'bson'; +import { EJSON } from 'bson'; import { Writable } from 'stream'; import { @@ -7,11 +7,16 @@ import { CommandSucceededEvent } from './cmap/command_monitoring_events'; import { + ConnectionCheckedInEvent, + ConnectionCheckedOutEvent, + ConnectionCheckOutFailedEvent, + ConnectionCheckOutStartedEvent, ConnectionClosedEvent, ConnectionCreatedEvent, ConnectionPoolClearedEvent, ConnectionPoolClosedEvent, ConnectionPoolCreatedEvent, + ConnectionPoolMonitoringEvent, ConnectionPoolReadyEvent, ConnectionReadyEvent } from './cmap/connection_pool_events'; @@ -35,7 +40,28 @@ export const SeverityLevel = Object.freeze({ export type SeverityLevel = (typeof SeverityLevel)[keyof typeof SeverityLevel]; /** @internal */ -export const SeverityLevelMap: Map = new Map([ +class SeverityLevelMap extends Map { + constructor(entries: [SeverityLevel | number, SeverityLevel | number][]) { + const newEntries: [number | SeverityLevel, SeverityLevel | number][] = []; + for (const [level, value] of entries) { + newEntries.push([value, level]); + } + + newEntries.push(...entries); + super(newEntries); + } + + getNumericSeverityLevel(severity: SeverityLevel): number { + return this.get(severity) as number; + } + + getSeverityLevelName(level: number): SeverityLevel | undefined { + return this.get(level) as SeverityLevel | undefined; + } +} + +/** @internal */ +export const SEVERITY_LEVEL_MAP = new SeverityLevelMap([ [SeverityLevel.OFF, -Infinity], [SeverityLevel.EMERGENCY, 0], [SeverityLevel.ALERT, 1], @@ -48,10 +74,6 @@ export const SeverityLevelMap: Map = new Map([ [SeverityLevel.TRACE, 8] ]); -for (const [level, value] of SeverityLevelMap) { - SeverityLevelMap.set(value, level); -} - /** @internal */ export const MongoLoggableComponent = Object.freeze({ COMMAND: 'command', @@ -170,66 +192,158 @@ export interface MongoDBLogWritable { } function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { - const s0Num = SeverityLevelMap.get(s0) as number; - const s1Num = SeverityLevelMap.get(s1) as number; + const s0Num = SEVERITY_LEVEL_MAP.getNumericSeverityLevel(s0); + const s1Num = SEVERITY_LEVEL_MAP.getNumericSeverityLevel(s1); return s0Num < s1Num ? -1 : s0Num > s1Num ? 1 : 0; } -type LogTransform = (message: Record) => Record; +function DEFAULT_LOG_TRANSFORM(logObject: Record): Omit { + let log: Omit = {}; -const DEFAULT_LOG_TRANSFORM = (message: Record): Record => { - const commandCommonFields = ( - message: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent + const getHostPort = (s: string): { host: string; port: number } => { + const lastColon = s.lastIndexOf(':'); + const host = s.slice(0, lastColon); + const port = Number.parseInt(s.slice(lastColon + 1)); + return { host, port }; + }; + + const attachCommandFields = ( + l: any, + ev: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent ) => { - return { - commandName: message.commandName, - requestId: message.requestId, - driverConnectionId: message.connectionId, - serverHost: message.address, - serverPort: message.address, - serviceId: message.serviceId - }; + l.commandName = ev.commandName; + l.requestId = ev.requestId; + //log.operationId = ev. + if (ev.connectionId) { + l.driverConnectionId = ev.connectionId; + } + const { host, port } = getHostPort(ev.address); + l.serverHost = host; + l.serverPort = port; + if (ev.serviceId) { + l.serviceId = ev.serviceId; + } + + return l; }; - const maybeTruncate = (doc: Document, len: number): string => { - const rv = EJSON.stringify(doc); - return rv.length > len ? rv.slice(0, len) + '...' : rv; + + const attachConnectionFields = (l: any, ev: ConnectionPoolMonitoringEvent) => { + const { host, port } = getHostPort(ev.address); + l.serverHost = host; + l.serverPort = port; + + return l; }; - if (message instanceof CommandStartedEvent) { - return { - ...commandCommonFields(message), - message: 'Command started', - command: maybeTruncate(message.command, 1000), - databaseName: message.databaseName - }; - } else if (message instanceof CommandSucceededEvent) { - return { - ...commandCommonFields(message), - message: 'Command succeeded', - durationMS: message.duration, - reply: maybeTruncate(message.reply as Document, 1000) - }; - } else if (message instanceof CommandFailedEvent) { - return { - ...commandCommonFields(message), - message: 'Command failed', - durationMS: message.duration, - failure: message.failure - }; - } else if (message instanceof ConnectionReadyEvent) { - } else if (message instanceof ConnectionClosedEvent) { - } else if (message instanceof ConnectionCreatedEvent) { - } else if (message instanceof ConnectionPoolReadyEvent) { - } else if (message instanceof ConnectionPoolClosedEvent) { - } else if (message instanceof ConnectionPoolClearedEvent) { - } else if (message instanceof ConnectionPoolCreatedEvent) { - } else { - return message; + let ev; + switch (logObject.constructor) { + case CommandStartedEvent: + ev = logObject as CommandStartedEvent; + log = attachCommandFields(log, ev); + log.message = 'Command started'; + log.command = EJSON.stringify(ev.command); + log.databaseName = ev.databaseName; + break; + case CommandSucceededEvent: + ev = logObject as CommandSucceededEvent; + log = attachCommandFields(log, ev); + log.message = 'Command succeeded'; + log.durationMS = ev.duration; + log.reply = EJSON.stringify(ev.reply); + break; + case CommandFailedEvent: + ev = logObject as CommandFailedEvent; + log = attachCommandFields(log, ev); + log.message = 'Command failed'; + log.durationMS = ev.duration; + log.failure = ev.failure; + break; + case ConnectionPoolCreatedEvent: + ev = logObject as ConnectionPoolCreatedEvent; + log = attachConnectionFields(log, ev); + log.message = 'Connection pool created'; + if (ev.options) { + const { maxIdleTimeMS, minPoolSize, maxPoolSize, maxConnecting, waitQueueTimeoutMS } = + ev.options; + log = { + ...log, + maxIdleTimeMS, + minPoolSize, + maxPoolSize, + maxConnecting, + waitQueueTimeoutMS + }; + } + // TODO: Get waitQueueSize + // TODO: Get waitQueueMultiple + break; + case ConnectionPoolReadyEvent: + ev = logObject as ConnectionPoolReadyEvent; + log = attachConnectionFields(log, ev); + log.message = 'Connection pool ready'; + break; + case ConnectionPoolClearedEvent: + ev = logObject as ConnectionPoolClearedEvent; + log = attachConnectionFields(log, ev); + log.message = 'Connection pool cleared'; + if (ev.serviceId) { + log.serviceId = ev.serviceId; + } + break; + case ConnectionPoolClosedEvent: + ev = logObject as ConnectionPoolClosedEvent; + log = attachConnectionFields(log, ev); + log.message = 'Connection pool closed'; + break; + case ConnectionCreatedEvent: + ev = logObject as ConnectionCreatedEvent; + log = attachConnectionFields(log, ev); + log.message = 'Connection created'; + log.driverConnectionId = ev.connectionId; + break; + case ConnectionReadyEvent: + ev = logObject as ConnectionReadyEvent; + log = attachConnectionFields(log, ev); + log.message = 'Connection ready'; + log.driverConnectionId = ev.connectionId; + break; + case ConnectionClosedEvent: + ev = logObject as ConnectionClosedEvent; + log = attachConnectionFields(log, ev); + log.message = 'Connection closed'; + log.driverConnectionId = ev.connectionId; + log.reason = ev.reason; + // log.error FIXME + break; + case ConnectionCheckOutStartedEvent: + ev = logObject as ConnectionCheckOutStartedEvent; + log = attachConnectionFields(log, ev); + log.message = 'Connection checkout started'; + break; + case ConnectionCheckOutFailedEvent: + ev = logObject as ConnectionCheckOutFailedEvent; + log = attachConnectionFields(log, ev); + log.message = 'Connection checkout failed'; + log.reason = ev.reason; + break; + case ConnectionCheckedOutEvent: + ev = logObject as ConnectionCheckedOutEvent; + log = attachConnectionFields(log, ev); + log.message = 'Connection checked out'; + log.driverConnectionId = ev.connectionId; + break; + case ConnectionCheckedInEvent: + ev = logObject as ConnectionCheckedInEvent; + log = attachConnectionFields(log, ev); + log.message = 'Connection checked in'; + log.driverConnectionId = ev.connectionId; + break; + default: + log = { ...log, ...logObject }; } - - return {}; -}; + return log; +} /** @internal */ export class MongoLogger { @@ -243,78 +357,57 @@ export class MongoLogger { this.logDestination = options.logDestination; } - emergency( - component: MongoLoggableComponent, - message: Record | string, - transform?: LogTransform - ): void { - this.log(component, 'emergency', message, transform); + /** @experimental */ + emergency(component: MongoLoggableComponent, message: Record | string): void { + this.log(component, 'emergency', message); } - alert( - component: MongoLoggableComponent, - message: Record | string, - transform?: LogTransform - ): void { - this.log(component, 'alert', message, transform); + /** @experimental */ + alert(component: MongoLoggableComponent, message: Record | string): void { + this.log(component, 'alert', message); } - critical( - component: MongoLoggableComponent, - message: Record | string, - transform: LogTransform = DEFAULT_LOG_TRANSFORM - ): void { - this.log(component, 'critical', message, transform); + /** @experimental */ + critical(component: MongoLoggableComponent, message: Record | string): void { + this.log(component, 'critical', message); } - error( - component: MongoLoggableComponent, - message: Record | string, - transform?: LogTransform - ): void { - this.log(component, 'error', message, transform); + /** @experimental */ + error(component: MongoLoggableComponent, message: Record | string): void { + this.log(component, 'error', message); } - warn( - component: MongoLoggableComponent, - message: Record | string, - transform?: LogTransform - ): void { - this.log(component, 'warn', message, transform); + /** @experimental */ + notice(component: MongoLoggableComponent, message: Record | string): void { + this.log(component, 'notice', message); } - info( - component: MongoLoggableComponent, - message: Record | string, - transform?: LogTransform - ): void { - this.log(component, 'info', message, transform); + /** @experimental */ + warn(component: MongoLoggableComponent, message: Record | string): void { + this.log(component, 'warn', message); } - debug( - component: MongoLoggableComponent, - message: Record | string, - transform?: LogTransform - ): void { - this.log(component, 'debug', message, transform); + /** @experimental */ + info(component: MongoLoggableComponent, message: Record | string): void { + this.log(component, 'info', message); } - trace( - component: MongoLoggableComponent, - message: Record | string, - transform?: LogTransform - ): void { - this.log(component, 'trace', message, transform); + /** @experimental */ + debug(component: MongoLoggableComponent, message: Record | string): void { + this.log(component, 'debug', message); + } + /** @experimental */ + trace(component: MongoLoggableComponent, message: Record | string): void { + this.log(component, 'trace', message); } private log( component: MongoLoggableComponent, severity: SeverityLevel, - message: Record | string, - transform?: LogTransform + message: Record | string ): void { if (compareSeverity(severity, this.componentSeverities[component]) <= 0) { let logMessage: Log = { t: new Date(), c: component, s: severity }; if (typeof message === 'string') { logMessage.message = message; } else { - if (transform) { - logMessage = { ...logMessage, ...transform(message) }; + if (message.toLog && typeof message.toLog === 'function') { + logMessage = { ...logMessage, ...message.toLog() }; } else { - logMessage = { ...logMessage, ...message }; + logMessage = { ...logMessage, ...DEFAULT_LOG_TRANSFORM(message) }; } } this.logDestination.write(logMessage); From d2ff692846a92583ba3cb90eccdffd803654bb59 Mon Sep 17 00:00:00 2001 From: Warren James Date: Wed, 29 Mar 2023 14:37:22 -0400 Subject: [PATCH 03/39] style(NODE-4813): eslint --- test/unit/mongo_logger.test.ts | 109 ++++++++++++++++++++++++++++++--- 1 file changed, 101 insertions(+), 8 deletions(-) diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 34b1bc2ddf..9996345fc3 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -1,10 +1,10 @@ import { expect } from 'chai'; import { Readable, Writable } from 'stream'; -import { MongoLogger, MongoLoggerOptions, SeverityLevel } from '../mongodb'; +import { MongoLogger, MongoLoggerOptions, SEVERITY_LEVEL_MAP, SeverityLevel } from '../mongodb'; class BufferingStream extends Writable { - buffer: string[] = []; + buffer: any[] = []; constructor(options = {}) { super({ ...options, objectMode: true }); @@ -526,13 +526,106 @@ describe('class MongoLogger', function () { expect(stream.buffer).to.have.lengthOf(0); }); - context('when the log severity is lower than what was configured', function () { - it('does not call Loggable.toLog'); - it('does not write to logDestination'); + context('when the log severity is greater than what was configured', function () { + it('does not write to logDestination', function () { + const stream = new BufferingStream(); + const logger = new MongoLogger({ + componentSeverities: { + command: severityLevel + } as any, + logDestination: stream + } as any); + + const TRACE = 8; + for ( + let l = SEVERITY_LEVEL_MAP.getNumericSeverityLevel(severityLevel) + 1; + l <= TRACE; + l++ + ) { + const severity = SEVERITY_LEVEL_MAP.getSeverityLevelName(l); + logger[severity as SeverityLevel]('command', 'Hello'); + } + + expect(stream.buffer).to.have.lengthOf(0); + }); + }); + context('when log severity is equal to or less than what was configured', function () { + it('writes log to logDestination', function () { + const stream = new BufferingStream(); + const logger = new MongoLogger({ + componentSeverities: { + command: severityLevel + } as any, + logDestination: stream + } as any); + + const EMERGENCY = 0; + // Calls all severity logging methods with a level less than or equal to what severityLevel + for ( + let l = SEVERITY_LEVEL_MAP.getNumericSeverityLevel(severityLevel); + l >= EMERGENCY; + l-- + ) { + const severity = SEVERITY_LEVEL_MAP.getSeverityLevelName(l); + logger[severity as SeverityLevel]('command', 'Hello'); + } + + expect(stream.buffer).to.have.lengthOf( + SEVERITY_LEVEL_MAP.getNumericSeverityLevel(severityLevel) + 1 + ); + }); }); - context('when log severity is equal to or greater than what was configured', function () { - it('successfully writes to a newly created Writable'); - it('successfully writes to a previously used Writable'); + + context('when object with toLog method is being logged', function () { + const obj = { + a: 10, + b: 12, + toLog() { + return { sum: this.a + this.b }; + } + }; + it('calls toLog and constructs log message with the result of toLog', function () { + const stream = new BufferingStream(); + const logger = new MongoLogger({ + componentSeverities: { command: severityLevel } as any, + logDestination: stream + } as any); + + logger[severityLevel]('command', obj); + + expect(stream.buffer).to.have.lengthOf(1); + expect(stream.buffer[0]).to.have.property('sum', 22); + }); + }); + + context('when object without toLog method is being logged', function () { + const obj = { a: 10, b: 12 }; + it('uses the existing fields to build the log message', function () { + const stream = new BufferingStream(); + const logger = new MongoLogger({ + componentSeverities: { command: severityLevel } as any, + logDestination: stream + } as any); + + logger[severityLevel]('command', obj); + expect(stream.buffer).to.have.lengthOf(1); + expect(stream.buffer[0]).to.have.property('a', 10); + expect(stream.buffer[0]).to.have.property('b', 12); + }); + }); + context('when string is being logged', function () { + const message = 'Hello world'; + it('puts the string in the message field of the emitted log message', function () { + const stream = new BufferingStream(); + const logger = new MongoLogger({ + componentSeverities: { command: severityLevel } as any, + logDestination: stream + } as any); + + logger[severityLevel]('command', message); + expect(stream.buffer).to.have.lengthOf(1); + expect(stream.buffer[0]).to.have.property('message', message); + }); }); }); } From a52b1aee69d4c95228b116057036974b71088897 Mon Sep 17 00:00:00 2001 From: Warren James Date: Wed, 29 Mar 2023 15:53:50 -0400 Subject: [PATCH 04/39] refactor(NODE-4813): Add changes to MongoLogger and ConnectionClosedEvent --- src/cmap/connection_pool_events.ts | 3 +++ src/mongo_logger.ts | 8 +++++--- 2 files changed, 8 insertions(+), 3 deletions(-) diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index 0f56bf6bbb..d330a53359 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -29,11 +29,14 @@ export class ConnectionPoolMonitoringEvent { export class ConnectionPoolCreatedEvent extends ConnectionPoolMonitoringEvent { /** The options used to create this connection pool */ options?: ConnectionPoolOptions; + /** The size of the ConnectionPool's waitQueue */ + waitQueueSize: number; /** @internal */ constructor(pool: ConnectionPool) { super(pool); this.options = pool.options; + this.waitQueueSize = pool.waitQueueSize; } } diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index ece6987379..721bd1ec35 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -274,9 +274,8 @@ function DEFAULT_LOG_TRANSFORM(logObject: Record): Omit): Omit Date: Fri, 31 Mar 2023 16:31:00 -0400 Subject: [PATCH 05/39] test(NODE-4813): WIP - start adding tests --- src/cmap/command_monitoring_events.ts | 12 ++ src/cmap/connection_pool_events.ts | 35 ++++ src/mongo_logger.ts | 43 ++-- test/unit/mongo_logger.test.ts | 284 ++++++++++++++++++++++++++ 4 files changed, 349 insertions(+), 25 deletions(-) diff --git a/src/cmap/command_monitoring_events.ts b/src/cmap/command_monitoring_events.ts index 229ef98e5b..c1ba87bf38 100644 --- a/src/cmap/command_monitoring_events.ts +++ b/src/cmap/command_monitoring_events.ts @@ -50,6 +50,10 @@ export class CommandStartedEvent { get hasServiceId(): boolean { return !!this.serviceId; } + + get name(): string { + return 'CommandStarted'; + } } /** @@ -98,6 +102,10 @@ export class CommandSucceededEvent { get hasServiceId(): boolean { return !!this.serviceId; } + + get name(): string { + return 'CommandSucceeded'; + } } /** @@ -147,6 +155,10 @@ export class CommandFailedEvent { get hasServiceId(): boolean { return !!this.serviceId; } + + get name(): string { + return 'CommandFailed'; + } } /** diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index d330a53359..afed5b8db9 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -38,6 +38,10 @@ export class ConnectionPoolCreatedEvent extends ConnectionPoolMonitoringEvent { this.options = pool.options; this.waitQueueSize = pool.waitQueueSize; } + + get name(): string { + return 'ConnectionPoolCreated'; + } } /** @@ -50,6 +54,9 @@ export class ConnectionPoolReadyEvent extends ConnectionPoolMonitoringEvent { constructor(pool: ConnectionPool) { super(pool); } + get name(): string { + return 'ConnectionPoolReady'; + } } /** @@ -62,6 +69,9 @@ export class ConnectionPoolClosedEvent extends ConnectionPoolMonitoringEvent { constructor(pool: ConnectionPool) { super(pool); } + get name(): string { + return 'ConnectionPoolClosed'; + } } /** @@ -78,6 +88,9 @@ export class ConnectionCreatedEvent extends ConnectionPoolMonitoringEvent { super(pool); this.connectionId = connection.id; } + get name(): string { + return 'ConnectionCreated'; + } } /** @@ -94,6 +107,9 @@ export class ConnectionReadyEvent extends ConnectionPoolMonitoringEvent { super(pool); this.connectionId = connection.id; } + get name(): string { + return 'ConnectionReady'; + } } /** @@ -119,6 +135,9 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { this.reason = reason || 'unknown'; this.serviceId = connection.serviceId; } + get name(): string { + return 'ConnectionClosed'; + } } /** @@ -131,6 +150,9 @@ export class ConnectionCheckOutStartedEvent extends ConnectionPoolMonitoringEven constructor(pool: ConnectionPool) { super(pool); } + get name(): string { + return 'ConnectionCheckOutStarted'; + } } /** @@ -147,6 +169,9 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent super(pool); this.reason = reason; } + get name(): string { + return 'ConnectionCheckOutFailed'; + } } /** @@ -163,6 +188,9 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { super(pool); this.connectionId = connection.id; } + get name(): string { + return 'ConnectionCheckedOut'; + } } /** @@ -179,6 +207,9 @@ export class ConnectionCheckedInEvent extends ConnectionPoolMonitoringEvent { super(pool); this.connectionId = connection.id; } + get name(): string { + return 'ConnectionCheckedIn'; + } } /** @@ -201,4 +232,8 @@ export class ConnectionPoolClearedEvent extends ConnectionPoolMonitoringEvent { this.serviceId = options.serviceId; this.interruptInUseConnections = options.interruptInUseConnections; } + + get name(): string { + return 'ConnectionPoolCleared'; + } } diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 721bd1ec35..6f66bce13c 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -214,16 +214,11 @@ function DEFAULT_LOG_TRANSFORM(logObject: Record): Omit { l.commandName = ev.commandName; l.requestId = ev.requestId; - //log.operationId = ev. - if (ev.connectionId) { - l.driverConnectionId = ev.connectionId; - } + l.driverConnectionId = ev?.connectionId; const { host, port } = getHostPort(ev.address); l.serverHost = host; l.serverPort = port; - if (ev.serviceId) { - l.serviceId = ev.serviceId; - } + l.serviceId = ev?.serviceId; return l; }; @@ -237,29 +232,29 @@ function DEFAULT_LOG_TRANSFORM(logObject: Record): Omit): Omit): Omit EJSON.parse(log.command)).to.not.throw(); + }); + + it('emits a log with field `databaseName` that is a string', function () { + expect(log).to.have.property('databaseName').that.is.a('string'); + }); + }); + + context('when CommandSucceededEvent is logged', function () { + beforeEach(function () { + (logger as MongoLogger)[severityLevel]('command', commandSucceeded); + expect(stream?.buffer).to.have.lengthOf(1); + log = stream?.buffer[0] as any; + }); + + commonCommandComponentAssertions(); + it('emits a log with field `message` = "Command succeeded"', function () { + expect(log).to.have.property('message', 'Command succeeded'); + }); + + it('emits a log with field `durationMS` that is a number', function () { + expect(log).to.have.property('durationMS').that.is.a('number'); + }); + + it('emits a log with field `reply` that is an EJSON string', function () { + expect(log).to.have.property('reply').that.is.a('string'); + + expect(() => EJSON.parse(log.reply)).to.not.throw(); + }); + }); + + context('when CommandFailedEvent is logged', function () { + beforeEach(function () { + (logger as MongoLogger)[severityLevel]('command', commandFailed); + expect(stream?.buffer).to.have.lengthOf(1); + log = stream?.buffer[0] as any; + }); + + commonCommandComponentAssertions(); + it('emits a log with field `message` = "Command failed"', function () { + expect(log).to.have.property('message', 'Command failed'); + }); + + it('emits a log with field `durationMS` that is a number', function () { + expect(log).to.have.property('durationMS').that.is.a('number'); + }); + + it('emits a log with field `failure`', function () { + expect(log).to.have.property('failure'); + }); + }); + }); + + context('connection component', function () { + let log; + const options = { + maxIdleTimeMS: 0, + minPoolSize: 0, + maxPoolSize: 0, + maxConnecting: 0, + waitQueueTimeoutMS: 100 + }; + const connectionPoolCreated = { + name: 'ConnectionPoolCreated', + waitQueueSize: 0, + options + }; + const connectionPoolReady = { + name: 'ConnectionPoolReady', + options + }; + const connectionPoolCleared = { + name: 'ConnectionPoolCleared', + serviceId: 0, + options + }; + const connectionPoolClosed = { + name: 'ConnectionPoolClosed', + options + }; + const connectionCreated = { + name: 'ConnectionCreated', + connectionId: 0, + options + }; + const connectionCheckOutStarted = { + name: 'ConnectionCheckOutStarted', + options + }; + const connectionCheckOutFailed = { + name: 'ConnectionCheckoutFailed', + reason: 'wups', + options + }; + const connectionCheckedOut = { + name: 'ConnectionCheckedOut', + connectionId: 0, + options + }; + const connectionCheckedIn = { + name: 'ConnectionCheckedIn', + connectionId: 0, + options + }; + function commonConnectionComponentAssertions() { + const fields = [ + ['serverPort', 'number'], + ['serverHost', 'string'] + ]; + for (const [fieldName, type] of fields) { + it(`emits a log with field \`${fieldName}\` that is of type ${type}`, function () { + expect(stream?.buffer).to.have.lengthOf(1); + expect(stream?.buffer[0]).to.have.property(fieldName).that.is.a(type); + }); + } + } + context('when ConnectionPoolCreatedEvent is logged', function () { + beforeEach(function () { + (logger as MongoLogger)[severityLevel]('connection', connectionPoolCreated); + expect(stream?.buffer).to.have.lengthOf(1); + log = stream?.buffer[0]; + }); + commonConnectionComponentAssertions(); + it('emits a log with field `message` = "Connection pool created"', function () {}); + it('emits a log with field `maxIdleTimeMS` that is a number'); + it('emits a log with field `minPoolSize` that is a number'); + it('emits a log with field `maxPoolSize` that is a number'); + it('emits a log with field `maxConnecting` that is a number'); + it('emits a log with field `waitQueueTimeoutMS` that is a number'); + it('emits a log with field `waitQueueSize` that is a number'); + }); + context('when ConnectionPoolReadyEvent is logged', function () { + beforeEach(function () { + (logger as MongoLogger)[severityLevel]('connection', connectionPoolReady); + expect(stream?.buffer).to.have.lengthOf(1); + log = stream?.buffer[0]; + }); + commonConnectionComponentAssertions(); + it('emits a log with field `message` = "Connection pool ready"'); + }); + context('when ConnectionPoolClearedEvent is logged', function () { + beforeEach(function () { + (logger as MongoLogger)[severityLevel]('connection', connectionPoolCleared); + expect(stream?.buffer).to.have.lengthOf(1); + log = stream?.buffer[0]; + }); + commonConnectionComponentAssertions(); + it('emits a log with field `message` = "Connection pool cleared"'); + it('emits a log with field `serviceId` that is a string'); // TODO: Only in LB mode + }); + context('when ConnectionPoolClosedEvent is logged', function () { + beforeEach(function () { + (logger as MongoLogger)[severityLevel]('connection', connectionPoolClosed); + expect(stream?.buffer).to.have.lengthOf(1); + log = stream?.buffer[0]; + }); + commonConnectionComponentAssertions(); + it('emits a log with field `message` = "Connection pool closed"'); + }); + + context('when ConnectionCreatedEvent is logged', function () { + beforeEach(function () { + (logger as MongoLogger)[severityLevel]('connection', connectionCreated); + expect(stream?.buffer).to.have.lengthOf(1); + log = stream?.buffer[0]; + }); + commonConnectionComponentAssertions(); + }); + context('when ConnectionCheckOutStartedEvent is logged', function () { + beforeEach(function () { + (logger as MongoLogger)[severityLevel]('connection', connectionCheckOutStarted); + expect(stream?.buffer).to.have.lengthOf(1); + log = stream?.buffer[0]; + }); + commonConnectionComponentAssertions(); + }); + context('when ConnectionCheckOutFailedEvent is logged', function () { + beforeEach(function () { + (logger as MongoLogger)[severityLevel]('connection', connectionCheckOutFailed); + expect(stream?.buffer).to.have.lengthOf(1); + log = stream?.buffer[0]; + }); + commonConnectionComponentAssertions(); + }); + context('when ConnectionCheckedInEvent is logged', function () { + beforeEach(function () { + (logger as MongoLogger)[severityLevel]('connection', connectionCheckedIn); + expect(stream?.buffer).to.have.lengthOf(1); + log = stream?.buffer[0]; + }); + commonConnectionComponentAssertions(); + }); + context('when ConnectionCheckedOutEvent is logged', function () { + beforeEach(function () { + (logger as MongoLogger)[severityLevel]('connection', connectionCheckedOut); + expect(stream?.buffer).to.have.lengthOf(1); + log = stream?.buffer[0]; + }); + commonConnectionComponentAssertions(); + }); + }); + }); }); } }); From b88003e76189f445bc1835be8cc4aeed1aca96a3 Mon Sep 17 00:00:00 2001 From: Warren James Date: Mon, 3 Apr 2023 14:32:46 -0400 Subject: [PATCH 06/39] fix(NODE-4813): use HostAddress --- src/mongo_logger.ts | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 6f66bce13c..d5f32dcbe1 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -1,12 +1,12 @@ import { EJSON } from 'bson'; import { Writable } from 'stream'; -import { +import type { CommandFailedEvent, CommandStartedEvent, CommandSucceededEvent } from './cmap/command_monitoring_events'; -import { +import type { ConnectionCheckedInEvent, ConnectionCheckedOutEvent, ConnectionCheckOutFailedEvent, @@ -20,7 +20,7 @@ import { ConnectionPoolReadyEvent, ConnectionReadyEvent } from './cmap/connection_pool_events'; -import { parseUnsignedInteger } from './utils'; +import { HostAddress, parseUnsignedInteger } from './utils'; /** @internal */ export const SeverityLevel = Object.freeze({ @@ -201,10 +201,12 @@ function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { function DEFAULT_LOG_TRANSFORM(logObject: Record): Omit { let log: Omit = {}; - const getHostPort = (s: string): { host: string; port: number } => { - const lastColon = s.lastIndexOf(':'); - const host = s.slice(0, lastColon); - const port = Number.parseInt(s.slice(lastColon + 1)); + const getHostPort = (address: string): { host: string; port: number } => { + const hostAddress = new HostAddress(address); + + // Should only default when the address is a socket address + const host = hostAddress.host ?? ''; + const port = hostAddress.port ?? 0; return { host, port }; }; From 06a1bf06b0b67a3b034b467c92850b28990eb63d Mon Sep 17 00:00:00 2001 From: Warren James Date: Mon, 3 Apr 2023 15:36:52 -0400 Subject: [PATCH 07/39] fix(NODE-4813): Add Loggable interface --- src/mongo_logger.ts | 28 ++++++++++++++++------------ 1 file changed, 16 insertions(+), 12 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index d5f32dcbe1..8909fcfb29 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -198,13 +198,17 @@ function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { return s0Num < s1Num ? -1 : s0Num > s1Num ? 1 : 0; } -function DEFAULT_LOG_TRANSFORM(logObject: Record): Omit { +export interface Loggable extends Record { + toLog?(): Record; +} + +function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit { let log: Omit = {}; const getHostPort = (address: string): { host: string; port: number } => { const hostAddress = new HostAddress(address); - // Should only default when the address is a socket address + // NOTE: Should only default when the address is a socket address const host = hostAddress.host ?? ''; const port = hostAddress.port ?? 0; return { host, port }; @@ -355,46 +359,46 @@ export class MongoLogger { } /** @experimental */ - emergency(component: MongoLoggableComponent, message: Record | string): void { + emergency(component: MongoLoggableComponent, message: Loggable | string): void { this.log(component, 'emergency', message); } /** @experimental */ - alert(component: MongoLoggableComponent, message: Record | string): void { + alert(component: MongoLoggableComponent, message: Loggable | string): void { this.log(component, 'alert', message); } /** @experimental */ - critical(component: MongoLoggableComponent, message: Record | string): void { + critical(component: MongoLoggableComponent, message: Loggable | string): void { this.log(component, 'critical', message); } /** @experimental */ - error(component: MongoLoggableComponent, message: Record | string): void { + error(component: MongoLoggableComponent, message: Loggable | string): void { this.log(component, 'error', message); } /** @experimental */ - notice(component: MongoLoggableComponent, message: Record | string): void { + notice(component: MongoLoggableComponent, message: Loggable | string): void { this.log(component, 'notice', message); } /** @experimental */ - warn(component: MongoLoggableComponent, message: Record | string): void { + warn(component: MongoLoggableComponent, message: Loggable | string): void { this.log(component, 'warn', message); } /** @experimental */ - info(component: MongoLoggableComponent, message: Record | string): void { + info(component: MongoLoggableComponent, message: Loggable | string): void { this.log(component, 'info', message); } /** @experimental */ - debug(component: MongoLoggableComponent, message: Record | string): void { + debug(component: MongoLoggableComponent, message: Loggable | string): void { this.log(component, 'debug', message); } /** @experimental */ - trace(component: MongoLoggableComponent, message: Record | string): void { + trace(component: MongoLoggableComponent, message: Loggable | string): void { this.log(component, 'trace', message); } private log( component: MongoLoggableComponent, severity: SeverityLevel, - message: Record | string + message: Loggable | string ): void { if (compareSeverity(severity, this.componentSeverities[component]) <= 0) { let logMessage: Log = { t: new Date(), c: component, s: severity }; From 3501a356a25584ee68230fe7e3d0a1d29f0312c9 Mon Sep 17 00:00:00 2001 From: Warren James Date: Mon, 3 Apr 2023 15:37:22 -0400 Subject: [PATCH 08/39] test(NODE-4813): Add connection events tests --- test/unit/mongo_logger.test.ts | 170 +++++++++++++++++++++++---------- 1 file changed, 117 insertions(+), 53 deletions(-) diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index a268328a3e..12b6e9d6a8 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -632,8 +632,8 @@ describe('class MongoLogger', function () { }); context('spec-required logs', function () { - let stream: BufferingStream | undefined; - let logger: MongoLogger | undefined; + let stream: BufferingStream; + let logger: MongoLogger; beforeEach(function () { stream = new BufferingStream(); @@ -696,9 +696,9 @@ describe('class MongoLogger', function () { context('when CommandStartedEvent is logged', function () { beforeEach(function () { - (logger as MongoLogger)[severityLevel]('command', commandStarted); - expect(stream?.buffer).to.have.lengthOf(1); - log = stream?.buffer[0]; + logger[severityLevel]('command', commandStarted); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; }); commonCommandComponentAssertions(); @@ -719,9 +719,9 @@ describe('class MongoLogger', function () { context('when CommandSucceededEvent is logged', function () { beforeEach(function () { - (logger as MongoLogger)[severityLevel]('command', commandSucceeded); - expect(stream?.buffer).to.have.lengthOf(1); - log = stream?.buffer[0] as any; + logger[severityLevel]('command', commandSucceeded); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0] as any; }); commonCommandComponentAssertions(); @@ -742,9 +742,9 @@ describe('class MongoLogger', function () { context('when CommandFailedEvent is logged', function () { beforeEach(function () { - (logger as MongoLogger)[severityLevel]('command', commandFailed); - expect(stream?.buffer).to.have.lengthOf(1); - log = stream?.buffer[0] as any; + logger[severityLevel]('command', commandFailed); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0] as any; }); commonCommandComponentAssertions(); @@ -774,43 +774,52 @@ describe('class MongoLogger', function () { const connectionPoolCreated = { name: 'ConnectionPoolCreated', waitQueueSize: 0, + address: '127.0.0.1:27017', options }; const connectionPoolReady = { name: 'ConnectionPoolReady', + address: '127.0.0.1:27017', options }; const connectionPoolCleared = { name: 'ConnectionPoolCleared', - serviceId: 0, + serviceId: 'abcdef', + address: '127.0.0.1:27017', options }; const connectionPoolClosed = { name: 'ConnectionPoolClosed', + address: '127.0.0.1:27017', options }; const connectionCreated = { name: 'ConnectionCreated', connectionId: 0, + address: '127.0.0.1:27017', options }; const connectionCheckOutStarted = { name: 'ConnectionCheckOutStarted', + address: '127.0.0.1:27017', options }; const connectionCheckOutFailed = { - name: 'ConnectionCheckoutFailed', + name: 'ConnectionCheckOutFailed', reason: 'wups', + address: '127.0.0.1:27017', options }; const connectionCheckedOut = { name: 'ConnectionCheckedOut', connectionId: 0, + address: '127.0.0.1:27017', options }; const connectionCheckedIn = { name: 'ConnectionCheckedIn', connectionId: 0, + address: '127.0.0.1:27017', options }; function commonConnectionComponentAssertions() { @@ -820,94 +829,149 @@ describe('class MongoLogger', function () { ]; for (const [fieldName, type] of fields) { it(`emits a log with field \`${fieldName}\` that is of type ${type}`, function () { - expect(stream?.buffer).to.have.lengthOf(1); - expect(stream?.buffer[0]).to.have.property(fieldName).that.is.a(type); + expect(log).to.have.property(fieldName).that.is.a(type); }); } } + context('when ConnectionPoolCreatedEvent is logged', function () { beforeEach(function () { - (logger as MongoLogger)[severityLevel]('connection', connectionPoolCreated); - expect(stream?.buffer).to.have.lengthOf(1); - log = stream?.buffer[0]; + logger[severityLevel]('connection', connectionPoolCreated); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; }); commonConnectionComponentAssertions(); - it('emits a log with field `message` = "Connection pool created"', function () {}); - it('emits a log with field `maxIdleTimeMS` that is a number'); - it('emits a log with field `minPoolSize` that is a number'); - it('emits a log with field `maxPoolSize` that is a number'); - it('emits a log with field `maxConnecting` that is a number'); - it('emits a log with field `waitQueueTimeoutMS` that is a number'); - it('emits a log with field `waitQueueSize` that is a number'); + it('emits a log with field `message` = "Connection pool created"', function () { + expect(log).to.have.property('message', 'Connection pool created'); + }); + it('emits a log with field `maxIdleTimeMS` that is a number', function () { + expect(log).to.have.property('maxIdleTimeMS').that.is.a('number'); + }); + it('emits a log with field `minPoolSize` that is a number', function () { + expect(log).to.have.property('minPoolSize').that.is.a('number'); + }); + it('emits a log with field `maxPoolSize` that is a number', function () { + expect(log).to.have.property('maxPoolSize').that.is.a('number'); + }); + it('emits a log with field `maxConnecting` that is a number', function () { + expect(log).to.have.property('maxConnecting').that.is.a('number'); + }); + it('emits a log with field `waitQueueTimeoutMS` that is a number', function () { + expect(log).to.have.property('waitQueueTimeoutMS').that.is.a('number'); + }); + it('emits a log with field `waitQueueSize` that is a number', function () { + expect(log).to.have.property('waitQueueSize').that.is.a('number'); + }); }); + context('when ConnectionPoolReadyEvent is logged', function () { beforeEach(function () { - (logger as MongoLogger)[severityLevel]('connection', connectionPoolReady); - expect(stream?.buffer).to.have.lengthOf(1); - log = stream?.buffer[0]; + logger[severityLevel]('connection', connectionPoolReady); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; }); + commonConnectionComponentAssertions(); - it('emits a log with field `message` = "Connection pool ready"'); + it('emits a log with field `message` = "Connection pool ready"', function () { + expect(log).to.have.property('message', 'Connection pool ready'); + }); }); context('when ConnectionPoolClearedEvent is logged', function () { beforeEach(function () { - (logger as MongoLogger)[severityLevel]('connection', connectionPoolCleared); - expect(stream?.buffer).to.have.lengthOf(1); - log = stream?.buffer[0]; + logger[severityLevel]('connection', connectionPoolCleared); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; }); + commonConnectionComponentAssertions(); - it('emits a log with field `message` = "Connection pool cleared"'); - it('emits a log with field `serviceId` that is a string'); // TODO: Only in LB mode + it('emits a log with field `message` = "Connection pool cleared"', function () { + expect(log).to.have.property('message', 'Connection pool cleared'); + }); + + // TODO: Only in LB mode + it('emits a log with field `serviceId` that is a string when it is present', function () { + expect(stream.buffer).to.have.lengthOf(1); + expect(stream.buffer[0]).to.have.property('serviceId').that.is.a('string'); + }); }); + context('when ConnectionPoolClosedEvent is logged', function () { beforeEach(function () { - (logger as MongoLogger)[severityLevel]('connection', connectionPoolClosed); - expect(stream?.buffer).to.have.lengthOf(1); - log = stream?.buffer[0]; + logger[severityLevel]('connection', connectionPoolClosed); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; }); + commonConnectionComponentAssertions(); - it('emits a log with field `message` = "Connection pool closed"'); + it('emits a log with field `message` = "Connection pool closed"', function () { + expect(log).to.have.property('message', 'Connection pool closed'); + }); }); context('when ConnectionCreatedEvent is logged', function () { beforeEach(function () { - (logger as MongoLogger)[severityLevel]('connection', connectionCreated); - expect(stream?.buffer).to.have.lengthOf(1); - log = stream?.buffer[0]; + logger[severityLevel]('connection', connectionCreated); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; }); + commonConnectionComponentAssertions(); + it('emits a log with field `message` = "Connection created"', function () { + expect(log).to.have.property('message', 'Connection created'); + }); }); + context('when ConnectionCheckOutStartedEvent is logged', function () { beforeEach(function () { - (logger as MongoLogger)[severityLevel]('connection', connectionCheckOutStarted); - expect(stream?.buffer).to.have.lengthOf(1); - log = stream?.buffer[0]; + logger[severityLevel]('connection', connectionCheckOutStarted); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; }); + commonConnectionComponentAssertions(); + + it('emits a log with field `message` = "Connection checkout started"', function () { + expect(log).to.have.property('message', 'Connection checkout started'); + }); }); + context('when ConnectionCheckOutFailedEvent is logged', function () { beforeEach(function () { - (logger as MongoLogger)[severityLevel]('connection', connectionCheckOutFailed); - expect(stream?.buffer).to.have.lengthOf(1); - log = stream?.buffer[0]; + logger[severityLevel]('connection', connectionCheckOutFailed); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; }); commonConnectionComponentAssertions(); + + it('emits a log with field `message` = "Connection checkout failed"', function () { + expect(log).to.have.property('message', 'Connection checkout failed'); + }); }); + context('when ConnectionCheckedInEvent is logged', function () { beforeEach(function () { - (logger as MongoLogger)[severityLevel]('connection', connectionCheckedIn); - expect(stream?.buffer).to.have.lengthOf(1); - log = stream?.buffer[0]; + logger[severityLevel]('connection', connectionCheckedIn); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; }); + commonConnectionComponentAssertions(); + it('emits a log with field `message` = "Connection checked in"', function () { + expect(log).to.have.property('message', 'Connection checked in'); + }); }); + context('when ConnectionCheckedOutEvent is logged', function () { beforeEach(function () { - (logger as MongoLogger)[severityLevel]('connection', connectionCheckedOut); - expect(stream?.buffer).to.have.lengthOf(1); - log = stream?.buffer[0]; + logger[severityLevel]('connection', connectionCheckedOut); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; }); + commonConnectionComponentAssertions(); + it('emits a log with field `message` = "Connection checked out"', function () { + expect(log).to.have.property('message', 'Connection checked out'); + }); }); }); }); From bf591b91fb71552cc1c71230ca9ca0cfc1f38958 Mon Sep 17 00:00:00 2001 From: Warren James Date: Mon, 3 Apr 2023 16:45:38 -0400 Subject: [PATCH 09/39] fix(NODE-4813): omit nullish fields --- src/mongo_logger.ts | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 8909fcfb29..7e2624ea21 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -224,7 +224,7 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit const { host, port } = getHostPort(ev.address); l.serverHost = host; l.serverPort = port; - l.serviceId = ev?.serviceId; + l.serviceId = ev?.serviceId?.toHexString(); return l; }; @@ -287,7 +287,9 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit ev = logObject as ConnectionPoolClearedEvent; log = attachConnectionFields(log, ev); log.message = 'Connection pool cleared'; - log.serviceId = ev?.serviceId; + if (ev.serviceId?._bsontype === 'ObjectId') { + log.serviceId = ev.serviceId.toHexString(); + } break; case 'ConnectionPoolClosed': ev = logObject as ConnectionPoolClosedEvent; @@ -341,7 +343,12 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit log.driverConnectionId = ev.connectionId; break; default: - log = { ...log, ...logObject }; + for (const key in logObject) { + const value = logObject[key]; + // eslint-disable-next-line no-restricted-syntax + if (value === undefined || value === null) continue; + log[key] = value; + } } return log; } From 36e2e320706c925dce11edb266cdc12d6bef899f Mon Sep 17 00:00:00 2001 From: Warren James Date: Mon, 3 Apr 2023 16:46:24 -0400 Subject: [PATCH 10/39] test(NODE-4813): update tests --- test/unit/mongo_logger.test.ts | 43 +++++++++++++++++++++++++++------- 1 file changed, 34 insertions(+), 9 deletions(-) diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 12b6e9d6a8..488b7d5ca4 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -1,4 +1,4 @@ -import { EJSON } from 'bson'; +import { EJSON, ObjectId } from 'bson'; import { expect } from 'chai'; import { Readable, Writable } from 'stream'; @@ -96,7 +96,7 @@ describe('class MongoLogger', function () { context('when MONGODB_LOG_ALL is valid', () => { for (const [validOption, expectedValue] of validNonDefaultOptions) { - context(`{ MONGODB_LOG_ALL: '${validOption} }'`, () => { + context(`{ MONGODB_LOG_ALL: '${validOption}' }`, () => { it('sets default to the value of MONGODB_LOG_ALL', () => { const { componentSeverities } = MongoLogger.resolveOptions( { @@ -493,7 +493,11 @@ describe('class MongoLogger', function () { context('when mongodbLogPath is set to valid client option', function () { for (const validEnvironmentOption of validEnvironmentOptions) { for (const validValue of validClientOptions) { - it(`{environment: "${validEnvironmentOption}", client: "${validValue}"} uses the value from the client options`, function () { + it(`{environment: "${validEnvironmentOption}", client: ${ + typeof validValue === 'object' + ? 'new ' + validValue.constructor.name + '(...)' + : '"' + validValue.toString() + '"' + }} uses the value from the client options`, function () { const options = MongoLogger.resolveOptions( { MONGODB_LOG_PATH: validEnvironmentOption @@ -616,6 +620,28 @@ describe('class MongoLogger', function () { }); }); + context('when object with nullish top level fields is being logged', function () { + const obj = { + A: undefined, + B: null, + C: 'Hello World!' + }; + it('emits a log message that omits the nullish top-level fields by default', function () { + const stream = new BufferingStream(); + const logger = new MongoLogger({ + componentSeverities: { command: severityLevel } as any, + logDestination: stream + } as any); + + logger[severityLevel]('command', obj); + + expect(stream.buffer).to.have.lengthOf(1); + expect(stream.buffer[0]).to.not.have.property('A'); + expect(stream.buffer[0]).to.not.have.property('B'); + expect(stream.buffer[0]).to.have.property('C', 'Hello World!'); + }); + }); + context('when string is being logged', function () { const message = 'Hello world'; it('puts the string in the message field of the emitted log message', function () { @@ -653,7 +679,7 @@ describe('class MongoLogger', function () { requestId: 0, connectionId: 0, address: '127.0.0.1:27017', - serviceId: '0x1234567890', + serviceId: new ObjectId(), databaseName: 'db', name: 'CommandStarted' }; @@ -663,7 +689,7 @@ describe('class MongoLogger', function () { connectionId: 0, duration: 0, address: '127.0.0.1:27017', - serviceId: '0x1234567890', + serviceId: new ObjectId(), databaseName: 'db', name: 'CommandSucceeded' }; @@ -673,7 +699,7 @@ describe('class MongoLogger', function () { duration: 0, connectionId: 0, address: '127.0.0.1:27017', - serviceId: '0x1234567890', + serviceId: new ObjectId(), databaseName: 'db', name: 'CommandFailed' }; @@ -784,7 +810,7 @@ describe('class MongoLogger', function () { }; const connectionPoolCleared = { name: 'ConnectionPoolCleared', - serviceId: 'abcdef', + serviceId: new ObjectId(), address: '127.0.0.1:27017', options }; @@ -890,8 +916,7 @@ describe('class MongoLogger', function () { // TODO: Only in LB mode it('emits a log with field `serviceId` that is a string when it is present', function () { - expect(stream.buffer).to.have.lengthOf(1); - expect(stream.buffer[0]).to.have.property('serviceId').that.is.a('string'); + expect(log).to.have.property('serviceId').that.is.a('string'); }); }); From 80fbecdbc25fabd7d044d7193530012f0fd9db31 Mon Sep 17 00:00:00 2001 From: Warren James Date: Tue, 4 Apr 2023 15:25:30 -0400 Subject: [PATCH 11/39] refactor(NODE-4813): Update mongo client to accept @@mdb.internalLogConfig feature flag and remove strict writable requirement for log sink in mongologger --- src/connection_string.ts | 3 ++- src/index.ts | 3 +++ src/mongo_logger.ts | 57 ++++++++++++---------------------------- 3 files changed, 22 insertions(+), 41 deletions(-) diff --git a/src/connection_string.ts b/src/connection_string.ts index 096af0545a..ae6ffb2da2 100644 --- a/src/connection_string.ts +++ b/src/connection_string.ts @@ -1301,5 +1301,6 @@ export const DEFAULT_OPTIONS = new CaseInsensitiveMap( */ export const FEATURE_FLAGS = new Set([ Symbol.for('@@mdb.skipPingOnConnect'), - Symbol.for('@@mdb.enableMongoLogger') + Symbol.for('@@mdb.enableMongoLogger'), + Symbol.for('@@mdb.internalLoggerConfig') ]); diff --git a/src/index.ts b/src/index.ts index 2ea5b26124..f4d1d42b70 100644 --- a/src/index.ts +++ b/src/index.ts @@ -289,6 +289,9 @@ export type { WithSessionCallback } from './mongo_client'; export type { + Log, + Loggable, + MongoDBLogWritable, MongoLoggableComponent, MongoLogger, MongoLoggerEnvOptions, diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 7e2624ea21..9aaafd209a 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -1,5 +1,4 @@ import { EJSON } from 'bson'; -import { Writable } from 'stream'; import type { CommandFailedEvent, @@ -107,7 +106,7 @@ export interface MongoLoggerEnvOptions { /** @internal */ export interface MongoLoggerMongoClientOptions { /** Destination for log messages */ - mongodbLogPath?: 'stdout' | 'stderr' | Writable; + mongodbLogPath?: 'stdout' | 'stderr' | MongoDBLogWritable; } /** @internal */ @@ -161,25 +160,33 @@ function resolveLogPath( }: { mongodbLogPath?: unknown; } -): Writable { +): MongoDBLogWritable { const isValidLogDestinationString = (destination: string) => ['stdout', 'stderr'].includes(destination.toLowerCase()); if (typeof mongodbLogPath === 'string' && isValidLogDestinationString(mongodbLogPath)) { - return mongodbLogPath.toLowerCase() === 'stderr' ? process.stderr : process.stdout; + return (mongodbLogPath.toLowerCase() === 'stderr' + ? process.stderr + : process.stdout) as unknown as MongoDBLogWritable; } // TODO(NODE-4813): check for minimal interface instead of instanceof Writable - if (typeof mongodbLogPath === 'object' && mongodbLogPath instanceof Writable) { - return mongodbLogPath; + if ( + typeof mongodbLogPath === 'object' && + Object.prototype.hasOwnProperty.call(mongodbLogPath, 'write') + ) { + return mongodbLogPath as MongoDBLogWritable; } if (typeof MONGODB_LOG_PATH === 'string' && isValidLogDestinationString(MONGODB_LOG_PATH)) { - return MONGODB_LOG_PATH.toLowerCase() === 'stderr' ? process.stderr : process.stdout; + return (MONGODB_LOG_PATH.toLowerCase() === 'stderr' + ? process.stderr + : process.stdout) as unknown as MongoDBLogWritable; } - return process.stderr; + return process.stderr as unknown as MongoDBLogWritable; } +/** @internal */ export interface Log extends Record { s: SeverityLevel; t: Date; @@ -187,6 +194,7 @@ export interface Log extends Record { message?: string; } +/** @internal */ export interface MongoDBLogWritable { write(log: Log): unknown; } @@ -198,6 +206,7 @@ function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { return s0Num < s1Num ? -1 : s0Num > s1Num ? 1 : 0; } +/** @internal */ export interface Loggable extends Record { toLog?(): Record; } @@ -369,38 +378,6 @@ export class MongoLogger { emergency(component: MongoLoggableComponent, message: Loggable | string): void { this.log(component, 'emergency', message); } - /** @experimental */ - alert(component: MongoLoggableComponent, message: Loggable | string): void { - this.log(component, 'alert', message); - } - /** @experimental */ - critical(component: MongoLoggableComponent, message: Loggable | string): void { - this.log(component, 'critical', message); - } - /** @experimental */ - error(component: MongoLoggableComponent, message: Loggable | string): void { - this.log(component, 'error', message); - } - /** @experimental */ - notice(component: MongoLoggableComponent, message: Loggable | string): void { - this.log(component, 'notice', message); - } - /** @experimental */ - warn(component: MongoLoggableComponent, message: Loggable | string): void { - this.log(component, 'warn', message); - } - /** @experimental */ - info(component: MongoLoggableComponent, message: Loggable | string): void { - this.log(component, 'info', message); - } - /** @experimental */ - debug(component: MongoLoggableComponent, message: Loggable | string): void { - this.log(component, 'debug', message); - } - /** @experimental */ - trace(component: MongoLoggableComponent, message: Loggable | string): void { - this.log(component, 'trace', message); - } private log( component: MongoLoggableComponent, From da4f89cb343df02aa195112259879f0dca7cfd75 Mon Sep 17 00:00:00 2001 From: Warren James Date: Tue, 4 Apr 2023 15:26:02 -0400 Subject: [PATCH 12/39] test(NODE-4813): Add integration tests --- .../command_logging.test.ts | 77 +++++++++++++++++++ test/unit/mongo_logger.test.ts | 14 +++- 2 files changed, 89 insertions(+), 2 deletions(-) create mode 100644 test/integration/command-logging-and-monitoring/command_logging.test.ts diff --git a/test/integration/command-logging-and-monitoring/command_logging.test.ts b/test/integration/command-logging-and-monitoring/command_logging.test.ts new file mode 100644 index 0000000000..3e65c4442d --- /dev/null +++ b/test/integration/command-logging-and-monitoring/command_logging.test.ts @@ -0,0 +1,77 @@ +import { expect } from 'chai'; +import * as process from 'process'; + +import { + CommandFailedEvent, + CommandStartedEvent, + CommandSucceededEvent, + Db, + Log, + MongoClient +} from '../../mongodb'; +import { setupDatabase } from '../shared'; + +describe('Command Logging', function () { + before(function () { + return setupDatabase(this.configuration); + }); + + const logDestination = { + buffer: [], + write(log: Log) { + this.buffer.push(log); + } + } as { buffer: any[]; write: (log: Log) => void }; + let client: MongoClient; + let db: Db; + //let coll: Collection; + + beforeEach(async function () { + client = new MongoClient( + process.env.MONGODB_URI as string, + { + monitorCommands: true, + [Symbol.for('@@mdb.internalLoggerConfig')]: { + MONGODB_LOG_ALL: 'emergency', + MONGODB_LOG_COMMAND: 'emergency' + }, + [Symbol.for('@@mdb.enableMongoLogger')]: true, + mongodbLogPath: logDestination + } as any + ); + await client.connect(); + db = client.db('command_logging'); + }); + + afterEach(async function () { + if (db) { + await db.dropDatabase(); + } + await client.close().catch(() => null); + }); + + context('sensitive commands', function () { + it('should redact sensitive commands', async function () { + const log = (ev: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent) => { + client.mongoLogger.emergency('command', ev); + }; + client.on('commandStarted', log); + client.on('commandSucceeded', log); + client.on('commandFailed', log); + + const result = await db.command({ hello: 1, speculativeAuthenticate: { saslStart: 1 } }); + expect(result).to.exist; + expect(logDestination.buffer).to.have.lengthOf(2); + + const commandStarted = logDestination.buffer[0]; + const commandSucceeded = logDestination.buffer[1]; + expect(commandStarted).to.exist; + expect(commandStarted).to.have.property('command', '{}'); + expect(commandStarted).to.have.property('message', 'Command started'); + + expect(commandSucceeded).to.exist; + expect(commandSucceeded).to.have.property('reply', '{}'); + expect(commandSucceeded).to.have.property('message', 'Command succeeded'); + }); + }); +}); diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 488b7d5ca4..54566630b7 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -515,7 +515,8 @@ describe('class MongoLogger', function () { }); describe('severity helpers', function () { - const severities = Object.values(SeverityLevel).filter(severity => severity !== 'off'); + // TODO(NODE-4814): Ensure we test on all valid severity levels + const severities = Object.values(SeverityLevel).filter(severity => severity === 'emergency'); for (const severityLevel of severities) { describe(`${severityLevel}()`, function () { it('does not log when logging for the component is disabled', () => { @@ -531,7 +532,8 @@ describe('class MongoLogger', function () { expect(stream.buffer).to.have.lengthOf(0); }); - context('when the log severity is greater than what was configured', function () { + // TODO(NODE-4814): Unskip this test + context.skip('when the log severity is greater than what was configured', function () { it('does not write to logDestination', function () { const stream = new BufferingStream(); const logger = new MongoLogger({ @@ -764,6 +766,10 @@ describe('class MongoLogger', function () { expect(() => EJSON.parse(log.reply)).to.not.throw(); }); + + context('when the command is sensitive', function () { + it('redacts the `reply` field'); + }); }); context('when CommandFailedEvent is logged', function () { @@ -785,6 +791,10 @@ describe('class MongoLogger', function () { it('emits a log with field `failure`', function () { expect(log).to.have.property('failure'); }); + + context('when the command is sensitive', function () { + it('redacts the `failure` field'); + }); }); }); From 3c76aebdf606c3a9371ab5d9fce84cb4bc4d046a Mon Sep 17 00:00:00 2001 From: Warren James Date: Tue, 4 Apr 2023 15:55:43 -0400 Subject: [PATCH 13/39] test(NODE-4813): ensure that mongo logger works with MongoDBLogWritable implementors --- test/unit/mongo_logger.test.ts | 52 +++++++++++++++++++++++++++++----- 1 file changed, 45 insertions(+), 7 deletions(-) diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 54566630b7..e5ab431588 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -2,7 +2,13 @@ import { EJSON, ObjectId } from 'bson'; import { expect } from 'chai'; import { Readable, Writable } from 'stream'; -import { MongoLogger, MongoLoggerOptions, SEVERITY_LEVEL_MAP, SeverityLevel } from '../mongodb'; +import { + Log, + MongoLogger, + MongoLoggerOptions, + SEVERITY_LEVEL_MAP, + SeverityLevel +} from '../mongodb'; class BufferingStream extends Writable { buffer: any[] = []; @@ -46,6 +52,44 @@ describe('class MongoLogger', function () { expect(logger).to.have.property('maxDocumentLength', 10); expect(logger).to.have.property('logDestination', stream); }); + + context('when logDestination is an object that implements MongoDBLogWritable', function () { + it('successfully writes logs to the MongoDBLogWritable', function () { + const logDestination = { + buffer: [], + write(log: Log) { + this.buffer.push(log); + } + } as { buffer: any[]; write: (log: Log) => void }; + const logger = new MongoLogger({ + componentSeverities: { command: 'emergency' } as any, + logDestination + } as any); + + logger.emergency('command', 'Hello world!'); + expect(logDestination.buffer).to.have.lengthOf(1); + }); + }); + + context('when logDestination implements nodejs:stream.Writable', function () { + it('successfully writes logs to the Writable', function () { + const buffer: any[] = []; + const logDestination = new Writable({ + objectMode: true, + write(log: Log): void { + buffer.push(log); + } + }); + + const logger = new MongoLogger({ + componentSeverities: { command: 'emergency' } as any, + logDestination + } as any); + + logger.emergency('command', 'Hello world!'); + expect(buffer).to.have.lengthOf(1); + }); + }); }); describe('static #resolveOptions()', function () { @@ -387,12 +431,6 @@ describe('class MongoLogger', function () { } } }); - context('when mongodbLogPath is an object that implements MongoDBLogWritable', function () { - it('successfully writes logs to the MongoDBLogWritable'); - }); - context('when mongodbLogPath implements nodejs:stream.Writable', function () { - it('successfully writes logs to the Writable'); - }); }); context( From a39965fe444a54561cf655d5ed66c0e501172824 Mon Sep 17 00:00:00 2001 From: Warren James Date: Tue, 4 Apr 2023 15:57:35 -0400 Subject: [PATCH 14/39] style(NODE-4813): remove todo comment --- src/mongo_logger.ts | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 9aaafd209a..febdcaa81f 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -169,7 +169,6 @@ function resolveLogPath( : process.stdout) as unknown as MongoDBLogWritable; } - // TODO(NODE-4813): check for minimal interface instead of instanceof Writable if ( typeof mongodbLogPath === 'object' && Object.prototype.hasOwnProperty.call(mongodbLogPath, 'write') @@ -233,7 +232,9 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit const { host, port } = getHostPort(ev.address); l.serverHost = host; l.serverPort = port; - l.serviceId = ev?.serviceId?.toHexString(); + if (ev?.serviceId) { + l.serviceId = ev.serviceId.toHexString(); + } return l; }; From 97c8eba9c4545921fe4687412bac679f59e7edc1 Mon Sep 17 00:00:00 2001 From: Warren James Date: Wed, 5 Apr 2023 10:17:56 -0400 Subject: [PATCH 15/39] refactor(NODE-5169): Change name getter on events to a property --- src/cmap/command_monitoring_events.ts | 23 +++++----- src/cmap/connection_pool_events.ts | 62 ++++++++++++--------------- src/mongo_logger.ts | 46 ++++++++++++++------ 3 files changed, 69 insertions(+), 62 deletions(-) diff --git a/src/cmap/command_monitoring_events.ts b/src/cmap/command_monitoring_events.ts index c1ba87bf38..47eb2bd5ea 100644 --- a/src/cmap/command_monitoring_events.ts +++ b/src/cmap/command_monitoring_events.ts @@ -1,5 +1,11 @@ import type { Document, ObjectId } from '../bson'; -import { LEGACY_HELLO_COMMAND, LEGACY_HELLO_COMMAND_CAMEL_CASE } from '../constants'; +import { + COMMAND_FAILED, + COMMAND_STARTED, + COMMAND_SUCCEEDED, + LEGACY_HELLO_COMMAND, + LEGACY_HELLO_COMMAND_CAMEL_CASE +} from '../constants'; import { calculateDurationInMs, deepCopy } from '../utils'; import { Msg, WriteProtocolMessageType } from './commands'; import type { Connection } from './connection'; @@ -18,6 +24,7 @@ export class CommandStartedEvent { address: string; connectionId?: string | number; serviceId?: ObjectId; + name: string = COMMAND_STARTED; /** * Create a started event @@ -50,10 +57,6 @@ export class CommandStartedEvent { get hasServiceId(): boolean { return !!this.serviceId; } - - get name(): string { - return 'CommandStarted'; - } } /** @@ -69,6 +72,7 @@ export class CommandSucceededEvent { commandName: string; reply: unknown; serviceId?: ObjectId; + name: string = COMMAND_SUCCEEDED; /** * Create a succeeded event @@ -102,10 +106,6 @@ export class CommandSucceededEvent { get hasServiceId(): boolean { return !!this.serviceId; } - - get name(): string { - return 'CommandSucceeded'; - } } /** @@ -121,6 +121,7 @@ export class CommandFailedEvent { commandName: string; failure: Error; serviceId?: ObjectId; + name: string = COMMAND_FAILED; /** * Create a failure event @@ -155,10 +156,6 @@ export class CommandFailedEvent { get hasServiceId(): boolean { return !!this.serviceId; } - - get name(): string { - return 'CommandFailed'; - } } /** diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index afed5b8db9..4c722a6427 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -1,4 +1,17 @@ import type { ObjectId } from '../bson'; +import { + CONNECTION_CHECK_OUT_FAILED, + CONNECTION_CHECK_OUT_STARTED, + CONNECTION_CHECKED_IN, + CONNECTION_CHECKED_OUT, + CONNECTION_CLOSED, + CONNECTION_CREATED, + CONNECTION_POOL_CLEARED, + CONNECTION_POOL_CLOSED, + CONNECTION_POOL_CREATED, + CONNECTION_POOL_READY, + CONNECTION_READY +} from '../constants'; import type { AnyError } from '../error'; import type { Connection } from './connection'; import type { ConnectionPool, ConnectionPoolOptions } from './connection_pool'; @@ -31,6 +44,7 @@ export class ConnectionPoolCreatedEvent extends ConnectionPoolMonitoringEvent { options?: ConnectionPoolOptions; /** The size of the ConnectionPool's waitQueue */ waitQueueSize: number; + name: string = CONNECTION_POOL_CREATED; /** @internal */ constructor(pool: ConnectionPool) { @@ -38,10 +52,6 @@ export class ConnectionPoolCreatedEvent extends ConnectionPoolMonitoringEvent { this.options = pool.options; this.waitQueueSize = pool.waitQueueSize; } - - get name(): string { - return 'ConnectionPoolCreated'; - } } /** @@ -50,13 +60,12 @@ export class ConnectionPoolCreatedEvent extends ConnectionPoolMonitoringEvent { * @category Event */ export class ConnectionPoolReadyEvent extends ConnectionPoolMonitoringEvent { + name: string = CONNECTION_POOL_READY; + /** @internal */ constructor(pool: ConnectionPool) { super(pool); } - get name(): string { - return 'ConnectionPoolReady'; - } } /** @@ -65,13 +74,12 @@ export class ConnectionPoolReadyEvent extends ConnectionPoolMonitoringEvent { * @category Event */ export class ConnectionPoolClosedEvent extends ConnectionPoolMonitoringEvent { + name: string = CONNECTION_POOL_CLOSED; + /** @internal */ constructor(pool: ConnectionPool) { super(pool); } - get name(): string { - return 'ConnectionPoolClosed'; - } } /** @@ -82,15 +90,13 @@ export class ConnectionPoolClosedEvent extends ConnectionPoolMonitoringEvent { export class ConnectionCreatedEvent extends ConnectionPoolMonitoringEvent { /** A monotonically increasing, per-pool id for the newly created connection */ connectionId: number | ''; + name: string = CONNECTION_CREATED; /** @internal */ constructor(pool: ConnectionPool, connection: { id: number | '' }) { super(pool); this.connectionId = connection.id; } - get name(): string { - return 'ConnectionCreated'; - } } /** @@ -101,15 +107,13 @@ export class ConnectionCreatedEvent extends ConnectionPoolMonitoringEvent { export class ConnectionReadyEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; + name: string = CONNECTION_READY; /** @internal */ constructor(pool: ConnectionPool, connection: Connection) { super(pool); this.connectionId = connection.id; } - get name(): string { - return 'ConnectionReady'; - } } /** @@ -123,6 +127,7 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { /** The reason the connection was closed */ reason: string; serviceId?: ObjectId; + name: string = CONNECTION_CLOSED; /** @internal */ constructor( @@ -135,9 +140,6 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { this.reason = reason || 'unknown'; this.serviceId = connection.serviceId; } - get name(): string { - return 'ConnectionClosed'; - } } /** @@ -146,13 +148,12 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { * @category Event */ export class ConnectionCheckOutStartedEvent extends ConnectionPoolMonitoringEvent { + name: string = CONNECTION_CHECK_OUT_STARTED; + /** @internal */ constructor(pool: ConnectionPool) { super(pool); } - get name(): string { - return 'ConnectionCheckOutStarted'; - } } /** @@ -163,15 +164,13 @@ export class ConnectionCheckOutStartedEvent extends ConnectionPoolMonitoringEven export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent { /** The reason the attempt to check out failed */ reason: AnyError | string; + name: string = CONNECTION_CHECK_OUT_FAILED; /** @internal */ constructor(pool: ConnectionPool, reason: AnyError | string) { super(pool); this.reason = reason; } - get name(): string { - return 'ConnectionCheckOutFailed'; - } } /** @@ -182,15 +181,13 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; + name: string = CONNECTION_CHECKED_OUT; /** @internal */ constructor(pool: ConnectionPool, connection: Connection) { super(pool); this.connectionId = connection.id; } - get name(): string { - return 'ConnectionCheckedOut'; - } } /** @@ -201,15 +198,13 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { export class ConnectionCheckedInEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; + name: string = CONNECTION_CHECKED_IN; /** @internal */ constructor(pool: ConnectionPool, connection: Connection) { super(pool); this.connectionId = connection.id; } - get name(): string { - return 'ConnectionCheckedIn'; - } } /** @@ -222,6 +217,7 @@ export class ConnectionPoolClearedEvent extends ConnectionPoolMonitoringEvent { serviceId?: ObjectId; interruptInUseConnections?: boolean; + name: string = CONNECTION_POOL_CLEARED; /** @internal */ constructor( @@ -232,8 +228,4 @@ export class ConnectionPoolClearedEvent extends ConnectionPoolMonitoringEvent { this.serviceId = options.serviceId; this.interruptInUseConnections = options.interruptInUseConnections; } - - get name(): string { - return 'ConnectionPoolCleared'; - } } diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index febdcaa81f..350d68b812 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -19,6 +19,22 @@ import type { ConnectionPoolReadyEvent, ConnectionReadyEvent } from './cmap/connection_pool_events'; +import { + COMMAND_FAILED, + COMMAND_STARTED, + COMMAND_SUCCEEDED, + CONNECTION_CHECK_OUT_FAILED, + CONNECTION_CHECK_OUT_STARTED, + CONNECTION_CHECKED_IN, + CONNECTION_CHECKED_OUT, + CONNECTION_CLOSED, + CONNECTION_CREATED, + CONNECTION_POOL_CLEARED, + CONNECTION_POOL_CLOSED, + CONNECTION_POOL_CREATED, + CONNECTION_POOL_READY, + CONNECTION_READY +} from './constants'; import { HostAddress, parseUnsignedInteger } from './utils'; /** @internal */ @@ -171,6 +187,8 @@ function resolveLogPath( if ( typeof mongodbLogPath === 'object' && + // eslint-disable-next-line no-restricted-syntax + mongodbLogPath !== null && Object.prototype.hasOwnProperty.call(mongodbLogPath, 'write') ) { return mongodbLogPath as MongoDBLogWritable; @@ -249,28 +267,28 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit let ev; switch (logObject.name) { - case 'CommandStarted': + case COMMAND_STARTED: ev = logObject as CommandStartedEvent; log = attachCommandFields(log, ev); log.message = 'Command started'; log.command = EJSON.stringify(ev.command); log.databaseName = ev.databaseName; break; - case 'CommandSucceeded': + case COMMAND_SUCCEEDED: ev = logObject as CommandSucceededEvent; log = attachCommandFields(log, ev); log.message = 'Command succeeded'; log.durationMS = ev.duration; log.reply = EJSON.stringify(ev.reply); break; - case 'CommandFailed': + case COMMAND_FAILED: ev = logObject as CommandFailedEvent; log = attachCommandFields(log, ev); log.message = 'Command failed'; log.durationMS = ev.duration; log.failure = ev.failure; break; - case 'ConnectionPoolCreated': + case CONNECTION_POOL_CREATED: ev = logObject as ConnectionPoolCreatedEvent; log = attachConnectionFields(log, ev); log.message = 'Connection pool created'; @@ -288,12 +306,12 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit log.waitQueueSize = ev.waitQueueSize; } break; - case 'ConnectionPoolReady': + case CONNECTION_POOL_READY: ev = logObject as ConnectionPoolReadyEvent; log = attachConnectionFields(log, ev); log.message = 'Connection pool ready'; break; - case 'ConnectionPoolCleared': + case CONNECTION_POOL_CLEARED: ev = logObject as ConnectionPoolClearedEvent; log = attachConnectionFields(log, ev); log.message = 'Connection pool cleared'; @@ -301,24 +319,24 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit log.serviceId = ev.serviceId.toHexString(); } break; - case 'ConnectionPoolClosed': + case CONNECTION_POOL_CLOSED: ev = logObject as ConnectionPoolClosedEvent; log = attachConnectionFields(log, ev); log.message = 'Connection pool closed'; break; - case 'ConnectionCreated': + case CONNECTION_CREATED: ev = logObject as ConnectionCreatedEvent; log = attachConnectionFields(log, ev); log.message = 'Connection created'; log.driverConnectionId = ev.connectionId; break; - case 'ConnectionReady': + case CONNECTION_READY: ev = logObject as ConnectionReadyEvent; log = attachConnectionFields(log, ev); log.message = 'Connection ready'; log.driverConnectionId = ev.connectionId; break; - case 'ConnectionClosed': + case CONNECTION_CLOSED: ev = logObject as ConnectionClosedEvent; log = attachConnectionFields(log, ev); log.message = 'Connection closed'; @@ -329,24 +347,24 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit // log.error = ev } break; - case 'ConnectionCheckOutStarted': + case CONNECTION_CHECK_OUT_STARTED: ev = logObject as ConnectionCheckOutStartedEvent; log = attachConnectionFields(log, ev); log.message = 'Connection checkout started'; break; - case 'ConnectionCheckOutFailed': + case CONNECTION_CHECK_OUT_FAILED: ev = logObject as ConnectionCheckOutFailedEvent; log = attachConnectionFields(log, ev); log.message = 'Connection checkout failed'; log.reason = ev.reason; break; - case 'ConnectionCheckedOut': + case CONNECTION_CHECKED_OUT: ev = logObject as ConnectionCheckedOutEvent; log = attachConnectionFields(log, ev); log.message = 'Connection checked out'; log.driverConnectionId = ev.connectionId; break; - case 'ConnectionCheckedIn': + case CONNECTION_CHECKED_IN: ev = logObject as ConnectionCheckedInEvent; log = attachConnectionFields(log, ev); log.message = 'Connection checked in'; From d4b6300c780f3953310a06816b47d5dee111dc26 Mon Sep 17 00:00:00 2001 From: Warren James Date: Wed, 5 Apr 2023 11:26:30 -0400 Subject: [PATCH 16/39] refactor(NODE-5169): refactor to make use of existing constants --- src/mongo_logger.ts | 230 +++++++++++++++++++++++--------------------- 1 file changed, 119 insertions(+), 111 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 350d68b812..767ad3e1cb 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -20,6 +20,8 @@ import type { ConnectionReadyEvent } from './cmap/connection_pool_events'; import { + APM_EVENTS, + CMAP_EVENTS, COMMAND_FAILED, COMMAND_STARTED, COMMAND_SUCCEEDED, @@ -266,117 +268,123 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit }; let ev; - switch (logObject.name) { - case COMMAND_STARTED: - ev = logObject as CommandStartedEvent; - log = attachCommandFields(log, ev); - log.message = 'Command started'; - log.command = EJSON.stringify(ev.command); - log.databaseName = ev.databaseName; - break; - case COMMAND_SUCCEEDED: - ev = logObject as CommandSucceededEvent; - log = attachCommandFields(log, ev); - log.message = 'Command succeeded'; - log.durationMS = ev.duration; - log.reply = EJSON.stringify(ev.reply); - break; - case COMMAND_FAILED: - ev = logObject as CommandFailedEvent; - log = attachCommandFields(log, ev); - log.message = 'Command failed'; - log.durationMS = ev.duration; - log.failure = ev.failure; - break; - case CONNECTION_POOL_CREATED: - ev = logObject as ConnectionPoolCreatedEvent; - log = attachConnectionFields(log, ev); - log.message = 'Connection pool created'; - if (ev.options) { - const { maxIdleTimeMS, minPoolSize, maxPoolSize, maxConnecting, waitQueueTimeoutMS } = - ev.options; - log = { - ...log, - maxIdleTimeMS, - minPoolSize, - maxPoolSize, - maxConnecting, - waitQueueTimeoutMS - }; - log.waitQueueSize = ev.waitQueueSize; - } - break; - case CONNECTION_POOL_READY: - ev = logObject as ConnectionPoolReadyEvent; - log = attachConnectionFields(log, ev); - log.message = 'Connection pool ready'; - break; - case CONNECTION_POOL_CLEARED: - ev = logObject as ConnectionPoolClearedEvent; - log = attachConnectionFields(log, ev); - log.message = 'Connection pool cleared'; - if (ev.serviceId?._bsontype === 'ObjectId') { - log.serviceId = ev.serviceId.toHexString(); - } - break; - case CONNECTION_POOL_CLOSED: - ev = logObject as ConnectionPoolClosedEvent; - log = attachConnectionFields(log, ev); - log.message = 'Connection pool closed'; - break; - case CONNECTION_CREATED: - ev = logObject as ConnectionCreatedEvent; - log = attachConnectionFields(log, ev); - log.message = 'Connection created'; - log.driverConnectionId = ev.connectionId; - break; - case CONNECTION_READY: - ev = logObject as ConnectionReadyEvent; - log = attachConnectionFields(log, ev); - log.message = 'Connection ready'; - log.driverConnectionId = ev.connectionId; - break; - case CONNECTION_CLOSED: - ev = logObject as ConnectionClosedEvent; - log = attachConnectionFields(log, ev); - log.message = 'Connection closed'; - log.driverConnectionId = ev.connectionId; - log.reason = ev.reason; - if (ev.reason === 'error') { - // TODO: Set log.error - // log.error = ev - } - break; - case CONNECTION_CHECK_OUT_STARTED: - ev = logObject as ConnectionCheckOutStartedEvent; - log = attachConnectionFields(log, ev); - log.message = 'Connection checkout started'; - break; - case CONNECTION_CHECK_OUT_FAILED: - ev = logObject as ConnectionCheckOutFailedEvent; - log = attachConnectionFields(log, ev); - log.message = 'Connection checkout failed'; - log.reason = ev.reason; - break; - case CONNECTION_CHECKED_OUT: - ev = logObject as ConnectionCheckedOutEvent; - log = attachConnectionFields(log, ev); - log.message = 'Connection checked out'; - log.driverConnectionId = ev.connectionId; - break; - case CONNECTION_CHECKED_IN: - ev = logObject as ConnectionCheckedInEvent; - log = attachConnectionFields(log, ev); - log.message = 'Connection checked in'; - log.driverConnectionId = ev.connectionId; - break; - default: - for (const key in logObject) { - const value = logObject[key]; - // eslint-disable-next-line no-restricted-syntax - if (value === undefined || value === null) continue; - log[key] = value; - } + if (APM_EVENTS.findIndex(e => e === logObject.name) !== -1) { + log = attachCommandFields(log, logObject as any); + switch (logObject.name) { + case COMMAND_STARTED: + ev = logObject as CommandStartedEvent; + log.message = 'Command started'; + log.command = EJSON.stringify(ev.command); + log.databaseName = ev.databaseName; + break; + case COMMAND_SUCCEEDED: + ev = logObject as CommandSucceededEvent; + log.message = 'Command succeeded'; + log.durationMS = ev.duration; + log.reply = EJSON.stringify(ev.reply); + break; + case COMMAND_FAILED: + ev = logObject as CommandFailedEvent; + log.message = 'Command failed'; + log.durationMS = ev.duration; + log.failure = ev.failure; + break; + } + } else if (CMAP_EVENTS.findIndex(e => e === logObject.name) !== -1) { + log = attachConnectionFields(log, logObject as ConnectionPoolMonitoringEvent); + switch (logObject.name) { + case CONNECTION_POOL_CREATED: + ev = logObject as ConnectionPoolCreatedEvent; + log.message = 'Connection pool created'; + if (ev.options) { + const { maxIdleTimeMS, minPoolSize, maxPoolSize, maxConnecting, waitQueueTimeoutMS } = + ev.options; + log = { + ...log, + maxIdleTimeMS, + minPoolSize, + maxPoolSize, + maxConnecting, + waitQueueTimeoutMS + }; + log.waitQueueSize = ev.waitQueueSize; + } + break; + case CONNECTION_POOL_READY: + ev = logObject as ConnectionPoolReadyEvent; + log.message = 'Connection pool ready'; + break; + case CONNECTION_POOL_CLEARED: + ev = logObject as ConnectionPoolClearedEvent; + log.message = 'Connection pool cleared'; + if (ev.serviceId?._bsontype === 'ObjectId') { + log.serviceId = ev.serviceId.toHexString(); + } + break; + case CONNECTION_POOL_CLOSED: + ev = logObject as ConnectionPoolClosedEvent; + log.message = 'Connection pool closed'; + break; + case CONNECTION_CREATED: + ev = logObject as ConnectionCreatedEvent; + log.message = 'Connection created'; + log.driverConnectionId = ev.connectionId; + break; + case CONNECTION_READY: + ev = logObject as ConnectionReadyEvent; + log.message = 'Connection ready'; + log.driverConnectionId = ev.connectionId; + break; + case CONNECTION_CLOSED: + ev = logObject as ConnectionClosedEvent; + log.message = 'Connection closed'; + log.driverConnectionId = ev.connectionId; + switch (ev.reason) { + case 'stale': + log.reason = 'Connection became stale because the pool was cleared'; + break; + case 'idle': + log.reason = + 'Connection has been available but unused for longer than the configured max idle time'; + break; + case 'error': + log.reason = 'An error occurred while using the connection'; + // TODO: we need to expose the error on the ConnectionClosedEvent object if it exists + break; + case 'poolClosed': + log.reason = 'Connection pool was closed'; + break; + default: + // Omit if we have some other reason as it would be invalid + } + break; + case CONNECTION_CHECK_OUT_STARTED: + ev = logObject as ConnectionCheckOutStartedEvent; + log.message = 'Connection checkout started'; + break; + case CONNECTION_CHECK_OUT_FAILED: + ev = logObject as ConnectionCheckOutFailedEvent; + log.message = 'Connection checkout failed'; + log.reason = ev.reason; + break; + case CONNECTION_CHECKED_OUT: + ev = logObject as ConnectionCheckedOutEvent; + log.message = 'Connection checked out'; + log.driverConnectionId = ev.connectionId; + break; + case CONNECTION_CHECKED_IN: + ev = logObject as ConnectionCheckedInEvent; + log.message = 'Connection checked in'; + log.driverConnectionId = ev.connectionId; + break; + } + } else { + for (const key in logObject) { + const value = logObject[key]; + // eslint-disable-next-line no-restricted-syntax + if (value === undefined || value === null) continue; + log[key] = value; + } } return log; } From ac7223c532ac0f4330d34dddc488f805ee862de1 Mon Sep 17 00:00:00 2001 From: Warren James Date: Wed, 5 Apr 2023 11:27:44 -0400 Subject: [PATCH 17/39] test(NODE-5169): Updates tests for ConnectionClosedEvent logging --- test/unit/mongo_logger.test.ts | 111 +++++++++++++++++++++++++++++---- 1 file changed, 98 insertions(+), 13 deletions(-) diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index e5ab431588..4fe876745e 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -3,6 +3,20 @@ import { expect } from 'chai'; import { Readable, Writable } from 'stream'; import { + COMMAND_FAILED, + COMMAND_STARTED, + COMMAND_SUCCEEDED, + CONNECTION_CHECK_OUT_FAILED, + CONNECTION_CHECK_OUT_STARTED, + CONNECTION_CHECKED_IN, + CONNECTION_CHECKED_OUT, + CONNECTION_CLOSED, + CONNECTION_CREATED, + CONNECTION_POOL_CLEARED, + CONNECTION_POOL_CLOSED, + CONNECTION_POOL_CREATED, + CONNECTION_POOL_READY, + CONNECTION_READY, Log, MongoLogger, MongoLoggerOptions, @@ -721,7 +735,7 @@ describe('class MongoLogger', function () { address: '127.0.0.1:27017', serviceId: new ObjectId(), databaseName: 'db', - name: 'CommandStarted' + name: COMMAND_STARTED }; const commandSucceeded = { commandName: 'find', @@ -731,7 +745,7 @@ describe('class MongoLogger', function () { address: '127.0.0.1:27017', serviceId: new ObjectId(), databaseName: 'db', - name: 'CommandSucceeded' + name: COMMAND_SUCCEEDED }; const commandFailed = { commandName: 'find', @@ -741,7 +755,7 @@ describe('class MongoLogger', function () { address: '127.0.0.1:27017', serviceId: new ObjectId(), databaseName: 'db', - name: 'CommandFailed' + name: COMMAND_FAILED }; function commonCommandComponentAssertions() { @@ -846,52 +860,63 @@ describe('class MongoLogger', function () { waitQueueTimeoutMS: 100 }; const connectionPoolCreated = { - name: 'ConnectionPoolCreated', + name: CONNECTION_POOL_CREATED, waitQueueSize: 0, address: '127.0.0.1:27017', options }; const connectionPoolReady = { - name: 'ConnectionPoolReady', + name: CONNECTION_POOL_READY, address: '127.0.0.1:27017', options }; const connectionPoolCleared = { - name: 'ConnectionPoolCleared', + name: CONNECTION_POOL_CLEARED, serviceId: new ObjectId(), address: '127.0.0.1:27017', options }; const connectionPoolClosed = { - name: 'ConnectionPoolClosed', + name: CONNECTION_POOL_CLOSED, address: '127.0.0.1:27017', options }; const connectionCreated = { - name: 'ConnectionCreated', + name: CONNECTION_CREATED, connectionId: 0, address: '127.0.0.1:27017', options }; const connectionCheckOutStarted = { - name: 'ConnectionCheckOutStarted', + name: CONNECTION_CHECK_OUT_STARTED, address: '127.0.0.1:27017', options }; const connectionCheckOutFailed = { - name: 'ConnectionCheckOutFailed', - reason: 'wups', + name: CONNECTION_CHECK_OUT_FAILED, address: '127.0.0.1:27017', options }; const connectionCheckedOut = { - name: 'ConnectionCheckedOut', + name: CONNECTION_CHECKED_OUT, connectionId: 0, address: '127.0.0.1:27017', options }; const connectionCheckedIn = { - name: 'ConnectionCheckedIn', + name: CONNECTION_CHECKED_IN, + connectionId: 0, + address: '127.0.0.1:27017', + options + }; + const connectionReady = { + name: CONNECTION_READY, + connectionId: 0, + address: '127.0.0.1:27017', + options + }; + const connectionClosed = { + name: CONNECTION_CLOSED, connectionId: 0, address: '127.0.0.1:27017', options @@ -1046,6 +1071,66 @@ describe('class MongoLogger', function () { expect(log).to.have.property('message', 'Connection checked out'); }); }); + + context('when ConnectionReadyEvent is logged', function () { + beforeEach(function () { + logger[severityLevel]('connection', connectionReady); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; + }); + + commonConnectionComponentAssertions(); + it('emits a log with field `message` = "Connection checked out"', function () { + expect(log).to.have.property('message', 'Connection ready'); + }); + }); + + // TODO: Write tests for ConnectionClosedEvent + context('when ConnectionClosedEvent is logged', function () { + for (const [reason, message] of [ + ['error', 'An error occurred while using the connection'], + [ + 'idle', + 'Connection has been available but unused for longer than the configured max idle time' + ], + ['stale', 'Connection became stale because the pool was cleared'], + ['poolClosed', 'Connection pool was closed'] + ]) { + context(`with reason = "${reason}"`, function () { + beforeEach(function () { + logger[severityLevel]('connection', { ...connectionClosed, reason }); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; + }); + + commonConnectionComponentAssertions(); + it(`emits a log with field \`reason\` = "${message}"`, function () { + expect(log).to.have.property('reason', message); + }); + + if (reason === 'error') { + // TODO(NODE-5169): We need to expose the error on the ConnectionClosedEvent if + // it exists + it.skip('emits a log with field `error`', function () { + expect(log).to.have.property('error'); + }); + } + }); + } + + context('with invalid reason', function () { + beforeEach(function () { + logger[severityLevel]('connection', { ...connectionClosed, reason: 'woops' }); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; + }); + + commonConnectionComponentAssertions(); + it('emits a log without field `reason`', function () { + expect(log).to.not.have.property('reason'); + }); + }); + }); }); }); }); From f46ab9bd3eb1a5220c0439d22259364a807d63a6 Mon Sep 17 00:00:00 2001 From: Warren James Date: Wed, 5 Apr 2023 14:32:54 -0400 Subject: [PATCH 18/39] refactor(NODE-5169): Update logging of ConnectionClosedEvent to include possible error --- src/cmap/connection_pool.ts | 7 +++- src/cmap/connection_pool_events.ts | 5 ++- src/mongo_logger.ts | 4 ++- test/unit/mongo_logger.test.ts | 55 +++++++++++++++++++++--------- 4 files changed, 52 insertions(+), 19 deletions(-) diff --git a/src/cmap/connection_pool.ts b/src/cmap/connection_pool.ts index e3d4228135..6ec1b05df9 100644 --- a/src/cmap/connection_pool.ts +++ b/src/cmap/connection_pool.ts @@ -701,7 +701,12 @@ export class ConnectionPool extends TypedEventEmitter { this[kPending]--; this.emit( ConnectionPool.CONNECTION_CLOSED, - new ConnectionClosedEvent(this, { id: connectOptions.id, serviceId: undefined }, 'error') + new ConnectionClosedEvent( + this, + { id: connectOptions.id, serviceId: undefined }, + 'error', + err + ) ); if (err instanceof MongoNetworkError || err instanceof MongoServerError) { err.connectionGeneration = connectOptions.generation; diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index 4c722a6427..c5f5f51aad 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -128,17 +128,20 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { reason: string; serviceId?: ObjectId; name: string = CONNECTION_CLOSED; + error: Error | undefined; /** @internal */ constructor( pool: ConnectionPool, connection: Pick, - reason: string + reason: string, + error?: Error ) { super(pool); this.connectionId = connection.id; this.reason = reason || 'unknown'; this.serviceId = connection.serviceId; + this.error = error; } } diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 767ad3e1cb..87fbe02862 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -349,7 +349,9 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit break; case 'error': log.reason = 'An error occurred while using the connection'; - // TODO: we need to expose the error on the ConnectionClosedEvent object if it exists + if (ev.error) { + log.error = ev.error; + } break; case 'poolClosed': log.reason = 'Connection pool was closed'; diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 4fe876745e..423e38997e 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -975,21 +975,43 @@ describe('class MongoLogger', function () { expect(log).to.have.property('message', 'Connection pool ready'); }); }); + context('when ConnectionPoolClearedEvent is logged', function () { - beforeEach(function () { - logger[severityLevel]('connection', connectionPoolCleared); - expect(stream.buffer).to.have.lengthOf(1); - log = stream.buffer[0]; - }); + context('when serviceId is present', function () { + beforeEach(function () { + logger[severityLevel]('connection', connectionPoolCleared); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; + }); - commonConnectionComponentAssertions(); - it('emits a log with field `message` = "Connection pool cleared"', function () { - expect(log).to.have.property('message', 'Connection pool cleared'); + commonConnectionComponentAssertions(); + it('emits a log with field `message` = "Connection pool cleared"', function () { + expect(log).to.have.property('message', 'Connection pool cleared'); + }); + + it('emits a log with field `serviceId` that is a string when it is present', function () { + expect(log).to.have.property('serviceId').that.is.a('string'); + }); }); - // TODO: Only in LB mode - it('emits a log with field `serviceId` that is a string when it is present', function () { - expect(log).to.have.property('serviceId').that.is.a('string'); + context('when serviceId is not present', function () { + beforeEach(function () { + // eslint-disable-next-line @typescript-eslint/no-unused-vars + const { serviceId: _, ...connectionPoolClearedNoServiceId } = + connectionPoolCleared; + logger[severityLevel]('connection', connectionPoolClearedNoServiceId); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; + }); + + commonConnectionComponentAssertions(); + it('emits a log with field `message` = "Connection pool cleared"', function () { + expect(log).to.have.property('message', 'Connection pool cleared'); + }); + + it('emits a log without field `serviceId`', function () { + expect(log).to.not.have.property('serviceId'); + }); }); }); @@ -1085,7 +1107,6 @@ describe('class MongoLogger', function () { }); }); - // TODO: Write tests for ConnectionClosedEvent context('when ConnectionClosedEvent is logged', function () { for (const [reason, message] of [ ['error', 'An error occurred while using the connection'], @@ -1098,7 +1119,11 @@ describe('class MongoLogger', function () { ]) { context(`with reason = "${reason}"`, function () { beforeEach(function () { - logger[severityLevel]('connection', { ...connectionClosed, reason }); + const event = + reason === 'error' + ? { ...connectionClosed, reason, error: new Error('this is an error') } + : { ...connectionClosed, reason }; + logger[severityLevel]('connection', event); expect(stream.buffer).to.have.lengthOf(1); log = stream.buffer[0]; }); @@ -1109,9 +1134,7 @@ describe('class MongoLogger', function () { }); if (reason === 'error') { - // TODO(NODE-5169): We need to expose the error on the ConnectionClosedEvent if - // it exists - it.skip('emits a log with field `error`', function () { + it('emits a log with field `error`', function () { expect(log).to.have.property('error'); }); } From c7d8f8d609934eac03b55c88fb6c3bac2cddb8b4 Mon Sep 17 00:00:00 2001 From: Warren James Date: Wed, 5 Apr 2023 15:02:15 -0400 Subject: [PATCH 19/39] refactor(NODE-5619): continue refactor to use minimal writable interface --- src/mongo_logger.ts | 15 +++++---------- test/unit/mongo_logger.test.ts | 5 +++-- 2 files changed, 8 insertions(+), 12 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 87fbe02862..21f153bf60 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -176,7 +176,7 @@ function resolveLogPath( { mongodbLogPath }: { - mongodbLogPath?: unknown; + mongodbLogPath?: string | MongoDBLogWritable; } ): MongoDBLogWritable { const isValidLogDestinationString = (destination: string) => @@ -187,13 +187,8 @@ function resolveLogPath( : process.stdout) as unknown as MongoDBLogWritable; } - if ( - typeof mongodbLogPath === 'object' && - // eslint-disable-next-line no-restricted-syntax - mongodbLogPath !== null && - Object.prototype.hasOwnProperty.call(mongodbLogPath, 'write') - ) { - return mongodbLogPath as MongoDBLogWritable; + if (mongodbLogPath && typeof mongodbLogPath === 'object') { + return mongodbLogPath; } if (typeof MONGODB_LOG_PATH === 'string' && isValidLogDestinationString(MONGODB_LOG_PATH)) { @@ -268,7 +263,7 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit }; let ev; - if (APM_EVENTS.findIndex(e => e === logObject.name) !== -1) { + if (APM_EVENTS.includes(logObject.name)) { log = attachCommandFields(log, logObject as any); switch (logObject.name) { case COMMAND_STARTED: @@ -290,7 +285,7 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit log.failure = ev.failure; break; } - } else if (CMAP_EVENTS.findIndex(e => e === logObject.name) !== -1) { + } else if (CMAP_EVENTS.includes(logObject.name)) { log = attachConnectionFields(log, logObject as ConnectionPoolMonitoringEvent); switch (logObject.name) { case CONNECTION_POOL_CREATED: diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 423e38997e..22d74bfbfa 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -18,6 +18,7 @@ import { CONNECTION_POOL_READY, CONNECTION_READY, Log, + MongoDBLogWritable, MongoLogger, MongoLoggerOptions, SEVERITY_LEVEL_MAP, @@ -384,13 +385,13 @@ describe('class MongoLogger', function () { context('logDestination', function () { const stream = new Writable(); - const validOptions: Map = new Map([ + const validOptions: Map = new Map([ ['stdout', process.stdout], ['stderr', process.stderr], [stream, stream], ['stdOut', process.stdout], ['stdErr', process.stderr] - ] as Array<[any, Writable]>); + ] as Array<[any, MongoDBLogWritable]>); const unsetOptions = ['', undefined]; const invalidEnvironmentOptions = ['non-acceptable-string']; const invalidClientOptions = ['', ' ', undefined, null, 0, false, new Readable()]; From 993058f89f2662719c9c7b2460e037d6d2b61280 Mon Sep 17 00:00:00 2001 From: Warren James Date: Wed, 5 Apr 2023 16:51:57 -0400 Subject: [PATCH 20/39] refactor(NODE-5619): fix janky typecasting --- src/mongo_logger.ts | 24 ++++++++++++++++-------- 1 file changed, 16 insertions(+), 8 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 21f153bf60..a16a27e155 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -1,4 +1,6 @@ import { EJSON } from 'bson'; +import { Writable } from 'stream'; +import { inspect } from 'util'; import type { CommandFailedEvent, @@ -145,7 +147,7 @@ export interface MongoLoggerOptions { /** Max length of embedded EJSON docs. Setting to 0 disables truncation. Defaults to 1000. */ maxDocumentLength: number; /** Destination for log messages. */ - logDestination: MongoDBLogWritable; + logDestination: Writable | MongoDBLogWritable; } /** @@ -176,25 +178,25 @@ function resolveLogPath( { mongodbLogPath }: { - mongodbLogPath?: string | MongoDBLogWritable; + mongodbLogPath?: string | Writable | MongoDBLogWritable; } -): MongoDBLogWritable { +): Writable | MongoDBLogWritable { const isValidLogDestinationString = (destination: string) => ['stdout', 'stderr'].includes(destination.toLowerCase()); if (typeof mongodbLogPath === 'string' && isValidLogDestinationString(mongodbLogPath)) { return (mongodbLogPath.toLowerCase() === 'stderr' ? process.stderr - : process.stdout) as unknown as MongoDBLogWritable; + : process.stdout); } - if (mongodbLogPath && typeof mongodbLogPath === 'object') { + if (mongodbLogPath && typeof mongodbLogPath === 'object' && (mongodbLogPath instanceof Writable || mongodbLogPath?.write)) { return mongodbLogPath; } if (typeof MONGODB_LOG_PATH === 'string' && isValidLogDestinationString(MONGODB_LOG_PATH)) { return (MONGODB_LOG_PATH.toLowerCase() === 'stderr' ? process.stderr - : process.stdout) as unknown as MongoDBLogWritable; + : process.stdout); } return process.stderr as unknown as MongoDBLogWritable; @@ -390,12 +392,14 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit export class MongoLogger { componentSeverities: Record; maxDocumentLength: number; - logDestination: MongoDBLogWritable; + logDestination: MongoDBLogWritable | Writable; + writeStringifiedLogs: boolean; constructor(options: MongoLoggerOptions) { this.componentSeverities = options.componentSeverities; this.maxDocumentLength = options.maxDocumentLength; this.logDestination = options.logDestination; + this.writeStringifiedLogs = this.logDestination === process.stderr || this.logDestination === process.stdout; } /** @experimental */ @@ -419,7 +423,11 @@ export class MongoLogger { logMessage = { ...logMessage, ...DEFAULT_LOG_TRANSFORM(message) }; } } - this.logDestination.write(logMessage); + if (this.writeStringifiedLogs) { + (this.logDestination as Writable).write(inspect(logMessage, { compact: true, breakLength: Infinity }), 'utf-8'); + } else { + (this.logDestination as MongoDBLogWritable).write(logMessage); + } } } From 0d91ccd1e9dfeda89201c7c51c644e7a868c2af9 Mon Sep 17 00:00:00 2001 From: Warren James Date: Thu, 6 Apr 2023 15:02:18 -0400 Subject: [PATCH 21/39] style(NODE-5169): eslint --- src/mongo_logger.ts | 22 +++++++++++++--------- 1 file changed, 13 insertions(+), 9 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index a16a27e155..1773a01dbe 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -184,19 +184,19 @@ function resolveLogPath( const isValidLogDestinationString = (destination: string) => ['stdout', 'stderr'].includes(destination.toLowerCase()); if (typeof mongodbLogPath === 'string' && isValidLogDestinationString(mongodbLogPath)) { - return (mongodbLogPath.toLowerCase() === 'stderr' - ? process.stderr - : process.stdout); + return mongodbLogPath.toLowerCase() === 'stderr' ? process.stderr : process.stdout; } - if (mongodbLogPath && typeof mongodbLogPath === 'object' && (mongodbLogPath instanceof Writable || mongodbLogPath?.write)) { + if ( + mongodbLogPath && + typeof mongodbLogPath === 'object' && + (mongodbLogPath instanceof Writable || mongodbLogPath?.write) + ) { return mongodbLogPath; } if (typeof MONGODB_LOG_PATH === 'string' && isValidLogDestinationString(MONGODB_LOG_PATH)) { - return (MONGODB_LOG_PATH.toLowerCase() === 'stderr' - ? process.stderr - : process.stdout); + return MONGODB_LOG_PATH.toLowerCase() === 'stderr' ? process.stderr : process.stdout; } return process.stderr as unknown as MongoDBLogWritable; @@ -399,7 +399,8 @@ export class MongoLogger { this.componentSeverities = options.componentSeverities; this.maxDocumentLength = options.maxDocumentLength; this.logDestination = options.logDestination; - this.writeStringifiedLogs = this.logDestination === process.stderr || this.logDestination === process.stdout; + this.writeStringifiedLogs = + this.logDestination === process.stderr || this.logDestination === process.stdout; } /** @experimental */ @@ -424,7 +425,10 @@ export class MongoLogger { } } if (this.writeStringifiedLogs) { - (this.logDestination as Writable).write(inspect(logMessage, { compact: true, breakLength: Infinity }), 'utf-8'); + (this.logDestination as Writable).write( + inspect(logMessage, { compact: true, breakLength: Infinity }), + 'utf-8' + ); } else { (this.logDestination as MongoDBLogWritable).write(logMessage); } From 0fe2d2b601cf3e608000c2e562f6ec16ac1368fc Mon Sep 17 00:00:00 2001 From: Warren James Date: Thu, 6 Apr 2023 15:02:49 -0400 Subject: [PATCH 22/39] test(NODE-5169): Remove unneeded tests --- test/unit/mongo_logger.test.ts | 8 -------- 1 file changed, 8 deletions(-) diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 22d74bfbfa..369520ed5f 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -819,10 +819,6 @@ describe('class MongoLogger', function () { expect(() => EJSON.parse(log.reply)).to.not.throw(); }); - - context('when the command is sensitive', function () { - it('redacts the `reply` field'); - }); }); context('when CommandFailedEvent is logged', function () { @@ -844,10 +840,6 @@ describe('class MongoLogger', function () { it('emits a log with field `failure`', function () { expect(log).to.have.property('failure'); }); - - context('when the command is sensitive', function () { - it('redacts the `failure` field'); - }); }); }); From 0a5b9cd1281dd12476648426a25b112d231603fa Mon Sep 17 00:00:00 2001 From: Warren James Date: Fri, 7 Apr 2023 16:03:47 -0400 Subject: [PATCH 23/39] refactor(NODE-5169): Start implementing review changes --- src/cmap/command_monitoring_events.ts | 6 +- src/cmap/connection_pool_events.ts | 32 +++--- src/mongo_logger.ts | 147 ++++++++++++-------------- 3 files changed, 85 insertions(+), 100 deletions(-) diff --git a/src/cmap/command_monitoring_events.ts b/src/cmap/command_monitoring_events.ts index 47eb2bd5ea..cfbab54990 100644 --- a/src/cmap/command_monitoring_events.ts +++ b/src/cmap/command_monitoring_events.ts @@ -24,7 +24,7 @@ export class CommandStartedEvent { address: string; connectionId?: string | number; serviceId?: ObjectId; - name: string = COMMAND_STARTED; + name = COMMAND_STARTED; /** * Create a started event @@ -72,7 +72,7 @@ export class CommandSucceededEvent { commandName: string; reply: unknown; serviceId?: ObjectId; - name: string = COMMAND_SUCCEEDED; + name = COMMAND_SUCCEEDED; /** * Create a succeeded event @@ -121,7 +121,7 @@ export class CommandFailedEvent { commandName: string; failure: Error; serviceId?: ObjectId; - name: string = COMMAND_FAILED; + name = COMMAND_FAILED; /** * Create a failure event diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index c5f5f51aad..5663eac518 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -12,7 +12,7 @@ import { CONNECTION_POOL_READY, CONNECTION_READY } from '../constants'; -import type { AnyError } from '../error'; +import type { AnyError, MongoError } from '../error'; import type { Connection } from './connection'; import type { ConnectionPool, ConnectionPoolOptions } from './connection_pool'; @@ -44,7 +44,7 @@ export class ConnectionPoolCreatedEvent extends ConnectionPoolMonitoringEvent { options?: ConnectionPoolOptions; /** The size of the ConnectionPool's waitQueue */ waitQueueSize: number; - name: string = CONNECTION_POOL_CREATED; + name = CONNECTION_POOL_CREATED; /** @internal */ constructor(pool: ConnectionPool) { @@ -60,7 +60,7 @@ export class ConnectionPoolCreatedEvent extends ConnectionPoolMonitoringEvent { * @category Event */ export class ConnectionPoolReadyEvent extends ConnectionPoolMonitoringEvent { - name: string = CONNECTION_POOL_READY; + name = CONNECTION_POOL_READY; /** @internal */ constructor(pool: ConnectionPool) { @@ -74,7 +74,7 @@ export class ConnectionPoolReadyEvent extends ConnectionPoolMonitoringEvent { * @category Event */ export class ConnectionPoolClosedEvent extends ConnectionPoolMonitoringEvent { - name: string = CONNECTION_POOL_CLOSED; + name = CONNECTION_POOL_CLOSED; /** @internal */ constructor(pool: ConnectionPool) { @@ -90,7 +90,7 @@ export class ConnectionPoolClosedEvent extends ConnectionPoolMonitoringEvent { export class ConnectionCreatedEvent extends ConnectionPoolMonitoringEvent { /** A monotonically increasing, per-pool id for the newly created connection */ connectionId: number | ''; - name: string = CONNECTION_CREATED; + name = CONNECTION_CREATED; /** @internal */ constructor(pool: ConnectionPool, connection: { id: number | '' }) { @@ -107,7 +107,7 @@ export class ConnectionCreatedEvent extends ConnectionPoolMonitoringEvent { export class ConnectionReadyEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; - name: string = CONNECTION_READY; + name = CONNECTION_READY; /** @internal */ constructor(pool: ConnectionPool, connection: Connection) { @@ -125,21 +125,21 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; /** The reason the connection was closed */ - reason: string; + reason: 'idle' | 'stale' | 'poolClosed' | 'error'; serviceId?: ObjectId; - name: string = CONNECTION_CLOSED; + name = CONNECTION_CLOSED; error: Error | undefined; /** @internal */ constructor( pool: ConnectionPool, connection: Pick, - reason: string, - error?: Error + reason: 'idle' | 'stale' | 'poolClosed' | 'error', + error?: MongoError ) { super(pool); this.connectionId = connection.id; - this.reason = reason || 'unknown'; + this.reason = reason; this.serviceId = connection.serviceId; this.error = error; } @@ -151,7 +151,7 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { * @category Event */ export class ConnectionCheckOutStartedEvent extends ConnectionPoolMonitoringEvent { - name: string = CONNECTION_CHECK_OUT_STARTED; + name = CONNECTION_CHECK_OUT_STARTED; /** @internal */ constructor(pool: ConnectionPool) { @@ -167,7 +167,7 @@ export class ConnectionCheckOutStartedEvent extends ConnectionPoolMonitoringEven export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent { /** The reason the attempt to check out failed */ reason: AnyError | string; - name: string = CONNECTION_CHECK_OUT_FAILED; + name = CONNECTION_CHECK_OUT_FAILED; /** @internal */ constructor(pool: ConnectionPool, reason: AnyError | string) { @@ -184,7 +184,7 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; - name: string = CONNECTION_CHECKED_OUT; + name = CONNECTION_CHECKED_OUT; /** @internal */ constructor(pool: ConnectionPool, connection: Connection) { @@ -201,7 +201,7 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { export class ConnectionCheckedInEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; - name: string = CONNECTION_CHECKED_IN; + name = CONNECTION_CHECKED_IN; /** @internal */ constructor(pool: ConnectionPool, connection: Connection) { @@ -220,7 +220,7 @@ export class ConnectionPoolClearedEvent extends ConnectionPoolMonitoringEvent { serviceId?: ObjectId; interruptInUseConnections?: boolean; - name: string = CONNECTION_POOL_CLEARED; + name = CONNECTION_POOL_CLEARED; /** @internal */ constructor( diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 1773a01dbe..3134a9fea6 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -1,5 +1,5 @@ import { EJSON } from 'bson'; -import { Writable } from 'stream'; +import type { Writable } from 'stream'; import { inspect } from 'util'; import type { @@ -167,6 +167,18 @@ function parseSeverityFromString(s?: string): SeverityLevel | null { return null; } +type ClientLogPathOptions = { + mongodbLogPath?: string | Writable | MongoDBLogWritable; +}; + +function createStdLogger(stream: { write: NodeJS.WriteStream['write'] }): MongoDBLogWritable { + return { + write: (log: Log): unknown => { + stream.write(inspect(log, { compact: true, breakLength: Infinity }), 'utf-8'); + return; + } + }; +} /** * resolves the MONGODB_LOG_PATH and mongodbLogPath options from the environment and the * mongo client options respectively. @@ -175,38 +187,26 @@ function parseSeverityFromString(s?: string): SeverityLevel | null { */ function resolveLogPath( { MONGODB_LOG_PATH }: MongoLoggerEnvOptions, - { - mongodbLogPath - }: { - mongodbLogPath?: string | Writable | MongoDBLogWritable; - } -): Writable | MongoDBLogWritable { - const isValidLogDestinationString = (destination: string) => - ['stdout', 'stderr'].includes(destination.toLowerCase()); - if (typeof mongodbLogPath === 'string' && isValidLogDestinationString(mongodbLogPath)) { - return mongodbLogPath.toLowerCase() === 'stderr' ? process.stderr : process.stdout; - } + { mongodbLogPath }: ClientLogPathOptions +): MongoDBLogWritable { + if (mongodbLogPath === 'stderr') return createStdLogger(process.stderr); + if (mongodbLogPath === 'stdout') return createStdLogger(process.stdout); - if ( - mongodbLogPath && - typeof mongodbLogPath === 'object' && - (mongodbLogPath instanceof Writable || mongodbLogPath?.write) - ) { + if (typeof mongodbLogPath === 'object' && typeof mongodbLogPath?.write === 'function') { return mongodbLogPath; } - if (typeof MONGODB_LOG_PATH === 'string' && isValidLogDestinationString(MONGODB_LOG_PATH)) { - return MONGODB_LOG_PATH.toLowerCase() === 'stderr' ? process.stderr : process.stdout; - } + if (MONGODB_LOG_PATH === 'stderr') return createStdLogger(process.stderr); + if (MONGODB_LOG_PATH === 'stdout') return createStdLogger(process.stdout); - return process.stderr as unknown as MongoDBLogWritable; + return createStdLogger(process.stderr); } /** @internal */ export interface Log extends Record { - s: SeverityLevel; t: Date; c: MongoLoggableComponent; + s: SeverityLevel; message?: string; } @@ -227,42 +227,42 @@ export interface Loggable extends Record { toLog?(): Record; } -function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit { - let log: Omit = {}; +function getHostPort(address: string): { host: string; port: number } { + const hostAddress = new HostAddress(address); - const getHostPort = (address: string): { host: string; port: number } => { - const hostAddress = new HostAddress(address); + // NOTE: Should only default when the address is a socket address + const host = hostAddress.host ?? ''; + const port = hostAddress.port ?? 0; + return { host, port }; +} - // NOTE: Should only default when the address is a socket address - const host = hostAddress.host ?? ''; - const port = hostAddress.port ?? 0; - return { host, port }; - }; +function attachCommandFields( + l: any, + ev: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent +) { + l.commandName = ev.commandName; + l.requestId = ev.requestId; + l.driverConnectionId = ev?.connectionId; + const { host, port } = getHostPort(ev.address); + l.serverHost = host; + l.serverPort = port; + if (ev?.serviceId) { + l.serviceId = ev.serviceId.toHexString(); + } - const attachCommandFields = ( - l: any, - ev: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent - ) => { - l.commandName = ev.commandName; - l.requestId = ev.requestId; - l.driverConnectionId = ev?.connectionId; - const { host, port } = getHostPort(ev.address); - l.serverHost = host; - l.serverPort = port; - if (ev?.serviceId) { - l.serviceId = ev.serviceId.toHexString(); - } + return l; +} - return l; - }; +function attachConnectionFields(l: any, ev: ConnectionPoolMonitoringEvent) { + const { host, port } = getHostPort(ev.address); + l.serverHost = host; + l.serverPort = port; - const attachConnectionFields = (l: any, ev: ConnectionPoolMonitoringEvent) => { - const { host, port } = getHostPort(ev.address); - l.serverHost = host; - l.serverPort = port; + return l; +} - return l; - }; +function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit { + let log: Omit = Object.create(null); let ev; if (APM_EVENTS.includes(logObject.name)) { @@ -378,11 +378,8 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit break; } } else { - for (const key in logObject) { - const value = logObject[key]; - // eslint-disable-next-line no-restricted-syntax - if (value === undefined || value === null) continue; - log[key] = value; + for (const [key, value] of Object.entries(logObject)) { + if (value != null) log[key] = value; } } return log; @@ -393,46 +390,34 @@ export class MongoLogger { componentSeverities: Record; maxDocumentLength: number; logDestination: MongoDBLogWritable | Writable; - writeStringifiedLogs: boolean; constructor(options: MongoLoggerOptions) { this.componentSeverities = options.componentSeverities; this.maxDocumentLength = options.maxDocumentLength; this.logDestination = options.logDestination; - this.writeStringifiedLogs = - this.logDestination === process.stderr || this.logDestination === process.stdout; } /** @experimental */ - emergency(component: MongoLoggableComponent, message: Loggable | string): void { - this.log(component, 'emergency', message); - } + emergency = this.log.bind(this, 'emergency'); private log( - component: MongoLoggableComponent, severity: SeverityLevel, + component: MongoLoggableComponent, message: Loggable | string ): void { - if (compareSeverity(severity, this.componentSeverities[component]) <= 0) { - let logMessage: Log = { t: new Date(), c: component, s: severity }; - if (typeof message === 'string') { - logMessage.message = message; - } else { - if (message.toLog && typeof message.toLog === 'function') { - logMessage = { ...logMessage, ...message.toLog() }; - } else { - logMessage = { ...logMessage, ...DEFAULT_LOG_TRANSFORM(message) }; - } - } - if (this.writeStringifiedLogs) { - (this.logDestination as Writable).write( - inspect(logMessage, { compact: true, breakLength: Infinity }), - 'utf-8' - ); + if (compareSeverity(severity, this.componentSeverities[component]) > 0) return; + + let logMessage: Log = { t: new Date(), c: component, s: severity }; + if (typeof message === 'string') { + logMessage.message = message; + } else { + if (message.toLog && typeof message.toLog === 'function') { + logMessage = { ...logMessage, ...message.toLog() }; } else { - (this.logDestination as MongoDBLogWritable).write(logMessage); + logMessage = { ...logMessage, ...DEFAULT_LOG_TRANSFORM(message) }; } } + this.logDestination.write(logMessage); } /** From bdde7cf1fc3d590213feab04df09e05a0b1648c2 Mon Sep 17 00:00:00 2001 From: Warren James Date: Mon, 10 Apr 2023 12:58:32 -0400 Subject: [PATCH 24/39] fix(NODE-5169): review comments --- src/cmap/connection_pool.ts | 5 +- src/cmap/connection_pool_events.ts | 4 +- src/index.ts | 2 + src/mongo_logger.ts | 95 +++++++++++++++++------------- 4 files changed, 63 insertions(+), 43 deletions(-) diff --git a/src/cmap/connection_pool.ts b/src/cmap/connection_pool.ts index 6ec1b05df9..f58310e867 100644 --- a/src/cmap/connection_pool.ts +++ b/src/cmap/connection_pool.ts @@ -641,7 +641,10 @@ export class ConnectionPool extends TypedEventEmitter { } } - private destroyConnection(connection: Connection, reason: string) { + private destroyConnection( + connection: Connection, + reason: 'error' | 'idle' | 'stale' | 'poolClosed' + ) { this.emit( ConnectionPool.CONNECTION_CLOSED, new ConnectionClosedEvent(this, connection, reason) diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index 5663eac518..2fbfdc0980 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -12,7 +12,7 @@ import { CONNECTION_POOL_READY, CONNECTION_READY } from '../constants'; -import type { AnyError, MongoError } from '../error'; +import type { AnyError } from '../error'; import type { Connection } from './connection'; import type { ConnectionPool, ConnectionPoolOptions } from './connection_pool'; @@ -135,7 +135,7 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { pool: ConnectionPool, connection: Pick, reason: 'idle' | 'stale' | 'poolClosed' | 'error', - error?: MongoError + error?: AnyError ) { super(pool); this.connectionId = connection.id; diff --git a/src/index.ts b/src/index.ts index 75fed95926..a9660718c2 100644 --- a/src/index.ts +++ b/src/index.ts @@ -290,7 +290,9 @@ export type { } from './mongo_client'; export type { Log, + LogConvertible, Loggable, + LoggableEvent, MongoDBLogWritable, MongoLoggableComponent, MongoLogger, diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 3134a9fea6..bce3cd92c9 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -223,14 +223,44 @@ function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { } /** @internal */ -export interface Loggable extends Record { - toLog?(): Record; +export type LoggableEvent = + | CommandStartedEvent + | CommandSucceededEvent + | CommandFailedEvent + | ConnectionPoolCreatedEvent + | ConnectionPoolReadyEvent + | ConnectionPoolClosedEvent + | ConnectionPoolClearedEvent + | ConnectionCreatedEvent + | ConnectionReadyEvent + | ConnectionClosedEvent + | ConnectionCheckedInEvent + | ConnectionCheckedOutEvent + | ConnectionCheckOutStartedEvent + | ConnectionCheckOutFailedEvent; + +/** @internal */ +export interface LogConvertible extends Record { + toLog(): Record; +} + +/** @internal */ +export type Loggable = LoggableEvent | LogConvertible; + +function isLogConvertible(obj: Loggable): obj is LogConvertible { + const objAsLogConvertible = obj as LogConvertible; + // eslint-disable-next-line no-restricted-syntax + return objAsLogConvertible.toLog !== undefined && typeof objAsLogConvertible === 'function'; } function getHostPort(address: string): { host: string; port: number } { const hostAddress = new HostAddress(address); // NOTE: Should only default when the address is a socket address + if (hostAddress.socketPath) { + return { host: hostAddress.socketPath, port: 0 }; + } + const host = hostAddress.host ?? ''; const port = hostAddress.port ?? 0; return { host, port }; @@ -264,38 +294,33 @@ function attachConnectionFields(l: any, ev: ConnectionPoolMonitoringEvent) { function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit { let log: Omit = Object.create(null); - let ev; if (APM_EVENTS.includes(logObject.name)) { log = attachCommandFields(log, logObject as any); switch (logObject.name) { case COMMAND_STARTED: - ev = logObject as CommandStartedEvent; log.message = 'Command started'; - log.command = EJSON.stringify(ev.command); - log.databaseName = ev.databaseName; + log.command = EJSON.stringify(logObject.command); + log.databaseName = logObject.databaseName; break; case COMMAND_SUCCEEDED: - ev = logObject as CommandSucceededEvent; log.message = 'Command succeeded'; - log.durationMS = ev.duration; - log.reply = EJSON.stringify(ev.reply); + log.durationMS = logObject.duration; + log.reply = EJSON.stringify(logObject.reply); break; case COMMAND_FAILED: - ev = logObject as CommandFailedEvent; log.message = 'Command failed'; - log.durationMS = ev.duration; - log.failure = ev.failure; + log.durationMS = logObject.duration; + log.failure = logObject.failure; break; } } else if (CMAP_EVENTS.includes(logObject.name)) { log = attachConnectionFields(log, logObject as ConnectionPoolMonitoringEvent); switch (logObject.name) { case CONNECTION_POOL_CREATED: - ev = logObject as ConnectionPoolCreatedEvent; log.message = 'Connection pool created'; - if (ev.options) { + if (logObject.options) { const { maxIdleTimeMS, minPoolSize, maxPoolSize, maxConnecting, waitQueueTimeoutMS } = - ev.options; + logObject.options; log = { ...log, maxIdleTimeMS, @@ -304,39 +329,33 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit maxConnecting, waitQueueTimeoutMS }; - log.waitQueueSize = ev.waitQueueSize; + log.waitQueueSize = logObject.waitQueueSize; } break; case CONNECTION_POOL_READY: - ev = logObject as ConnectionPoolReadyEvent; log.message = 'Connection pool ready'; break; case CONNECTION_POOL_CLEARED: - ev = logObject as ConnectionPoolClearedEvent; log.message = 'Connection pool cleared'; - if (ev.serviceId?._bsontype === 'ObjectId') { - log.serviceId = ev.serviceId.toHexString(); + if (logObject.serviceId?._bsontype === 'ObjectId') { + log.serviceId = logObject.serviceId.toHexString(); } break; case CONNECTION_POOL_CLOSED: - ev = logObject as ConnectionPoolClosedEvent; log.message = 'Connection pool closed'; break; case CONNECTION_CREATED: - ev = logObject as ConnectionCreatedEvent; log.message = 'Connection created'; - log.driverConnectionId = ev.connectionId; + log.driverConnectionId = logObject.connectionId; break; case CONNECTION_READY: - ev = logObject as ConnectionReadyEvent; log.message = 'Connection ready'; - log.driverConnectionId = ev.connectionId; + log.driverConnectionId = logObject.connectionId; break; case CONNECTION_CLOSED: - ev = logObject as ConnectionClosedEvent; log.message = 'Connection closed'; - log.driverConnectionId = ev.connectionId; - switch (ev.reason) { + log.driverConnectionId = logObject.connectionId; + switch (logObject.reason) { case 'stale': log.reason = 'Connection became stale because the pool was cleared'; break; @@ -346,8 +365,8 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit break; case 'error': log.reason = 'An error occurred while using the connection'; - if (ev.error) { - log.error = ev.error; + if (logObject.error) { + log.error = logObject.error; } break; case 'poolClosed': @@ -358,23 +377,19 @@ function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit } break; case CONNECTION_CHECK_OUT_STARTED: - ev = logObject as ConnectionCheckOutStartedEvent; log.message = 'Connection checkout started'; break; case CONNECTION_CHECK_OUT_FAILED: - ev = logObject as ConnectionCheckOutFailedEvent; log.message = 'Connection checkout failed'; - log.reason = ev.reason; + log.reason = logObject.reason; break; case CONNECTION_CHECKED_OUT: - ev = logObject as ConnectionCheckedOutEvent; log.message = 'Connection checked out'; - log.driverConnectionId = ev.connectionId; + log.driverConnectionId = logObject.connectionId; break; case CONNECTION_CHECKED_IN: - ev = logObject as ConnectionCheckedInEvent; log.message = 'Connection checked in'; - log.driverConnectionId = ev.connectionId; + log.driverConnectionId = logObject.connectionId; break; } } else { @@ -403,15 +418,15 @@ export class MongoLogger { private log( severity: SeverityLevel, component: MongoLoggableComponent, - message: Loggable | string + message: LoggableEvent | LogConvertible | string ): void { if (compareSeverity(severity, this.componentSeverities[component]) > 0) return; let logMessage: Log = { t: new Date(), c: component, s: severity }; if (typeof message === 'string') { logMessage.message = message; - } else { - if (message.toLog && typeof message.toLog === 'function') { + } else if (typeof message === 'object') { + if (isLogConvertible(message)) { logMessage = { ...logMessage, ...message.toLog() }; } else { logMessage = { ...logMessage, ...DEFAULT_LOG_TRANSFORM(message) }; From f11f9d2c7c549b672cb226e30e92b91853776d9d Mon Sep 17 00:00:00 2001 From: Warren James Date: Mon, 10 Apr 2023 12:59:39 -0400 Subject: [PATCH 25/39] test(NODE-5169): add feature flag tests --- .../node-specific/feature_flags.test.ts | 45 +++++++++++++++++++ 1 file changed, 45 insertions(+) diff --git a/test/integration/node-specific/feature_flags.test.ts b/test/integration/node-specific/feature_flags.test.ts index 88da73adbd..065ca497f6 100644 --- a/test/integration/node-specific/feature_flags.test.ts +++ b/test/integration/node-specific/feature_flags.test.ts @@ -140,4 +140,49 @@ describe('Feature Flags', () => { }); } }); + + describe('@@mdb.internalLoggerConfig', () => { + let cachedEnv: NodeJS.ProcessEnv; + + before(() => { + cachedEnv = process.env; + }); + after(() => { + process.env = cachedEnv; + }); + + context('when undefined', function () { + before(() => { + process.env.MONGODB_LOG_COMMAND = SeverityLevel.EMERGENCY; + }); + + it('falls back to environment options', function () { + const client = new MongoClient('mongodb://localhost:27017', { + [Symbol.for('@@mdb.enableMongoLogger')]: true, + [Symbol.for('@@mdb.internalLoggerConfig')]: undefined + }); + + expect(client.mongoLogger.componentSeverities).to.have.property( + 'command', + SeverityLevel.EMERGENCY + ); + }); + }); + + context('when defined', function () { + it('overrides environment options', function () { + const client = new MongoClient('mongodb://localhost:27017', { + [Symbol.for('@@mdb.enableMongoLogger')]: true, + [Symbol.for('@@mdb.internalLoggerConfig')]: { + MONGODB_LOG_COMMAND: SeverityLevel.ALERT + } + }); + + expect(client.mongoLogger.componentSeverities).to.have.property( + 'command', + SeverityLevel.ALERT + ); + }); + }); + }); }); From 3c742d60c709131d0d17cabb375c127e870333c7 Mon Sep 17 00:00:00 2001 From: Warren James Date: Mon, 10 Apr 2023 13:12:33 -0400 Subject: [PATCH 26/39] refactor(NODE-5169): Change log signature --- src/mongo_logger.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index bce3cd92c9..f5daae6379 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -418,7 +418,7 @@ export class MongoLogger { private log( severity: SeverityLevel, component: MongoLoggableComponent, - message: LoggableEvent | LogConvertible | string + message: Loggable | string ): void { if (compareSeverity(severity, this.componentSeverities[component]) > 0) return; From 4db07e6dcd2c12ad85a5a8cd92c6b59f508480cc Mon Sep 17 00:00:00 2001 From: Warren James Date: Mon, 10 Apr 2023 16:19:05 -0400 Subject: [PATCH 27/39] fix(NODE-5169): fix check --- src/index.ts | 1 + src/mongo_logger.ts | 8 ++++++-- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/src/index.ts b/src/index.ts index a9660718c2..0c414d02c2 100644 --- a/src/index.ts +++ b/src/index.ts @@ -301,6 +301,7 @@ export type { MongoLoggerOptions, SeverityLevel } from './mongo_logger'; +export { createStdLogger } from './mongo_logger'; export type { CommonEvents, EventsDescription, diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index f5daae6379..b25841c191 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -171,7 +171,10 @@ type ClientLogPathOptions = { mongodbLogPath?: string | Writable | MongoDBLogWritable; }; -function createStdLogger(stream: { write: NodeJS.WriteStream['write'] }): MongoDBLogWritable { +/** @internal */ +export function createStdLogger(stream: { + write: NodeJS.WriteStream['write']; +}): MongoDBLogWritable { return { write: (log: Log): unknown => { stream.write(inspect(log, { compact: true, breakLength: Infinity }), 'utf-8'); @@ -179,6 +182,7 @@ function createStdLogger(stream: { write: NodeJS.WriteStream['write'] }): MongoD } }; } + /** * resolves the MONGODB_LOG_PATH and mongodbLogPath options from the environment and the * mongo client options respectively. @@ -250,7 +254,7 @@ export type Loggable = LoggableEvent | LogConvertible; function isLogConvertible(obj: Loggable): obj is LogConvertible { const objAsLogConvertible = obj as LogConvertible; // eslint-disable-next-line no-restricted-syntax - return objAsLogConvertible.toLog !== undefined && typeof objAsLogConvertible === 'function'; + return objAsLogConvertible.toLog !== undefined && typeof objAsLogConvertible.toLog === 'function'; } function getHostPort(address: string): { host: string; port: number } { From 896a0108c464fc8415737b167fcc7339ef7b8533 Mon Sep 17 00:00:00 2001 From: Warren James Date: Mon, 10 Apr 2023 16:30:53 -0400 Subject: [PATCH 28/39] test(NODE-5169): test wip --- test/unit/mongo_logger.test.ts | 133 ++++++++++++++++++++++++++------- 1 file changed, 106 insertions(+), 27 deletions(-) diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 369520ed5f..1d841fb63e 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -1,6 +1,8 @@ import { EJSON, ObjectId } from 'bson'; import { expect } from 'chai'; +import * as sinon from 'sinon'; import { Readable, Writable } from 'stream'; +import { inspect } from 'util'; import { COMMAND_FAILED, @@ -384,19 +386,32 @@ describe('class MongoLogger', function () { }); context('logDestination', function () { + let stdout; + let stderr; + let validOptions: Map; const stream = new Writable(); - const validOptions: Map = new Map([ - ['stdout', process.stdout], - ['stderr', process.stderr], - [stream, stream], - ['stdOut', process.stdout], - ['stdErr', process.stderr] - ] as Array<[any, MongoDBLogWritable]>); const unsetOptions = ['', undefined]; const invalidEnvironmentOptions = ['non-acceptable-string']; const invalidClientOptions = ['', ' ', undefined, null, 0, false, new Readable()]; const validClientOptions = ['stderr', 'stdout', stream, 'stdErr', 'stdOut']; const validEnvironmentOptions = ['stderr', 'stdout', 'stdOut', 'stdErr']; + + beforeEach(function () { + stdout = sinon.stub(process.stdout); + stderr = sinon.stub(process.stderr); + validOptions = new Map([ + ['stdout', stdout], + ['stderr', stderr], + [stream, stream], + ['stdOut', stdout], + ['stdErr', stderr] + ] as Array<[any, MongoDBLogWritable]>); + }); + + afterEach(function () { + sinon.restore(); + }); + context('when MONGODB_LOG_DESTINATION is unset in the environment', function () { context('when mongodbLogPath is unset as a client option', function () { for (const unsetEnvironmentOption of unsetOptions) { @@ -404,11 +419,17 @@ describe('class MongoLogger', function () { it(`{environment: "${unsetEnvironmentOption}", client: "${unsetOption}"} defaults to process.stderr`, function () { const options = MongoLogger.resolveOptions( { - MONGODB_LOG_PATH: unsetEnvironmentOption + MONGODB_LOG_PATH: unsetEnvironmentOption, + MONGODB_LOG_COMMAND: 'emergency' }, { mongodbLogPath: unsetOption as any } ); - expect(options.logDestination).to.equal(process.stderr); + const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; + options.logDestination.write(log); + + expect(stderr.write).to.have.been.calledOnceWith( + inspect(log, { breakLength: Infinity, compact: true }) + ); }); } } @@ -420,11 +441,17 @@ describe('class MongoLogger', function () { it(`{environment: "${unsetEnvironmentOption}", client: "${invalidOption}"} defaults to process.stderr`, function () { const options = MongoLogger.resolveOptions( { - MONGODB_LOG_PATH: unsetEnvironmentOption + MONGODB_LOG_PATH: unsetEnvironmentOption, + MONGODB_LOG_COMMAND: 'emergency' }, { mongodbLogPath: invalidOption as any } ); - expect(options.logDestination).to.equal(process.stderr); + const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; + options.logDestination.write(log); + + expect(stderr.write).to.have.been.calledOnceWith( + inspect(log, { breakLength: Infinity, compact: true }) + ); }); } } @@ -433,15 +460,27 @@ describe('class MongoLogger', function () { context('when mongodbLogPath is a valid client option', function () { for (const unsetEnvironmentOption of unsetOptions) { for (const validOption of validClientOptions) { - it(`{environment: "${unsetEnvironmentOption}", client: "${validOption}"} uses the value from the client options`, function () { + it.skip(`{environment: "${unsetEnvironmentOption}", client: "${validOption}"} uses the value from the client options`, function () { const options = MongoLogger.resolveOptions( { - MONGODB_LOG_PATH: unsetEnvironmentOption + MONGODB_LOG_PATH: unsetEnvironmentOption, + MONGODB_LOG_COMMAND: 'emergency' }, { mongodbLogPath: validOption as any } ); + + const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; + options.logDestination.write(log); + const correctDestination = validOptions.get(validOption); - expect(options.logDestination).to.equal(correctDestination); + if (correctDestination === stdout || correctDestination === stderr) { + expect(correctDestination?.write).to.have.been.calledOnceWith( + inspect(log, { breakLength: Infinity, compact: true }) + ); + } else { + expect(correctDestination?.write).to.have.been.calledOnceWith(log); + } + //expect(options.logDestination).to.equal(correctDestination); }); } } @@ -457,11 +496,17 @@ describe('class MongoLogger', function () { it(`{environment: "${invalidEnvironmentOption}", client: "${unsetClientOption}"} defaults to process.stderr`, function () { const options = MongoLogger.resolveOptions( { - MONGODB_LOG_PATH: invalidEnvironmentOption + MONGODB_LOG_PATH: invalidEnvironmentOption, + MONGODB_LOG_COMMAND: 'emergency' }, { mongodbLogPath: unsetClientOption as any } ); - expect(options.logDestination).to.equal(process.stderr); + const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; + options.logDestination.write(log); + + expect(stderr.write).to.have.been.calledOnceWith( + inspect(log, { breakLength: Infinity, compact: true }) + ); }); } } @@ -475,11 +520,17 @@ describe('class MongoLogger', function () { it(`{environment: "${invalidEnvironmentOption}", client: "${invalidOption}"} defaults to process.stderr`, function () { const options = MongoLogger.resolveOptions( { - MONGODB_LOG_PATH: invalidEnvironmentOption + MONGODB_LOG_PATH: invalidEnvironmentOption, + MONGODB_LOG_COMMAND: 'emergency' }, { mongodbLogPath: invalidOption as any } ); - expect(options.logDestination).to.equal(process.stderr); + const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; + options.logDestination.write(log); + + expect(stderr.write).to.have.been.calledOnceWith( + inspect(log, { breakLength: Infinity, compact: true }) + ); }); } } @@ -492,12 +543,13 @@ describe('class MongoLogger', function () { it(`{environment: "${invalidEnvironmentOption}", client: "${validOption}"} uses the value from the client options`, function () { const options = MongoLogger.resolveOptions( { - MONGODB_LOG_PATH: invalidEnvironmentOption + MONGODB_LOG_PATH: invalidEnvironmentOption, + MONGODB_LOG_COMMAND: 'emergency' }, { mongodbLogPath: validOption as any } ); const correctDestination = validOptions.get(validOption); - expect(options.logDestination).to.equal(correctDestination); + expect(options.logDestination).to.deep.equal(correctDestination); }); } } @@ -512,12 +564,15 @@ describe('class MongoLogger', function () { it(`{environment: "${validEnvironmentOption}", client: "${unsetOption}"} uses process.${validEnvironmentOption}`, function () { const options = MongoLogger.resolveOptions( { - MONGODB_LOG_PATH: validEnvironmentOption + MONGODB_LOG_PATH: validEnvironmentOption, + MONGODB_LOG_COMMAND: 'emergency' }, { mongodbLogPath: unsetOption as any } ); const correctDestination = validOptions.get(validEnvironmentOption); - expect(options.logDestination).to.equal(correctDestination); + expect(options.logDestination.write.toString()).to.equal( + correctDestination?.write.toString() + ); }); } } @@ -528,15 +583,34 @@ describe('class MongoLogger', function () { function () { for (const validEnvironmentOption of validEnvironmentOptions) { for (const invalidValue of invalidClientOptions) { - it(`{environment: "${validEnvironmentOption}", client: "${invalidValue}"} uses process.${validEnvironmentOption}`, function () { + it.only(`{environment: "${validEnvironmentOption}", client: "${invalidValue}"} uses process.${validEnvironmentOption}`, function () { const options = MongoLogger.resolveOptions( { - MONGODB_LOG_PATH: validEnvironmentOption + MONGODB_LOG_PATH: validEnvironmentOption, + MONGODB_LOG_COMMAND: 'emergency' }, { mongodbLogPath: invalidValue as any } ); + const correctDestination = validOptions.get(validEnvironmentOption); - expect(options.logDestination).to.equal(correctDestination); + + if (validEnvironmentOption.toLowerCase() === 'stderr') { + const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; + options.logDestination.write(log); + expect(stderr.write).to.have.been.calledOnceWith( + inspect(log, { breakLength: Infinity, compact: true }) + ); + } else if (validEnvironmentOption.toLowerCase() === 'stdout') { + const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; + options.logDestination.write(log); + expect(stdout.write).to.have.been.calledOnceWith( + inspect(log, { breakLength: Infinity, compact: true }) + ); + } else { + expect(options.logDestination.write.toString()).to.equal( + correctDestination?.write.toString() + ); + } }); } } @@ -553,12 +627,17 @@ describe('class MongoLogger', function () { }} uses the value from the client options`, function () { const options = MongoLogger.resolveOptions( { - MONGODB_LOG_PATH: validEnvironmentOption + MONGODB_LOG_PATH: validEnvironmentOption, + MONGODB_LOG_COMMAND: 'emergency' }, { mongodbLogPath: validValue as any } ); const correctDestination = validOptions.get(validValue); - expect(options.logDestination).to.equal(correctDestination); + // NOTE: here we are checking if we set the write function correctly + // Deep and shallow equality do not work for functions + expect(options.logDestination.write.toString()).to.equal( + correctDestination?.write.toString() + ); }); } } From af2d8ed118334101f0063183fae9333d88078c66 Mon Sep 17 00:00:00 2001 From: Warren James Date: Tue, 11 Apr 2023 10:14:19 -0400 Subject: [PATCH 29/39] refactor(NODE-5169): Refactor of resolveOptions and DEFAULT_LOG_TRANSFORM --- src/cmap/connection_pool_events.ts | 14 +- src/mongo_logger.ts | 230 ++++++++++++++++------------- test/unit/mongo_logger.test.ts | 86 +++++------ 3 files changed, 172 insertions(+), 158 deletions(-) diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index 2fbfdc0980..39a96f63d7 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -21,11 +21,23 @@ import type { ConnectionPool, ConnectionPoolOptions } from './connection_pool'; * @public * @category Event */ -export class ConnectionPoolMonitoringEvent { +export abstract class ConnectionPoolMonitoringEvent { /** A timestamp when the event was created */ time: Date; /** The address (host/port pair) of the pool */ address: string; + abstract name: + | typeof CONNECTION_CHECK_OUT_FAILED + | typeof CONNECTION_CHECK_OUT_STARTED + | typeof CONNECTION_CHECKED_IN + | typeof CONNECTION_CHECKED_OUT + | typeof CONNECTION_CLOSED + | typeof CONNECTION_CREATED + | typeof CONNECTION_POOL_CLEARED + | typeof CONNECTION_POOL_CLOSED + | typeof CONNECTION_POOL_CREATED + | typeof CONNECTION_POOL_READY + | typeof CONNECTION_READY; /** @internal */ constructor(pool: ConnectionPool) { diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index b25841c191..4de179666e 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -22,8 +22,6 @@ import type { ConnectionReadyEvent } from './cmap/connection_pool_events'; import { - APM_EVENTS, - CMAP_EVENTS, COMMAND_FAILED, COMMAND_STARTED, COMMAND_SUCCEEDED, @@ -193,15 +191,21 @@ function resolveLogPath( { MONGODB_LOG_PATH }: MongoLoggerEnvOptions, { mongodbLogPath }: ClientLogPathOptions ): MongoDBLogWritable { - if (mongodbLogPath === 'stderr') return createStdLogger(process.stderr); - if (mongodbLogPath === 'stdout') return createStdLogger(process.stdout); + if (typeof mongodbLogPath === 'string' && /^stderr$/i.test(mongodbLogPath)) + return createStdLogger(process.stderr); + if (typeof mongodbLogPath === 'string' && /^stdout$/i.test(mongodbLogPath)) + return createStdLogger(process.stdout); if (typeof mongodbLogPath === 'object' && typeof mongodbLogPath?.write === 'function') { return mongodbLogPath; } - if (MONGODB_LOG_PATH === 'stderr') return createStdLogger(process.stderr); - if (MONGODB_LOG_PATH === 'stdout') return createStdLogger(process.stdout); + if (MONGODB_LOG_PATH && /^stderr$/i.test(MONGODB_LOG_PATH)) { + return createStdLogger(process.stderr); + } + if (MONGODB_LOG_PATH && /^stdout$/i.test(MONGODB_LOG_PATH)) { + return createStdLogger(process.stdout); + } return createStdLogger(process.stderr); } @@ -228,6 +232,7 @@ function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { /** @internal */ export type LoggableEvent = + //| ConnectionPoolMonitoringEvent | CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent @@ -295,111 +300,124 @@ function attachConnectionFields(l: any, ev: ConnectionPoolMonitoringEvent) { return l; } -function DEFAULT_LOG_TRANSFORM(logObject: Loggable): Omit { +function DEFAULT_LOG_TRANSFORM(logObject: LoggableEvent): Omit { let log: Omit = Object.create(null); - if (APM_EVENTS.includes(logObject.name)) { - log = attachCommandFields(log, logObject as any); - switch (logObject.name) { - case COMMAND_STARTED: - log.message = 'Command started'; - log.command = EJSON.stringify(logObject.command); - log.databaseName = logObject.databaseName; - break; - case COMMAND_SUCCEEDED: - log.message = 'Command succeeded'; - log.durationMS = logObject.duration; - log.reply = EJSON.stringify(logObject.reply); - break; - case COMMAND_FAILED: - log.message = 'Command failed'; - log.durationMS = logObject.duration; - log.failure = logObject.failure; - break; - } - } else if (CMAP_EVENTS.includes(logObject.name)) { - log = attachConnectionFields(log, logObject as ConnectionPoolMonitoringEvent); - switch (logObject.name) { - case CONNECTION_POOL_CREATED: - log.message = 'Connection pool created'; - if (logObject.options) { - const { maxIdleTimeMS, minPoolSize, maxPoolSize, maxConnecting, waitQueueTimeoutMS } = - logObject.options; - log = { - ...log, - maxIdleTimeMS, - minPoolSize, - maxPoolSize, - maxConnecting, - waitQueueTimeoutMS - }; - log.waitQueueSize = logObject.waitQueueSize; - } - break; - case CONNECTION_POOL_READY: - log.message = 'Connection pool ready'; - break; - case CONNECTION_POOL_CLEARED: - log.message = 'Connection pool cleared'; - if (logObject.serviceId?._bsontype === 'ObjectId') { - log.serviceId = logObject.serviceId.toHexString(); - } - break; - case CONNECTION_POOL_CLOSED: - log.message = 'Connection pool closed'; - break; - case CONNECTION_CREATED: - log.message = 'Connection created'; - log.driverConnectionId = logObject.connectionId; - break; - case CONNECTION_READY: - log.message = 'Connection ready'; - log.driverConnectionId = logObject.connectionId; - break; - case CONNECTION_CLOSED: - log.message = 'Connection closed'; + switch (logObject.name) { + case COMMAND_STARTED: + log = attachCommandFields(log, logObject); + log.message = 'Command started'; + log.command = EJSON.stringify(logObject.command); + log.databaseName = logObject.databaseName; + break; + case COMMAND_SUCCEEDED: + log = attachCommandFields(log, logObject); + log.message = 'Command succeeded'; + log.durationMS = logObject.duration; + log.reply = EJSON.stringify(logObject.reply); + break; + case COMMAND_FAILED: + log = attachCommandFields(log, logObject); + log.message = 'Command failed'; + log.durationMS = logObject.duration; + log.failure = logObject.failure; + break; + case CONNECTION_POOL_CREATED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection pool created'; + if (logObject.options) { + const { maxIdleTimeMS, minPoolSize, maxPoolSize, maxConnecting, waitQueueTimeoutMS } = + logObject.options; + log = { + ...log, + maxIdleTimeMS, + minPoolSize, + maxPoolSize, + maxConnecting, + waitQueueTimeoutMS + }; + log.waitQueueSize = logObject.waitQueueSize; + } + break; + case CONNECTION_POOL_READY: + log = attachConnectionFields(log, logObject); + log.message = 'Connection pool ready'; + break; + case CONNECTION_POOL_CLEARED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection pool cleared'; + if (logObject.serviceId?._bsontype === 'ObjectId') { + log.serviceId = logObject.serviceId.toHexString(); + } + break; + case CONNECTION_POOL_CLOSED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection pool closed'; + break; + case CONNECTION_CREATED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection created'; + if ('connectionId' in logObject) { log.driverConnectionId = logObject.connectionId; - switch (logObject.reason) { - case 'stale': - log.reason = 'Connection became stale because the pool was cleared'; - break; - case 'idle': - log.reason = - 'Connection has been available but unused for longer than the configured max idle time'; - break; - case 'error': - log.reason = 'An error occurred while using the connection'; - if (logObject.error) { - log.error = logObject.error; - } - break; - case 'poolClosed': - log.reason = 'Connection pool was closed'; - break; - default: - // Omit if we have some other reason as it would be invalid - } - break; - case CONNECTION_CHECK_OUT_STARTED: - log.message = 'Connection checkout started'; - break; - case CONNECTION_CHECK_OUT_FAILED: - log.message = 'Connection checkout failed'; - log.reason = logObject.reason; - break; - case CONNECTION_CHECKED_OUT: - log.message = 'Connection checked out'; + } + break; + case CONNECTION_READY: + log = attachConnectionFields(log, logObject); + log.message = 'Connection ready'; + if ('connectionId' in logObject) { log.driverConnectionId = logObject.connectionId; - break; - case CONNECTION_CHECKED_IN: - log.message = 'Connection checked in'; + } + break; + case CONNECTION_CLOSED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection closed'; + if ('connectionId' in logObject) { log.driverConnectionId = logObject.connectionId; - break; - } - } else { - for (const [key, value] of Object.entries(logObject)) { - if (value != null) log[key] = value; - } + } + switch (logObject.reason) { + case 'stale': + log.reason = 'Connection became stale because the pool was cleared'; + break; + case 'idle': + log.reason = + 'Connection has been available but unused for longer than the configured max idle time'; + break; + case 'error': + log.reason = 'An error occurred while using the connection'; + if (logObject.error) { + log.error = logObject.error; + } + break; + case 'poolClosed': + log.reason = 'Connection pool was closed'; + break; + default: + // Omit if we have some other reason as it would be invalid + } + break; + case CONNECTION_CHECK_OUT_STARTED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection checkout started'; + break; + case CONNECTION_CHECK_OUT_FAILED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection checkout failed'; + log.reason = logObject.reason; + break; + case CONNECTION_CHECKED_OUT: + log = attachConnectionFields(log, logObject); + log.message = 'Connection checked out'; + log.driverConnectionId = logObject.connectionId; + break; + case CONNECTION_CHECKED_IN: + log = attachConnectionFields(log, logObject); + log.message = 'Connection checked in'; + log.driverConnectionId = logObject.connectionId; + break; + default: + for (const [key, value] of Object.entries(logObject)) { + if (value != null) log[key] = value; + } } return log; } diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 1d841fb63e..ce8354f64d 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -386,10 +386,16 @@ describe('class MongoLogger', function () { }); context('logDestination', function () { - let stdout; - let stderr; + let stdoutStub; + let stderrStub; + let streamStub; let validOptions: Map; - const stream = new Writable(); + const stream: { write: (log: Log) => void; buffer: Log[] } = { + write(log: Log): void { + this.buffer.push(log); + }, + buffer: [] + }; const unsetOptions = ['', undefined]; const invalidEnvironmentOptions = ['non-acceptable-string']; const invalidClientOptions = ['', ' ', undefined, null, 0, false, new Readable()]; @@ -397,14 +403,15 @@ describe('class MongoLogger', function () { const validEnvironmentOptions = ['stderr', 'stdout', 'stdOut', 'stdErr']; beforeEach(function () { - stdout = sinon.stub(process.stdout); - stderr = sinon.stub(process.stderr); + stdoutStub = sinon.stub(process.stdout); + stderrStub = sinon.stub(process.stderr); + streamStub = sinon.stub(stream); validOptions = new Map([ - ['stdout', stdout], - ['stderr', stderr], - [stream, stream], - ['stdOut', stdout], - ['stdErr', stderr] + ['stdout', stdoutStub], + ['stderr', stderrStub], + [stream, streamStub], + ['stdOut', stdoutStub], + ['stdErr', stderrStub] ] as Array<[any, MongoDBLogWritable]>); }); @@ -427,7 +434,7 @@ describe('class MongoLogger', function () { const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; options.logDestination.write(log); - expect(stderr.write).to.have.been.calledOnceWith( + expect(stderrStub.write).to.have.been.calledOnceWith( inspect(log, { breakLength: Infinity, compact: true }) ); }); @@ -449,7 +456,7 @@ describe('class MongoLogger', function () { const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; options.logDestination.write(log); - expect(stderr.write).to.have.been.calledOnceWith( + expect(stderrStub.write).to.have.been.calledOnceWith( inspect(log, { breakLength: Infinity, compact: true }) ); }); @@ -460,7 +467,7 @@ describe('class MongoLogger', function () { context('when mongodbLogPath is a valid client option', function () { for (const unsetEnvironmentOption of unsetOptions) { for (const validOption of validClientOptions) { - it.skip(`{environment: "${unsetEnvironmentOption}", client: "${validOption}"} uses the value from the client options`, function () { + it(`{environment: "${unsetEnvironmentOption}", client: "${validOption}"} uses the value from the client options`, function () { const options = MongoLogger.resolveOptions( { MONGODB_LOG_PATH: unsetEnvironmentOption, @@ -471,16 +478,8 @@ describe('class MongoLogger', function () { const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; options.logDestination.write(log); - const correctDestination = validOptions.get(validOption); - if (correctDestination === stdout || correctDestination === stderr) { - expect(correctDestination?.write).to.have.been.calledOnceWith( - inspect(log, { breakLength: Infinity, compact: true }) - ); - } else { - expect(correctDestination?.write).to.have.been.calledOnceWith(log); - } - //expect(options.logDestination).to.equal(correctDestination); + expect(correctDestination?.write).to.have.been.calledOnce; }); } } @@ -504,7 +503,7 @@ describe('class MongoLogger', function () { const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; options.logDestination.write(log); - expect(stderr.write).to.have.been.calledOnceWith( + expect(stderrStub.write).to.have.been.calledOnceWith( inspect(log, { breakLength: Infinity, compact: true }) ); }); @@ -528,7 +527,7 @@ describe('class MongoLogger', function () { const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; options.logDestination.write(log); - expect(stderr.write).to.have.been.calledOnceWith( + expect(stderrStub.write).to.have.been.calledOnceWith( inspect(log, { breakLength: Infinity, compact: true }) ); }); @@ -549,7 +548,9 @@ describe('class MongoLogger', function () { { mongodbLogPath: validOption as any } ); const correctDestination = validOptions.get(validOption); - expect(options.logDestination).to.deep.equal(correctDestination); + const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; + options.logDestination.write(log); + expect(correctDestination?.write).to.have.been.calledOnce; }); } } @@ -570,9 +571,9 @@ describe('class MongoLogger', function () { { mongodbLogPath: unsetOption as any } ); const correctDestination = validOptions.get(validEnvironmentOption); - expect(options.logDestination.write.toString()).to.equal( - correctDestination?.write.toString() - ); + options.logDestination.write({ t: new Date(), c: 'command', s: 'emergency' }); + + expect(correctDestination?.write).to.have.been.calledOnce; }); } } @@ -583,7 +584,7 @@ describe('class MongoLogger', function () { function () { for (const validEnvironmentOption of validEnvironmentOptions) { for (const invalidValue of invalidClientOptions) { - it.only(`{environment: "${validEnvironmentOption}", client: "${invalidValue}"} uses process.${validEnvironmentOption}`, function () { + it(`{environment: "${validEnvironmentOption}", client: "${invalidValue}"} uses process.${validEnvironmentOption}`, function () { const options = MongoLogger.resolveOptions( { MONGODB_LOG_PATH: validEnvironmentOption, @@ -593,24 +594,10 @@ describe('class MongoLogger', function () { ); const correctDestination = validOptions.get(validEnvironmentOption); + const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; + options.logDestination.write(log); - if (validEnvironmentOption.toLowerCase() === 'stderr') { - const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; - options.logDestination.write(log); - expect(stderr.write).to.have.been.calledOnceWith( - inspect(log, { breakLength: Infinity, compact: true }) - ); - } else if (validEnvironmentOption.toLowerCase() === 'stdout') { - const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; - options.logDestination.write(log); - expect(stdout.write).to.have.been.calledOnceWith( - inspect(log, { breakLength: Infinity, compact: true }) - ); - } else { - expect(options.logDestination.write.toString()).to.equal( - correctDestination?.write.toString() - ); - } + expect(correctDestination?.write).to.have.been.calledOnce; }); } } @@ -633,11 +620,8 @@ describe('class MongoLogger', function () { { mongodbLogPath: validValue as any } ); const correctDestination = validOptions.get(validValue); - // NOTE: here we are checking if we set the write function correctly - // Deep and shallow equality do not work for functions - expect(options.logDestination.write.toString()).to.equal( - correctDestination?.write.toString() - ); + options.logDestination.write({ t: new Date(), c: 'command', s: 'emergency' }); + expect(correctDestination?.write).to.have.been.calledOnce; }); } } From 3e262c01e62f2e133c3cdeb676a42e348ed6f093 Mon Sep 17 00:00:00 2001 From: Warren James Date: Tue, 11 Apr 2023 15:40:07 -0400 Subject: [PATCH 30/39] refactor(NODE-5169): Export appropriate constants --- src/constants.ts | 11 +++++++++++ src/index.ts | 15 ++++++++++++++- 2 files changed, 25 insertions(+), 1 deletion(-) diff --git a/src/constants.ts b/src/constants.ts index eec4b07571..23cbe5edf3 100644 --- a/src/constants.ts +++ b/src/constants.ts @@ -23,16 +23,27 @@ export const SERVER_DESCRIPTION_CHANGED = 'serverDescriptionChanged' as const; export const TOPOLOGY_OPENING = 'topologyOpening' as const; export const TOPOLOGY_CLOSED = 'topologyClosed' as const; export const TOPOLOGY_DESCRIPTION_CHANGED = 'topologyDescriptionChanged' as const; +/** @public */ export const CONNECTION_POOL_CREATED = 'connectionPoolCreated' as const; +/** @public */ export const CONNECTION_POOL_CLOSED = 'connectionPoolClosed' as const; +/** @public */ export const CONNECTION_POOL_CLEARED = 'connectionPoolCleared' as const; +/** @public */ export const CONNECTION_POOL_READY = 'connectionPoolReady' as const; +/** @public */ export const CONNECTION_CREATED = 'connectionCreated' as const; +/** @public */ export const CONNECTION_READY = 'connectionReady' as const; +/** @public */ export const CONNECTION_CLOSED = 'connectionClosed' as const; +/** @public */ export const CONNECTION_CHECK_OUT_STARTED = 'connectionCheckOutStarted' as const; +/** @public */ export const CONNECTION_CHECK_OUT_FAILED = 'connectionCheckOutFailed' as const; +/** @public */ export const CONNECTION_CHECKED_OUT = 'connectionCheckedOut' as const; +/** @public */ export const CONNECTION_CHECKED_IN = 'connectionCheckedIn' as const; export const CLUSTER_TIME_RECEIVED = 'clusterTimeReceived' as const; export const COMMAND_STARTED = 'commandStarted' as const; diff --git a/src/index.ts b/src/index.ts index 0c414d02c2..58a36b311c 100644 --- a/src/index.ts +++ b/src/index.ts @@ -247,7 +247,20 @@ export type { ConnectionPoolMetrics } from './cmap/metrics'; export type { StreamDescription, StreamDescriptionOptions } from './cmap/stream_description'; export type { CompressorName } from './cmap/wire_protocol/compression'; export type { CollectionOptions, CollectionPrivate, ModifyResult } from './collection'; -export type { MONGO_CLIENT_EVENTS } from './constants'; +export type { + CONNECTION_CHECK_OUT_FAILED, + CONNECTION_CHECK_OUT_STARTED, + CONNECTION_CHECKED_IN, + CONNECTION_CHECKED_OUT, + CONNECTION_CLOSED, + CONNECTION_CREATED, + CONNECTION_POOL_CLEARED, + CONNECTION_POOL_CLOSED, + CONNECTION_POOL_CREATED, + CONNECTION_POOL_READY, + CONNECTION_READY, + MONGO_CLIENT_EVENTS +} from './constants'; export type { AbstractCursorEvents, AbstractCursorOptions, From 18ed1e8c1d1946a58f0fce0154f873df38f6892d Mon Sep 17 00:00:00 2001 From: Warren James Date: Tue, 11 Apr 2023 17:02:43 -0400 Subject: [PATCH 31/39] refactor(NODE-5169): Address review comments --- src/cmap/connection_pool_events.ts | 6 +- src/index.ts | 2 +- src/mongo_logger.ts | 117 ++++++++++++---------------- src/utils.ts | 10 +++ test/unit/connection_string.test.ts | 3 +- test/unit/index.test.ts | 1 + test/unit/mongo_logger.test.ts | 10 +-- 7 files changed, 71 insertions(+), 78 deletions(-) diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index 39a96f63d7..67880ca583 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -137,10 +137,10 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; /** The reason the connection was closed */ - reason: 'idle' | 'stale' | 'poolClosed' | 'error'; + reason: string; serviceId?: ObjectId; name = CONNECTION_CLOSED; - error: Error | undefined; + error: AnyError | null; /** @internal */ constructor( @@ -153,7 +153,7 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { this.connectionId = connection.id; this.reason = reason; this.serviceId = connection.serviceId; - this.error = error; + this.error = error ?? null; } } diff --git a/src/index.ts b/src/index.ts index 58a36b311c..cd291daa92 100644 --- a/src/index.ts +++ b/src/index.ts @@ -314,7 +314,7 @@ export type { MongoLoggerOptions, SeverityLevel } from './mongo_logger'; -export { createStdLogger } from './mongo_logger'; +export { createStdioLogger } from './mongo_logger'; export type { CommonEvents, EventsDescription, diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 4de179666e..7ac1368011 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -170,7 +170,7 @@ type ClientLogPathOptions = { }; /** @internal */ -export function createStdLogger(stream: { +export function createStdioLogger(stream: { write: NodeJS.WriteStream['write']; }): MongoDBLogWritable { return { @@ -191,23 +191,25 @@ function resolveLogPath( { MONGODB_LOG_PATH }: MongoLoggerEnvOptions, { mongodbLogPath }: ClientLogPathOptions ): MongoDBLogWritable { - if (typeof mongodbLogPath === 'string' && /^stderr$/i.test(mongodbLogPath)) - return createStdLogger(process.stderr); - if (typeof mongodbLogPath === 'string' && /^stdout$/i.test(mongodbLogPath)) - return createStdLogger(process.stdout); + if (typeof mongodbLogPath === 'string' && /^stderr$/i.test(mongodbLogPath)) { + return createStdioLogger(process.stderr); + } + if (typeof mongodbLogPath === 'string' && /^stdout$/i.test(mongodbLogPath)) { + return createStdioLogger(process.stdout); + } if (typeof mongodbLogPath === 'object' && typeof mongodbLogPath?.write === 'function') { return mongodbLogPath; } if (MONGODB_LOG_PATH && /^stderr$/i.test(MONGODB_LOG_PATH)) { - return createStdLogger(process.stderr); + return createStdioLogger(process.stderr); } if (MONGODB_LOG_PATH && /^stdout$/i.test(MONGODB_LOG_PATH)) { - return createStdLogger(process.stdout); + return createStdioLogger(process.stdout); } - return createStdLogger(process.stderr); + return createStdioLogger(process.stderr); } /** @internal */ @@ -220,7 +222,7 @@ export interface Log extends Record { /** @internal */ export interface MongoDBLogWritable { - write(log: Log): unknown; + write(log: Log): void; } function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { @@ -232,7 +234,6 @@ function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { /** @internal */ export type LoggableEvent = - //| ConnectionPoolMonitoringEvent | CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent @@ -262,45 +263,35 @@ function isLogConvertible(obj: Loggable): obj is LogConvertible { return objAsLogConvertible.toLog !== undefined && typeof objAsLogConvertible.toLog === 'function'; } -function getHostPort(address: string): { host: string; port: number } { - const hostAddress = new HostAddress(address); - - // NOTE: Should only default when the address is a socket address - if (hostAddress.socketPath) { - return { host: hostAddress.socketPath, port: 0 }; - } - - const host = hostAddress.host ?? ''; - const port = hostAddress.port ?? 0; - return { host, port }; -} - function attachCommandFields( - l: any, - ev: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent + log: Record, + commandEvent: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent ) { - l.commandName = ev.commandName; - l.requestId = ev.requestId; - l.driverConnectionId = ev?.connectionId; - const { host, port } = getHostPort(ev.address); - l.serverHost = host; - l.serverPort = port; - if (ev?.serviceId) { - l.serviceId = ev.serviceId.toHexString(); + log.commandName = commandEvent.commandName; + log.requestId = commandEvent.requestId; + 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(); } - return l; + return log; } -function attachConnectionFields(l: any, ev: ConnectionPoolMonitoringEvent) { - const { host, port } = getHostPort(ev.address); - l.serverHost = host; - l.serverPort = port; +function attachConnectionFields( + log: Record, + connectionPoolEvent: ConnectionPoolMonitoringEvent +) { + const { host, port } = HostAddress.fromString(connectionPoolEvent.address).toHostPort(); + log.serverHost = host; + log.serverPort = port; - return l; + return log; } -function DEFAULT_LOG_TRANSFORM(logObject: LoggableEvent): Omit { +function defaultLogTransform(logObject: LoggableEvent): Omit { let log: Omit = Object.create(null); switch (logObject.name) { @@ -309,19 +300,19 @@ function DEFAULT_LOG_TRANSFORM(logObject: LoggableEvent): Omit { it('should be stored in the FEATURE_FLAGS Set', () => { - expect(FEATURE_FLAGS.size).to.equal(2); + expect(FEATURE_FLAGS.size).to.equal(3); expect(FEATURE_FLAGS.has(Symbol.for('@@mdb.skipPingOnConnect'))).to.be.true; expect(FEATURE_FLAGS.has(Symbol.for('@@mdb.enableMongoLogger'))).to.be.true; + expect(FEATURE_FLAGS.has(Symbol.for('@@mdb.internalLoggerConfig'))).to.be.true; // Add more flags here }); diff --git a/test/unit/index.test.ts b/test/unit/index.test.ts index 833082b983..85d25c7bab 100644 --- a/test/unit/index.test.ts +++ b/test/unit/index.test.ts @@ -46,6 +46,7 @@ const EXPECTED_EXPORTS = [ 'ConnectionPoolMonitoringEvent', 'ConnectionPoolReadyEvent', 'ConnectionReadyEvent', + 'createStdioLogger', 'CURSOR_FLAGS', 'Db', 'DBRef', diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index ce8354f64d..bc7e111771 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -1014,9 +1014,6 @@ describe('class MongoLogger', function () { it('emits a log with field `waitQueueTimeoutMS` that is a number', function () { expect(log).to.have.property('waitQueueTimeoutMS').that.is.a('number'); }); - it('emits a log with field `waitQueueSize` that is a number', function () { - expect(log).to.have.property('waitQueueSize').that.is.a('number'); - }); }); context('when ConnectionPoolReadyEvent is logged', function () { @@ -1197,7 +1194,7 @@ describe('class MongoLogger', function () { }); } - context('with invalid reason', function () { + context('with unknown reason', function () { beforeEach(function () { logger[severityLevel]('connection', { ...connectionClosed, reason: 'woops' }); expect(stream.buffer).to.have.lengthOf(1); @@ -1205,8 +1202,9 @@ describe('class MongoLogger', function () { }); commonConnectionComponentAssertions(); - it('emits a log without field `reason`', function () { - expect(log).to.not.have.property('reason'); + it('emits a log with field `reason` prefixed by "Unknown close reason: "', function () { + expect(log).to.have.property('reason'); + expect(log.reason).to.match(/^Unknown close reason: .*$/); }); }); }); From b76ba6de74074bc56544ca7f77b54ddd512e0da0 Mon Sep 17 00:00:00 2001 From: Warren James Date: Wed, 12 Apr 2023 09:34:22 -0400 Subject: [PATCH 32/39] fix(NODE-5169): Remove createdStdioLogger from export --- src/index.ts | 1 - test/unit/index.test.ts | 1 - 2 files changed, 2 deletions(-) diff --git a/src/index.ts b/src/index.ts index cd291daa92..a9b47beb64 100644 --- a/src/index.ts +++ b/src/index.ts @@ -314,7 +314,6 @@ export type { MongoLoggerOptions, SeverityLevel } from './mongo_logger'; -export { createStdioLogger } from './mongo_logger'; export type { CommonEvents, EventsDescription, diff --git a/test/unit/index.test.ts b/test/unit/index.test.ts index 85d25c7bab..833082b983 100644 --- a/test/unit/index.test.ts +++ b/test/unit/index.test.ts @@ -46,7 +46,6 @@ const EXPECTED_EXPORTS = [ 'ConnectionPoolMonitoringEvent', 'ConnectionPoolReadyEvent', 'ConnectionReadyEvent', - 'createStdioLogger', 'CURSOR_FLAGS', 'Db', 'DBRef', From 4db491370329885cba54af900173fd5697544b18 Mon Sep 17 00:00:00 2001 From: Warren James Date: Wed, 12 Apr 2023 11:58:43 -0400 Subject: [PATCH 33/39] refactor(NODE-5169): Addres review comments --- src/cmap/connect.ts | 1 + src/cmap/connection_pool.ts | 3 ++- src/cmap/connection_pool_events.ts | 9 +++------ 3 files changed, 6 insertions(+), 7 deletions(-) diff --git a/src/cmap/connect.ts b/src/cmap/connect.ts index 7b2866adf2..05ab9c73c4 100644 --- a/src/cmap/connect.ts +++ b/src/cmap/connect.ts @@ -400,6 +400,7 @@ function makeConnection(options: MakeConnectionOptions, _callback: Callback { this, { id: connectOptions.id, serviceId: undefined }, 'error', - err + // TODO(NODE-5192): Remove this cast + err as MongoError ) ); if (err instanceof MongoNetworkError || err instanceof MongoServerError) { diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index 67880ca583..7218fad1e4 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -12,7 +12,7 @@ import { CONNECTION_POOL_READY, CONNECTION_READY } from '../constants'; -import type { AnyError } from '../error'; +import type { AnyError, MongoError } from '../error'; import type { Connection } from './connection'; import type { ConnectionPool, ConnectionPoolOptions } from './connection_pool'; @@ -54,15 +54,12 @@ export abstract class ConnectionPoolMonitoringEvent { export class ConnectionPoolCreatedEvent extends ConnectionPoolMonitoringEvent { /** The options used to create this connection pool */ options?: ConnectionPoolOptions; - /** The size of the ConnectionPool's waitQueue */ - waitQueueSize: number; name = CONNECTION_POOL_CREATED; /** @internal */ constructor(pool: ConnectionPool) { super(pool); this.options = pool.options; - this.waitQueueSize = pool.waitQueueSize; } } @@ -140,14 +137,14 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { reason: string; serviceId?: ObjectId; name = CONNECTION_CLOSED; - error: AnyError | null; + error: MongoError | null; /** @internal */ constructor( pool: ConnectionPool, connection: Pick, reason: 'idle' | 'stale' | 'poolClosed' | 'error', - error?: AnyError + error?: MongoError ) { super(pool); this.connectionId = connection.id; From be04325efb078cc3c2f2c52459d3d572bf4c0529 Mon Sep 17 00:00:00 2001 From: Warren James Date: Wed, 12 Apr 2023 13:09:18 -0400 Subject: [PATCH 34/39] test(NODE-5169): remove unneeded test file --- .../command_logging.test.ts | 77 ------------------- 1 file changed, 77 deletions(-) delete mode 100644 test/integration/command-logging-and-monitoring/command_logging.test.ts diff --git a/test/integration/command-logging-and-monitoring/command_logging.test.ts b/test/integration/command-logging-and-monitoring/command_logging.test.ts deleted file mode 100644 index 3e65c4442d..0000000000 --- a/test/integration/command-logging-and-monitoring/command_logging.test.ts +++ /dev/null @@ -1,77 +0,0 @@ -import { expect } from 'chai'; -import * as process from 'process'; - -import { - CommandFailedEvent, - CommandStartedEvent, - CommandSucceededEvent, - Db, - Log, - MongoClient -} from '../../mongodb'; -import { setupDatabase } from '../shared'; - -describe('Command Logging', function () { - before(function () { - return setupDatabase(this.configuration); - }); - - const logDestination = { - buffer: [], - write(log: Log) { - this.buffer.push(log); - } - } as { buffer: any[]; write: (log: Log) => void }; - let client: MongoClient; - let db: Db; - //let coll: Collection; - - beforeEach(async function () { - client = new MongoClient( - process.env.MONGODB_URI as string, - { - monitorCommands: true, - [Symbol.for('@@mdb.internalLoggerConfig')]: { - MONGODB_LOG_ALL: 'emergency', - MONGODB_LOG_COMMAND: 'emergency' - }, - [Symbol.for('@@mdb.enableMongoLogger')]: true, - mongodbLogPath: logDestination - } as any - ); - await client.connect(); - db = client.db('command_logging'); - }); - - afterEach(async function () { - if (db) { - await db.dropDatabase(); - } - await client.close().catch(() => null); - }); - - context('sensitive commands', function () { - it('should redact sensitive commands', async function () { - const log = (ev: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent) => { - client.mongoLogger.emergency('command', ev); - }; - client.on('commandStarted', log); - client.on('commandSucceeded', log); - client.on('commandFailed', log); - - const result = await db.command({ hello: 1, speculativeAuthenticate: { saslStart: 1 } }); - expect(result).to.exist; - expect(logDestination.buffer).to.have.lengthOf(2); - - const commandStarted = logDestination.buffer[0]; - const commandSucceeded = logDestination.buffer[1]; - expect(commandStarted).to.exist; - expect(commandStarted).to.have.property('command', '{}'); - expect(commandStarted).to.have.property('message', 'Command started'); - - expect(commandSucceeded).to.exist; - expect(commandSucceeded).to.have.property('reply', '{}'); - expect(commandSucceeded).to.have.property('message', 'Command succeeded'); - }); - }); -}); From 57a643cc9ec156817c6674f7e8a30426d7f75479 Mon Sep 17 00:00:00 2001 From: Warren James Date: Thu, 13 Apr 2023 15:33:55 -0400 Subject: [PATCH 35/39] fix(NODE-5169): Addres review comments and fix ConnectionCheckOutFailed case --- src/cmap/command_monitoring_events.ts | 3 ++ src/cmap/connection_pool.ts | 8 +++-- src/cmap/connection_pool_events.ts | 24 +++++++++++++-- src/constants.ts | 22 +++++++------- src/mongo_logger.ts | 29 +++++++++++++----- test/unit/mongo_logger.test.ts | 44 +++++++++++++++++++++------ 6 files changed, 98 insertions(+), 32 deletions(-) diff --git a/src/cmap/command_monitoring_events.ts b/src/cmap/command_monitoring_events.ts index cfbab54990..fd12961a5e 100644 --- a/src/cmap/command_monitoring_events.ts +++ b/src/cmap/command_monitoring_events.ts @@ -24,6 +24,7 @@ export class CommandStartedEvent { address: string; connectionId?: string | number; serviceId?: ObjectId; + /** @internal */ name = COMMAND_STARTED; /** @@ -72,6 +73,7 @@ export class CommandSucceededEvent { commandName: string; reply: unknown; serviceId?: ObjectId; + /** @internal */ name = COMMAND_SUCCEEDED; /** @@ -121,6 +123,7 @@ export class CommandFailedEvent { commandName: string; failure: Error; serviceId?: ObjectId; + /** @internal */ name = COMMAND_FAILED; /** diff --git a/src/cmap/connection_pool.ts b/src/cmap/connection_pool.ts index 8498a11404..f006ec5866 100644 --- a/src/cmap/connection_pool.ts +++ b/src/cmap/connection_pool.ts @@ -821,7 +821,11 @@ export class ConnectionPool extends TypedEventEmitter { const error = this.closed ? new PoolClosedError(this) : new PoolClearedError(this); this.emit( ConnectionPool.CONNECTION_CHECK_OUT_FAILED, - new ConnectionCheckOutFailedEvent(this, reason) + new ConnectionCheckOutFailedEvent( + this, + reason, + reason === 'connectionError' ? error : undefined + ) ); if (waitQueueMember.timer) { clearTimeout(waitQueueMember.timer); @@ -874,7 +878,7 @@ export class ConnectionPool extends TypedEventEmitter { if (err) { this.emit( ConnectionPool.CONNECTION_CHECK_OUT_FAILED, - new ConnectionCheckOutFailedEvent(this, 'connectionError') + new ConnectionCheckOutFailedEvent(this, 'connectionError', err) ); } else if (connection) { this[kCheckedOut].add(connection); diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index 7218fad1e4..081aceeb9d 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -26,6 +26,7 @@ export abstract class ConnectionPoolMonitoringEvent { time: Date; /** The address (host/port pair) of the pool */ address: string; + /** @internal */ abstract name: | typeof CONNECTION_CHECK_OUT_FAILED | typeof CONNECTION_CHECK_OUT_STARTED @@ -54,6 +55,7 @@ export abstract class ConnectionPoolMonitoringEvent { export class ConnectionPoolCreatedEvent extends ConnectionPoolMonitoringEvent { /** The options used to create this connection pool */ options?: ConnectionPoolOptions; + /** @internal */ name = CONNECTION_POOL_CREATED; /** @internal */ @@ -69,6 +71,7 @@ export class ConnectionPoolCreatedEvent extends ConnectionPoolMonitoringEvent { * @category Event */ export class ConnectionPoolReadyEvent extends ConnectionPoolMonitoringEvent { + /** @internal */ name = CONNECTION_POOL_READY; /** @internal */ @@ -83,6 +86,7 @@ export class ConnectionPoolReadyEvent extends ConnectionPoolMonitoringEvent { * @category Event */ export class ConnectionPoolClosedEvent extends ConnectionPoolMonitoringEvent { + /** @internal */ name = CONNECTION_POOL_CLOSED; /** @internal */ @@ -99,6 +103,7 @@ export class ConnectionPoolClosedEvent extends ConnectionPoolMonitoringEvent { export class ConnectionCreatedEvent extends ConnectionPoolMonitoringEvent { /** A monotonically increasing, per-pool id for the newly created connection */ connectionId: number | ''; + /** @internal */ name = CONNECTION_CREATED; /** @internal */ @@ -116,6 +121,7 @@ export class ConnectionCreatedEvent extends ConnectionPoolMonitoringEvent { export class ConnectionReadyEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; + /** @internal */ name = CONNECTION_READY; /** @internal */ @@ -136,7 +142,9 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { /** The reason the connection was closed */ reason: string; serviceId?: ObjectId; + /** @internal */ name = CONNECTION_CLOSED; + /** @internal */ error: MongoError | null; /** @internal */ @@ -160,6 +168,7 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { * @category Event */ export class ConnectionCheckOutStartedEvent extends ConnectionPoolMonitoringEvent { + /** @internal */ name = CONNECTION_CHECK_OUT_STARTED; /** @internal */ @@ -175,13 +184,21 @@ export class ConnectionCheckOutStartedEvent extends ConnectionPoolMonitoringEven */ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent { /** The reason the attempt to check out failed */ - reason: AnyError | string; + reason: string; + /** @internal */ + error?: AnyError; + /** @internal */ name = CONNECTION_CHECK_OUT_FAILED; /** @internal */ - constructor(pool: ConnectionPool, reason: AnyError | string) { + constructor( + pool: ConnectionPool, + reason: 'poolClosed' | 'timeout' | 'connectionError', + error?: AnyError + ) { super(pool); this.reason = reason; + this.error = error; } } @@ -193,6 +210,7 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; + /** @internal */ name = CONNECTION_CHECKED_OUT; /** @internal */ @@ -210,6 +228,7 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { export class ConnectionCheckedInEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; + /** @internal */ name = CONNECTION_CHECKED_IN; /** @internal */ @@ -229,6 +248,7 @@ export class ConnectionPoolClearedEvent extends ConnectionPoolMonitoringEvent { serviceId?: ObjectId; interruptInUseConnections?: boolean; + /** @internal */ name = CONNECTION_POOL_CLEARED; /** @internal */ diff --git a/src/constants.ts b/src/constants.ts index 23cbe5edf3..e3da4efaae 100644 --- a/src/constants.ts +++ b/src/constants.ts @@ -23,27 +23,27 @@ export const SERVER_DESCRIPTION_CHANGED = 'serverDescriptionChanged' as const; export const TOPOLOGY_OPENING = 'topologyOpening' as const; export const TOPOLOGY_CLOSED = 'topologyClosed' as const; export const TOPOLOGY_DESCRIPTION_CHANGED = 'topologyDescriptionChanged' as const; -/** @public */ +/** @internal */ export const CONNECTION_POOL_CREATED = 'connectionPoolCreated' as const; -/** @public */ +/** @internal */ export const CONNECTION_POOL_CLOSED = 'connectionPoolClosed' as const; -/** @public */ +/** @internal */ export const CONNECTION_POOL_CLEARED = 'connectionPoolCleared' as const; -/** @public */ +/** @internal */ export const CONNECTION_POOL_READY = 'connectionPoolReady' as const; -/** @public */ +/** @internal */ export const CONNECTION_CREATED = 'connectionCreated' as const; -/** @public */ +/** @internal */ export const CONNECTION_READY = 'connectionReady' as const; -/** @public */ +/** @internal */ export const CONNECTION_CLOSED = 'connectionClosed' as const; -/** @public */ +/** @internal */ export const CONNECTION_CHECK_OUT_STARTED = 'connectionCheckOutStarted' as const; -/** @public */ +/** @internal */ export const CONNECTION_CHECK_OUT_FAILED = 'connectionCheckOutFailed' as const; -/** @public */ +/** @internal */ export const CONNECTION_CHECKED_OUT = 'connectionCheckedOut' as const; -/** @public */ +/** @internal */ export const CONNECTION_CHECKED_IN = 'connectionCheckedIn' as const; export const CLUSTER_TIME_RECEIVED = 'clusterTimeReceived' as const; export const COMMAND_STARTED = 'commandStarted' as const; diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 7ac1368011..018fa581e7 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -165,10 +165,6 @@ function parseSeverityFromString(s?: string): SeverityLevel | null { return null; } -type ClientLogPathOptions = { - mongodbLogPath?: string | Writable | MongoDBLogWritable; -}; - /** @internal */ export function createStdioLogger(stream: { write: NodeJS.WriteStream['write']; @@ -183,13 +179,14 @@ export function createStdioLogger(stream: { /** * resolves the MONGODB_LOG_PATH and mongodbLogPath options from the environment and the - * mongo client options respectively. + * mongo client options respectively. The mongodbLogPath can be either 'stdout', 'stderr', a NodeJS + * Writable or an object which has a `write` method with the signature (log: Log) => void * - * @returns the Writable stream to write logs to + * @returns the MongoDBLogWritable object to write logs to */ function resolveLogPath( { MONGODB_LOG_PATH }: MongoLoggerEnvOptions, - { mongodbLogPath }: ClientLogPathOptions + { mongodbLogPath }: { mongodbLogPath?: string | Writable | MongoDBLogWritable } ): MongoDBLogWritable { if (typeof mongodbLogPath === 'string' && /^stderr$/i.test(mongodbLogPath)) { return createStdioLogger(process.stderr); @@ -386,11 +383,27 @@ function defaultLogTransform(logObject: LoggableEvent): Omit Date: Fri, 14 Apr 2023 10:49:38 -0400 Subject: [PATCH 36/39] fix(NODE-5169): update signature --- src/mongo_logger.ts | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 018fa581e7..088ccc221d 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -180,13 +180,16 @@ export function createStdioLogger(stream: { /** * resolves the MONGODB_LOG_PATH and mongodbLogPath options from the environment and the * mongo client options respectively. The mongodbLogPath can be either 'stdout', 'stderr', a NodeJS - * Writable or an object which has a `write` method with the signature (log: Log) => void + * Writable or an object which has a `write` method with the signature: + * ```ts + * write(log: Log): void + * ``` * * @returns the MongoDBLogWritable object to write logs to */ function resolveLogPath( { MONGODB_LOG_PATH }: MongoLoggerEnvOptions, - { mongodbLogPath }: { mongodbLogPath?: string | Writable | MongoDBLogWritable } + { mongodbLogPath }: { mongodbLogPath?: string | Writable | MongoDBLogWritable } ): MongoDBLogWritable { if (typeof mongodbLogPath === 'string' && /^stderr$/i.test(mongodbLogPath)) { return createStdioLogger(process.stderr); From f258901d8464158122f85b64f6ddbb1dd264355d Mon Sep 17 00:00:00 2001 From: Warren James Date: Fri, 14 Apr 2023 10:54:42 -0400 Subject: [PATCH 37/39] fix(NODE-5169): convert to MongoError --- src/cmap/connection_pool.ts | 5 +++-- src/cmap/connection_pool_events.ts | 4 ++-- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/src/cmap/connection_pool.ts b/src/cmap/connection_pool.ts index f006ec5866..1d1ae529ca 100644 --- a/src/cmap/connection_pool.ts +++ b/src/cmap/connection_pool.ts @@ -824,7 +824,7 @@ export class ConnectionPool extends TypedEventEmitter { new ConnectionCheckOutFailedEvent( this, reason, - reason === 'connectionError' ? error : undefined + error ) ); if (waitQueueMember.timer) { @@ -878,7 +878,8 @@ export class ConnectionPool extends TypedEventEmitter { if (err) { this.emit( ConnectionPool.CONNECTION_CHECK_OUT_FAILED, - new ConnectionCheckOutFailedEvent(this, 'connectionError', err) + // TODO(NODE-5192): Remove this cast + new ConnectionCheckOutFailedEvent(this, 'connectionError', err as MongoError) ); } else if (connection) { this[kCheckedOut].add(connection); diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index 081aceeb9d..d14d137797 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -186,7 +186,7 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent /** The reason the attempt to check out failed */ reason: string; /** @internal */ - error?: AnyError; + error?: MongoError; /** @internal */ name = CONNECTION_CHECK_OUT_FAILED; @@ -194,7 +194,7 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent constructor( pool: ConnectionPool, reason: 'poolClosed' | 'timeout' | 'connectionError', - error?: AnyError + error?: MongoError ) { super(pool); this.reason = reason; From 442557bf32e95bae606d7ff6cf9621b09006cda0 Mon Sep 17 00:00:00 2001 From: Warren James Date: Fri, 14 Apr 2023 10:57:27 -0400 Subject: [PATCH 38/39] style(NODE-5169): eslint --- src/cmap/connection_pool.ts | 6 +----- src/cmap/connection_pool_events.ts | 2 +- 2 files changed, 2 insertions(+), 6 deletions(-) diff --git a/src/cmap/connection_pool.ts b/src/cmap/connection_pool.ts index 1d1ae529ca..01feb78fdd 100644 --- a/src/cmap/connection_pool.ts +++ b/src/cmap/connection_pool.ts @@ -821,11 +821,7 @@ export class ConnectionPool extends TypedEventEmitter { const error = this.closed ? new PoolClosedError(this) : new PoolClearedError(this); this.emit( ConnectionPool.CONNECTION_CHECK_OUT_FAILED, - new ConnectionCheckOutFailedEvent( - this, - reason, - error - ) + new ConnectionCheckOutFailedEvent(this, reason, error) ); if (waitQueueMember.timer) { clearTimeout(waitQueueMember.timer); diff --git a/src/cmap/connection_pool_events.ts b/src/cmap/connection_pool_events.ts index d14d137797..4c90444133 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -12,7 +12,7 @@ import { CONNECTION_POOL_READY, CONNECTION_READY } from '../constants'; -import type { AnyError, MongoError } from '../error'; +import type { MongoError } from '../error'; import type { Connection } from './connection'; import type { ConnectionPool, ConnectionPoolOptions } from './connection_pool'; From dd66ea35f6ba6e4067bbd083805bd65031457ec5 Mon Sep 17 00:00:00 2001 From: Warren James Date: Fri, 14 Apr 2023 14:08:43 -0400 Subject: [PATCH 39/39] refactor(NODE-5169): update function signature --- src/mongo_logger.ts | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 088ccc221d..40102ed550 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -291,7 +291,9 @@ function attachConnectionFields( return log; } -function defaultLogTransform(logObject: LoggableEvent): Omit { +function defaultLogTransform( + logObject: LoggableEvent | Record +): Omit { let log: Omit = Object.create(null); switch (logObject.name) {