feat(NODE-4687): Add logging to server selection (#3946)

Co-authored-by: Durran Jordan <[email protected]>

Author: aditi-khare-mongoDB

src/change_stream.ts

@@ -934,10 +934,14 @@ export class ChangeStream<
       this.cursor.close().catch(() => null);
 
       const topology = getTopology(this.parent);
-      topology.selectServer(this.cursor.readPreference, {}, serverSelectionError => {
-        if (serverSelectionError) return this._closeEmitterModeWithError(changeStreamError);
-        this.cursor = this._createChangeStreamCursor(this.cursor.resumeOptions);
-      });
+      topology.selectServer(
+        this.cursor.readPreference,
+        { operationName: 'reconnect topology in change stream' },
+        serverSelectionError => {
+          if (serverSelectionError) return this._closeEmitterModeWithError(changeStreamError);
+          this.cursor = this._createChangeStreamCursor(this.cursor.resumeOptions);
+        }
+      );
     } else {
       this._closeEmitterModeWithError(changeStreamError);
     }
@@ -962,7 +966,9 @@ export class ChangeStream<
     await this.cursor.close().catch(() => null);
     const topology = getTopology(this.parent);
     try {
-      await topology.selectServerAsync(this.cursor.readPreference, {});
+      await topology.selectServerAsync(this.cursor.readPreference, {
+        operationName: 'reconnect topology in change stream'
+      });
       this.cursor = this._createChangeStreamCursor(this.cursor.resumeOptions);
     } catch {
       // if the topology can't reconnect, close the stream

src/constants.ts

@@ -30,6 +30,14 @@ export const TOPOLOGY_CLOSED = 'topologyClosed' as const;
 /** @internal */
 export const TOPOLOGY_DESCRIPTION_CHANGED = 'topologyDescriptionChanged' as const;
 /** @internal */
+export const SERVER_SELECTION_STARTED = 'serverSelectionStarted' as const;
+/** @internal */
+export const SERVER_SELECTION_FAILED = 'serverSelectionFailed' as const;
+/** @internal */
+export const SERVER_SELECTION_SUCCEEDED = 'serverSelectionSucceeded' as const;
+/** @internal */
+export const WAITING_FOR_SUITABLE_SERVER = 'waitingForSuitableServer' as const;
+/** @internal */
 export const CONNECTION_POOL_CREATED = 'connectionPoolCreated' as const;
 /** @internal */
 export const CONNECTION_POOL_CLOSED = 'connectionPoolClosed' as const;

src/index.ts

@@ -147,6 +147,13 @@ export {
   TopologyDescriptionChangedEvent,
   TopologyOpeningEvent
 } from './sdam/events';
+export {
+  ServerSelectionEvent,
+  ServerSelectionFailedEvent,
+  ServerSelectionStartedEvent,
+  ServerSelectionSucceededEvent,
+  WaitingForSuitableServerEvent
+} from './sdam/server_selection_events';
 export { SrvPollingEvent } from './sdam/srv_polling';
 
 // type only exports below, these are removed from emitted JS
@@ -303,9 +310,13 @@ export type {
   SERVER_HEARTBEAT_STARTED,
   SERVER_HEARTBEAT_SUCCEEDED,
   SERVER_OPENING,
+  SERVER_SELECTION_FAILED,
+  SERVER_SELECTION_STARTED,
+  SERVER_SELECTION_SUCCEEDED,
   TOPOLOGY_CLOSED,
   TOPOLOGY_DESCRIPTION_CHANGED,
-  TOPOLOGY_OPENING
+  TOPOLOGY_OPENING,
+  WAITING_FOR_SUITABLE_SERVER
 } from './constants';
 export type {
   AbstractCursorEvents,

src/mongo_logger.ts

@@ -17,7 +17,6 @@ import type {
   ConnectionPoolClearedEvent,
   ConnectionPoolClosedEvent,
   ConnectionPoolCreatedEvent,
-  ConnectionPoolMonitoringEvent,
   ConnectionPoolReadyEvent,
   ConnectionReadyEvent
 } from './cmap/connection_pool_events';
@@ -41,9 +40,13 @@ import {
   SERVER_HEARTBEAT_STARTED,
   SERVER_HEARTBEAT_SUCCEEDED,
   SERVER_OPENING,
+  SERVER_SELECTION_FAILED,
+  SERVER_SELECTION_STARTED,
+  SERVER_SELECTION_SUCCEEDED,
   TOPOLOGY_CLOSED,
   TOPOLOGY_DESCRIPTION_CHANGED,
-  TOPOLOGY_OPENING
+  TOPOLOGY_OPENING,
+  WAITING_FOR_SUITABLE_SERVER
 } from './constants';
 import type {
   ServerClosedEvent,
@@ -52,6 +55,13 @@ import type {
   TopologyDescriptionChangedEvent,
   TopologyOpeningEvent
 } from './sdam/events';
+import type {
+  ServerSelectionEvent,
+  ServerSelectionFailedEvent,
+  ServerSelectionStartedEvent,
+  ServerSelectionSucceededEvent,
+  WaitingForSuitableServerEvent
+} from './sdam/server_selection_events';
 import { HostAddress, parseUnsignedInteger } from './utils';
 
 /** @internal */
@@ -335,6 +345,10 @@ type SDAMLoggableEvent =
 
 /** @internal */
 export type LoggableEvent =
+  | ServerSelectionStartedEvent
+  | ServerSelectionFailedEvent
+  | ServerSelectionSucceededEvent
+  | WaitingForSuitableServerEvent
   | CommandStartedEvent
   | CommandSucceededEvent
   | CommandFailedEvent
@@ -369,11 +383,16 @@ export function stringifyWithMaxLen(
   maxDocumentLength: number,
   options: EJSONOptions = {}
 ): string {
-  const ejson = EJSON.stringify(value, options);
+  let strToTruncate: string;
+  if (typeof value === 'function') {
+    strToTruncate = value.toString();
+  } else {
+    strToTruncate = EJSON.stringify(value, options);
+  }
 
-  return maxDocumentLength !== 0 && ejson.length > maxDocumentLength
-    ? `${ejson.slice(0, maxDocumentLength)}...`
-    : ejson;
+  return maxDocumentLength !== 0 && strToTruncate.length > maxDocumentLength
+    ? `${strToTruncate.slice(0, maxDocumentLength)}...`
+    : strToTruncate;
 }
 
 /** @internal */
@@ -385,6 +404,20 @@ function isLogConvertible(obj: Loggable): obj is LogConvertible {
   return objAsLogConvertible.toLog !== undefined && typeof objAsLogConvertible.toLog === 'function';
 }
 
+function attachServerSelectionFields(
+  log: Record<string, any>,
+  serverSelectionEvent: ServerSelectionEvent,
+  maxDocumentLength: number = DEFAULT_MAX_DOCUMENT_LENGTH
+) {
+  const { selector, operation, topologyDescription, message } = serverSelectionEvent;
+  log.selector = stringifyWithMaxLen(selector, maxDocumentLength);
+  log.operation = operation;
+  log.topologyDescription = stringifyWithMaxLen(topologyDescription, maxDocumentLength);
+  log.message = message;
+
+  return log;
+}
+
 function attachCommandFields(
   log: Record<string, any>,
   commandEvent: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent
@@ -402,10 +435,7 @@ function attachCommandFields(
   return log;
 }
 
-function attachConnectionFields(
-  log: Record<string, any>,
-  event: ConnectionPoolMonitoringEvent | ServerOpeningEvent | ServerClosedEvent
-) {
+function attachConnectionFields(log: Record<string, any>, event: any) {
   const { host, port } = HostAddress.fromString(event.address).toHostPort();
   log.serverHost = host;
   log.serverPort = port;
@@ -441,6 +471,22 @@ function defaultLogTransform(
   let log: Omit<Log, 's' | 't' | 'c'> = Object.create(null);
 
   switch (logObject.name) {
+    case SERVER_SELECTION_STARTED:
+      log = attachServerSelectionFields(log, logObject, maxDocumentLength);
+      return log;
+    case SERVER_SELECTION_FAILED:
+      log = attachServerSelectionFields(log, logObject, maxDocumentLength);
+      log.failure = logObject.failure.message;
+      return log;
+    case SERVER_SELECTION_SUCCEEDED:
+      log = attachServerSelectionFields(log, logObject, maxDocumentLength);
+      log.serverHost = logObject.serverHost;
+      log.serverPort = logObject.serverPort;
+      return log;
+    case WAITING_FOR_SUITABLE_SERVER:
+      log = attachServerSelectionFields(log, logObject, maxDocumentLength);
+      log.remainingTimeMS = logObject.remainingTimeMS;
+      return log;
     case COMMAND_STARTED:
       log = attachCommandFields(log, logObject);
       log.message = 'Command started';

src/operations/execute_operation.ts

@@ -151,7 +151,10 @@ async function executeOperationAsync<
     selector = readPreference;
   }
 
-  const server = await topology.selectServerAsync(selector, { session });
+  const server = await topology.selectServerAsync(selector, {
+    session,
+    operationName: operation.commandName
+  });
 
   if (session == null) {
     // No session also means it is not retryable, early exit
@@ -251,7 +254,10 @@ async function retryOperation<
   }
 
   // select a new server, and attempt to retry the operation
-  const server = await topology.selectServerAsync(selector, { session });
+  const server = await topology.selectServerAsync(selector, {
+    session,
+    operationName: operation.commandName
+  });
 
   if (isWriteOperation && !supportsRetryableWrites(server)) {
     throw new MongoUnexpectedServerResponseError(

src/sdam/server_selection_events.ts

@@ -0,0 +1,142 @@
+import { HostAddress } from '.././utils';
+import {
+  SERVER_SELECTION_FAILED,
+  SERVER_SELECTION_STARTED,
+  SERVER_SELECTION_SUCCEEDED,
+  WAITING_FOR_SUITABLE_SERVER
+} from '../constants';
+import { type ReadPreference } from '../read_preference';
+import { type ServerSelector } from './server_selection';
+import type { TopologyDescription } from './topology_description';
+
+/**
+ * The base export class for all logs published from server selection
+ * @internal
+ * @category Log Type
+ */
+export abstract class ServerSelectionEvent {
+  /** String representation of the selector being used to select the server.
+   *  Defaults to 'custom selector' for application-provided custom selector case.
+   */
+  selector: string | ReadPreference | ServerSelector;
+  /** The name of the operation for which a server is being selected.  */
+  operation: string;
+  /** 	The current topology description.  */
+  topologyDescription: TopologyDescription;
+
+  /** @internal */
+  abstract name:
+    | typeof SERVER_SELECTION_STARTED
+    | typeof SERVER_SELECTION_SUCCEEDED
+    | typeof SERVER_SELECTION_FAILED
+    | typeof WAITING_FOR_SUITABLE_SERVER;
+
+  abstract message: string;
+
+  /** @internal */
+  constructor(
+    selector: string | ReadPreference | ServerSelector,
+    topologyDescription: TopologyDescription,
+    operation: string
+  ) {
+    this.selector = selector;
+    this.operation = operation;
+    this.topologyDescription = topologyDescription;
+  }
+}
+
+/**
+ * An event published when server selection starts
+ * @internal
+ * @category Event
+ */
+export class ServerSelectionStartedEvent extends ServerSelectionEvent {
+  /** @internal */
+  name = SERVER_SELECTION_STARTED;
+  message = 'Server selection started';
+
+  /** @internal */
+  constructor(
+    selector: string | ReadPreference | ServerSelector,
+    topologyDescription: TopologyDescription,
+    operation: string
+  ) {
+    super(selector, topologyDescription, operation);
+  }
+}
+
+/**
+ * An event published when a server selection fails
+ * @internal
+ * @category Event
+ */
+export class ServerSelectionFailedEvent extends ServerSelectionEvent {
+  /** @internal */
+  name = SERVER_SELECTION_FAILED;
+  message = 'Server selection failed';
+  /** Representation of the error the driver will throw regarding server selection failing. */
+  failure: Error;
+
+  /** @internal */
+  constructor(
+    selector: string | ReadPreference | ServerSelector,
+    topologyDescription: TopologyDescription,
+    error: Error,
+    operation: string
+  ) {
+    super(selector, topologyDescription, operation);
+    this.failure = error;
+  }
+}
+
+/**
+ * An event published when server selection succeeds
+ * @internal
+ * @category Event
+ */
+export class ServerSelectionSucceededEvent extends ServerSelectionEvent {
+  /** @internal */
+  name = SERVER_SELECTION_SUCCEEDED;
+  message = 'Server selection succeeded';
+  /** 	The hostname, IP address, or Unix domain socket path for the selected server. */
+  serverHost: string;
+  /** The port for the selected server. Optional; not present for Unix domain sockets. When the user does not specify a port and the default (27017) is used, the driver SHOULD include it here. */
+  serverPort: number | undefined;
+
+  /** @internal */
+  constructor(
+    selector: string | ReadPreference | ServerSelector,
+    topologyDescription: TopologyDescription,
+    address: string,
+    operation: string
+  ) {
+    super(selector, topologyDescription, operation);
+    const { host, port } = HostAddress.fromString(address).toHostPort();
+    this.serverHost = host;
+    this.serverPort = port;
+  }
+}
+
+/**
+ * An event published when server selection is waiting for a suitable server to become available
+ * @internal
+ * @category Event
+ */
+export class WaitingForSuitableServerEvent extends ServerSelectionEvent {
+  /** @internal */
+  name = WAITING_FOR_SUITABLE_SERVER;
+  message = 'Waiting for suitable server to become available';
+  /** The remaining time left until server selection will time out. */
+  remainingTimeMS: number;
+
+  /** @internal */
+  constructor(
+    selector: string | ReadPreference | ServerSelector,
+    topologyDescription: TopologyDescription,
+    remainingTimeMS: number,
+    operation: string
+  ) {
+    super(selector, topologyDescription, operation);
+    this.remainingTimeMS = remainingTimeMS;
+  }
+}