From 6d32c3253fa0bc127c9ac4caebb602753b58a454 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Wed, 20 Dec 2023 14:26:37 -0500 Subject: [PATCH 01/25] rebased changes --- src/cmap/connection.ts | 2 + src/cmap/connection_pool.ts | 3 +- src/constants.ts | 3 + src/index.ts | 5 ++ src/mongo_logger.ts | 63 +++++++++++++++---- src/mongo_types.ts | 24 +++++++ ...ommand_logging_and_monitoring.spec.test.ts | 17 ++++- test/tools/unified-spec-runner/match.ts | 3 + 8 files changed, 103 insertions(+), 17 deletions(-) diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 904709d7604..74dfac30c19 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -24,6 +24,7 @@ import { MongoWriteConcernError } from '../error'; import type { ServerApi, SupportedNodeConnectionOptions } from '../mongo_client'; +import { MongoLoggableComponent, type MongoLogger, SeverityLevel } from '../mongo_logger'; import { type CancellationToken, TypedEventEmitter } from '../mongo_types'; import type { ReadPreferenceLike } from '../read_preference'; import { applySession, type ClientSession, updateSessionFromResponse } from '../sessions'; @@ -114,6 +115,7 @@ export interface ConnectionOptions socketTimeoutMS?: number; cancellationToken?: CancellationToken; metadata: ClientMetadata; + mongoLogger: MongoLogger | undefined; } /** @internal */ diff --git a/src/cmap/connection_pool.ts b/src/cmap/connection_pool.ts index 0df93f688af..6d9312cbaf8 100644 --- a/src/cmap/connection_pool.ts +++ b/src/cmap/connection_pool.ts @@ -699,7 +699,8 @@ export class ConnectionPool extends TypedEventEmitter { ...this.options, id: this[kConnectionCounter].next().value, generation: this[kGeneration], - cancellationToken: this[kCancellationToken] + cancellationToken: this[kCancellationToken], + mongoLogger: this[kServer].topology.client.mongoLogger }; this[kPending]++; diff --git a/src/constants.ts b/src/constants.ts index fab65bee210..f073d5cefdb 100644 --- a/src/constants.ts +++ b/src/constants.ts @@ -52,8 +52,11 @@ 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; +/** @internal */ export const COMMAND_STARTED = 'commandStarted' as const; +/** @internal */ export const COMMAND_SUCCEEDED = 'commandSucceeded' as const; +/** @internal */ export const COMMAND_FAILED = 'commandFailed' as const; /** @internal */ export const SERVER_HEARTBEAT_STARTED = 'serverHeartbeatStarted' as const; diff --git a/src/index.ts b/src/index.ts index a0f93947432..77c3d750a9d 100644 --- a/src/index.ts +++ b/src/index.ts @@ -285,6 +285,9 @@ export type { StreamDescription, StreamDescriptionOptions } from './cmap/stream_ export type { CompressorName } from './cmap/wire_protocol/compression'; export type { CollectionOptions, CollectionPrivate, ModifyResult } from './collection'; export type { + COMMAND_FAILED, + COMMAND_STARTED, + COMMAND_SUCCEEDED, CONNECTION_CHECK_OUT_FAILED, CONNECTION_CHECK_OUT_STARTED, CONNECTION_CHECKED_IN, @@ -356,6 +359,8 @@ export type { LogComponentSeveritiesClientOptions, LogConvertible, Loggable, + LoggableCommandFailedEvent, + LoggableCommandSucceededEvent, LoggableEvent, LoggableServerHeartbeatFailedEvent, LoggableServerHeartbeatStartedEvent, diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index affb3207201..b8a9acd742a 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -1,12 +1,8 @@ -import { type Document, EJSON, type EJSONOptions } from 'bson'; +import { type Document, EJSON, type EJSONOptions, type ObjectId } from 'bson'; import type { Writable } from 'stream'; import { inspect } from 'util'; -import type { - CommandFailedEvent, - CommandStartedEvent, - CommandSucceededEvent -} from './cmap/command_monitoring_events'; +import type { CommandStartedEvent } from './cmap/command_monitoring_events'; import type { ConnectionCheckedInEvent, ConnectionCheckedOutEvent, @@ -285,6 +281,40 @@ function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 { return s0Num < s1Num ? -1 : s0Num > s1Num ? 1 : 0; } +/** + * @internal + * Must be separate from Events API due to differences in spec requirements for logging a command success + */ +export type LoggableCommandSucceededEvent = { + address: string; + connectionId?: string | number; + requestId: number; + duration: number; + commandName: string; + reply: Document | undefined; + serviceId?: ObjectId; + name: typeof COMMAND_SUCCEEDED; + serverConnectionId: bigint | null; + databaseName: string; +}; + +/** + * @internal + * Must be separate from Events API due to differences in spec requirements for logging a command failure + */ +export type LoggableCommandFailedEvent = { + address: string; + connectionId?: string | number; + requestId: number; + duration: number; + commandName: string; + failure: Error; + serviceId?: ObjectId; + name: typeof COMMAND_FAILED; + serverConnectionId: bigint | null; + databaseName: string; +}; + /** * @internal * Must be separate from Events API due to differences in spec requirements for logging server heartbeat beginning @@ -336,8 +366,8 @@ type SDAMLoggableEvent = /** @internal */ export type LoggableEvent = | CommandStartedEvent - | CommandSucceededEvent - | CommandFailedEvent + | LoggableCommandSucceededEvent + | LoggableCommandFailedEvent | ConnectionPoolCreatedEvent | ConnectionPoolReadyEvent | ConnectionPoolClosedEvent @@ -387,7 +417,7 @@ function isLogConvertible(obj: Loggable): obj is LogConvertible { function attachCommandFields( log: Record, - commandEvent: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent + commandEvent: CommandStartedEvent | LoggableCommandSucceededEvent | LoggableCommandFailedEvent ) { log.commandName = commandEvent.commandName; log.requestId = commandEvent.requestId; @@ -398,6 +428,8 @@ function attachCommandFields( if (commandEvent?.serviceId) { log.serviceId = commandEvent.serviceId.toHexString(); } + log.databaseName = commandEvent.databaseName; + log.serverConnectionId = commandEvent?.serverConnectionId; return log; } @@ -444,20 +476,20 @@ function defaultLogTransform( case COMMAND_STARTED: log = attachCommandFields(log, logObject); log.message = 'Command started'; - log.command = stringifyWithMaxLen(logObject.command, maxDocumentLength); + log.command = stringifyWithMaxLen(logObject.command, maxDocumentLength, { relaxed: true }); log.databaseName = logObject.databaseName; return log; case COMMAND_SUCCEEDED: log = attachCommandFields(log, logObject); log.message = 'Command succeeded'; log.durationMS = logObject.duration; - log.reply = stringifyWithMaxLen(logObject.reply, maxDocumentLength); + log.reply = stringifyWithMaxLen(logObject.reply, maxDocumentLength, { relaxed: true }); return log; case COMMAND_FAILED: log = attachCommandFields(log, logObject); log.message = 'Command failed'; log.durationMS = logObject.duration; - log.failure = logObject.failure; + log.failure = logObject.failure.message; return log; case CONNECTION_POOL_CREATED: log = attachConnectionFields(log, logObject); @@ -655,12 +687,16 @@ export class MongoLogger { this.logDestination = options.logDestination; } + willLog(severity: SeverityLevel, component: MongoLoggableComponent): boolean { + return compareSeverity(severity, this.componentSeverities[component]) <= 0; + } + private log( severity: SeverityLevel, component: MongoLoggableComponent, message: Loggable | string ): void { - if (compareSeverity(severity, this.componentSeverities[component]) > 0) return; + if (!this.willLog(severity, component)) return; let logMessage: Log = { t: new Date(), c: component, s: severity }; if (typeof message === 'string') { @@ -669,6 +705,7 @@ export class MongoLogger { if (isLogConvertible(message)) { logMessage = { ...logMessage, ...message.toLog() }; } else { + logMessage = { ...logMessage, ...defaultLogTransform(message, this.maxDocumentLength) }; } } diff --git a/src/mongo_types.ts b/src/mongo_types.ts index 5682ecf8783..c724078c103 100644 --- a/src/mongo_types.ts +++ b/src/mongo_types.ts @@ -12,7 +12,10 @@ import type { ObjectId, Timestamp } from './bson'; +import { type CommandStartedEvent } from './cmap/command_monitoring_events'; import type { + LoggableCommandFailedEvent, + LoggableCommandSucceededEvent, LoggableServerHeartbeatFailedEvent, LoggableServerHeartbeatStartedEvent, LoggableServerHeartbeatSucceededEvent, @@ -438,6 +441,27 @@ export class TypedEventEmitter extends EventEm this.mongoLogger?.debug(this.component, loggableHeartbeatEvent); } } + /** @internal */ + emitAndLogCommand( + monitorCommands: boolean, + event: EventKey | symbol, + databaseName: string, + ...args: Parameters + ): void { + if (monitorCommands) { + this.emit(event, ...args); + } + if (this.component && typeof args[0]?.serverConnectionId === 'bigint') { + const loggableCommandEvent: + | CommandStartedEvent + | LoggableCommandFailedEvent + | LoggableCommandSucceededEvent = { + databaseName: databaseName, + ...args[0] + }; + this.mongoLogger?.debug(this.component, loggableCommandEvent); + } + } } /** @public */ diff --git a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.spec.test.ts b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.spec.test.ts index 8d2446ab0cf..3130f33b51d 100644 --- a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.spec.test.ts +++ b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.spec.test.ts @@ -22,7 +22,18 @@ describe('Command Logging and Monitoring Spec', function () { ); }); - describe.skip('Command Logging Spec', () => { - runUnifiedSuite(loadSpecTests(path.join('command-logging-and-monitoring', 'logging'))); - }).skipReason = 'TODO(NODE-4686): Unskip these tests'; + describe.only('Command Logging Spec', () => { + const tests = loadSpecTests(path.join('command-logging-and-monitoring', 'logging')); + runUnifiedSuite(tests, test => { + if ( + [ + 'Successful bulk write command log messages include operationIds', + 'Failed bulk write command log message includes operationId' + ].includes(test.description) + ) { + return 'not applicable: operationId not supported'; + } + return false; + }); + }); }); diff --git a/test/tools/unified-spec-runner/match.ts b/test/tools/unified-spec-runner/match.ts index 0a30d158917..d646584085d 100644 --- a/test/tools/unified-spec-runner/match.ts +++ b/test/tools/unified-spec-runner/match.ts @@ -675,6 +675,9 @@ export function compareLogs( actual: ExpectedLogMessage[], entities: EntitiesMap ): void { + console.log('ACTUAL', actual); + console.log('EXPECTED', expected); + expect(actual).to.have.lengthOf(expected.length); for (const [index, actualLog] of actual.entries()) { From 5f5d77e4a1003c6fee782e93b2f610df6b6d379f Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Wed, 20 Dec 2023 16:02:55 -0500 Subject: [PATCH 02/25] All tests passing, need to add in prose tests --- src/cmap/connection.ts | 3 ++- src/mongo_logger.ts | 1 - ...ommand_logging_and_monitoring.spec.test.ts | 2 +- test/tools/unified-spec-runner/match.ts | 5 +--- test/tools/unified-spec-runner/runner.ts | 24 +++++++++++++++---- 5 files changed, 24 insertions(+), 11 deletions(-) diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 74dfac30c19..9e3a5ac23d3 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -115,7 +115,8 @@ export interface ConnectionOptions socketTimeoutMS?: number; cancellationToken?: CancellationToken; metadata: ClientMetadata; - mongoLogger: MongoLogger | undefined; + /** @internal */ + mongoLogger?: MongoLogger | undefined; } /** @internal */ diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index b8a9acd742a..f492a69aa6f 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -705,7 +705,6 @@ export class MongoLogger { if (isLogConvertible(message)) { logMessage = { ...logMessage, ...message.toLog() }; } else { - logMessage = { ...logMessage, ...defaultLogTransform(message, this.maxDocumentLength) }; } } diff --git a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.spec.test.ts b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.spec.test.ts index 3130f33b51d..62075e06b77 100644 --- a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.spec.test.ts +++ b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.spec.test.ts @@ -22,7 +22,7 @@ describe('Command Logging and Monitoring Spec', function () { ); }); - describe.only('Command Logging Spec', () => { + describe('Command Logging Spec', () => { const tests = loadSpecTests(path.join('command-logging-and-monitoring', 'logging')); runUnifiedSuite(tests, test => { if ( diff --git a/test/tools/unified-spec-runner/match.ts b/test/tools/unified-spec-runner/match.ts index d646584085d..1c81da40bce 100644 --- a/test/tools/unified-spec-runner/match.ts +++ b/test/tools/unified-spec-runner/match.ts @@ -648,7 +648,7 @@ export function matchesEvents( } } -export function filterLogs( +export function filterExtraLogs( logsToIgnore: ExpectedLogMessage[], actual: ExpectedLogMessage[], entities: EntitiesMap @@ -675,9 +675,6 @@ export function compareLogs( actual: ExpectedLogMessage[], entities: EntitiesMap ): void { - console.log('ACTUAL', actual); - console.log('EXPECTED', expected); - expect(actual).to.have.lengthOf(expected.length); for (const [index, actualLog] of actual.entries()) { diff --git a/test/tools/unified-spec-runner/runner.ts b/test/tools/unified-spec-runner/runner.ts index 050d7a2e879..925b8b9d617 100644 --- a/test/tools/unified-spec-runner/runner.ts +++ b/test/tools/unified-spec-runner/runner.ts @@ -3,11 +3,17 @@ import { expect } from 'chai'; import { gte as semverGte, satisfies as semverSatisfies } from 'semver'; import type { MongoClient } from '../../mongodb'; -import { MONGODB_ERROR_CODES, ns, ReadPreference, TopologyType } from '../../mongodb'; +import { + MONGODB_ERROR_CODES, + ns, + ReadPreference, + SENSITIVE_COMMANDS, + TopologyType +} from '../../mongodb'; import { ejson } from '../utils'; import { AstrolabeResultsWriter } from './astrolabe_results_writer'; import { EntitiesMap, type UnifiedMongoClient } from './entities'; -import { compareLogs, filterLogs, matchesEvents } from './match'; +import { compareLogs, filterExtraLogs, matchesEvents } from './match'; import { executeOperationAndCheck } from './operations'; import * as uni from './schema'; import { isAnyRequirementSatisfied, patchVersion, zip } from './unified-utils'; @@ -232,9 +238,19 @@ async function runUnifiedTest( const testClient = clientList.get(clientId); expect(testClient, `No client entity found with id ${clientId}`).to.exist; - const filteredTestClientLogs = expectedLogsForClient.ignoreMessages - ? filterLogs(expectedLogsForClient.ignoreMessages, testClient!.collectedLogs, entities) + let filteredTestClientLogs = expectedLogsForClient.ignoreMessages + ? filterExtraLogs( + expectedLogsForClient.ignoreMessages, + testClient!.collectedLogs, + entities + ) : testClient!.collectedLogs; + if (!testClient!.observeSensitiveCommands) { + filteredTestClientLogs = filteredTestClientLogs.filter( + log => + !(log.data && log.data.commandName && SENSITIVE_COMMANDS.has(log.data.commandName)) + ); + } compareLogs(expectedLogsForClient.messages, filteredTestClientLogs, entities); } } From 209ba27fc39d1e5d228630e2315be4f7dcef7685 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Wed, 20 Dec 2023 18:17:12 -0500 Subject: [PATCH 03/25] Added prose tests --- ...mmand_logging_and_monitoring.prose.test.ts | 201 ++++++++++++++++++ 1 file changed, 201 insertions(+) create mode 100644 test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts diff --git a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts new file mode 100644 index 00000000000..bd36ff354d9 --- /dev/null +++ b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts @@ -0,0 +1,201 @@ +import { expect } from 'chai'; + +import { DEFAULT_MAX_DOCUMENT_LENGTH, type Document } from '../../mongodb'; + +describe('Command Logging and Monitoring Prose Tests', function () { + const loggerFeatureFlag = Symbol.for('@@mdb.enableMongoLogger'); + const ELLIPSES_LENGTH = 3; + context('When no custom truncation limit is provided', function () { + /* + 1. Configure logging with a minimum severity level of "debug" for the "command" component. + Do not explicitly configure the max document length. + + 2. Construct an array docs containing the document {"x" : "y"} repeated 100 times. + + 3. Insert docs to a collection via insertMany. + + 4. Inspect the resulting "command started" log message and assert that + the "command" value is a string of length 1000 + (length of trailing ellipsis). + + 5. Inspect the resulting "command succeeded" log message and assert that + the "reply" value is a string of length <= 1000 + (length of trailing ellipsis). + + 6. Run find() on the collection where the document was inserted. + + 7. Inspect the resulting "command succeeded" log message and assert that + the reply is a string of length 1000 + (length of trailing ellipsis). + */ + + it('should follow default truncation limit of 1000', { + metadata: {}, + test: async function () { + const writable = { + buffer: [], + write(log) { + this.buffer.push(log); + } + }; + + // 1. + const client = this.configuration.newClient( + {}, + { + [loggerFeatureFlag]: true, + mongodbLogPath: writable, + mongodbLogComponentSeverities: { + command: 'debug' + } + } + ); + + // 2. + const docs: Array = []; + for (let i = 0; i < 100; i++) { + docs.push({ x: 'y' }); + } + + // 3. + await client.db('admin').collection('test').insertMany(docs); + + // 4. + const insertManyCommandStarted = writable.buffer[2]; + expect(insertManyCommandStarted?.message).to.equal('Command started'); + expect(insertManyCommandStarted?.command).to.be.a('string'); + expect(insertManyCommandStarted?.command?.length).to.equal( + DEFAULT_MAX_DOCUMENT_LENGTH + ELLIPSES_LENGTH + ); + + // 5. + const insertManyCommandSucceeded = writable.buffer[3]; + expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); + expect(insertManyCommandSucceeded?.reply).to.be.a('string'); + expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most( + DEFAULT_MAX_DOCUMENT_LENGTH + ELLIPSES_LENGTH + ); + + // 6. + await client.db('admin').collection('test').find()._initialize(); + + // 7. + const findCommandSucceeded = writable.buffer[5]; + expect(findCommandSucceeded?.message).to.equal('Command succeeded'); + expect(findCommandSucceeded?.reply).to.be.a('string'); + expect(findCommandSucceeded?.reply?.length).to.equal( + DEFAULT_MAX_DOCUMENT_LENGTH + ELLIPSES_LENGTH + ); + + await client.close(); + } + }); + }); + context('When custom truncation limit is provided', function () { + /* + 1. Configure logging with a minimum severity level of "debug" for the "command" component. + Set the max document length to 5. + + 2. Run the command {"hello": true}. + + 3. Inspect the resulting "command started" log message and assert that + the "command" value is a string of length 5 + (length of trailing ellipsis). + + 4. Inspect the resulting "command succeeded" log message and assert that + the "reply" value is a string of length 5 + (length of trailing ellipsis). + + 5. (Optional) + If the driver attaches raw server responses to failures + and can access these via log messages to assert on, + run the command {"notARealCommand": true}. + + Inspect the resulting "command failed" log message + and confirm that the server error is a string of length 5 + (length of trailing ellipsis). + */ + it('should follow custom truncation limit', { + metadata: {}, + test: async function () { + const writable = { + buffer: [], + write(log) { + this.buffer.push(log); + } + }; + + // 1. + const client = this.configuration.newClient( + {}, + { + [loggerFeatureFlag]: true, + mongodbLogPath: writable, + mongodbLogComponentSeverities: { + command: 'debug' + }, + mongodbLogMaxDocumentLength: 5 + } + ); + + // 2. + await client.db('admin').command({ hello: 'true' }); + + // 3. + const insertManyCommandStarted = writable.buffer[2]; + expect(insertManyCommandStarted?.message).to.equal('Command started'); + expect(insertManyCommandStarted?.command).to.be.a('string'); + expect(insertManyCommandStarted?.command?.length).to.equal(5 + ELLIPSES_LENGTH); + + // 4. + const insertManyCommandSucceeded = writable.buffer[3]; + expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); + expect(insertManyCommandSucceeded?.reply).to.be.a('string'); + expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most(5 + ELLIPSES_LENGTH); + + await client.close(); + } + }); + }); + context('Truncation with multi-byte codepoints', function () { + /* + A specific test case is not provided here due to the allowed variations in truncation logic + as well as varying extended JSON whitespace usage. + Drivers MUST write language-specific tests that confirm truncation of commands, replies, + and (if applicable) server responses included in error messages + work as expected when the data being truncated includes multi-byte Unicode codepoints. + + If the driver uses anything other than Unicode codepoints as the unit for max document length, + there also MUST be tests confirming that cases + where the max length falls in the middle of a multi-byte codepoint are handled gracefully. + */ + it('should handle unicode codepoints in middle and end of truncation gracefully', { + metadata: {}, + test: async function () { + const writable = { + buffer: [], + write(log) { + this.buffer.push(log); + } + }; + + const client = this.configuration.newClient( + {}, + { + [loggerFeatureFlag]: true, + mongodbLogPath: writable, + mongodbLogComponentSeverities: { + command: 'debug' + }, + mongodbLogMaxDocumentLength: 50 + } + ); + + const docs: Array = [{ x: '&&&&&&&&&&&&&&&&' }]; + + await client.db('admin').collection('test').insertMany(docs); + + const insertManyCommandStarted = writable.buffer[2]; + expect(insertManyCommandStarted?.message).to.equal('Command started'); + expect(insertManyCommandStarted?.command).to.be.a('string'); + expect(insertManyCommandStarted?.command?.length).to.equal(50 + ELLIPSES_LENGTH); + + await client.close(); + } + }); + }); +}); From 3bee17a5ea9cfa30256d4f51dd15b6ae0cf8bfa3 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Wed, 20 Dec 2023 18:21:28 -0500 Subject: [PATCH 04/25] Added forgotten edge case --- .../command_logging_and_monitoring.prose.test.ts | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts index bd36ff354d9..dd4444cd016 100644 --- a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts +++ b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts @@ -2,7 +2,7 @@ import { expect } from 'chai'; import { DEFAULT_MAX_DOCUMENT_LENGTH, type Document } from '../../mongodb'; -describe('Command Logging and Monitoring Prose Tests', function () { +describe.only('Command Logging and Monitoring Prose Tests', function () { const loggerFeatureFlag = Symbol.for('@@mdb.enableMongoLogger'); const ELLIPSES_LENGTH = 3; context('When no custom truncation limit is provided', function () { @@ -194,6 +194,11 @@ describe('Command Logging and Monitoring Prose Tests', function () { expect(insertManyCommandStarted?.command).to.be.a('string'); expect(insertManyCommandStarted?.command?.length).to.equal(50 + ELLIPSES_LENGTH); + const insertManyCommandSucceeded = writable.buffer[3]; + expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); + expect(insertManyCommandSucceeded?.reply).to.be.a('string'); + expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most(50 + ELLIPSES_LENGTH); + await client.close(); } }); From fcfc98bbe37e5a444bd99e60d7c93831b9397678 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Thu, 21 Dec 2023 10:26:18 -0500 Subject: [PATCH 05/25] removed stray only --- .../command_logging_and_monitoring.prose.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts index dd4444cd016..2f512f7e5f5 100644 --- a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts +++ b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts @@ -2,7 +2,7 @@ import { expect } from 'chai'; import { DEFAULT_MAX_DOCUMENT_LENGTH, type Document } from '../../mongodb'; -describe.only('Command Logging and Monitoring Prose Tests', function () { +describe('Command Logging and Monitoring Prose Tests', function () { const loggerFeatureFlag = Symbol.for('@@mdb.enableMongoLogger'); const ELLIPSES_LENGTH = 3; context('When no custom truncation limit is provided', function () { From 422c6a9d1957eb96df37a7dc6eda8307ce9bc17c Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Thu, 21 Dec 2023 13:47:00 -0500 Subject: [PATCH 06/25] workaround for messy messy rebase --- src/cmap/connection.ts | 3 --- 1 file changed, 3 deletions(-) diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 9e3a5ac23d3..904709d7604 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -24,7 +24,6 @@ import { MongoWriteConcernError } from '../error'; import type { ServerApi, SupportedNodeConnectionOptions } from '../mongo_client'; -import { MongoLoggableComponent, type MongoLogger, SeverityLevel } from '../mongo_logger'; import { type CancellationToken, TypedEventEmitter } from '../mongo_types'; import type { ReadPreferenceLike } from '../read_preference'; import { applySession, type ClientSession, updateSessionFromResponse } from '../sessions'; @@ -115,8 +114,6 @@ export interface ConnectionOptions socketTimeoutMS?: number; cancellationToken?: CancellationToken; metadata: ClientMetadata; - /** @internal */ - mongoLogger?: MongoLogger | undefined; } /** @internal */ From c360ec221f1017a47244a6f19c968c0cc77a6693 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Thu, 21 Dec 2023 14:02:04 -0500 Subject: [PATCH 07/25] refixed connection.ts, tests passing again --- src/cmap/connection.ts | 42 +++++++++++++++++++++++++++++++++++------- 1 file changed, 35 insertions(+), 7 deletions(-) diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 904709d7604..325c4291a00 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -24,6 +24,7 @@ import { MongoWriteConcernError } from '../error'; import type { ServerApi, SupportedNodeConnectionOptions } from '../mongo_client'; +import { MongoLoggableComponent, type MongoLogger, SeverityLevel } from '../mongo_logger'; import { type CancellationToken, TypedEventEmitter } from '../mongo_types'; import type { ReadPreferenceLike } from '../read_preference'; import { applySession, type ClientSession, updateSessionFromResponse } from '../sessions'; @@ -114,6 +115,8 @@ export interface ConnectionOptions socketTimeoutMS?: number; cancellationToken?: CancellationToken; metadata: ClientMetadata; + /** @internal */ + mongoLogger?: MongoLogger | undefined; } /** @internal */ @@ -174,6 +177,10 @@ export class Connection extends TypedEventEmitter { private messageStream: Readable; private socketWrite: (buffer: Uint8Array) => Promise; private clusterTime: Document | null = null; + /** @internal */ + override component = MongoLoggableComponent.COMMAND; + /** @internal */ + override mongoLogger: MongoLogger | undefined; /** @event */ static readonly COMMAND_STARTED = COMMAND_STARTED; @@ -198,6 +205,7 @@ export class Connection extends TypedEventEmitter { this.socketTimeoutMS = options.socketTimeoutMS ?? 0; this.monitorCommands = options.monitorCommands; this.serverApi = options.serverApi; + this.mongoLogger = options.mongoLogger; this.description = new StreamDescription(this.address, options); this.generation = options.generation; @@ -441,10 +449,16 @@ export class Connection extends TypedEventEmitter { const message = this.prepareCommand(ns.db, command, options); let started = 0; - if (this.monitorCommands) { + if ( + this.monitorCommands || + (typeof this.description.serverConnectionId === 'bigint' && + this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) + ) { started = now(); - this.emit( + this.emitAndLogCommand( + this.monitorCommands, Connection.COMMAND_STARTED, + message.databaseName, new CommandStartedEvent(this, message, this.description.serverConnectionId) ); } @@ -464,9 +478,15 @@ export class Connection extends TypedEventEmitter { throw new MongoServerError(document); } - if (this.monitorCommands) { - this.emit( + if ( + this.monitorCommands || + (typeof this.description.serverConnectionId === 'bigint' && + this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) + ) { + this.emitAndLogCommand( + this.monitorCommands, Connection.COMMAND_SUCCEEDED, + message.databaseName, new CommandSucceededEvent( this, message, @@ -481,10 +501,16 @@ export class Connection extends TypedEventEmitter { this.controller.signal.throwIfAborted(); } } catch (error) { - if (this.monitorCommands) { + if ( + this.monitorCommands || + (typeof this.description.serverConnectionId === 'bigint' && + this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) + ) { if (error.name === 'MongoWriteConcernError') { - this.emit( + this.emitAndLogCommand( + this.monitorCommands, Connection.COMMAND_SUCCEEDED, + message.databaseName, new CommandSucceededEvent( this, message, @@ -494,8 +520,10 @@ export class Connection extends TypedEventEmitter { ) ); } else { - this.emit( + this.emitAndLogCommand( + this.monitorCommands, Connection.COMMAND_FAILED, + message.databaseName, new CommandFailedEvent( this, message, From 054094fe0b819e27fb061fa7c0c97509602ecd4b Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Thu, 4 Jan 2024 10:58:08 -0500 Subject: [PATCH 08/25] PR requested changes --- src/cmap/connection.ts | 6 +++--- src/mongo_types.ts | 2 +- test/unit/mongo_logger.test.ts | 1 + 3 files changed, 5 insertions(+), 4 deletions(-) diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 325c4291a00..568df04434f 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -451,7 +451,7 @@ export class Connection extends TypedEventEmitter { let started = 0; if ( this.monitorCommands || - (typeof this.description.serverConnectionId === 'bigint' && + (this.description.serverConnectionId && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) ) { started = now(); @@ -480,7 +480,7 @@ export class Connection extends TypedEventEmitter { if ( this.monitorCommands || - (typeof this.description.serverConnectionId === 'bigint' && + (this.description.serverConnectionId && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) ) { this.emitAndLogCommand( @@ -503,7 +503,7 @@ export class Connection extends TypedEventEmitter { } catch (error) { if ( this.monitorCommands || - (typeof this.description.serverConnectionId === 'bigint' && + (this.description.serverConnectionId && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) ) { if (error.name === 'MongoWriteConcernError') { diff --git a/src/mongo_types.ts b/src/mongo_types.ts index c724078c103..44f90afdbcb 100644 --- a/src/mongo_types.ts +++ b/src/mongo_types.ts @@ -451,7 +451,7 @@ export class TypedEventEmitter extends EventEm if (monitorCommands) { this.emit(event, ...args); } - if (this.component && typeof args[0]?.serverConnectionId === 'bigint') { + if (this.component && typeof args[0]?.serverConnectionId) { const loggableCommandEvent: | CommandStartedEvent | LoggableCommandFailedEvent diff --git a/test/unit/mongo_logger.test.ts b/test/unit/mongo_logger.test.ts index 0d419164536..90a36437494 100644 --- a/test/unit/mongo_logger.test.ts +++ b/test/unit/mongo_logger.test.ts @@ -809,6 +809,7 @@ describe('class MongoLogger', function () { address: '127.0.0.1:27017', serviceId: new ObjectId(), databaseName: 'db', + failure: 'err', name: COMMAND_FAILED }; From 0d8d05100ec5405ce6fe3b6ef9a0e1e00fb2d1b6 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Thu, 4 Jan 2024 13:35:01 -0500 Subject: [PATCH 09/25] Error fix --- package-lock.json | 228 +++++++++++++++++++++++++++++---------------- src/mongo_types.ts | 2 +- 2 files changed, 151 insertions(+), 79 deletions(-) diff --git a/package-lock.json b/package-lock.json index 21b9b983b67..52f8b821dff 100644 --- a/package-lock.json +++ b/package-lock.json @@ -799,17 +799,89 @@ } }, "node_modules/@babel/code-frame": { - "version": "7.21.4", - "resolved": "https://registry.npmjs.org/@babel/code-frame/-/code-frame-7.21.4.tgz", - "integrity": "sha512-LYvhNKfwWSPpocw8GI7gpK2nq3HSDuEPC/uSYaALSJu9xjsalaaYFOq0Pwt5KmVqwEbZlDu81aLXwBOmD/Fv9g==", + "version": "7.23.5", + "resolved": "https://registry.npmjs.org/@babel/code-frame/-/code-frame-7.23.5.tgz", + "integrity": "sha512-CgH3s1a96LipHCmSUmYFPwY7MNx8C3avkq7i4Wl3cfa662ldtUe4VM1TPXX70pfmrlWTb6jLqTYrZyT2ZTJBgA==", "dev": true, "dependencies": { - "@babel/highlight": "^7.18.6" + "@babel/highlight": "^7.23.4", + "chalk": "^2.4.2" }, "engines": { "node": ">=6.9.0" } }, + "node_modules/@babel/code-frame/node_modules/ansi-styles": { + "version": "3.2.1", + "resolved": "https://registry.npmjs.org/ansi-styles/-/ansi-styles-3.2.1.tgz", + "integrity": "sha512-VT0ZI6kZRdTh8YyJw3SMbYm/u+NqfsAxEpWO0Pf9sq8/e94WxxOpPKx9FR1FlyCtOVDNOQ+8ntlqFxiRc+r5qA==", + "dev": true, + "dependencies": { + "color-convert": "^1.9.0" + }, + "engines": { + "node": ">=4" + } + }, + "node_modules/@babel/code-frame/node_modules/chalk": { + "version": "2.4.2", + "resolved": "https://registry.npmjs.org/chalk/-/chalk-2.4.2.tgz", + "integrity": "sha512-Mti+f9lpJNcwF4tWV8/OrTTtF1gZi+f8FqlyAdouralcFWFQWF2+NgCHShjkCb+IFBLq9buZwE1xckQU4peSuQ==", + "dev": true, + "dependencies": { + "ansi-styles": "^3.2.1", + "escape-string-regexp": "^1.0.5", + "supports-color": "^5.3.0" + }, + "engines": { + "node": ">=4" + } + }, + "node_modules/@babel/code-frame/node_modules/color-convert": { + "version": "1.9.3", + "resolved": "https://registry.npmjs.org/color-convert/-/color-convert-1.9.3.tgz", + "integrity": "sha512-QfAUtd+vFdAtFQcC8CCyYt1fYWxSqAiK2cSD6zDB8N3cpsEBAvRxp9zOGg6G/SHHJYAT88/az/IuDGALsNVbGg==", + "dev": true, + "dependencies": { + "color-name": "1.1.3" + } + }, + "node_modules/@babel/code-frame/node_modules/color-name": { + "version": "1.1.3", + "resolved": "https://registry.npmjs.org/color-name/-/color-name-1.1.3.tgz", + "integrity": "sha512-72fSenhMw2HZMTVHeCA9KCmpEIbzWiQsjN+BHcBbS9vr1mtt+vJjPdksIBNUmKAW8TFUDPJK5SUU3QhE9NEXDw==", + "dev": true + }, + "node_modules/@babel/code-frame/node_modules/escape-string-regexp": { + "version": "1.0.5", + "resolved": "https://registry.npmjs.org/escape-string-regexp/-/escape-string-regexp-1.0.5.tgz", + "integrity": "sha512-vbRorB5FUQWvla16U8R/qgaFIya2qGzwDrNmCZuYKrbdSUMG6I1ZCGQRefkRVhuOkIGVne7BQ35DSfo1qvJqFg==", + "dev": true, + "engines": { + "node": ">=0.8.0" + } + }, + "node_modules/@babel/code-frame/node_modules/has-flag": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/has-flag/-/has-flag-3.0.0.tgz", + "integrity": "sha512-sKJf1+ceQBr4SMkvQnBDNDtf4TXpVhVGateu0t918bl30FnbE2m4vNLX+VWe/dpjlb+HugGYzW7uQXH98HPEYw==", + "dev": true, + "engines": { + "node": ">=4" + } + }, + "node_modules/@babel/code-frame/node_modules/supports-color": { + "version": "5.5.0", + "resolved": "https://registry.npmjs.org/supports-color/-/supports-color-5.5.0.tgz", + "integrity": "sha512-QjVjwdXIt408MIiAqCX4oUKsgU2EqAGzs2Ppkm4aQYbjm+ZEWEcW4SfFNTr4uMNZma0ey4f5lgLrkB0aX0QMow==", + "dev": true, + "dependencies": { + "has-flag": "^3.0.0" + }, + "engines": { + "node": ">=4" + } + }, "node_modules/@babel/compat-data": { "version": "7.21.7", "resolved": "https://registry.npmjs.org/@babel/compat-data/-/compat-data-7.21.7.tgz", @@ -850,21 +922,21 @@ } }, "node_modules/@babel/core/node_modules/semver": { - "version": "6.3.0", - "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.0.tgz", - "integrity": "sha512-b39TBaTSfV6yBrapU89p5fKekE2m/NwnDocOVruQFS1/veMgdzuPcnOM34M6CwxW8jH/lxEa5rBoDeUwu5HHTw==", + "version": "6.3.1", + "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.1.tgz", + "integrity": "sha512-BR7VvDCVHO+q2xBEWskxS6DJE1qRnb7DxzUrogb71CWoSficBxYsiAGd+Kl0mmq/MprG9yArRkyrQxTO6XjMzA==", "dev": true, "bin": { "semver": "bin/semver.js" } }, "node_modules/@babel/generator": { - "version": "7.21.5", - "resolved": "https://registry.npmjs.org/@babel/generator/-/generator-7.21.5.tgz", - "integrity": "sha512-SrKK/sRv8GesIW1bDagf9cCG38IOMYZusoe1dfg0D8aiUe3Amvoj1QtjTPAWcfrZFvIwlleLb0gxzQidL9w14w==", + "version": "7.23.6", + "resolved": "https://registry.npmjs.org/@babel/generator/-/generator-7.23.6.tgz", + "integrity": "sha512-qrSfCYxYQB5owCmGLbl8XRpX1ytXlpueOb0N0UmQwA073KZxejgQTzAmJezxvpwQD9uGtK2shHdi55QT+MbjIw==", "dev": true, "dependencies": { - "@babel/types": "^7.21.5", + "@babel/types": "^7.23.6", "@jridgewell/gen-mapping": "^0.3.2", "@jridgewell/trace-mapping": "^0.3.17", "jsesc": "^2.5.1" @@ -893,43 +965,43 @@ } }, "node_modules/@babel/helper-compilation-targets/node_modules/semver": { - "version": "6.3.0", - "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.0.tgz", - "integrity": "sha512-b39TBaTSfV6yBrapU89p5fKekE2m/NwnDocOVruQFS1/veMgdzuPcnOM34M6CwxW8jH/lxEa5rBoDeUwu5HHTw==", + "version": "6.3.1", + "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.1.tgz", + "integrity": "sha512-BR7VvDCVHO+q2xBEWskxS6DJE1qRnb7DxzUrogb71CWoSficBxYsiAGd+Kl0mmq/MprG9yArRkyrQxTO6XjMzA==", "dev": true, "bin": { "semver": "bin/semver.js" } }, "node_modules/@babel/helper-environment-visitor": { - "version": "7.21.5", - "resolved": "https://registry.npmjs.org/@babel/helper-environment-visitor/-/helper-environment-visitor-7.21.5.tgz", - "integrity": "sha512-IYl4gZ3ETsWocUWgsFZLM5i1BYx9SoemminVEXadgLBa9TdeorzgLKm8wWLA6J1N/kT3Kch8XIk1laNzYoHKvQ==", + "version": "7.22.20", + "resolved": "https://registry.npmjs.org/@babel/helper-environment-visitor/-/helper-environment-visitor-7.22.20.tgz", + "integrity": "sha512-zfedSIzFhat/gFhWfHtgWvlec0nqB9YEIVrpuwjruLlXfUSnA8cJB0miHKwqDnQ7d32aKo2xt88/xZptwxbfhA==", "dev": true, "engines": { "node": ">=6.9.0" } }, "node_modules/@babel/helper-function-name": { - "version": "7.21.0", - "resolved": "https://registry.npmjs.org/@babel/helper-function-name/-/helper-function-name-7.21.0.tgz", - "integrity": "sha512-HfK1aMRanKHpxemaY2gqBmL04iAPOPRj7DxtNbiDOrJK+gdwkiNRVpCpUJYbUT+aZyemKN8brqTOxzCaG6ExRg==", + "version": "7.23.0", + "resolved": "https://registry.npmjs.org/@babel/helper-function-name/-/helper-function-name-7.23.0.tgz", + "integrity": "sha512-OErEqsrxjZTJciZ4Oo+eoZqeW9UIiOcuYKRJA4ZAgV9myA+pOXhhmpfNCKjEH/auVfEYVFJ6y1Tc4r0eIApqiw==", "dev": true, "dependencies": { - "@babel/template": "^7.20.7", - "@babel/types": "^7.21.0" + "@babel/template": "^7.22.15", + "@babel/types": "^7.23.0" }, "engines": { "node": ">=6.9.0" } }, "node_modules/@babel/helper-hoist-variables": { - "version": "7.18.6", - "resolved": "https://registry.npmjs.org/@babel/helper-hoist-variables/-/helper-hoist-variables-7.18.6.tgz", - "integrity": "sha512-UlJQPkFqFULIcyW5sbzgbkxn2FKRgwWiRexcuaR8RNJRy8+LLveqPjwZV/bwrLZCN0eUHD/x8D0heK1ozuoo6Q==", + "version": "7.22.5", + "resolved": "https://registry.npmjs.org/@babel/helper-hoist-variables/-/helper-hoist-variables-7.22.5.tgz", + "integrity": "sha512-wGjk9QZVzvknA6yKIUURb8zY3grXCcOZt+/7Wcy8O2uctxhplmUPkOdlgoNhmdVee2c92JXbf1xpMtVNbfoxRw==", "dev": true, "dependencies": { - "@babel/types": "^7.18.6" + "@babel/types": "^7.22.5" }, "engines": { "node": ">=6.9.0" @@ -979,30 +1051,30 @@ } }, "node_modules/@babel/helper-split-export-declaration": { - "version": "7.18.6", - "resolved": "https://registry.npmjs.org/@babel/helper-split-export-declaration/-/helper-split-export-declaration-7.18.6.tgz", - "integrity": "sha512-bde1etTx6ZyTmobl9LLMMQsaizFVZrquTEHOqKeQESMKo4PlObf+8+JA25ZsIpZhT/WEd39+vOdLXAFG/nELpA==", + "version": "7.22.6", + "resolved": "https://registry.npmjs.org/@babel/helper-split-export-declaration/-/helper-split-export-declaration-7.22.6.tgz", + "integrity": "sha512-AsUnxuLhRYsisFiaJwvp1QF+I3KjD5FOxut14q/GzovUe6orHLesW2C7d754kRm53h5gqrz6sFl6sxc4BVtE/g==", "dev": true, "dependencies": { - "@babel/types": "^7.18.6" + "@babel/types": "^7.22.5" }, "engines": { "node": ">=6.9.0" } }, "node_modules/@babel/helper-string-parser": { - "version": "7.21.5", - "resolved": "https://registry.npmjs.org/@babel/helper-string-parser/-/helper-string-parser-7.21.5.tgz", - "integrity": "sha512-5pTUx3hAJaZIdW99sJ6ZUUgWq/Y+Hja7TowEnLNMm1VivRgZQL3vpBY3qUACVsvw+yQU6+YgfBVmcbLaZtrA1w==", + "version": "7.23.4", + "resolved": "https://registry.npmjs.org/@babel/helper-string-parser/-/helper-string-parser-7.23.4.tgz", + "integrity": "sha512-803gmbQdqwdf4olxrX4AJyFBV/RTr3rSmOj0rKwesmzlfhYNDEs+/iOcznzpNWlJlIlTJC2QfPFcHB6DlzdVLQ==", "dev": true, "engines": { "node": ">=6.9.0" } }, "node_modules/@babel/helper-validator-identifier": { - "version": "7.19.1", - "resolved": "https://registry.npmjs.org/@babel/helper-validator-identifier/-/helper-validator-identifier-7.19.1.tgz", - "integrity": "sha512-awrNfaMtnHUr653GgGEs++LlAvW6w+DcPrOliSMXWCKo597CwL5Acf/wWdNkf/tfEQE3mjkeD1YOVZOUV/od1w==", + "version": "7.22.20", + "resolved": "https://registry.npmjs.org/@babel/helper-validator-identifier/-/helper-validator-identifier-7.22.20.tgz", + "integrity": "sha512-Y4OZ+ytlatR8AI+8KZfKuL5urKp7qey08ha31L8b3BwewJAoJamTzyvxPR/5D+KkdJCGPq/+8TukHBlY10FX9A==", "dev": true, "engines": { "node": ">=6.9.0" @@ -1032,13 +1104,13 @@ } }, "node_modules/@babel/highlight": { - "version": "7.18.6", - "resolved": "https://registry.npmjs.org/@babel/highlight/-/highlight-7.18.6.tgz", - "integrity": "sha512-u7stbOuYjaPezCuLj29hNW1v64M2Md2qupEKP1fHc7WdOA3DgLh37suiSrZYY7haUB7iBeQZ9P1uiRF359do3g==", + "version": "7.23.4", + "resolved": "https://registry.npmjs.org/@babel/highlight/-/highlight-7.23.4.tgz", + "integrity": "sha512-acGdbYSfp2WheJoJm/EBBBLh/ID8KDc64ISZ9DYtBmC8/Q204PZJLHyzeB5qMzJ5trcOkybd78M4x2KWsUq++A==", "dev": true, "dependencies": { - "@babel/helper-validator-identifier": "^7.18.6", - "chalk": "^2.0.0", + "@babel/helper-validator-identifier": "^7.22.20", + "chalk": "^2.4.2", "js-tokens": "^4.0.0" }, "engines": { @@ -1117,9 +1189,9 @@ } }, "node_modules/@babel/parser": { - "version": "7.21.8", - "resolved": "https://registry.npmjs.org/@babel/parser/-/parser-7.21.8.tgz", - "integrity": "sha512-6zavDGdzG3gUqAdWvlLFfk+36RilI+Pwyuuh7HItyeScCWP3k6i8vKclAQ0bM/0y/Kz/xiwvxhMv9MgTJP5gmA==", + "version": "7.23.6", + "resolved": "https://registry.npmjs.org/@babel/parser/-/parser-7.23.6.tgz", + "integrity": "sha512-Z2uID7YJ7oNvAI20O9X0bblw7Qqs8Q2hFy0R9tAfnfLkp5MW0UH9eUvnDSnFwKZ0AvgS1ucqR4KzvVHgnke1VQ==", "dev": true, "bin": { "parser": "bin/babel-parser.js" @@ -1129,34 +1201,34 @@ } }, "node_modules/@babel/template": { - "version": "7.20.7", - "resolved": "https://registry.npmjs.org/@babel/template/-/template-7.20.7.tgz", - "integrity": "sha512-8SegXApWe6VoNw0r9JHpSteLKTpTiLZ4rMlGIm9JQ18KiCtyQiAMEazujAHrUS5flrcqYZa75ukev3P6QmUwUw==", + "version": "7.22.15", + "resolved": "https://registry.npmjs.org/@babel/template/-/template-7.22.15.tgz", + "integrity": "sha512-QPErUVm4uyJa60rkI73qneDacvdvzxshT3kksGqlGWYdOTIUOwJ7RDUL8sGqslY1uXWSL6xMFKEXDS3ox2uF0w==", "dev": true, "dependencies": { - "@babel/code-frame": "^7.18.6", - "@babel/parser": "^7.20.7", - "@babel/types": "^7.20.7" + "@babel/code-frame": "^7.22.13", + "@babel/parser": "^7.22.15", + "@babel/types": "^7.22.15" }, "engines": { "node": ">=6.9.0" } }, "node_modules/@babel/traverse": { - "version": "7.21.5", - "resolved": "https://registry.npmjs.org/@babel/traverse/-/traverse-7.21.5.tgz", - "integrity": "sha512-AhQoI3YjWi6u/y/ntv7k48mcrCXmus0t79J9qPNlk/lAsFlCiJ047RmbfMOawySTHtywXhbXgpx/8nXMYd+oFw==", - "dev": true, - "dependencies": { - "@babel/code-frame": "^7.21.4", - "@babel/generator": "^7.21.5", - "@babel/helper-environment-visitor": "^7.21.5", - "@babel/helper-function-name": "^7.21.0", - "@babel/helper-hoist-variables": "^7.18.6", - "@babel/helper-split-export-declaration": "^7.18.6", - "@babel/parser": "^7.21.5", - "@babel/types": "^7.21.5", - "debug": "^4.1.0", + "version": "7.23.7", + "resolved": "https://registry.npmjs.org/@babel/traverse/-/traverse-7.23.7.tgz", + "integrity": "sha512-tY3mM8rH9jM0YHFGyfC0/xf+SB5eKUu7HPj7/k3fpi9dAlsMc5YbQvDi0Sh2QTPXqMhyaAtzAr807TIyfQrmyg==", + "dev": true, + "dependencies": { + "@babel/code-frame": "^7.23.5", + "@babel/generator": "^7.23.6", + "@babel/helper-environment-visitor": "^7.22.20", + "@babel/helper-function-name": "^7.23.0", + "@babel/helper-hoist-variables": "^7.22.5", + "@babel/helper-split-export-declaration": "^7.22.6", + "@babel/parser": "^7.23.6", + "@babel/types": "^7.23.6", + "debug": "^4.3.1", "globals": "^11.1.0" }, "engines": { @@ -1173,13 +1245,13 @@ } }, "node_modules/@babel/types": { - "version": "7.21.5", - "resolved": "https://registry.npmjs.org/@babel/types/-/types-7.21.5.tgz", - "integrity": "sha512-m4AfNvVF2mVC/F7fDEdH2El3HzUg9It/XsCxZiOTTA3m3qYfcSVSbTfM6Q9xG+hYDniZssYhlXKKUMD5m8tF4Q==", + "version": "7.23.6", + "resolved": "https://registry.npmjs.org/@babel/types/-/types-7.23.6.tgz", + "integrity": "sha512-+uarb83brBzPKN38NX1MkB6vb6+mwvR6amUulqAE7ccQw1pEl+bCia9TbdG1lsnFP7lZySvUn37CHyXQdfTwzg==", "dev": true, "dependencies": { - "@babel/helper-string-parser": "^7.21.5", - "@babel/helper-validator-identifier": "^7.19.1", + "@babel/helper-string-parser": "^7.23.4", + "@babel/helper-validator-identifier": "^7.22.20", "to-fast-properties": "^2.0.0" }, "engines": { @@ -6124,9 +6196,9 @@ } }, "node_modules/istanbul-lib-instrument/node_modules/semver": { - "version": "6.3.0", - "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.0.tgz", - "integrity": "sha512-b39TBaTSfV6yBrapU89p5fKekE2m/NwnDocOVruQFS1/veMgdzuPcnOM34M6CwxW8jH/lxEa5rBoDeUwu5HHTw==", + "version": "6.3.1", + "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.1.tgz", + "integrity": "sha512-BR7VvDCVHO+q2xBEWskxS6DJE1qRnb7DxzUrogb71CWoSficBxYsiAGd+Kl0mmq/MprG9yArRkyrQxTO6XjMzA==", "dev": true, "bin": { "semver": "bin/semver.js" @@ -6433,9 +6505,9 @@ } }, "node_modules/make-dir/node_modules/semver": { - "version": "6.3.0", - "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.0.tgz", - "integrity": "sha512-b39TBaTSfV6yBrapU89p5fKekE2m/NwnDocOVruQFS1/veMgdzuPcnOM34M6CwxW8jH/lxEa5rBoDeUwu5HHTw==", + "version": "6.3.1", + "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.1.tgz", + "integrity": "sha512-BR7VvDCVHO+q2xBEWskxS6DJE1qRnb7DxzUrogb71CWoSficBxYsiAGd+Kl0mmq/MprG9yArRkyrQxTO6XjMzA==", "dev": true, "bin": { "semver": "bin/semver.js" @@ -8954,9 +9026,9 @@ } }, "node_modules/tsd/node_modules/semver": { - "version": "5.7.1", - "resolved": "https://registry.npmjs.org/semver/-/semver-5.7.1.tgz", - "integrity": "sha512-sauaDf/PZdVgrLTNYHRtpXa1iRiKcaebiKQ1BJdpQlWH2lCvexQdX55snPFyK7QzpudqbCI0qXFfOasHdyNDGQ==", + "version": "5.7.2", + "resolved": "https://registry.npmjs.org/semver/-/semver-5.7.2.tgz", + "integrity": "sha512-cBznnQ9KjJqU67B52RMC65CMarK2600WFnbkcaiwWq3xy/5haFJlshgnpjovMVJ+Hff49d8GEn0b87C5pDQ10g==", "dev": true, "bin": { "semver": "bin/semver" diff --git a/src/mongo_types.ts b/src/mongo_types.ts index 44f90afdbcb..f75257165c8 100644 --- a/src/mongo_types.ts +++ b/src/mongo_types.ts @@ -451,7 +451,7 @@ export class TypedEventEmitter extends EventEm if (monitorCommands) { this.emit(event, ...args); } - if (this.component && typeof args[0]?.serverConnectionId) { + if (this.component && args[0]?.serverConnectionId) { const loggableCommandEvent: | CommandStartedEvent | LoggableCommandFailedEvent From 383f8909a054a54cdaf7ca5b2954ef65126f1f8c Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Thu, 4 Jan 2024 16:44:47 -0500 Subject: [PATCH 10/25] use hello not serverConnectionId to ensure support for versions below 4.2 --- src/cmap/connection.ts | 13 +++++++------ src/mongo_types.ts | 3 ++- 2 files changed, 9 insertions(+), 7 deletions(-) diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 568df04434f..318964e4c96 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -451,14 +451,14 @@ export class Connection extends TypedEventEmitter { let started = 0; if ( this.monitorCommands || - (this.description.serverConnectionId && - this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) + (this.description.hello && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) ) { started = now(); this.emitAndLogCommand( this.monitorCommands, Connection.COMMAND_STARTED, message.databaseName, + this.description.hello, new CommandStartedEvent(this, message, this.description.serverConnectionId) ); } @@ -480,13 +480,13 @@ export class Connection extends TypedEventEmitter { if ( this.monitorCommands || - (this.description.serverConnectionId && - this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) + (this.description.hello && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) ) { this.emitAndLogCommand( this.monitorCommands, Connection.COMMAND_SUCCEEDED, message.databaseName, + this.description.hello, new CommandSucceededEvent( this, message, @@ -503,14 +503,14 @@ export class Connection extends TypedEventEmitter { } catch (error) { if ( this.monitorCommands || - (this.description.serverConnectionId && - this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) + (this.description.hello && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) ) { if (error.name === 'MongoWriteConcernError') { this.emitAndLogCommand( this.monitorCommands, Connection.COMMAND_SUCCEEDED, message.databaseName, + this.description.hello, new CommandSucceededEvent( this, message, @@ -524,6 +524,7 @@ export class Connection extends TypedEventEmitter { this.monitorCommands, Connection.COMMAND_FAILED, message.databaseName, + this.description.hello, new CommandFailedEvent( this, message, diff --git a/src/mongo_types.ts b/src/mongo_types.ts index f75257165c8..2878ba2f123 100644 --- a/src/mongo_types.ts +++ b/src/mongo_types.ts @@ -446,12 +446,13 @@ export class TypedEventEmitter extends EventEm monitorCommands: boolean, event: EventKey | symbol, databaseName: string, + hello: Document | null, ...args: Parameters ): void { if (monitorCommands) { this.emit(event, ...args); } - if (this.component && args[0]?.serverConnectionId) { + if (this.component && hello) { const loggableCommandEvent: | CommandStartedEvent | LoggableCommandFailedEvent From 7033dc8d8958d9a01c01c0758f5e64e22d84c775 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Fri, 5 Jan 2024 15:15:04 -0500 Subject: [PATCH 11/25] test versioning fix and package.lock fix --- package-lock.json | 228 ++++++------------ src/cmap/connection_pool.ts | 2 +- ...mmand_logging_and_monitoring.prose.test.ts | 6 +- test/unit/cmap/connection_pool.test.js | 3 +- 4 files changed, 84 insertions(+), 155 deletions(-) diff --git a/package-lock.json b/package-lock.json index 52f8b821dff..21b9b983b67 100644 --- a/package-lock.json +++ b/package-lock.json @@ -799,89 +799,17 @@ } }, "node_modules/@babel/code-frame": { - "version": "7.23.5", - "resolved": "https://registry.npmjs.org/@babel/code-frame/-/code-frame-7.23.5.tgz", - "integrity": "sha512-CgH3s1a96LipHCmSUmYFPwY7MNx8C3avkq7i4Wl3cfa662ldtUe4VM1TPXX70pfmrlWTb6jLqTYrZyT2ZTJBgA==", + "version": "7.21.4", + "resolved": "https://registry.npmjs.org/@babel/code-frame/-/code-frame-7.21.4.tgz", + "integrity": "sha512-LYvhNKfwWSPpocw8GI7gpK2nq3HSDuEPC/uSYaALSJu9xjsalaaYFOq0Pwt5KmVqwEbZlDu81aLXwBOmD/Fv9g==", "dev": true, "dependencies": { - "@babel/highlight": "^7.23.4", - "chalk": "^2.4.2" + "@babel/highlight": "^7.18.6" }, "engines": { "node": ">=6.9.0" } }, - "node_modules/@babel/code-frame/node_modules/ansi-styles": { - "version": "3.2.1", - "resolved": "https://registry.npmjs.org/ansi-styles/-/ansi-styles-3.2.1.tgz", - "integrity": "sha512-VT0ZI6kZRdTh8YyJw3SMbYm/u+NqfsAxEpWO0Pf9sq8/e94WxxOpPKx9FR1FlyCtOVDNOQ+8ntlqFxiRc+r5qA==", - "dev": true, - "dependencies": { - "color-convert": "^1.9.0" - }, - "engines": { - "node": ">=4" - } - }, - "node_modules/@babel/code-frame/node_modules/chalk": { - "version": "2.4.2", - "resolved": "https://registry.npmjs.org/chalk/-/chalk-2.4.2.tgz", - "integrity": "sha512-Mti+f9lpJNcwF4tWV8/OrTTtF1gZi+f8FqlyAdouralcFWFQWF2+NgCHShjkCb+IFBLq9buZwE1xckQU4peSuQ==", - "dev": true, - "dependencies": { - "ansi-styles": "^3.2.1", - "escape-string-regexp": "^1.0.5", - "supports-color": "^5.3.0" - }, - "engines": { - "node": ">=4" - } - }, - "node_modules/@babel/code-frame/node_modules/color-convert": { - "version": "1.9.3", - "resolved": "https://registry.npmjs.org/color-convert/-/color-convert-1.9.3.tgz", - "integrity": "sha512-QfAUtd+vFdAtFQcC8CCyYt1fYWxSqAiK2cSD6zDB8N3cpsEBAvRxp9zOGg6G/SHHJYAT88/az/IuDGALsNVbGg==", - "dev": true, - "dependencies": { - "color-name": "1.1.3" - } - }, - "node_modules/@babel/code-frame/node_modules/color-name": { - "version": "1.1.3", - "resolved": "https://registry.npmjs.org/color-name/-/color-name-1.1.3.tgz", - "integrity": "sha512-72fSenhMw2HZMTVHeCA9KCmpEIbzWiQsjN+BHcBbS9vr1mtt+vJjPdksIBNUmKAW8TFUDPJK5SUU3QhE9NEXDw==", - "dev": true - }, - "node_modules/@babel/code-frame/node_modules/escape-string-regexp": { - "version": "1.0.5", - "resolved": "https://registry.npmjs.org/escape-string-regexp/-/escape-string-regexp-1.0.5.tgz", - "integrity": "sha512-vbRorB5FUQWvla16U8R/qgaFIya2qGzwDrNmCZuYKrbdSUMG6I1ZCGQRefkRVhuOkIGVne7BQ35DSfo1qvJqFg==", - "dev": true, - "engines": { - "node": ">=0.8.0" - } - }, - "node_modules/@babel/code-frame/node_modules/has-flag": { - "version": "3.0.0", - "resolved": "https://registry.npmjs.org/has-flag/-/has-flag-3.0.0.tgz", - "integrity": "sha512-sKJf1+ceQBr4SMkvQnBDNDtf4TXpVhVGateu0t918bl30FnbE2m4vNLX+VWe/dpjlb+HugGYzW7uQXH98HPEYw==", - "dev": true, - "engines": { - "node": ">=4" - } - }, - "node_modules/@babel/code-frame/node_modules/supports-color": { - "version": "5.5.0", - "resolved": "https://registry.npmjs.org/supports-color/-/supports-color-5.5.0.tgz", - "integrity": "sha512-QjVjwdXIt408MIiAqCX4oUKsgU2EqAGzs2Ppkm4aQYbjm+ZEWEcW4SfFNTr4uMNZma0ey4f5lgLrkB0aX0QMow==", - "dev": true, - "dependencies": { - "has-flag": "^3.0.0" - }, - "engines": { - "node": ">=4" - } - }, "node_modules/@babel/compat-data": { "version": "7.21.7", "resolved": "https://registry.npmjs.org/@babel/compat-data/-/compat-data-7.21.7.tgz", @@ -922,21 +850,21 @@ } }, "node_modules/@babel/core/node_modules/semver": { - "version": "6.3.1", - "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.1.tgz", - "integrity": "sha512-BR7VvDCVHO+q2xBEWskxS6DJE1qRnb7DxzUrogb71CWoSficBxYsiAGd+Kl0mmq/MprG9yArRkyrQxTO6XjMzA==", + "version": "6.3.0", + "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.0.tgz", + "integrity": "sha512-b39TBaTSfV6yBrapU89p5fKekE2m/NwnDocOVruQFS1/veMgdzuPcnOM34M6CwxW8jH/lxEa5rBoDeUwu5HHTw==", "dev": true, "bin": { "semver": "bin/semver.js" } }, "node_modules/@babel/generator": { - "version": "7.23.6", - "resolved": "https://registry.npmjs.org/@babel/generator/-/generator-7.23.6.tgz", - "integrity": "sha512-qrSfCYxYQB5owCmGLbl8XRpX1ytXlpueOb0N0UmQwA073KZxejgQTzAmJezxvpwQD9uGtK2shHdi55QT+MbjIw==", + "version": "7.21.5", + "resolved": "https://registry.npmjs.org/@babel/generator/-/generator-7.21.5.tgz", + "integrity": "sha512-SrKK/sRv8GesIW1bDagf9cCG38IOMYZusoe1dfg0D8aiUe3Amvoj1QtjTPAWcfrZFvIwlleLb0gxzQidL9w14w==", "dev": true, "dependencies": { - "@babel/types": "^7.23.6", + "@babel/types": "^7.21.5", "@jridgewell/gen-mapping": "^0.3.2", "@jridgewell/trace-mapping": "^0.3.17", "jsesc": "^2.5.1" @@ -965,43 +893,43 @@ } }, "node_modules/@babel/helper-compilation-targets/node_modules/semver": { - "version": "6.3.1", - "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.1.tgz", - "integrity": "sha512-BR7VvDCVHO+q2xBEWskxS6DJE1qRnb7DxzUrogb71CWoSficBxYsiAGd+Kl0mmq/MprG9yArRkyrQxTO6XjMzA==", + "version": "6.3.0", + "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.0.tgz", + "integrity": "sha512-b39TBaTSfV6yBrapU89p5fKekE2m/NwnDocOVruQFS1/veMgdzuPcnOM34M6CwxW8jH/lxEa5rBoDeUwu5HHTw==", "dev": true, "bin": { "semver": "bin/semver.js" } }, "node_modules/@babel/helper-environment-visitor": { - "version": "7.22.20", - "resolved": "https://registry.npmjs.org/@babel/helper-environment-visitor/-/helper-environment-visitor-7.22.20.tgz", - "integrity": "sha512-zfedSIzFhat/gFhWfHtgWvlec0nqB9YEIVrpuwjruLlXfUSnA8cJB0miHKwqDnQ7d32aKo2xt88/xZptwxbfhA==", + "version": "7.21.5", + "resolved": "https://registry.npmjs.org/@babel/helper-environment-visitor/-/helper-environment-visitor-7.21.5.tgz", + "integrity": "sha512-IYl4gZ3ETsWocUWgsFZLM5i1BYx9SoemminVEXadgLBa9TdeorzgLKm8wWLA6J1N/kT3Kch8XIk1laNzYoHKvQ==", "dev": true, "engines": { "node": ">=6.9.0" } }, "node_modules/@babel/helper-function-name": { - "version": "7.23.0", - "resolved": "https://registry.npmjs.org/@babel/helper-function-name/-/helper-function-name-7.23.0.tgz", - "integrity": "sha512-OErEqsrxjZTJciZ4Oo+eoZqeW9UIiOcuYKRJA4ZAgV9myA+pOXhhmpfNCKjEH/auVfEYVFJ6y1Tc4r0eIApqiw==", + "version": "7.21.0", + "resolved": "https://registry.npmjs.org/@babel/helper-function-name/-/helper-function-name-7.21.0.tgz", + "integrity": "sha512-HfK1aMRanKHpxemaY2gqBmL04iAPOPRj7DxtNbiDOrJK+gdwkiNRVpCpUJYbUT+aZyemKN8brqTOxzCaG6ExRg==", "dev": true, "dependencies": { - "@babel/template": "^7.22.15", - "@babel/types": "^7.23.0" + "@babel/template": "^7.20.7", + "@babel/types": "^7.21.0" }, "engines": { "node": ">=6.9.0" } }, "node_modules/@babel/helper-hoist-variables": { - "version": "7.22.5", - "resolved": "https://registry.npmjs.org/@babel/helper-hoist-variables/-/helper-hoist-variables-7.22.5.tgz", - "integrity": "sha512-wGjk9QZVzvknA6yKIUURb8zY3grXCcOZt+/7Wcy8O2uctxhplmUPkOdlgoNhmdVee2c92JXbf1xpMtVNbfoxRw==", + "version": "7.18.6", + "resolved": "https://registry.npmjs.org/@babel/helper-hoist-variables/-/helper-hoist-variables-7.18.6.tgz", + "integrity": "sha512-UlJQPkFqFULIcyW5sbzgbkxn2FKRgwWiRexcuaR8RNJRy8+LLveqPjwZV/bwrLZCN0eUHD/x8D0heK1ozuoo6Q==", "dev": true, "dependencies": { - "@babel/types": "^7.22.5" + "@babel/types": "^7.18.6" }, "engines": { "node": ">=6.9.0" @@ -1051,30 +979,30 @@ } }, "node_modules/@babel/helper-split-export-declaration": { - "version": "7.22.6", - "resolved": "https://registry.npmjs.org/@babel/helper-split-export-declaration/-/helper-split-export-declaration-7.22.6.tgz", - "integrity": "sha512-AsUnxuLhRYsisFiaJwvp1QF+I3KjD5FOxut14q/GzovUe6orHLesW2C7d754kRm53h5gqrz6sFl6sxc4BVtE/g==", + "version": "7.18.6", + "resolved": "https://registry.npmjs.org/@babel/helper-split-export-declaration/-/helper-split-export-declaration-7.18.6.tgz", + "integrity": "sha512-bde1etTx6ZyTmobl9LLMMQsaizFVZrquTEHOqKeQESMKo4PlObf+8+JA25ZsIpZhT/WEd39+vOdLXAFG/nELpA==", "dev": true, "dependencies": { - "@babel/types": "^7.22.5" + "@babel/types": "^7.18.6" }, "engines": { "node": ">=6.9.0" } }, "node_modules/@babel/helper-string-parser": { - "version": "7.23.4", - "resolved": "https://registry.npmjs.org/@babel/helper-string-parser/-/helper-string-parser-7.23.4.tgz", - "integrity": "sha512-803gmbQdqwdf4olxrX4AJyFBV/RTr3rSmOj0rKwesmzlfhYNDEs+/iOcznzpNWlJlIlTJC2QfPFcHB6DlzdVLQ==", + "version": "7.21.5", + "resolved": "https://registry.npmjs.org/@babel/helper-string-parser/-/helper-string-parser-7.21.5.tgz", + "integrity": "sha512-5pTUx3hAJaZIdW99sJ6ZUUgWq/Y+Hja7TowEnLNMm1VivRgZQL3vpBY3qUACVsvw+yQU6+YgfBVmcbLaZtrA1w==", "dev": true, "engines": { "node": ">=6.9.0" } }, "node_modules/@babel/helper-validator-identifier": { - "version": "7.22.20", - "resolved": "https://registry.npmjs.org/@babel/helper-validator-identifier/-/helper-validator-identifier-7.22.20.tgz", - "integrity": "sha512-Y4OZ+ytlatR8AI+8KZfKuL5urKp7qey08ha31L8b3BwewJAoJamTzyvxPR/5D+KkdJCGPq/+8TukHBlY10FX9A==", + "version": "7.19.1", + "resolved": "https://registry.npmjs.org/@babel/helper-validator-identifier/-/helper-validator-identifier-7.19.1.tgz", + "integrity": "sha512-awrNfaMtnHUr653GgGEs++LlAvW6w+DcPrOliSMXWCKo597CwL5Acf/wWdNkf/tfEQE3mjkeD1YOVZOUV/od1w==", "dev": true, "engines": { "node": ">=6.9.0" @@ -1104,13 +1032,13 @@ } }, "node_modules/@babel/highlight": { - "version": "7.23.4", - "resolved": "https://registry.npmjs.org/@babel/highlight/-/highlight-7.23.4.tgz", - "integrity": "sha512-acGdbYSfp2WheJoJm/EBBBLh/ID8KDc64ISZ9DYtBmC8/Q204PZJLHyzeB5qMzJ5trcOkybd78M4x2KWsUq++A==", + "version": "7.18.6", + "resolved": "https://registry.npmjs.org/@babel/highlight/-/highlight-7.18.6.tgz", + "integrity": "sha512-u7stbOuYjaPezCuLj29hNW1v64M2Md2qupEKP1fHc7WdOA3DgLh37suiSrZYY7haUB7iBeQZ9P1uiRF359do3g==", "dev": true, "dependencies": { - "@babel/helper-validator-identifier": "^7.22.20", - "chalk": "^2.4.2", + "@babel/helper-validator-identifier": "^7.18.6", + "chalk": "^2.0.0", "js-tokens": "^4.0.0" }, "engines": { @@ -1189,9 +1117,9 @@ } }, "node_modules/@babel/parser": { - "version": "7.23.6", - "resolved": "https://registry.npmjs.org/@babel/parser/-/parser-7.23.6.tgz", - "integrity": "sha512-Z2uID7YJ7oNvAI20O9X0bblw7Qqs8Q2hFy0R9tAfnfLkp5MW0UH9eUvnDSnFwKZ0AvgS1ucqR4KzvVHgnke1VQ==", + "version": "7.21.8", + "resolved": "https://registry.npmjs.org/@babel/parser/-/parser-7.21.8.tgz", + "integrity": "sha512-6zavDGdzG3gUqAdWvlLFfk+36RilI+Pwyuuh7HItyeScCWP3k6i8vKclAQ0bM/0y/Kz/xiwvxhMv9MgTJP5gmA==", "dev": true, "bin": { "parser": "bin/babel-parser.js" @@ -1201,34 +1129,34 @@ } }, "node_modules/@babel/template": { - "version": "7.22.15", - "resolved": "https://registry.npmjs.org/@babel/template/-/template-7.22.15.tgz", - "integrity": "sha512-QPErUVm4uyJa60rkI73qneDacvdvzxshT3kksGqlGWYdOTIUOwJ7RDUL8sGqslY1uXWSL6xMFKEXDS3ox2uF0w==", + "version": "7.20.7", + "resolved": "https://registry.npmjs.org/@babel/template/-/template-7.20.7.tgz", + "integrity": "sha512-8SegXApWe6VoNw0r9JHpSteLKTpTiLZ4rMlGIm9JQ18KiCtyQiAMEazujAHrUS5flrcqYZa75ukev3P6QmUwUw==", "dev": true, "dependencies": { - "@babel/code-frame": "^7.22.13", - "@babel/parser": "^7.22.15", - "@babel/types": "^7.22.15" + "@babel/code-frame": "^7.18.6", + "@babel/parser": "^7.20.7", + "@babel/types": "^7.20.7" }, "engines": { "node": ">=6.9.0" } }, "node_modules/@babel/traverse": { - "version": "7.23.7", - "resolved": "https://registry.npmjs.org/@babel/traverse/-/traverse-7.23.7.tgz", - "integrity": "sha512-tY3mM8rH9jM0YHFGyfC0/xf+SB5eKUu7HPj7/k3fpi9dAlsMc5YbQvDi0Sh2QTPXqMhyaAtzAr807TIyfQrmyg==", - "dev": true, - "dependencies": { - "@babel/code-frame": "^7.23.5", - "@babel/generator": "^7.23.6", - "@babel/helper-environment-visitor": "^7.22.20", - "@babel/helper-function-name": "^7.23.0", - "@babel/helper-hoist-variables": "^7.22.5", - "@babel/helper-split-export-declaration": "^7.22.6", - "@babel/parser": "^7.23.6", - "@babel/types": "^7.23.6", - "debug": "^4.3.1", + "version": "7.21.5", + "resolved": "https://registry.npmjs.org/@babel/traverse/-/traverse-7.21.5.tgz", + "integrity": "sha512-AhQoI3YjWi6u/y/ntv7k48mcrCXmus0t79J9qPNlk/lAsFlCiJ047RmbfMOawySTHtywXhbXgpx/8nXMYd+oFw==", + "dev": true, + "dependencies": { + "@babel/code-frame": "^7.21.4", + "@babel/generator": "^7.21.5", + "@babel/helper-environment-visitor": "^7.21.5", + "@babel/helper-function-name": "^7.21.0", + "@babel/helper-hoist-variables": "^7.18.6", + "@babel/helper-split-export-declaration": "^7.18.6", + "@babel/parser": "^7.21.5", + "@babel/types": "^7.21.5", + "debug": "^4.1.0", "globals": "^11.1.0" }, "engines": { @@ -1245,13 +1173,13 @@ } }, "node_modules/@babel/types": { - "version": "7.23.6", - "resolved": "https://registry.npmjs.org/@babel/types/-/types-7.23.6.tgz", - "integrity": "sha512-+uarb83brBzPKN38NX1MkB6vb6+mwvR6amUulqAE7ccQw1pEl+bCia9TbdG1lsnFP7lZySvUn37CHyXQdfTwzg==", + "version": "7.21.5", + "resolved": "https://registry.npmjs.org/@babel/types/-/types-7.21.5.tgz", + "integrity": "sha512-m4AfNvVF2mVC/F7fDEdH2El3HzUg9It/XsCxZiOTTA3m3qYfcSVSbTfM6Q9xG+hYDniZssYhlXKKUMD5m8tF4Q==", "dev": true, "dependencies": { - "@babel/helper-string-parser": "^7.23.4", - "@babel/helper-validator-identifier": "^7.22.20", + "@babel/helper-string-parser": "^7.21.5", + "@babel/helper-validator-identifier": "^7.19.1", "to-fast-properties": "^2.0.0" }, "engines": { @@ -6196,9 +6124,9 @@ } }, "node_modules/istanbul-lib-instrument/node_modules/semver": { - "version": "6.3.1", - "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.1.tgz", - "integrity": "sha512-BR7VvDCVHO+q2xBEWskxS6DJE1qRnb7DxzUrogb71CWoSficBxYsiAGd+Kl0mmq/MprG9yArRkyrQxTO6XjMzA==", + "version": "6.3.0", + "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.0.tgz", + "integrity": "sha512-b39TBaTSfV6yBrapU89p5fKekE2m/NwnDocOVruQFS1/veMgdzuPcnOM34M6CwxW8jH/lxEa5rBoDeUwu5HHTw==", "dev": true, "bin": { "semver": "bin/semver.js" @@ -6505,9 +6433,9 @@ } }, "node_modules/make-dir/node_modules/semver": { - "version": "6.3.1", - "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.1.tgz", - "integrity": "sha512-BR7VvDCVHO+q2xBEWskxS6DJE1qRnb7DxzUrogb71CWoSficBxYsiAGd+Kl0mmq/MprG9yArRkyrQxTO6XjMzA==", + "version": "6.3.0", + "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.0.tgz", + "integrity": "sha512-b39TBaTSfV6yBrapU89p5fKekE2m/NwnDocOVruQFS1/veMgdzuPcnOM34M6CwxW8jH/lxEa5rBoDeUwu5HHTw==", "dev": true, "bin": { "semver": "bin/semver.js" @@ -9026,9 +8954,9 @@ } }, "node_modules/tsd/node_modules/semver": { - "version": "5.7.2", - "resolved": "https://registry.npmjs.org/semver/-/semver-5.7.2.tgz", - "integrity": "sha512-cBznnQ9KjJqU67B52RMC65CMarK2600WFnbkcaiwWq3xy/5haFJlshgnpjovMVJ+Hff49d8GEn0b87C5pDQ10g==", + "version": "5.7.1", + "resolved": "https://registry.npmjs.org/semver/-/semver-5.7.1.tgz", + "integrity": "sha512-sauaDf/PZdVgrLTNYHRtpXa1iRiKcaebiKQ1BJdpQlWH2lCvexQdX55snPFyK7QzpudqbCI0qXFfOasHdyNDGQ==", "dev": true, "bin": { "semver": "bin/semver" diff --git a/src/cmap/connection_pool.ts b/src/cmap/connection_pool.ts index 6d9312cbaf8..5c7de8dd54c 100644 --- a/src/cmap/connection_pool.ts +++ b/src/cmap/connection_pool.ts @@ -700,7 +700,7 @@ export class ConnectionPool extends TypedEventEmitter { id: this[kConnectionCounter].next().value, generation: this[kGeneration], cancellationToken: this[kCancellationToken], - mongoLogger: this[kServer].topology.client.mongoLogger + mongoLogger: this.mongoLogger }; this[kPending]++; diff --git a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts index 2f512f7e5f5..d2aa7e64aa8 100644 --- a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts +++ b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts @@ -27,7 +27,7 @@ describe('Command Logging and Monitoring Prose Tests', function () { */ it('should follow default truncation limit of 1000', { - metadata: {}, + metadata: { requires: { mongodb: '>4.2.0' } }, test: async function () { const writable = { buffer: [], @@ -110,7 +110,7 @@ describe('Command Logging and Monitoring Prose Tests', function () { and confirm that the server error is a string of length 5 + (length of trailing ellipsis). */ it('should follow custom truncation limit', { - metadata: {}, + metadata: { requires: { mongodb: '>4.2.0' } }, test: async function () { const writable = { buffer: [], @@ -164,7 +164,7 @@ describe('Command Logging and Monitoring Prose Tests', function () { where the max length falls in the middle of a multi-byte codepoint are handled gracefully. */ it('should handle unicode codepoints in middle and end of truncation gracefully', { - metadata: {}, + metadata: { requires: { mongodb: '>4.2.0' } }, test: async function () { const writable = { buffer: [], diff --git a/test/unit/cmap/connection_pool.test.js b/test/unit/cmap/connection_pool.test.js index 9acf50e50af..cdbf00bf67f 100644 --- a/test/unit/cmap/connection_pool.test.js +++ b/test/unit/cmap/connection_pool.test.js @@ -18,7 +18,8 @@ describe('Connection Pool', function () { topology: { client: { mongoLogger: { - debug: () => null + debug: () => null, + willLog: () => null } } } From 0ae87929ede657020cffdd657bcba291dd525613 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Tue, 9 Jan 2024 11:30:34 -0500 Subject: [PATCH 12/25] test fix --- src/mongo_logger.ts | 4 +- ...mmand_logging_and_monitoring.prose.test.ts | 46 ++++++++++++++++--- 2 files changed, 42 insertions(+), 8 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 399b1c4978b..73f46029734 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -413,7 +413,9 @@ export function stringifyWithMaxLen( maxDocumentLength: number, options: EJSONOptions = {} ): string { - let strToTruncate: string; + // eslint-disable-next-line @typescript-eslint/no-inferrable-types + let strToTruncate: string = ''; + if (typeof value === 'function') { strToTruncate = value.toString(); } else { diff --git a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts index d2aa7e64aa8..8ef5c51e03a 100644 --- a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts +++ b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts @@ -57,8 +57,17 @@ describe('Command Logging and Monitoring Prose Tests', function () { // 3. await client.db('admin').collection('test').insertMany(docs); + // remove sensitive commands for uniformity + const cleanedBuffer = []; + const afterInsertBufferLength = writable.buffer.length; + for (let i = 0; i < afterInsertBufferLength; i++) { + if (writable.buffer[i].command !== '{}' && writable.buffer[i].reply !== '{}') { + cleanedBuffer.push(writable.buffer[i]); + } + } + // 4. - const insertManyCommandStarted = writable.buffer[2]; + const insertManyCommandStarted = cleanedBuffer[0]; expect(insertManyCommandStarted?.message).to.equal('Command started'); expect(insertManyCommandStarted?.command).to.be.a('string'); expect(insertManyCommandStarted?.command?.length).to.equal( @@ -66,7 +75,7 @@ describe('Command Logging and Monitoring Prose Tests', function () { ); // 5. - const insertManyCommandSucceeded = writable.buffer[3]; + const insertManyCommandSucceeded = cleanedBuffer[1]; expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); expect(insertManyCommandSucceeded?.reply).to.be.a('string'); expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most( @@ -76,8 +85,15 @@ describe('Command Logging and Monitoring Prose Tests', function () { // 6. await client.db('admin').collection('test').find()._initialize(); + // remove sensitive commands again for uniformity + for (let j = afterInsertBufferLength; j < writable.buffer.length; j++) { + if (writable.buffer[j].command !== '{}' && writable.buffer[j].reply !== '{}') { + cleanedBuffer.push(writable.buffer[j]); + } + } + // 7. - const findCommandSucceeded = writable.buffer[5]; + const findCommandSucceeded = cleanedBuffer[3]; expect(findCommandSucceeded?.message).to.equal('Command succeeded'); expect(findCommandSucceeded?.reply).to.be.a('string'); expect(findCommandSucceeded?.reply?.length).to.equal( @@ -135,14 +151,22 @@ describe('Command Logging and Monitoring Prose Tests', function () { // 2. await client.db('admin').command({ hello: 'true' }); + // remove sensitive commands for uniformity + const cleanedBuffer = []; + for (let i = 0; i < writable.buffer.length; i++) { + if (writable.buffer[i].command !== '{}' && writable.buffer[i].reply !== '{}') { + cleanedBuffer.push(writable.buffer[i]); + } + } + // 3. - const insertManyCommandStarted = writable.buffer[2]; + const insertManyCommandStarted = cleanedBuffer[0]; expect(insertManyCommandStarted?.message).to.equal('Command started'); expect(insertManyCommandStarted?.command).to.be.a('string'); expect(insertManyCommandStarted?.command?.length).to.equal(5 + ELLIPSES_LENGTH); // 4. - const insertManyCommandSucceeded = writable.buffer[3]; + const insertManyCommandSucceeded = cleanedBuffer[1]; expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); expect(insertManyCommandSucceeded?.reply).to.be.a('string'); expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most(5 + ELLIPSES_LENGTH); @@ -189,12 +213,20 @@ describe('Command Logging and Monitoring Prose Tests', function () { await client.db('admin').collection('test').insertMany(docs); - const insertManyCommandStarted = writable.buffer[2]; + // remove sensitive commands for uniformity + const cleanedBuffer = []; + for (let i = 0; i < writable.buffer.length; i++) { + if (writable.buffer[i].command !== '{}' && writable.buffer[i].reply !== '{}') { + cleanedBuffer.push(writable.buffer[i]); + } + } + + const insertManyCommandStarted = cleanedBuffer[0]; expect(insertManyCommandStarted?.message).to.equal('Command started'); expect(insertManyCommandStarted?.command).to.be.a('string'); expect(insertManyCommandStarted?.command?.length).to.equal(50 + ELLIPSES_LENGTH); - const insertManyCommandSucceeded = writable.buffer[3]; + const insertManyCommandSucceeded = cleanedBuffer[1]; expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); expect(insertManyCommandSucceeded?.reply).to.be.a('string'); expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most(50 + ELLIPSES_LENGTH); From e92849d5c42ab7aa6792a49ec61a402be8d18a95 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Tue, 9 Jan 2024 11:51:40 -0500 Subject: [PATCH 13/25] versioning fix --- .../command_logging_and_monitoring.prose.test.ts | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts index 8ef5c51e03a..9d24862fed0 100644 --- a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts +++ b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts @@ -27,7 +27,7 @@ describe('Command Logging and Monitoring Prose Tests', function () { */ it('should follow default truncation limit of 1000', { - metadata: { requires: { mongodb: '>4.2.0' } }, + metadata: {}, test: async function () { const writable = { buffer: [], @@ -126,7 +126,7 @@ describe('Command Logging and Monitoring Prose Tests', function () { and confirm that the server error is a string of length 5 + (length of trailing ellipsis). */ it('should follow custom truncation limit', { - metadata: { requires: { mongodb: '>4.2.0' } }, + metadata: {}, test: async function () { const writable = { buffer: [], @@ -188,7 +188,7 @@ describe('Command Logging and Monitoring Prose Tests', function () { where the max length falls in the middle of a multi-byte codepoint are handled gracefully. */ it('should handle unicode codepoints in middle and end of truncation gracefully', { - metadata: { requires: { mongodb: '>4.2.0' } }, + metadata: {}, test: async function () { const writable = { buffer: [], From 9776ec973c7ba7a389c7f3d169559292956dc046 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Thu, 11 Jan 2024 02:00:12 -0500 Subject: [PATCH 14/25] PR requested changes, all tests passing --- src/mongo_logger.ts | 2 +- .../logging/redacted-commands.json | 3 ++- test/tools/unified-spec-runner/entities.ts | 16 +++++++++++++--- test/tools/unified-spec-runner/match.ts | 2 +- test/tools/unified-spec-runner/runner.ts | 2 +- test/unit/tools/unified_spec_runner.test.ts | 4 ++-- 6 files changed, 20 insertions(+), 9 deletions(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index 73f46029734..16b56ff388d 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -537,7 +537,7 @@ function defaultLogTransform( log = attachCommandFields(log, logObject); log.message = 'Command failed'; log.durationMS = logObject.duration; - log.failure = logObject.failure.message; + log.failure = logObject.failure.message ?? '{}'; return log; case CONNECTION_POOL_CREATED: log = attachConnectionFields(log, logObject); diff --git a/test/spec/command-logging-and-monitoring/logging/redacted-commands.json b/test/spec/command-logging-and-monitoring/logging/redacted-commands.json index 43b9ff74f29..7c96195d489 100644 --- a/test/spec/command-logging-and-monitoring/logging/redacted-commands.json +++ b/test/spec/command-logging-and-monitoring/logging/redacted-commands.json @@ -14,7 +14,8 @@ "useMultipleMongoses": false, "observeLogMessages": { "command": "debug" - } + }, + "observeSensitiveCommands": true } }, { diff --git a/test/tools/unified-spec-runner/entities.ts b/test/tools/unified-spec-runner/entities.ts index de137966ce1..5809e392128 100644 --- a/test/tools/unified-spec-runner/entities.ts +++ b/test/tools/unified-spec-runner/entities.ts @@ -232,18 +232,17 @@ export class UnifiedMongoClient extends MongoClient { mongodbLogMaxDocumentLength: 1250 } as any); this.logCollector = logCollector; + this.observeSensitiveCommands = description.observeSensitiveCommands ?? false; this.ignoredEvents = [ ...(description.ignoreCommandMonitoringEvents ?? []), 'configureFailPoint' ]; - if (!description.observeSensitiveCommands) { + if (!this.observeSensitiveCommands) { this.ignoredEvents.push(...Array.from(SENSITIVE_COMMANDS)); } - this.observeSensitiveCommands = description.observeSensitiveCommands ?? false; - this.observedCommandEvents = (description.observeEvents ?? []) .map(e => UnifiedMongoClient.COMMAND_EVENT_NAME_LOOKUP[e]) .filter(e => !!e); @@ -283,6 +282,17 @@ export class UnifiedMongoClient extends MongoClient { return false; } + isSensitiveLog(log: LogMessage): boolean { + if ( + (log.data?.message === 'Command started' && log.data?.command === '{}') || + (log.data?.message === 'Command succeeded' && log.data?.reply === '{}') || + (log.data?.message === 'Command failed' && log.data?.failure === '{}') + ) { + return true; + } + return false; + } + isIgnored(e: CommandEvent): boolean { return this.ignoredEvents.includes(e.commandName); } diff --git a/test/tools/unified-spec-runner/match.ts b/test/tools/unified-spec-runner/match.ts index 1c81da40bce..e5e23bfefa4 100644 --- a/test/tools/unified-spec-runner/match.ts +++ b/test/tools/unified-spec-runner/match.ts @@ -694,7 +694,7 @@ export function compareLogs( expect(actualLog.data.failure, 'Expected failure to exist').to.exist; if (expectedLog.failureIsRedacted) { // Assert that failure has been redacted - expect(actualLog.data.failure, 'Expected failure to have been redacted').to.deep.equal({}); + expect(actualLog.data.failure, 'Expected failure to have been redacted').to.equal('{}'); } else { // Assert that failure has not been redacted expect( diff --git a/test/tools/unified-spec-runner/runner.ts b/test/tools/unified-spec-runner/runner.ts index 925b8b9d617..f5adc4224b6 100644 --- a/test/tools/unified-spec-runner/runner.ts +++ b/test/tools/unified-spec-runner/runner.ts @@ -248,7 +248,7 @@ async function runUnifiedTest( if (!testClient!.observeSensitiveCommands) { filteredTestClientLogs = filteredTestClientLogs.filter( log => - !(log.data && log.data.commandName && SENSITIVE_COMMANDS.has(log.data.commandName)) + !SENSITIVE_COMMANDS.has(log?.data?.commandName) && !testClient!.isSensitiveLog(log) ); } compareLogs(expectedLogsForClient.messages, filteredTestClientLogs, entities); diff --git a/test/unit/tools/unified_spec_runner.test.ts b/test/unit/tools/unified_spec_runner.test.ts index bf78b75c9a3..38d45887bf4 100644 --- a/test/unit/tools/unified_spec_runner.test.ts +++ b/test/unit/tools/unified_spec_runner.test.ts @@ -151,7 +151,7 @@ describe('Unified Spec Runner', function () { sinon.restore(); }); - context('when failureIsRedacted is present', function () { + context.only('when failureIsRedacted is present', function () { context('when failureIsRedacted=true', function () { beforeEach(function () { expected = { @@ -167,7 +167,7 @@ describe('Unified Spec Runner', function () { level: 'debug', component: 'command', data: { - failure: {} + failure: '{}' } }; compareLogsSpy([expected], [actual], entitiesMap); From 3332f9444e23e5add09ff15552a7d9384e3a0815 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Thu, 11 Jan 2024 02:03:58 -0500 Subject: [PATCH 15/25] extraneous .only removal --- test/unit/tools/unified_spec_runner.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/unit/tools/unified_spec_runner.test.ts b/test/unit/tools/unified_spec_runner.test.ts index 38d45887bf4..4c197db28d2 100644 --- a/test/unit/tools/unified_spec_runner.test.ts +++ b/test/unit/tools/unified_spec_runner.test.ts @@ -151,7 +151,7 @@ describe('Unified Spec Runner', function () { sinon.restore(); }); - context.only('when failureIsRedacted is present', function () { + context('when failureIsRedacted is present', function () { context('when failureIsRedacted=true', function () { beforeEach(function () { expected = { From cacaed26f14fb67a18974fbe3d284d0e01339532 Mon Sep 17 00:00:00 2001 From: aditi-khare-mongoDB <106987683+aditi-khare-mongoDB@users.noreply.github.com> Date: Thu, 11 Jan 2024 14:25:44 -0500 Subject: [PATCH 16/25] Update src/mongo_logger.ts Co-authored-by: Alena Khineika --- 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 16b56ff388d..ad8bd46507a 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -414,7 +414,7 @@ export function stringifyWithMaxLen( options: EJSONOptions = {} ): string { // eslint-disable-next-line @typescript-eslint/no-inferrable-types - let strToTruncate: string = ''; + let strToTruncate = ''; if (typeof value === 'function') { strToTruncate = value.toString(); From fa223cf0c88cfae37ecd1a9d9db393a2659dc121 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Thu, 11 Jan 2024 16:00:40 -0500 Subject: [PATCH 17/25] lint fix --- src/mongo_logger.ts | 1 - 1 file changed, 1 deletion(-) diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index ad8bd46507a..df23c63da73 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -413,7 +413,6 @@ export function stringifyWithMaxLen( maxDocumentLength: number, options: EJSONOptions = {} ): string { - // eslint-disable-next-line @typescript-eslint/no-inferrable-types let strToTruncate = ''; if (typeof value === 'function') { From 299e8a1956491c8fc7959888b4ee779637cbcea1 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Tue, 16 Jan 2024 11:37:03 -0500 Subject: [PATCH 18/25] neal's pr requested changes --- src/bson.ts | 2 + src/cmap/connect.ts | 4 + src/cmap/connection.ts | 16 +- src/mongo_logger.ts | 4 +- src/mongo_types.ts | 4 +- ...mmand_logging_and_monitoring.prose.test.ts | 192 +++++++++--------- .../logging/redacted-commands.json | 3 +- test/tools/unified-spec-runner/entities.ts | 11 - test/tools/unified-spec-runner/match.ts | 4 +- test/tools/unified-spec-runner/runner.ts | 16 +- test/unit/tools/unified_spec_runner.test.ts | 2 +- 11 files changed, 117 insertions(+), 141 deletions(-) diff --git a/src/bson.ts b/src/bson.ts index 80c54360d7b..2c0b43df12a 100644 --- a/src/bson.ts +++ b/src/bson.ts @@ -13,6 +13,8 @@ export { deserialize, Document, Double, + EJSON, + EJSONOptions, Int32, Long, MaxKey, diff --git a/src/cmap/connect.ts b/src/cmap/connect.ts index b22eb34059c..7a961c4a08a 100644 --- a/src/cmap/connect.ts +++ b/src/cmap/connect.ts @@ -186,6 +186,10 @@ async function performInitialHandshake( throw error; } } + + // Connection establishment is socket creatio (tcp handshake, tls handshake, MongoDB handshake (saslStart, saslContinue)) + // Once connection is established, command logging and monitoring can emit and/or log events (if either are enabled) + conn.established = true; } export interface HandshakeDocument extends Document { diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 318964e4c96..5142a128bde 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -168,6 +168,7 @@ export class Connection extends TypedEventEmitter { public delayedTimeoutId: NodeJS.Timeout | null = null; public generation: number; public readonly description: Readonly; + public established: boolean; private lastUseTime: number; private socketTimeoutMS: number; @@ -206,6 +207,7 @@ export class Connection extends TypedEventEmitter { this.monitorCommands = options.monitorCommands; this.serverApi = options.serverApi; this.mongoLogger = options.mongoLogger; + this.established = false; this.description = new StreamDescription(this.address, options); this.generation = options.generation; @@ -451,14 +453,14 @@ export class Connection extends TypedEventEmitter { let started = 0; if ( this.monitorCommands || - (this.description.hello && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) + (this.established && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) ) { started = now(); this.emitAndLogCommand( this.monitorCommands, Connection.COMMAND_STARTED, message.databaseName, - this.description.hello, + this.established, new CommandStartedEvent(this, message, this.description.serverConnectionId) ); } @@ -480,13 +482,13 @@ export class Connection extends TypedEventEmitter { if ( this.monitorCommands || - (this.description.hello && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) + (this.established && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) ) { this.emitAndLogCommand( this.monitorCommands, Connection.COMMAND_SUCCEEDED, message.databaseName, - this.description.hello, + this.established, new CommandSucceededEvent( this, message, @@ -503,14 +505,14 @@ export class Connection extends TypedEventEmitter { } catch (error) { if ( this.monitorCommands || - (this.description.hello && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) + (this.established && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) ) { if (error.name === 'MongoWriteConcernError') { this.emitAndLogCommand( this.monitorCommands, Connection.COMMAND_SUCCEEDED, message.databaseName, - this.description.hello, + this.established, new CommandSucceededEvent( this, message, @@ -524,7 +526,7 @@ export class Connection extends TypedEventEmitter { this.monitorCommands, Connection.COMMAND_FAILED, message.databaseName, - this.description.hello, + this.established, new CommandFailedEvent( this, message, diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts index df23c63da73..23f270bd4a3 100644 --- a/src/mongo_logger.ts +++ b/src/mongo_logger.ts @@ -1,7 +1,7 @@ -import { type Document, EJSON, type EJSONOptions, type ObjectId } from 'bson'; import type { Writable } from 'stream'; import { inspect } from 'util'; +import { type Document, EJSON, type EJSONOptions, type ObjectId } from './bson'; import type { CommandStartedEvent } from './cmap/command_monitoring_events'; import type { ConnectionCheckedInEvent, @@ -536,7 +536,7 @@ function defaultLogTransform( log = attachCommandFields(log, logObject); log.message = 'Command failed'; log.durationMS = logObject.duration; - log.failure = logObject.failure.message ?? '{}'; + log.failure = logObject.failure.message ?? '(redacted)'; return log; case CONNECTION_POOL_CREATED: log = attachConnectionFields(log, logObject); diff --git a/src/mongo_types.ts b/src/mongo_types.ts index 7ee50292600..ef854886f34 100644 --- a/src/mongo_types.ts +++ b/src/mongo_types.ts @@ -450,13 +450,13 @@ export class TypedEventEmitter extends EventEm monitorCommands: boolean, event: EventKey | symbol, databaseName: string, - hello: Document | null, + connectionEstablished: boolean, ...args: Parameters ): void { if (monitorCommands) { this.emit(event, ...args); } - if (this.component && hello) { + if (this.component && connectionEstablished) { const loggableCommandEvent: | CommandStartedEvent | LoggableCommandFailedEvent diff --git a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts index 9d24862fed0..da66e92f013 100644 --- a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts +++ b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts @@ -5,6 +5,9 @@ import { DEFAULT_MAX_DOCUMENT_LENGTH, type Document } from '../../mongodb'; describe('Command Logging and Monitoring Prose Tests', function () { const loggerFeatureFlag = Symbol.for('@@mdb.enableMongoLogger'); const ELLIPSES_LENGTH = 3; + let client; + let writable; + context('When no custom truncation limit is provided', function () { /* 1. Configure logging with a minimum severity level of "debug" for the "command" component. @@ -26,28 +29,33 @@ describe('Command Logging and Monitoring Prose Tests', function () { the reply is a string of length 1000 + (length of trailing ellipsis). */ - it('should follow default truncation limit of 1000', { - metadata: {}, - test: async function () { - const writable = { - buffer: [], - write(log) { - this.buffer.push(log); + beforeEach(async function () { + writable = { + buffer: [], + write(log) { + this.buffer.push(log); + } + }; + // 1. + client = this.configuration.newClient( + {}, + { + [loggerFeatureFlag]: true, + mongodbLogPath: writable, + mongodbLogComponentSeverities: { + command: 'debug' } - }; + } + ); + }); - // 1. - const client = this.configuration.newClient( - {}, - { - [loggerFeatureFlag]: true, - mongodbLogPath: writable, - mongodbLogComponentSeverities: { - command: 'debug' - } - } - ); + afterEach(async function () { + await client.close(); + }); + it('should follow default truncation limit of 1000', { + metadata: {}, + test: async function () { // 2. const docs: Array = []; for (let i = 0; i < 100; i++) { @@ -57,17 +65,8 @@ describe('Command Logging and Monitoring Prose Tests', function () { // 3. await client.db('admin').collection('test').insertMany(docs); - // remove sensitive commands for uniformity - const cleanedBuffer = []; - const afterInsertBufferLength = writable.buffer.length; - for (let i = 0; i < afterInsertBufferLength; i++) { - if (writable.buffer[i].command !== '{}' && writable.buffer[i].reply !== '{}') { - cleanedBuffer.push(writable.buffer[i]); - } - } - // 4. - const insertManyCommandStarted = cleanedBuffer[0]; + const insertManyCommandStarted = writable.buffer[0]; expect(insertManyCommandStarted?.message).to.equal('Command started'); expect(insertManyCommandStarted?.command).to.be.a('string'); expect(insertManyCommandStarted?.command?.length).to.equal( @@ -75,7 +74,7 @@ describe('Command Logging and Monitoring Prose Tests', function () { ); // 5. - const insertManyCommandSucceeded = cleanedBuffer[1]; + const insertManyCommandSucceeded = writable.buffer[1]; expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); expect(insertManyCommandSucceeded?.reply).to.be.a('string'); expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most( @@ -83,27 +82,19 @@ describe('Command Logging and Monitoring Prose Tests', function () { ); // 6. - await client.db('admin').collection('test').find()._initialize(); - - // remove sensitive commands again for uniformity - for (let j = afterInsertBufferLength; j < writable.buffer.length; j++) { - if (writable.buffer[j].command !== '{}' && writable.buffer[j].reply !== '{}') { - cleanedBuffer.push(writable.buffer[j]); - } - } + await client.db('admin').collection('test').find().toArray(); // 7. - const findCommandSucceeded = cleanedBuffer[3]; + const findCommandSucceeded = writable.buffer[3]; expect(findCommandSucceeded?.message).to.equal('Command succeeded'); expect(findCommandSucceeded?.reply).to.be.a('string'); expect(findCommandSucceeded?.reply?.length).to.equal( DEFAULT_MAX_DOCUMENT_LENGTH + ELLIPSES_LENGTH ); - - await client.close(); } }); }); + context('When custom truncation limit is provided', function () { /* 1. Configure logging with a minimum severity level of "debug" for the "command" component. @@ -125,48 +116,45 @@ describe('Command Logging and Monitoring Prose Tests', function () { Inspect the resulting "command failed" log message and confirm that the server error is a string of length 5 + (length of trailing ellipsis). */ + beforeEach(async function () { + writable = { + buffer: [], + write(log) { + this.buffer.push(log); + } + }; + // 1. + client = this.configuration.newClient( + {}, + { + [loggerFeatureFlag]: true, + mongodbLogPath: writable, + mongodbLogComponentSeverities: { + command: 'debug' + }, + mongodbLogMaxDocumentLength: 5 + } + ); + }); + + afterEach(async function () { + await client.close(); + }); + it('should follow custom truncation limit', { metadata: {}, test: async function () { - const writable = { - buffer: [], - write(log) { - this.buffer.push(log); - } - }; - - // 1. - const client = this.configuration.newClient( - {}, - { - [loggerFeatureFlag]: true, - mongodbLogPath: writable, - mongodbLogComponentSeverities: { - command: 'debug' - }, - mongodbLogMaxDocumentLength: 5 - } - ); - // 2. await client.db('admin').command({ hello: 'true' }); - // remove sensitive commands for uniformity - const cleanedBuffer = []; - for (let i = 0; i < writable.buffer.length; i++) { - if (writable.buffer[i].command !== '{}' && writable.buffer[i].reply !== '{}') { - cleanedBuffer.push(writable.buffer[i]); - } - } - // 3. - const insertManyCommandStarted = cleanedBuffer[0]; + const insertManyCommandStarted = writable.buffer[0]; expect(insertManyCommandStarted?.message).to.equal('Command started'); expect(insertManyCommandStarted?.command).to.be.a('string'); expect(insertManyCommandStarted?.command?.length).to.equal(5 + ELLIPSES_LENGTH); // 4. - const insertManyCommandSucceeded = cleanedBuffer[1]; + const insertManyCommandSucceeded = writable.buffer[1]; expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); expect(insertManyCommandSucceeded?.reply).to.be.a('string'); expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most(5 + ELLIPSES_LENGTH); @@ -175,6 +163,7 @@ describe('Command Logging and Monitoring Prose Tests', function () { } }); }); + context('Truncation with multi-byte codepoints', function () { /* A specific test case is not provided here due to the allowed variations in truncation logic @@ -187,51 +176,52 @@ describe('Command Logging and Monitoring Prose Tests', function () { there also MUST be tests confirming that cases where the max length falls in the middle of a multi-byte codepoint are handled gracefully. */ + + beforeEach(async function () { + writable = { + buffer: [], + write(log) { + this.buffer.push(log); + } + }; + // 1. + client = this.configuration.newClient( + {}, + { + [loggerFeatureFlag]: true, + mongodbLogPath: writable, + mongodbLogComponentSeverities: { + command: 'debug' + }, + mongodbLogMaxDocumentLength: 50 + } + ); + }); + + afterEach(async function () { + await client.close(); + }); + it('should handle unicode codepoints in middle and end of truncation gracefully', { metadata: {}, test: async function () { - const writable = { - buffer: [], - write(log) { - this.buffer.push(log); - } - }; - - const client = this.configuration.newClient( - {}, + const docs: Array = [ { - [loggerFeatureFlag]: true, - mongodbLogPath: writable, - mongodbLogComponentSeverities: { - command: 'debug' - }, - mongodbLogMaxDocumentLength: 50 + x: '\u2603\u2603\u2603\u2603' } - ); - - const docs: Array = [{ x: '&&&&&&&&&&&&&&&&' }]; + ]; await client.db('admin').collection('test').insertMany(docs); - // remove sensitive commands for uniformity - const cleanedBuffer = []; - for (let i = 0; i < writable.buffer.length; i++) { - if (writable.buffer[i].command !== '{}' && writable.buffer[i].reply !== '{}') { - cleanedBuffer.push(writable.buffer[i]); - } - } - - const insertManyCommandStarted = cleanedBuffer[0]; + const insertManyCommandStarted = writable.buffer[0]; expect(insertManyCommandStarted?.message).to.equal('Command started'); expect(insertManyCommandStarted?.command).to.be.a('string'); expect(insertManyCommandStarted?.command?.length).to.equal(50 + ELLIPSES_LENGTH); - const insertManyCommandSucceeded = cleanedBuffer[1]; + const insertManyCommandSucceeded = writable.buffer[1]; expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); expect(insertManyCommandSucceeded?.reply).to.be.a('string'); expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most(50 + ELLIPSES_LENGTH); - - await client.close(); } }); }); diff --git a/test/spec/command-logging-and-monitoring/logging/redacted-commands.json b/test/spec/command-logging-and-monitoring/logging/redacted-commands.json index 7c96195d489..43b9ff74f29 100644 --- a/test/spec/command-logging-and-monitoring/logging/redacted-commands.json +++ b/test/spec/command-logging-and-monitoring/logging/redacted-commands.json @@ -14,8 +14,7 @@ "useMultipleMongoses": false, "observeLogMessages": { "command": "debug" - }, - "observeSensitiveCommands": true + } } }, { diff --git a/test/tools/unified-spec-runner/entities.ts b/test/tools/unified-spec-runner/entities.ts index 5809e392128..0e5a8f3d5d7 100644 --- a/test/tools/unified-spec-runner/entities.ts +++ b/test/tools/unified-spec-runner/entities.ts @@ -282,17 +282,6 @@ export class UnifiedMongoClient extends MongoClient { return false; } - isSensitiveLog(log: LogMessage): boolean { - if ( - (log.data?.message === 'Command started' && log.data?.command === '{}') || - (log.data?.message === 'Command succeeded' && log.data?.reply === '{}') || - (log.data?.message === 'Command failed' && log.data?.failure === '{}') - ) { - return true; - } - return false; - } - isIgnored(e: CommandEvent): boolean { return this.ignoredEvents.includes(e.commandName); } diff --git a/test/tools/unified-spec-runner/match.ts b/test/tools/unified-spec-runner/match.ts index e5e23bfefa4..1098efc1fb1 100644 --- a/test/tools/unified-spec-runner/match.ts +++ b/test/tools/unified-spec-runner/match.ts @@ -694,7 +694,9 @@ export function compareLogs( expect(actualLog.data.failure, 'Expected failure to exist').to.exist; if (expectedLog.failureIsRedacted) { // Assert that failure has been redacted - expect(actualLog.data.failure, 'Expected failure to have been redacted').to.equal('{}'); + expect(actualLog.data.failure, 'Expected failure to have been redacted').to.equal( + '(redacted)' + ); } else { // Assert that failure has not been redacted expect( diff --git a/test/tools/unified-spec-runner/runner.ts b/test/tools/unified-spec-runner/runner.ts index f5adc4224b6..9f1fb3925f5 100644 --- a/test/tools/unified-spec-runner/runner.ts +++ b/test/tools/unified-spec-runner/runner.ts @@ -3,13 +3,7 @@ import { expect } from 'chai'; import { gte as semverGte, satisfies as semverSatisfies } from 'semver'; import type { MongoClient } from '../../mongodb'; -import { - MONGODB_ERROR_CODES, - ns, - ReadPreference, - SENSITIVE_COMMANDS, - TopologyType -} from '../../mongodb'; +import { MONGODB_ERROR_CODES, ns, ReadPreference, TopologyType } from '../../mongodb'; import { ejson } from '../utils'; import { AstrolabeResultsWriter } from './astrolabe_results_writer'; import { EntitiesMap, type UnifiedMongoClient } from './entities'; @@ -238,19 +232,13 @@ async function runUnifiedTest( const testClient = clientList.get(clientId); expect(testClient, `No client entity found with id ${clientId}`).to.exist; - let filteredTestClientLogs = expectedLogsForClient.ignoreMessages + const filteredTestClientLogs = expectedLogsForClient.ignoreMessages ? filterExtraLogs( expectedLogsForClient.ignoreMessages, testClient!.collectedLogs, entities ) : testClient!.collectedLogs; - if (!testClient!.observeSensitiveCommands) { - filteredTestClientLogs = filteredTestClientLogs.filter( - log => - !SENSITIVE_COMMANDS.has(log?.data?.commandName) && !testClient!.isSensitiveLog(log) - ); - } compareLogs(expectedLogsForClient.messages, filteredTestClientLogs, entities); } } diff --git a/test/unit/tools/unified_spec_runner.test.ts b/test/unit/tools/unified_spec_runner.test.ts index 4c197db28d2..647005411fe 100644 --- a/test/unit/tools/unified_spec_runner.test.ts +++ b/test/unit/tools/unified_spec_runner.test.ts @@ -167,7 +167,7 @@ describe('Unified Spec Runner', function () { level: 'debug', component: 'command', data: { - failure: '{}' + failure: '(redacted)' } }; compareLogsSpy([expected], [actual], entitiesMap); From 1181991c1a6bacb5271e313d9ef7052a12212dc5 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Tue, 16 Jan 2024 13:10:31 -0500 Subject: [PATCH 19/25] pr again --- src/cmap/message_stream.ts | 220 ++++++++++++++++++ ...mmand_logging_and_monitoring.prose.test.ts | 2 +- 2 files changed, 221 insertions(+), 1 deletion(-) create mode 100644 src/cmap/message_stream.ts diff --git a/src/cmap/message_stream.ts b/src/cmap/message_stream.ts new file mode 100644 index 00000000000..42d16ae26e5 --- /dev/null +++ b/src/cmap/message_stream.ts @@ -0,0 +1,220 @@ +import { Duplex, type DuplexOptions } from 'stream'; + +import type { BSONSerializeOptions, Document } from '../bson'; +import { MongoDecompressionError, MongoParseError } from '../error'; +import type { ClientSession } from '../sessions'; +import { BufferPool, type Callback } from '../utils'; +import { + type MessageHeader, + OpCompressedRequest, + OpMsgResponse, + OpQueryResponse, + type WriteProtocolMessageType +} from './commands'; +import { compress, Compressor, type CompressorName, decompress } from './wire_protocol/compression'; +import { OP_COMPRESSED, OP_MSG } from './wire_protocol/constants'; + +const MESSAGE_HEADER_SIZE = 16; +const COMPRESSION_DETAILS_SIZE = 9; // originalOpcode + uncompressedSize, compressorID + +const kDefaultMaxBsonMessageSize = 1024 * 1024 * 16 * 4; +/** @internal */ +const kBuffer = Symbol('buffer'); + +/** @internal */ +export interface MessageStreamOptions extends DuplexOptions { + maxBsonMessageSize?: number; +} + +/** @internal */ +export interface OperationDescription extends BSONSerializeOptions { + started: number; + cb: Callback; + documentsReturnedIn?: string; + noResponse: boolean; + raw: boolean; + requestId: number; + session?: ClientSession; + agreedCompressor?: CompressorName; + zlibCompressionLevel?: number; + $clusterTime?: Document; +} + +/** + * A duplex stream that is capable of reading and writing raw wire protocol messages, with + * support for optional compression + * @internal + */ +export class MessageStream extends Duplex { + /** @internal */ + maxBsonMessageSize: number; + /** @internal */ + [kBuffer]: BufferPool; + /** @internal */ + isMonitoringConnection = false; + + constructor(options: MessageStreamOptions = {}) { + super(options); + this.maxBsonMessageSize = options.maxBsonMessageSize || kDefaultMaxBsonMessageSize; + this[kBuffer] = new BufferPool(); + } + + get buffer(): BufferPool { + return this[kBuffer]; + } + + override _write(chunk: Buffer, _: unknown, callback: Callback): void { + this[kBuffer].append(chunk); + processIncomingData(this, callback); + } + + override _read(/* size */): void { + // NOTE: This implementation is empty because we explicitly push data to be read + // when `writeMessage` is called. + return; + } + + writeCommand( + command: WriteProtocolMessageType, + operationDescription: OperationDescription + ): void { + const agreedCompressor = operationDescription.agreedCompressor ?? 'none'; + if (agreedCompressor === 'none' || !OpCompressedRequest.canCompress(command)) { + const data = command.toBin(); + this.push(Array.isArray(data) ? Buffer.concat(data) : data); + return; + } + // otherwise, compress the message + const concatenatedOriginalCommandBuffer = Buffer.concat(command.toBin()); + const messageToBeCompressed = concatenatedOriginalCommandBuffer.slice(MESSAGE_HEADER_SIZE); + + // Extract information needed for OP_COMPRESSED from the uncompressed message + const originalCommandOpCode = concatenatedOriginalCommandBuffer.readInt32LE(12); + + const options = { + agreedCompressor, + zlibCompressionLevel: operationDescription.zlibCompressionLevel ?? 0 + }; + // Compress the message body + compress(options, messageToBeCompressed).then( + compressedMessage => { + // Create the msgHeader of OP_COMPRESSED + const msgHeader = Buffer.alloc(MESSAGE_HEADER_SIZE); + msgHeader.writeInt32LE( + MESSAGE_HEADER_SIZE + COMPRESSION_DETAILS_SIZE + compressedMessage.length, + 0 + ); // messageLength + msgHeader.writeInt32LE(command.requestId, 4); // requestID + msgHeader.writeInt32LE(0, 8); // responseTo (zero) + msgHeader.writeInt32LE(OP_COMPRESSED, 12); // opCode + + // Create the compression details of OP_COMPRESSED + const compressionDetails = Buffer.alloc(COMPRESSION_DETAILS_SIZE); + compressionDetails.writeInt32LE(originalCommandOpCode, 0); // originalOpcode + compressionDetails.writeInt32LE(messageToBeCompressed.length, 4); // Size of the uncompressed compressedMessage, excluding the MsgHeader + compressionDetails.writeUInt8(Compressor[agreedCompressor], 8); // compressorID + this.push(Buffer.concat([msgHeader, compressionDetails, compressedMessage])); + }, + error => { + operationDescription.cb(error); + } + ); + } +} + +function processIncomingData(stream: MessageStream, callback: Callback): void { + const buffer = stream[kBuffer]; + const sizeOfMessage = buffer.getInt32(); + + if (sizeOfMessage == null) { + return callback(); + } + + if (sizeOfMessage < 0) { + return callback(new MongoParseError(`Invalid message size: ${sizeOfMessage}`)); + } + + if (sizeOfMessage > stream.maxBsonMessageSize) { + return callback( + new MongoParseError( + `Invalid message size: ${sizeOfMessage}, max allowed: ${stream.maxBsonMessageSize}` + ) + ); + } + + if (sizeOfMessage > buffer.length) { + return callback(); + } + + const message = buffer.read(sizeOfMessage); + const messageHeader: MessageHeader = { + length: message.readInt32LE(0), + requestId: message.readInt32LE(4), + responseTo: message.readInt32LE(8), + opCode: message.readInt32LE(12) + }; + + const monitorHasAnotherHello = () => { + if (stream.isMonitoringConnection) { + // Can we read the next message size? + const sizeOfMessage = buffer.getInt32(); + if (sizeOfMessage != null && sizeOfMessage <= buffer.length) { + return true; + } + } + return false; + }; + + let ResponseType = messageHeader.opCode === OP_MSG ? OpMsgResponse : OpQueryResponse; + if (messageHeader.opCode !== OP_COMPRESSED) { + const messageBody = message.subarray(MESSAGE_HEADER_SIZE); + + // If we are a monitoring connection message stream and + // there is more in the buffer that can be read, skip processing since we + // want the last hello command response that is in the buffer. + if (monitorHasAnotherHello()) { + return processIncomingData(stream, callback); + } + + stream.emit('message', new ResponseType(message, messageHeader, messageBody)); + + if (buffer.length >= 4) { + return processIncomingData(stream, callback); + } + return callback(); + } + + messageHeader.fromCompressed = true; + messageHeader.opCode = message.readInt32LE(MESSAGE_HEADER_SIZE); + messageHeader.length = message.readInt32LE(MESSAGE_HEADER_SIZE + 4); + const compressorID = message[MESSAGE_HEADER_SIZE + 8]; + const compressedBuffer = message.slice(MESSAGE_HEADER_SIZE + 9); + + // recalculate based on wrapped opcode + ResponseType = messageHeader.opCode === OP_MSG ? OpMsgResponse : OpQueryResponse; + decompress(compressorID, compressedBuffer).then( + messageBody => { + if (messageBody.length !== messageHeader.length) { + return callback( + new MongoDecompressionError('Message body and message header must be the same length') + ); + } + + // If we are a monitoring connection message stream and + // there is more in the buffer that can be read, skip processing since we + // want the last hello command response that is in the buffer. + if (monitorHasAnotherHello()) { + return processIncomingData(stream, callback); + } + stream.emit('message', new ResponseType(message, messageHeader, messageBody)); + + if (buffer.length >= 4) { + return processIncomingData(stream, callback); + } + return callback(); + }, + error => { + return callback(error); + } + ); +} diff --git a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts index da66e92f013..2b7f6d66b04 100644 --- a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts +++ b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts @@ -2,7 +2,7 @@ import { expect } from 'chai'; import { DEFAULT_MAX_DOCUMENT_LENGTH, type Document } from '../../mongodb'; -describe('Command Logging and Monitoring Prose Tests', function () { +describe.only('Command Logging and Monitoring Prose Tests', function () { const loggerFeatureFlag = Symbol.for('@@mdb.enableMongoLogger'); const ELLIPSES_LENGTH = 3; let client; From 8f6c860342a4515fdfdcf006e6f7b341da424b0c Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Tue, 16 Jan 2024 14:12:24 -0500 Subject: [PATCH 20/25] pr requested changes again --- src/cmap/connect.ts | 4 +- src/cmap/connection.ts | 8 + ...mmand_logging_and_monitoring.prose.test.ts | 173 ++++++++---------- 3 files changed, 91 insertions(+), 94 deletions(-) diff --git a/src/cmap/connect.ts b/src/cmap/connect.ts index 7a961c4a08a..4c7c9179987 100644 --- a/src/cmap/connect.ts +++ b/src/cmap/connect.ts @@ -187,8 +187,8 @@ async function performInitialHandshake( } } - // Connection establishment is socket creatio (tcp handshake, tls handshake, MongoDB handshake (saslStart, saslContinue)) - // Once connection is established, command logging and monitoring can emit and/or log events (if either are enabled) + // Connection establishment is socket creation (tcp handshake, tls handshake, MongoDB handshake (saslStart, saslContinue)) + // Once connection is established, command logging can log events (if enabled) conn.established = true; } diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 5142a128bde..604ff73875e 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -168,6 +168,14 @@ export class Connection extends TypedEventEmitter { public delayedTimeoutId: NodeJS.Timeout | null = null; public generation: number; public readonly description: Readonly; + /** + * @public + * Represents if the connection has been established: + * - TCP handshake + * - TLS negotiated + * - mongodb handshake (saslStart, saslContinue), includes authentication + * Once connection is established, command logging can log events (if enabled) + */ public established: boolean; private lastUseTime: number; diff --git a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts index 2b7f6d66b04..7c38d54652b 100644 --- a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts +++ b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts @@ -2,7 +2,7 @@ import { expect } from 'chai'; import { DEFAULT_MAX_DOCUMENT_LENGTH, type Document } from '../../mongodb'; -describe.only('Command Logging and Monitoring Prose Tests', function () { +describe('Command Logging and Monitoring Prose Tests', function () { const loggerFeatureFlag = Symbol.for('@@mdb.enableMongoLogger'); const ELLIPSES_LENGTH = 3; let client; @@ -10,22 +10,22 @@ describe.only('Command Logging and Monitoring Prose Tests', function () { context('When no custom truncation limit is provided', function () { /* - 1. Configure logging with a minimum severity level of "debug" for the "command" component. + 1. Configure logging with a minimum severity level of "debug" for the "command" component. Do not explicitly configure the max document length. 2. Construct an array docs containing the document {"x" : "y"} repeated 100 times. 3. Insert docs to a collection via insertMany. - 4. Inspect the resulting "command started" log message and assert that + 4. Inspect the resulting "command started" log message and assert that the "command" value is a string of length 1000 + (length of trailing ellipsis). - 5. Inspect the resulting "command succeeded" log message and assert that + 5. Inspect the resulting "command succeeded" log message and assert that the "reply" value is a string of length <= 1000 + (length of trailing ellipsis). 6. Run find() on the collection where the document was inserted. - 7. Inspect the resulting "command succeeded" log message and assert that + 7. Inspect the resulting "command succeeded" log message and assert that the reply is a string of length 1000 + (length of trailing ellipsis). */ @@ -53,67 +53,64 @@ describe.only('Command Logging and Monitoring Prose Tests', function () { await client.close(); }); - it('should follow default truncation limit of 1000', { - metadata: {}, - test: async function () { - // 2. - const docs: Array = []; - for (let i = 0; i < 100; i++) { - docs.push({ x: 'y' }); - } - - // 3. - await client.db('admin').collection('test').insertMany(docs); - - // 4. - const insertManyCommandStarted = writable.buffer[0]; - expect(insertManyCommandStarted?.message).to.equal('Command started'); - expect(insertManyCommandStarted?.command).to.be.a('string'); - expect(insertManyCommandStarted?.command?.length).to.equal( - DEFAULT_MAX_DOCUMENT_LENGTH + ELLIPSES_LENGTH - ); - - // 5. - const insertManyCommandSucceeded = writable.buffer[1]; - expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); - expect(insertManyCommandSucceeded?.reply).to.be.a('string'); - expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most( - DEFAULT_MAX_DOCUMENT_LENGTH + ELLIPSES_LENGTH - ); - - // 6. - await client.db('admin').collection('test').find().toArray(); - - // 7. - const findCommandSucceeded = writable.buffer[3]; - expect(findCommandSucceeded?.message).to.equal('Command succeeded'); - expect(findCommandSucceeded?.reply).to.be.a('string'); - expect(findCommandSucceeded?.reply?.length).to.equal( - DEFAULT_MAX_DOCUMENT_LENGTH + ELLIPSES_LENGTH - ); + it('should follow default truncation limit of 1000', async function () { + // 2. + const docs: Array = []; + for (let i = 0; i < 100; i++) { + docs.push({ x: 'y' }); } + + // 3. + await client.db('admin').collection('test').insertMany(docs); + + // 4. + const insertManyCommandStarted = writable.buffer[0]; + expect(insertManyCommandStarted?.message).to.equal('Command started'); + expect(insertManyCommandStarted?.command).to.be.a('string'); + expect(insertManyCommandStarted?.command?.length).to.equal( + DEFAULT_MAX_DOCUMENT_LENGTH + ELLIPSES_LENGTH + ); + + // 5. + const insertManyCommandSucceeded = writable.buffer[1]; + expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); + expect(insertManyCommandSucceeded?.reply).to.be.a('string'); + expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most( + DEFAULT_MAX_DOCUMENT_LENGTH + ELLIPSES_LENGTH + ); + + // 6. + await client.db('admin').collection('test').find().toArray(); + + // 7. + const findCommandSucceeded = writable.buffer[3]; + expect(findCommandSucceeded?.message).to.equal('Command succeeded'); + expect(findCommandSucceeded?.reply).to.be.a('string'); + expect(findCommandSucceeded?.reply?.length).to.equal( + DEFAULT_MAX_DOCUMENT_LENGTH + ELLIPSES_LENGTH + ); }); }); context('When custom truncation limit is provided', function () { /* - 1. Configure logging with a minimum severity level of "debug" for the "command" component. + 1. Configure logging with a minimum severity level of "debug" for the "command" component. Set the max document length to 5. 2. Run the command {"hello": true}. - 3. Inspect the resulting "command started" log message and assert that + 3. Inspect the resulting "command started" log message and assert that the "command" value is a string of length 5 + (length of trailing ellipsis). 4. Inspect the resulting "command succeeded" log message and assert that the "reply" value is a string of length 5 + (length of trailing ellipsis). - + 5. (Optional) If the driver attaches raw server responses to failures - and can access these via log messages to assert on, - run the command {"notARealCommand": true}. + and can access these via log messages to assert on, + run the command {"notARealCommand": true}. - Inspect the resulting "command failed" log message + Inspect the resulting "command failed" log message and confirm that the server error is a string of length 5 + (length of trailing ellipsis). */ beforeEach(async function () { @@ -141,38 +138,33 @@ describe.only('Command Logging and Monitoring Prose Tests', function () { await client.close(); }); - it('should follow custom truncation limit', { - metadata: {}, - test: async function () { - // 2. - await client.db('admin').command({ hello: 'true' }); - - // 3. - const insertManyCommandStarted = writable.buffer[0]; - expect(insertManyCommandStarted?.message).to.equal('Command started'); - expect(insertManyCommandStarted?.command).to.be.a('string'); - expect(insertManyCommandStarted?.command?.length).to.equal(5 + ELLIPSES_LENGTH); - - // 4. - const insertManyCommandSucceeded = writable.buffer[1]; - expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); - expect(insertManyCommandSucceeded?.reply).to.be.a('string'); - expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most(5 + ELLIPSES_LENGTH); - - await client.close(); - } + it('should follow custom truncation limit', async function () { + // 2. + await client.db('admin').command({ hello: 'true' }); + + // 3. + const insertManyCommandStarted = writable.buffer[0]; + expect(insertManyCommandStarted?.message).to.equal('Command started'); + expect(insertManyCommandStarted?.command).to.be.a('string'); + expect(insertManyCommandStarted?.command?.length).to.equal(5 + ELLIPSES_LENGTH); + + // 4. + const insertManyCommandSucceeded = writable.buffer[1]; + expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); + expect(insertManyCommandSucceeded?.reply).to.be.a('string'); + expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most(5 + ELLIPSES_LENGTH); }); }); context('Truncation with multi-byte codepoints', function () { /* A specific test case is not provided here due to the allowed variations in truncation logic - as well as varying extended JSON whitespace usage. - Drivers MUST write language-specific tests that confirm truncation of commands, replies, - and (if applicable) server responses included in error messages + as well as varying extended JSON whitespace usage. + Drivers MUST write language-specific tests that confirm truncation of commands, replies, + and (if applicable) server responses included in error messages work as expected when the data being truncated includes multi-byte Unicode codepoints. - - If the driver uses anything other than Unicode codepoints as the unit for max document length, + + If the driver uses anything other than Unicode codepoints as the unit for max document length, there also MUST be tests confirming that cases where the max length falls in the middle of a multi-byte codepoint are handled gracefully. */ @@ -202,27 +194,24 @@ describe.only('Command Logging and Monitoring Prose Tests', function () { await client.close(); }); - it('should handle unicode codepoints in middle and end of truncation gracefully', { - metadata: {}, - test: async function () { - const docs: Array = [ - { - x: '\u2603\u2603\u2603\u2603' - } - ]; + it('should handle unicode codepoints in middle and end of truncation gracefully', async function () { + const docs: Array = [ + { + x: '\u2603\u2603\u2603\u2603' + } + ]; - await client.db('admin').collection('test').insertMany(docs); + await client.db('admin').collection('test').insertMany(docs); - const insertManyCommandStarted = writable.buffer[0]; - expect(insertManyCommandStarted?.message).to.equal('Command started'); - expect(insertManyCommandStarted?.command).to.be.a('string'); - expect(insertManyCommandStarted?.command?.length).to.equal(50 + ELLIPSES_LENGTH); + const insertManyCommandStarted = writable.buffer[0]; + expect(insertManyCommandStarted?.message).to.equal('Command started'); + expect(insertManyCommandStarted?.command).to.be.a('string'); + expect(insertManyCommandStarted?.command?.length).to.equal(50 + ELLIPSES_LENGTH); - const insertManyCommandSucceeded = writable.buffer[1]; - expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); - expect(insertManyCommandSucceeded?.reply).to.be.a('string'); - expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most(50 + ELLIPSES_LENGTH); - } + const insertManyCommandSucceeded = writable.buffer[1]; + expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); + expect(insertManyCommandSucceeded?.reply).to.be.a('string'); + expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most(50 + ELLIPSES_LENGTH); }); }); }); From dc9315179238dcfe40e3604b6cecda891593f60d Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Tue, 16 Jan 2024 17:55:28 -0500 Subject: [PATCH 21/25] pr requested changes 4 --- src/cmap/message_stream.ts | 220 ------------------ ...mmand_logging_and_monitoring.prose.test.ts | 29 ++- 2 files changed, 23 insertions(+), 226 deletions(-) delete mode 100644 src/cmap/message_stream.ts diff --git a/src/cmap/message_stream.ts b/src/cmap/message_stream.ts deleted file mode 100644 index 42d16ae26e5..00000000000 --- a/src/cmap/message_stream.ts +++ /dev/null @@ -1,220 +0,0 @@ -import { Duplex, type DuplexOptions } from 'stream'; - -import type { BSONSerializeOptions, Document } from '../bson'; -import { MongoDecompressionError, MongoParseError } from '../error'; -import type { ClientSession } from '../sessions'; -import { BufferPool, type Callback } from '../utils'; -import { - type MessageHeader, - OpCompressedRequest, - OpMsgResponse, - OpQueryResponse, - type WriteProtocolMessageType -} from './commands'; -import { compress, Compressor, type CompressorName, decompress } from './wire_protocol/compression'; -import { OP_COMPRESSED, OP_MSG } from './wire_protocol/constants'; - -const MESSAGE_HEADER_SIZE = 16; -const COMPRESSION_DETAILS_SIZE = 9; // originalOpcode + uncompressedSize, compressorID - -const kDefaultMaxBsonMessageSize = 1024 * 1024 * 16 * 4; -/** @internal */ -const kBuffer = Symbol('buffer'); - -/** @internal */ -export interface MessageStreamOptions extends DuplexOptions { - maxBsonMessageSize?: number; -} - -/** @internal */ -export interface OperationDescription extends BSONSerializeOptions { - started: number; - cb: Callback; - documentsReturnedIn?: string; - noResponse: boolean; - raw: boolean; - requestId: number; - session?: ClientSession; - agreedCompressor?: CompressorName; - zlibCompressionLevel?: number; - $clusterTime?: Document; -} - -/** - * A duplex stream that is capable of reading and writing raw wire protocol messages, with - * support for optional compression - * @internal - */ -export class MessageStream extends Duplex { - /** @internal */ - maxBsonMessageSize: number; - /** @internal */ - [kBuffer]: BufferPool; - /** @internal */ - isMonitoringConnection = false; - - constructor(options: MessageStreamOptions = {}) { - super(options); - this.maxBsonMessageSize = options.maxBsonMessageSize || kDefaultMaxBsonMessageSize; - this[kBuffer] = new BufferPool(); - } - - get buffer(): BufferPool { - return this[kBuffer]; - } - - override _write(chunk: Buffer, _: unknown, callback: Callback): void { - this[kBuffer].append(chunk); - processIncomingData(this, callback); - } - - override _read(/* size */): void { - // NOTE: This implementation is empty because we explicitly push data to be read - // when `writeMessage` is called. - return; - } - - writeCommand( - command: WriteProtocolMessageType, - operationDescription: OperationDescription - ): void { - const agreedCompressor = operationDescription.agreedCompressor ?? 'none'; - if (agreedCompressor === 'none' || !OpCompressedRequest.canCompress(command)) { - const data = command.toBin(); - this.push(Array.isArray(data) ? Buffer.concat(data) : data); - return; - } - // otherwise, compress the message - const concatenatedOriginalCommandBuffer = Buffer.concat(command.toBin()); - const messageToBeCompressed = concatenatedOriginalCommandBuffer.slice(MESSAGE_HEADER_SIZE); - - // Extract information needed for OP_COMPRESSED from the uncompressed message - const originalCommandOpCode = concatenatedOriginalCommandBuffer.readInt32LE(12); - - const options = { - agreedCompressor, - zlibCompressionLevel: operationDescription.zlibCompressionLevel ?? 0 - }; - // Compress the message body - compress(options, messageToBeCompressed).then( - compressedMessage => { - // Create the msgHeader of OP_COMPRESSED - const msgHeader = Buffer.alloc(MESSAGE_HEADER_SIZE); - msgHeader.writeInt32LE( - MESSAGE_HEADER_SIZE + COMPRESSION_DETAILS_SIZE + compressedMessage.length, - 0 - ); // messageLength - msgHeader.writeInt32LE(command.requestId, 4); // requestID - msgHeader.writeInt32LE(0, 8); // responseTo (zero) - msgHeader.writeInt32LE(OP_COMPRESSED, 12); // opCode - - // Create the compression details of OP_COMPRESSED - const compressionDetails = Buffer.alloc(COMPRESSION_DETAILS_SIZE); - compressionDetails.writeInt32LE(originalCommandOpCode, 0); // originalOpcode - compressionDetails.writeInt32LE(messageToBeCompressed.length, 4); // Size of the uncompressed compressedMessage, excluding the MsgHeader - compressionDetails.writeUInt8(Compressor[agreedCompressor], 8); // compressorID - this.push(Buffer.concat([msgHeader, compressionDetails, compressedMessage])); - }, - error => { - operationDescription.cb(error); - } - ); - } -} - -function processIncomingData(stream: MessageStream, callback: Callback): void { - const buffer = stream[kBuffer]; - const sizeOfMessage = buffer.getInt32(); - - if (sizeOfMessage == null) { - return callback(); - } - - if (sizeOfMessage < 0) { - return callback(new MongoParseError(`Invalid message size: ${sizeOfMessage}`)); - } - - if (sizeOfMessage > stream.maxBsonMessageSize) { - return callback( - new MongoParseError( - `Invalid message size: ${sizeOfMessage}, max allowed: ${stream.maxBsonMessageSize}` - ) - ); - } - - if (sizeOfMessage > buffer.length) { - return callback(); - } - - const message = buffer.read(sizeOfMessage); - const messageHeader: MessageHeader = { - length: message.readInt32LE(0), - requestId: message.readInt32LE(4), - responseTo: message.readInt32LE(8), - opCode: message.readInt32LE(12) - }; - - const monitorHasAnotherHello = () => { - if (stream.isMonitoringConnection) { - // Can we read the next message size? - const sizeOfMessage = buffer.getInt32(); - if (sizeOfMessage != null && sizeOfMessage <= buffer.length) { - return true; - } - } - return false; - }; - - let ResponseType = messageHeader.opCode === OP_MSG ? OpMsgResponse : OpQueryResponse; - if (messageHeader.opCode !== OP_COMPRESSED) { - const messageBody = message.subarray(MESSAGE_HEADER_SIZE); - - // If we are a monitoring connection message stream and - // there is more in the buffer that can be read, skip processing since we - // want the last hello command response that is in the buffer. - if (monitorHasAnotherHello()) { - return processIncomingData(stream, callback); - } - - stream.emit('message', new ResponseType(message, messageHeader, messageBody)); - - if (buffer.length >= 4) { - return processIncomingData(stream, callback); - } - return callback(); - } - - messageHeader.fromCompressed = true; - messageHeader.opCode = message.readInt32LE(MESSAGE_HEADER_SIZE); - messageHeader.length = message.readInt32LE(MESSAGE_HEADER_SIZE + 4); - const compressorID = message[MESSAGE_HEADER_SIZE + 8]; - const compressedBuffer = message.slice(MESSAGE_HEADER_SIZE + 9); - - // recalculate based on wrapped opcode - ResponseType = messageHeader.opCode === OP_MSG ? OpMsgResponse : OpQueryResponse; - decompress(compressorID, compressedBuffer).then( - messageBody => { - if (messageBody.length !== messageHeader.length) { - return callback( - new MongoDecompressionError('Message body and message header must be the same length') - ); - } - - // If we are a monitoring connection message stream and - // there is more in the buffer that can be read, skip processing since we - // want the last hello command response that is in the buffer. - if (monitorHasAnotherHello()) { - return processIncomingData(stream, callback); - } - stream.emit('message', new ResponseType(message, messageHeader, messageBody)); - - if (buffer.length >= 4) { - return processIncomingData(stream, callback); - } - return callback(); - }, - error => { - return callback(error); - } - ); -} diff --git a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts index 7c38d54652b..b6a841b26e3 100644 --- a/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts +++ b/test/integration/command-logging-and-monitoring/command_logging_and_monitoring.prose.test.ts @@ -156,7 +156,7 @@ describe('Command Logging and Monitoring Prose Tests', function () { }); }); - context('Truncation with multi-byte codepoints', function () { + context.skip('Truncation with multi-byte codepoints', function () { /* A specific test case is not provided here due to the allowed variations in truncation logic as well as varying extended JSON whitespace usage. @@ -169,6 +169,7 @@ describe('Command Logging and Monitoring Prose Tests', function () { where the max length falls in the middle of a multi-byte codepoint are handled gracefully. */ + const maxDocLength = 39; beforeEach(async function () { writable = { buffer: [], @@ -185,7 +186,7 @@ describe('Command Logging and Monitoring Prose Tests', function () { mongodbLogComponentSeverities: { command: 'debug' }, - mongodbLogMaxDocumentLength: 50 + mongodbLogMaxDocumentLength: maxDocLength } ); }); @@ -195,9 +196,12 @@ describe('Command Logging and Monitoring Prose Tests', function () { }); it('should handle unicode codepoints in middle and end of truncation gracefully', async function () { + const multibyteUnicode = '\uD801\uDC37'; + const firstByteChar = multibyteUnicode.charCodeAt(0); + const secondByteChar = multibyteUnicode.charCodeAt(1); const docs: Array = [ { - x: '\u2603\u2603\u2603\u2603' + x: `${multibyteUnicode}${multibyteUnicode}${multibyteUnicode}${multibyteUnicode}` } ]; @@ -206,12 +210,25 @@ describe('Command Logging and Monitoring Prose Tests', function () { const insertManyCommandStarted = writable.buffer[0]; expect(insertManyCommandStarted?.message).to.equal('Command started'); expect(insertManyCommandStarted?.command).to.be.a('string'); - expect(insertManyCommandStarted?.command?.length).to.equal(50 + ELLIPSES_LENGTH); + // maxDocLength - 1 because stringified response should be rounded down due to ending mid-codepoint + expect(insertManyCommandStarted?.command?.length).to.equal( + maxDocLength - 1 + ELLIPSES_LENGTH + ); + + // multi-byte codepoint in middle of truncated string + expect(insertManyCommandStarted?.command.charCodeAt(maxDocLength - 1)).to.equal( + firstByteChar + ); + expect(insertManyCommandStarted?.command.charCodeAt(maxDocLength - 1)).to.equal( + secondByteChar + ); const insertManyCommandSucceeded = writable.buffer[1]; expect(insertManyCommandSucceeded?.message).to.equal('Command succeeded'); expect(insertManyCommandSucceeded?.reply).to.be.a('string'); - expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most(50 + ELLIPSES_LENGTH); + expect(insertManyCommandSucceeded?.reply?.length).to.be.at.most( + maxDocLength + ELLIPSES_LENGTH + ); }); - }); + }).skipReason = 'todo(NODE-5839)'; }); From cbb5df66d4a6569dff1dc156f085e9f9d6769e50 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Wed, 17 Jan 2024 13:31:06 -0500 Subject: [PATCH 22/25] bailey's pr requested changes --- src/mongo_types.ts | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/src/mongo_types.ts b/src/mongo_types.ts index ef854886f34..d822f406d60 100644 --- a/src/mongo_types.ts +++ b/src/mongo_types.ts @@ -13,14 +13,14 @@ import type { Timestamp } from './bson'; import { type CommandStartedEvent } from './cmap/command_monitoring_events'; -import type { - LoggableCommandFailedEvent, - LoggableCommandSucceededEvent, - LoggableServerHeartbeatFailedEvent, - LoggableServerHeartbeatStartedEvent, - LoggableServerHeartbeatSucceededEvent, +import { + type LoggableCommandFailedEvent, + type LoggableCommandSucceededEvent, + type LoggableServerHeartbeatFailedEvent, + type LoggableServerHeartbeatStartedEvent, + type LoggableServerHeartbeatSucceededEvent, MongoLoggableComponent, - MongoLogger + type MongoLogger } from './mongo_logger'; import type { Sort } from './sort'; @@ -464,7 +464,7 @@ export class TypedEventEmitter extends EventEm databaseName: databaseName, ...args[0] }; - this.mongoLogger?.debug(this.component, loggableCommandEvent); + this.mongoLogger?.debug(MongoLoggableComponent.COMMAND, loggableCommandEvent); } } } From 9ace7a0b0df84eaf3367c037d25ead30b92ebd7d Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Wed, 17 Jan 2024 17:29:51 -0500 Subject: [PATCH 23/25] reauth support for connection.established --- src/cmap/auth/auth_provider.ts | 2 ++ src/cmap/connection.ts | 9 ++++----- src/mongo_types.ts | 2 +- 3 files changed, 7 insertions(+), 6 deletions(-) diff --git a/src/cmap/auth/auth_provider.ts b/src/cmap/auth/auth_provider.ts index 37a47889b91..292e13f3c1e 100644 --- a/src/cmap/auth/auth_provider.ts +++ b/src/cmap/auth/auth_provider.ts @@ -65,9 +65,11 @@ export abstract class AuthProvider { } try { context.reauthenticating = true; + context.connection.established = false; await this.auth(context); } finally { context.reauthenticating = false; + context.connection.established = true; } } } diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 604ff73875e..aab12e6f942 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -174,6 +174,7 @@ export class Connection extends TypedEventEmitter { * - TCP handshake * - TLS negotiated * - mongodb handshake (saslStart, saslContinue), includes authentication + * * Once connection is established, command logging can log events (if enabled) */ public established: boolean; @@ -186,8 +187,6 @@ export class Connection extends TypedEventEmitter { private messageStream: Readable; private socketWrite: (buffer: Uint8Array) => Promise; private clusterTime: Document | null = null; - /** @internal */ - override component = MongoLoggableComponent.COMMAND; /** @internal */ override mongoLogger: MongoLogger | undefined; @@ -461,7 +460,7 @@ export class Connection extends TypedEventEmitter { let started = 0; if ( this.monitorCommands || - (this.established && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) + (this.established && this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND)) ) { started = now(); this.emitAndLogCommand( @@ -490,7 +489,7 @@ export class Connection extends TypedEventEmitter { if ( this.monitorCommands || - (this.established && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) + (this.established && this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND)) ) { this.emitAndLogCommand( this.monitorCommands, @@ -513,7 +512,7 @@ export class Connection extends TypedEventEmitter { } catch (error) { if ( this.monitorCommands || - (this.established && this.mongoLogger?.willLog(SeverityLevel.DEBUG, this.component)) + (this.established && this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND)) ) { if (error.name === 'MongoWriteConcernError') { this.emitAndLogCommand( diff --git a/src/mongo_types.ts b/src/mongo_types.ts index d822f406d60..1924b2afe29 100644 --- a/src/mongo_types.ts +++ b/src/mongo_types.ts @@ -456,7 +456,7 @@ export class TypedEventEmitter extends EventEm if (monitorCommands) { this.emit(event, ...args); } - if (this.component && connectionEstablished) { + if (connectionEstablished) { const loggableCommandEvent: | CommandStartedEvent | LoggableCommandFailedEvent From e9d4f8d248203f88bb7c1c515af0862029244513 Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Wed, 17 Jan 2024 17:36:26 -0500 Subject: [PATCH 24/25] lint fix --- src/cmap/connection.ts | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index aab12e6f942..3279e9ae3ec 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -460,7 +460,8 @@ export class Connection extends TypedEventEmitter { let started = 0; if ( this.monitorCommands || - (this.established && this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND)) + (this.established && + this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND)) ) { started = now(); this.emitAndLogCommand( @@ -489,7 +490,8 @@ export class Connection extends TypedEventEmitter { if ( this.monitorCommands || - (this.established && this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND)) + (this.established && + this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND)) ) { this.emitAndLogCommand( this.monitorCommands, @@ -512,7 +514,8 @@ export class Connection extends TypedEventEmitter { } catch (error) { if ( this.monitorCommands || - (this.established && this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND)) + (this.established && + this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND)) ) { if (error.name === 'MongoWriteConcernError') { this.emitAndLogCommand( From 7892601e5ae8ab413ca238b03f1c391379e5f2bd Mon Sep 17 00:00:00 2001 From: Aditi Khare Date: Thu, 18 Jan 2024 10:33:56 -0500 Subject: [PATCH 25/25] added getter and using authContext?.authenticating directly --- src/cmap/auth/auth_provider.ts | 2 -- src/cmap/connection.ts | 28 +++++++++++++--------------- 2 files changed, 13 insertions(+), 17 deletions(-) diff --git a/src/cmap/auth/auth_provider.ts b/src/cmap/auth/auth_provider.ts index 292e13f3c1e..37a47889b91 100644 --- a/src/cmap/auth/auth_provider.ts +++ b/src/cmap/auth/auth_provider.ts @@ -65,11 +65,9 @@ export abstract class AuthProvider { } try { context.reauthenticating = true; - context.connection.established = false; await this.auth(context); } finally { context.reauthenticating = false; - context.connection.established = true; } } } diff --git a/src/cmap/connection.ts b/src/cmap/connection.ts index 3279e9ae3ec..e036457a586 100644 --- a/src/cmap/connection.ts +++ b/src/cmap/connection.ts @@ -275,6 +275,16 @@ export class Connection extends TypedEventEmitter { ); } + private get shouldEmitAndLogCommand(): boolean { + return ( + (this.monitorCommands || + (this.established && + !this.authContext?.reauthenticating && + this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND))) ?? + false + ); + } + public markAvailable(): void { this.lastUseTime = now(); } @@ -458,11 +468,7 @@ export class Connection extends TypedEventEmitter { const message = this.prepareCommand(ns.db, command, options); let started = 0; - if ( - this.monitorCommands || - (this.established && - this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND)) - ) { + if (this.shouldEmitAndLogCommand) { started = now(); this.emitAndLogCommand( this.monitorCommands, @@ -488,11 +494,7 @@ export class Connection extends TypedEventEmitter { throw new MongoServerError(document); } - if ( - this.monitorCommands || - (this.established && - this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND)) - ) { + if (this.shouldEmitAndLogCommand) { this.emitAndLogCommand( this.monitorCommands, Connection.COMMAND_SUCCEEDED, @@ -512,11 +514,7 @@ export class Connection extends TypedEventEmitter { this.controller.signal.throwIfAborted(); } } catch (error) { - if ( - this.monitorCommands || - (this.established && - this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND)) - ) { + if (this.shouldEmitAndLogCommand) { if (error.name === 'MongoWriteConcernError') { this.emitAndLogCommand( this.monitorCommands,