rebased changes

Author: aditi-khare-mongoDB

src/cmap/connection.ts

@@ -26,6 +26,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';
@@ -140,6 +141,7 @@ export interface ConnectionOptions
   socketTimeoutMS?: number;
   cancellationToken?: CancellationToken;
   metadata: ClientMetadata;
+  mongoLogger: MongoLogger | undefined;
 }
 
 /** @internal */
@@ -192,6 +194,10 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
   [kHello]: Document | null;
   /** @internal */
   [kClusterTime]: Document | null;
+  /** @internal  */
+  override component = MongoLoggableComponent.COMMAND;
+  /** @internal */
+  override mongoLogger: MongoLogger | undefined;
 
   /** @event */
   static readonly COMMAND_STARTED = COMMAND_STARTED;
@@ -221,6 +227,7 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
     this.closed = false;
     this[kHello] = null;
     this[kClusterTime] = null;
+    this.mongoLogger = options.mongoLogger;
 
     this[kDescription] = new StreamDescription(this.address, options);
     this[kGeneration] = options.generation;
@@ -717,9 +724,15 @@ function write(
   }
 
   // if command monitoring is enabled we need to modify the callback here
-  if (conn.monitorCommands) {
-    conn.emit(
+  if (
+    conn.monitorCommands ||
+    (typeof conn[kDescription].serverConnectionId === 'bigint' &&
+      conn.mongoLogger?.willLog(SeverityLevel.DEBUG, conn.component))
+  ) {
+    conn.emitAndLogCommand(
+      conn.monitorCommands,
       Connection.COMMAND_STARTED,
+      command.databaseName,
       new CommandStartedEvent(conn, command, conn[kDescription].serverConnectionId)
     );
 
@@ -729,8 +742,10 @@ function write(
       // a command succeeded event, even if there's an error. Write concern errors
       // will have an ok: 1 in their reply.
       if (err && reply?.ok !== 1) {
-        conn.emit(
+        conn.emitAndLogCommand(
+          conn.monitorCommands,
           Connection.COMMAND_FAILED,
+          command.databaseName,
           new CommandFailedEvent(
             conn,
             command,
@@ -741,8 +756,10 @@ function write(
         );
       } else {
         if (reply && (reply.ok === 0 || reply.$err)) {
-          conn.emit(
+          conn.emitAndLogCommand(
+            conn.monitorCommands,
             Connection.COMMAND_FAILED,
+            command.databaseName,
             new CommandFailedEvent(
               conn,
               command,
@@ -752,8 +769,10 @@ function write(
             )
           );
         } else {
-          conn.emit(
+          conn.emitAndLogCommand(
+            conn.monitorCommands,
             Connection.COMMAND_SUCCEEDED,
+            command.databaseName,
             new CommandSucceededEvent(
               conn,
               command,

src/cmap/connection_pool.ts

@@ -699,7 +699,8 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
       ...this.options,
       id: this[kConnectionCounter].next().value,
       generation: this[kGeneration],
-      cancellationToken: this[kCancellationToken]
+      cancellationToken: this[kCancellationToken],
+      mongoLogger: this[kServer].topology.client.mongoLogger
     };
 
     this[kPending]++;

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;

src/index.ts

@@ -291,6 +291,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,
@@ -362,6 +365,8 @@ export type {
   LogComponentSeveritiesClientOptions,
   LogConvertible,
   Loggable,
+  LoggableCommandFailedEvent,
+  LoggableCommandSucceededEvent,
   LoggableEvent,
   LoggableServerHeartbeatFailedEvent,
   LoggableServerHeartbeatStartedEvent,

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<string, any>,
-  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) };
       }
     }

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<Events extends EventsDescription> extends EventEm
       this.mongoLogger?.debug(this.component, loggableHeartbeatEvent);
     }
   }
+  /** @internal */
+  emitAndLogCommand<EventKey extends keyof Events>(
+    monitorCommands: boolean,
+    event: EventKey | symbol,
+    databaseName: string,
+    ...args: Parameters<Events[EventKey]>
+  ): 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 */

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;
+    });
+  });
 });

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()) {