diff --git a/src/cmap/command_monitoring_events.ts b/src/cmap/command_monitoring_events.ts index 229ef98e5b..fd12961a5e 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,8 @@ export class CommandStartedEvent { address: string; connectionId?: string | number; serviceId?: ObjectId; + /** @internal */ + name = COMMAND_STARTED; /** * Create a started event @@ -65,6 +73,8 @@ export class CommandSucceededEvent { commandName: string; reply: unknown; serviceId?: ObjectId; + /** @internal */ + name = COMMAND_SUCCEEDED; /** * Create a succeeded event @@ -113,6 +123,8 @@ export class CommandFailedEvent { commandName: string; failure: Error; serviceId?: ObjectId; + /** @internal */ + name = COMMAND_FAILED; /** * Create a failure event diff --git a/src/cmap/connect.ts b/src/cmap/connect.ts index 7789527f9d..6c89fdcd88 100644 --- a/src/cmap/connect.ts +++ b/src/cmap/connect.ts @@ -401,6 +401,7 @@ function makeConnection(options: MakeConnectionOptions, _callback: Callback { } } - 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) @@ -701,7 +704,13 @@ 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', + // TODO(NODE-5192): Remove this cast + err as MongoError + ) ); if (err instanceof MongoNetworkError || err instanceof MongoServerError) { err.connectionGeneration = connectOptions.generation; @@ -812,7 +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) + new ConnectionCheckOutFailedEvent(this, reason, error) ); if (waitQueueMember.timer) { clearTimeout(waitQueueMember.timer); @@ -865,7 +874,8 @@ export class ConnectionPool extends TypedEventEmitter { if (err) { this.emit( ConnectionPool.CONNECTION_CHECK_OUT_FAILED, - new ConnectionCheckOutFailedEvent(this, 'connectionError') + // 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 0f56bf6bbb..4c90444133 100644 --- a/src/cmap/connection_pool_events.ts +++ b/src/cmap/connection_pool_events.ts @@ -1,5 +1,18 @@ import type { ObjectId } from '../bson'; -import type { AnyError } from '../error'; +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 { MongoError } from '../error'; import type { Connection } from './connection'; import type { ConnectionPool, ConnectionPoolOptions } from './connection_pool'; @@ -8,11 +21,24 @@ 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; + /** @internal */ + 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) { @@ -29,6 +55,8 @@ export class ConnectionPoolMonitoringEvent { export class ConnectionPoolCreatedEvent extends ConnectionPoolMonitoringEvent { /** The options used to create this connection pool */ options?: ConnectionPoolOptions; + /** @internal */ + name = CONNECTION_POOL_CREATED; /** @internal */ constructor(pool: ConnectionPool) { @@ -43,6 +71,9 @@ export class ConnectionPoolCreatedEvent extends ConnectionPoolMonitoringEvent { * @category Event */ export class ConnectionPoolReadyEvent extends ConnectionPoolMonitoringEvent { + /** @internal */ + name = CONNECTION_POOL_READY; + /** @internal */ constructor(pool: ConnectionPool) { super(pool); @@ -55,6 +86,9 @@ export class ConnectionPoolReadyEvent extends ConnectionPoolMonitoringEvent { * @category Event */ export class ConnectionPoolClosedEvent extends ConnectionPoolMonitoringEvent { + /** @internal */ + name = CONNECTION_POOL_CLOSED; + /** @internal */ constructor(pool: ConnectionPool) { super(pool); @@ -69,6 +103,8 @@ 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 */ constructor(pool: ConnectionPool, connection: { id: number | '' }) { @@ -85,6 +121,8 @@ export class ConnectionCreatedEvent extends ConnectionPoolMonitoringEvent { export class ConnectionReadyEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; + /** @internal */ + name = CONNECTION_READY; /** @internal */ constructor(pool: ConnectionPool, connection: Connection) { @@ -104,17 +142,23 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { /** The reason the connection was closed */ reason: string; serviceId?: ObjectId; + /** @internal */ + name = CONNECTION_CLOSED; + /** @internal */ + error: MongoError | null; /** @internal */ constructor( pool: ConnectionPool, connection: Pick, - reason: string + 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 ?? null; } } @@ -124,6 +168,9 @@ export class ConnectionClosedEvent extends ConnectionPoolMonitoringEvent { * @category Event */ export class ConnectionCheckOutStartedEvent extends ConnectionPoolMonitoringEvent { + /** @internal */ + name = CONNECTION_CHECK_OUT_STARTED; + /** @internal */ constructor(pool: ConnectionPool) { super(pool); @@ -137,12 +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?: MongoError; + /** @internal */ + name = CONNECTION_CHECK_OUT_FAILED; /** @internal */ - constructor(pool: ConnectionPool, reason: AnyError | string) { + constructor( + pool: ConnectionPool, + reason: 'poolClosed' | 'timeout' | 'connectionError', + error?: MongoError + ) { super(pool); this.reason = reason; + this.error = error; } } @@ -154,6 +210,8 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; + /** @internal */ + name = CONNECTION_CHECKED_OUT; /** @internal */ constructor(pool: ConnectionPool, connection: Connection) { @@ -170,6 +228,8 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent { export class ConnectionCheckedInEvent extends ConnectionPoolMonitoringEvent { /** The id of the connection */ connectionId: number | ''; + /** @internal */ + name = CONNECTION_CHECKED_IN; /** @internal */ constructor(pool: ConnectionPool, connection: Connection) { @@ -188,6 +248,8 @@ export class ConnectionPoolClearedEvent extends ConnectionPoolMonitoringEvent { serviceId?: ObjectId; interruptInUseConnections?: boolean; + /** @internal */ + name = CONNECTION_POOL_CLEARED; /** @internal */ constructor( diff --git a/src/connection_string.ts b/src/connection_string.ts index c56c0e48b8..d4fc21aac8 100644 --- a/src/connection_string.ts +++ b/src/connection_string.ts @@ -1280,5 +1280,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/constants.ts b/src/constants.ts index eec4b07571..e3da4efaae 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; +/** @internal */ export const CONNECTION_POOL_CREATED = 'connectionPoolCreated' as const; +/** @internal */ export const CONNECTION_POOL_CLOSED = 'connectionPoolClosed' as const; +/** @internal */ export const CONNECTION_POOL_CLEARED = 'connectionPoolCleared' as const; +/** @internal */ export const CONNECTION_POOL_READY = 'connectionPoolReady' as const; +/** @internal */ export const CONNECTION_CREATED = 'connectionCreated' as const; +/** @internal */ export const CONNECTION_READY = 'connectionReady' as const; +/** @internal */ export const CONNECTION_CLOSED = 'connectionClosed' as const; +/** @internal */ export const CONNECTION_CHECK_OUT_STARTED = 'connectionCheckOutStarted' as const; +/** @internal */ export const CONNECTION_CHECK_OUT_FAILED = 'connectionCheckOutFailed' as const; +/** @internal */ export const CONNECTION_CHECKED_OUT = 'connectionCheckedOut' as const; +/** @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/index.ts b/src/index.ts index 057047684e..a0d67a322c 100644 --- a/src/index.ts +++ b/src/index.ts @@ -248,7 +248,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, @@ -290,6 +303,11 @@ export type { WithSessionCallback } from './mongo_client'; export type { + Log, + LogConvertible, + Loggable, + LoggableEvent, + MongoDBLogWritable, MongoLoggableComponent, MongoLogger, MongoLoggerEnvOptions, diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 6c55d16f89..40102ed550 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -1,6 +1,43 @@ -import { Writable } from 'stream'; +import { EJSON } from 'bson'; +import type { Writable } from 'stream'; +import { inspect } from 'util'; -import { parseUnsignedInteger } from './utils'; +import type { + CommandFailedEvent, + CommandStartedEvent, + CommandSucceededEvent +} from './cmap/command_monitoring_events'; +import type { + ConnectionCheckedInEvent, + ConnectionCheckedOutEvent, + ConnectionCheckOutFailedEvent, + ConnectionCheckOutStartedEvent, + ConnectionClosedEvent, + ConnectionCreatedEvent, + ConnectionPoolClearedEvent, + ConnectionPoolClosedEvent, + ConnectionPoolCreatedEvent, + ConnectionPoolMonitoringEvent, + 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 */ export const SeverityLevel = Object.freeze({ @@ -20,7 +57,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], @@ -33,10 +91,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', @@ -70,7 +124,7 @@ export interface MongoLoggerEnvOptions { /** @internal */ export interface MongoLoggerMongoClientOptions { /** Destination for log messages */ - mongodbLogPath?: 'stdout' | 'stderr' | Writable; + mongodbLogPath?: 'stdout' | 'stderr' | MongoDBLogWritable; } /** @internal */ @@ -91,7 +145,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: Writable | MongoDBLogWritable; } /** @@ -111,43 +165,270 @@ function parseSeverityFromString(s?: string): SeverityLevel | null { return null; } +/** @internal */ +export function createStdioLogger(stream: { + write: NodeJS.WriteStream['write']; +}): MongoDBLogWritable { + return { + write: (log: Log): unknown => { + stream.write(inspect(log, { compact: true, breakLength: Infinity }), 'utf-8'); + return; + } + }; +} + /** * 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: + * ```ts + * write(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 - }: { - mongodbLogPath?: unknown; + { mongodbLogPath }: { mongodbLogPath?: string | Writable | MongoDBLogWritable } +): MongoDBLogWritable { + if (typeof mongodbLogPath === 'string' && /^stderr$/i.test(mongodbLogPath)) { + return createStdioLogger(process.stderr); } -): Writable { - const isValidLogDestinationString = (destination: string) => - ['stdout', 'stderr'].includes(destination.toLowerCase()); - if (typeof mongodbLogPath === 'string' && isValidLogDestinationString(mongodbLogPath)) { - return mongodbLogPath.toLowerCase() === 'stderr' ? process.stderr : process.stdout; + if (typeof mongodbLogPath === 'string' && /^stdout$/i.test(mongodbLogPath)) { + return createStdioLogger(process.stdout); } - // TODO(NODE-4813): check for minimal interface instead of instanceof Writable - if (typeof mongodbLogPath === 'object' && mongodbLogPath instanceof Writable) { + 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$/i.test(MONGODB_LOG_PATH)) { + return createStdioLogger(process.stderr); + } + if (MONGODB_LOG_PATH && /^stdout$/i.test(MONGODB_LOG_PATH)) { + return createStdioLogger(process.stdout); } - return process.stderr; + return createStdioLogger(process.stderr); +} + +/** @internal */ +export interface Log extends Record { + t: Date; + c: MongoLoggableComponent; + s: SeverityLevel; + message?: string; +} + +/** @internal */ +export interface MongoDBLogWritable { + write(log: Log): void; +} + +function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { + const s0Num = SEVERITY_LEVEL_MAP.getNumericSeverityLevel(s0); + const s1Num = SEVERITY_LEVEL_MAP.getNumericSeverityLevel(s1); + + return s0Num < s1Num ? -1 : s0Num > s1Num ? 1 : 0; +} + +/** @internal */ +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.toLog === 'function'; +} + +function attachCommandFields( + log: Record, + commandEvent: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent +) { + 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 log; +} + +function attachConnectionFields( + log: Record, + connectionPoolEvent: ConnectionPoolMonitoringEvent +) { + const { host, port } = HostAddress.fromString(connectionPoolEvent.address).toHostPort(); + log.serverHost = host; + log.serverPort = port; + + return log; +} + +function defaultLogTransform( + logObject: LoggableEvent | Record +): Omit { + let log: Omit = Object.create(null); + + switch (logObject.name) { + case COMMAND_STARTED: + log = attachCommandFields(log, logObject); + log.message = 'Command started'; + log.command = EJSON.stringify(logObject.command); + log.databaseName = logObject.databaseName; + return log; + case COMMAND_SUCCEEDED: + log = attachCommandFields(log, logObject); + log.message = 'Command succeeded'; + log.durationMS = logObject.duration; + log.reply = EJSON.stringify(logObject.reply); + return log; + case COMMAND_FAILED: + log = attachCommandFields(log, logObject); + log.message = 'Command failed'; + log.durationMS = logObject.duration; + log.failure = logObject.failure; + return log; + 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 + }; + } + return log; + case CONNECTION_POOL_READY: + log = attachConnectionFields(log, logObject); + log.message = 'Connection pool ready'; + return log; + case CONNECTION_POOL_CLEARED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection pool cleared'; + if (logObject.serviceId?._bsontype === 'ObjectId') { + log.serviceId = logObject.serviceId.toHexString(); + } + return log; + case CONNECTION_POOL_CLOSED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection pool closed'; + return log; + case CONNECTION_CREATED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection created'; + log.driverConnectionId = logObject.connectionId; + return log; + case CONNECTION_READY: + log = attachConnectionFields(log, logObject); + log.message = 'Connection ready'; + log.driverConnectionId = logObject.connectionId; + return log; + case CONNECTION_CLOSED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection closed'; + 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: + log.reason = `Unknown close reason: ${logObject.reason}`; + } + return log; + case CONNECTION_CHECK_OUT_STARTED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection checkout started'; + return log; + case CONNECTION_CHECK_OUT_FAILED: + log = attachConnectionFields(log, logObject); + log.message = 'Connection checkout failed'; + switch (logObject.reason) { + case 'poolClosed': + log.reason = 'Connection pool was closed'; + break; + case 'timeout': + log.reason = 'Wait queue timeout elapsed without a connection becoming available'; + break; + case 'connectionError': + log.reason = 'An error occurred while trying to establish a new connection'; + if (logObject.error) { + log.error = logObject.error; + } + break; + default: + log.reason = `Unknown close reason: ${logObject.reason}`; + } + return log; + case CONNECTION_CHECKED_OUT: + log = attachConnectionFields(log, logObject); + log.message = 'Connection checked out'; + + log.driverConnectionId = logObject.connectionId; + return log; + case CONNECTION_CHECKED_IN: + log = attachConnectionFields(log, logObject); + log.message = 'Connection checked in'; + log.driverConnectionId = logObject.connectionId; + return log; + default: + for (const [key, value] of Object.entries(logObject)) { + if (value != null) log[key] = value; + } + } + return log; } /** @internal */ export class MongoLogger { componentSeverities: Record; maxDocumentLength: number; - logDestination: Writable; + logDestination: MongoDBLogWritable | Writable; constructor(options: MongoLoggerOptions) { this.componentSeverities = options.componentSeverities; @@ -155,25 +436,27 @@ 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 {} + emergency = this.log.bind(this, 'emergency'); - critical(component: any, message: any): void {} + private log( + severity: SeverityLevel, + component: MongoLoggableComponent, + message: Loggable | string + ): void { + if (compareSeverity(severity, this.componentSeverities[component]) > 0) return; - 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 {} - - trace(component: any, message: any): void {} + let logMessage: Log = { t: new Date(), c: component, s: severity }; + if (typeof message === 'string') { + logMessage.message = message; + } else if (typeof message === 'object') { + if (isLogConvertible(message)) { + logMessage = { ...logMessage, ...message.toLog() }; + } else { + logMessage = { ...logMessage, ...defaultLogTransform(message) }; + } + } + this.logDestination.write(logMessage); + } /** * Merges options set through environment variables and the MongoClient, preferring environment diff --git a/src/utils.ts b/src/utils.ts index 17257d6ddb..95bf757af2 100644 --- a/src/utils.ts +++ b/src/utils.ts @@ -1011,6 +1011,16 @@ export class HostAddress { static fromSrvRecord({ name, port }: SrvRecord): HostAddress { return HostAddress.fromHostPort(name, port); } + + toHostPort(): { host: string; port: number } { + if (this.socketPath) { + return { host: this.socketPath, port: 0 }; + } + + const host = this.host ?? ''; + const port = this.port ?? 0; + return { host, port }; + } } export const DEFAULT_PK_FACTORY = { 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 + ); + }); + }); + }); }); diff --git a/test/unit/connection_string.test.ts b/test/unit/connection_string.test.ts index 4a33259bb9..3bbdd7fdab 100644 --- a/test/unit/connection_string.test.ts +++ b/test/unit/connection_string.test.ts @@ -561,9 +561,10 @@ describe('Connection String', function () { describe('feature flags', () => { 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/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 8bf97cd80b..9f9ca46826 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -1,10 +1,34 @@ +import { EJSON, ObjectId } from 'bson'; import { expect } from 'chai'; +import * as sinon from 'sinon'; import { Readable, Writable } from 'stream'; +import { inspect } from 'util'; -import { MongoLogger, MongoLoggerOptions, SeverityLevel } from '../mongodb'; +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, + MongoDBLogWritable, + MongoLogger, + MongoLoggerOptions, + SEVERITY_LEVEL_MAP, + SeverityLevel +} from '../mongodb'; class BufferingStream extends Writable { - buffer: string[] = []; + buffer: any[] = []; constructor(options = {}) { super({ ...options, objectMode: true }); @@ -45,6 +69,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 () { @@ -95,7 +157,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( { @@ -324,19 +386,39 @@ describe('class MongoLogger', function () { }); context('logDestination', function () { - 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, Writable]>); + let stdoutStub; + let stderrStub; + let streamStub; + let validOptions: Map; + 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()]; const validClientOptions = ['stderr', 'stdout', stream, 'stdErr', 'stdOut']; const validEnvironmentOptions = ['stderr', 'stdout', 'stdOut', 'stdErr']; + + beforeEach(function () { + stdoutStub = sinon.stub(process.stdout); + stderrStub = sinon.stub(process.stderr); + streamStub = sinon.stub(stream); + validOptions = new Map([ + ['stdout', stdoutStub], + ['stderr', stderrStub], + [stream, streamStub], + ['stdOut', stdoutStub], + ['stdErr', stderrStub] + ] 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) { @@ -344,11 +426,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(stderrStub.write).to.have.been.calledOnceWith( + inspect(log, { breakLength: Infinity, compact: true }) + ); }); } } @@ -360,11 +448,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(stderrStub.write).to.have.been.calledOnceWith( + inspect(log, { breakLength: Infinity, compact: true }) + ); }); } } @@ -376,12 +470,16 @@ describe('class MongoLogger', function () { it(`{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); + expect(correctDestination?.write).to.have.been.calledOnce; }); } } @@ -397,11 +495,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(stderrStub.write).to.have.been.calledOnceWith( + inspect(log, { breakLength: Infinity, compact: true }) + ); }); } } @@ -415,11 +519,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(stderrStub.write).to.have.been.calledOnceWith( + inspect(log, { breakLength: Infinity, compact: true }) + ); }); } } @@ -432,12 +542,15 @@ 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); + const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; + options.logDestination.write(log); + expect(correctDestination?.write).to.have.been.calledOnce; }); } } @@ -452,12 +565,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); + options.logDestination.write({ t: new Date(), c: 'command', s: 'emergency' }); + + expect(correctDestination?.write).to.have.been.calledOnce; }); } } @@ -471,12 +587,17 @@ describe('class MongoLogger', function () { it(`{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); + const log: Log = { t: new Date(), c: 'command', s: 'emergency' }; + options.logDestination.write(log); + + expect(correctDestination?.write).to.have.been.calledOnce; }); } } @@ -486,15 +607,21 @@ 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 + MONGODB_LOG_PATH: validEnvironmentOption, + MONGODB_LOG_COMMAND: 'emergency' }, { mongodbLogPath: validValue as any } ); const correctDestination = validOptions.get(validValue); - expect(options.logDestination).to.equal(correctDestination); + options.logDestination.write({ t: new Date(), c: 'command', s: 'emergency' }); + expect(correctDestination?.write).to.have.been.calledOnce; }); } } @@ -504,7 +631,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', () => { @@ -519,6 +647,595 @@ describe('class MongoLogger', function () { logger[severityLevel]('topology', 'message'); expect(stream.buffer).to.have.lengthOf(0); }); + + // 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({ + 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 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 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 () { + 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); + }); + }); + + context('spec-required logs', function () { + let stream: BufferingStream; + let logger: MongoLogger; + + beforeEach(function () { + stream = new BufferingStream(); + logger = new MongoLogger({ + componentSeverities: { + command: 'trace', + connection: 'trace' + } as any, + logDestination: stream + } as any); + }); + + context('command component', function () { + let log; + const commandStarted = { + commandName: 'find', + requestId: 0, + connectionId: 0, + address: '127.0.0.1:27017', + serviceId: new ObjectId(), + databaseName: 'db', + name: COMMAND_STARTED + }; + const commandSucceeded = { + commandName: 'find', + requestId: 0, + connectionId: 0, + duration: 0, + address: '127.0.0.1:27017', + serviceId: new ObjectId(), + databaseName: 'db', + name: COMMAND_SUCCEEDED + }; + const commandFailed = { + commandName: 'find', + requestId: 0, + duration: 0, + connectionId: 0, + address: '127.0.0.1:27017', + serviceId: new ObjectId(), + databaseName: 'db', + name: COMMAND_FAILED + }; + + function commonCommandComponentAssertions() { + const fields = [ + ['commandName', 'string'], + ['requestId', 'number'], + ['driverConnectionId', 'number'], + ['serverHost', 'string'], + ['serverPort', 'number'], + ['serviceId', 'string'] + ]; + for (const [fieldName, type] of fields) { + it(`emits a log with field \`${fieldName}\` that is of type ${type}`, function () { + expect(log).to.have.property(fieldName).that.is.a(type); + }); + } + } + + context('when CommandStartedEvent is logged', function () { + beforeEach(function () { + logger[severityLevel]('command', commandStarted); + expect(stream.buffer).to.have.lengthOf(1); + log = stream.buffer[0]; + }); + + commonCommandComponentAssertions(); + + it('emits a log with field `message` = "Command started"', function () { + expect(log).to.have.property('message', 'Command started'); + }); + + it('emits a log with field `command` that is an EJSON string', function () { + expect(log).to.have.property('command').that.is.a('string'); + expect(() => 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[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[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: CONNECTION_POOL_CREATED, + waitQueueSize: 0, + address: '127.0.0.1:27017', + options + }; + const connectionPoolReady = { + name: CONNECTION_POOL_READY, + address: '127.0.0.1:27017', + options + }; + const connectionPoolCleared = { + name: CONNECTION_POOL_CLEARED, + serviceId: new ObjectId(), + address: '127.0.0.1:27017', + options + }; + const connectionPoolClosed = { + name: CONNECTION_POOL_CLOSED, + address: '127.0.0.1:27017', + options + }; + const connectionCreated = { + name: CONNECTION_CREATED, + connectionId: 0, + address: '127.0.0.1:27017', + options + }; + const connectionCheckOutStarted = { + name: CONNECTION_CHECK_OUT_STARTED, + address: '127.0.0.1:27017', + options + }; + const connectionCheckOutFailed = { + name: CONNECTION_CHECK_OUT_FAILED, + address: '127.0.0.1:27017', + options + }; + const connectionCheckedOut = { + name: CONNECTION_CHECKED_OUT, + connectionId: 0, + address: '127.0.0.1:27017', + options + }; + const 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 + }; + 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(log).to.have.property(fieldName).that.is.a(type); + }); + } + } + + context('when ConnectionPoolCreatedEvent is logged', function () { + beforeEach(function () { + 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 () { + 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'); + }); + }); + + context('when ConnectionPoolReadyEvent is logged', function () { + beforeEach(function () { + 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"', function () { + expect(log).to.have.property('message', 'Connection pool ready'); + }); + }); + + context('when ConnectionPoolClearedEvent is logged', function () { + 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'); + }); + + 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'); + }); + }); + }); + + context('when ConnectionPoolClosedEvent is logged', function () { + beforeEach(function () { + 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"', function () { + expect(log).to.have.property('message', 'Connection pool closed'); + }); + }); + + context('when ConnectionCreatedEvent is logged', function () { + beforeEach(function () { + 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[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 () { + for (const [reason, message] of [ + ['connectionError', 'An error occurred while trying to establish a new connection'], + ['timeout', 'Wait queue timeout elapsed without a connection becoming available'], + ['poolClosed', 'Connection pool was closed'] + ]) { + context(`with reason = "${reason}"`, function () { + beforeEach(function () { + const event = + reason === 'connectionError' + ? { + ...connectionCheckOutFailed, + reason, + error: new Error('this is an error') + } + : { ...connectionCheckOutFailed, reason }; + logger[severityLevel]('connection', event); + 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'); + }); + + it(`emits a log with field \`reason\` = "${message}"`, function () { + expect(log).to.have.property('reason', message); + }); + + if (reason === 'connectionError') { + it('emits a log with field `error`', function () { + expect(log).to.have.property('error').that.is.instanceOf(Error); + }); + } + }); + } + }); + + context('when ConnectionCheckedInEvent is logged', function () { + beforeEach(function () { + 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[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'); + }); + }); + + 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'); + }); + }); + + 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 () { + 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]; + }); + + commonConnectionComponentAssertions(); + it(`emits a log with field \`reason\` = "${message}"`, function () { + expect(log).to.have.property('reason', message); + }); + + if (reason === 'error') { + it('emits a log with field `error`', function () { + expect(log).to.have.property('error'); + }); + } + }); + } + + context('with unknown 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 with field `reason` prefixed by "Unknown close reason: "', function () { + expect(log).to.have.property('reason'); + expect(log.reason).to.match(/^Unknown close reason: .*$/); + }); + }); + }); + }); + }); }); } });