feat(NODE-4719): add SDAM Logging Spec (#3940)

mongodb · Dec 14, 2023 · a3c0298 · a3c0298
1 parent 371aae8
commit a3c0298
Show file tree

Hide file tree

Showing 64 changed files with 3,930 additions and 136 deletions.
diff --git a/src/constants.ts b/src/constants.ts
@@ -17,11 +17,17 @@ export const MESSAGE = 'message' as const;
 export const PINNED = 'pinned' as const;
 export const UNPINNED = 'unpinned' as const;
 export const DESCRIPTION_RECEIVED = 'descriptionReceived';
+/** @internal */
 export const SERVER_OPENING = 'serverOpening' as const;
+/** @internal */
 export const SERVER_CLOSED = 'serverClosed' as const;
+/** @internal */
 export const SERVER_DESCRIPTION_CHANGED = 'serverDescriptionChanged' as const;
+/** @internal */
 export const TOPOLOGY_OPENING = 'topologyOpening' as const;
+/** @internal */
 export const TOPOLOGY_CLOSED = 'topologyClosed' as const;
+/** @internal */
 export const TOPOLOGY_DESCRIPTION_CHANGED = 'topologyDescriptionChanged' as const;
 /** @internal */
 export const CONNECTION_POOL_CREATED = 'connectionPoolCreated' as const;
@@ -49,8 +55,11 @@ export const CLUSTER_TIME_RECEIVED = 'clusterTimeReceived' as const;
 export const COMMAND_STARTED = 'commandStarted' as const;
 export const COMMAND_SUCCEEDED = 'commandSucceeded' as const;
 export const COMMAND_FAILED = 'commandFailed' as const;
+/** @internal */
 export const SERVER_HEARTBEAT_STARTED = 'serverHeartbeatStarted' as const;
+/** @internal */
 export const SERVER_HEARTBEAT_SUCCEEDED = 'serverHeartbeatSucceeded' as const;
+/** @internal */
 export const SERVER_HEARTBEAT_FAILED = 'serverHeartbeatFailed' as const;
 export const RESPONSE = 'response' as const;
 export const MORE = 'more' as const;

diff --git a/src/index.ts b/src/index.ts
@@ -305,7 +305,16 @@ export type {
   CONNECTION_POOL_CREATED,
   CONNECTION_POOL_READY,
   CONNECTION_READY,
-  MONGO_CLIENT_EVENTS
+  MONGO_CLIENT_EVENTS,
+  SERVER_CLOSED,
+  SERVER_DESCRIPTION_CHANGED,
+  SERVER_HEARTBEAT_FAILED,
+  SERVER_HEARTBEAT_STARTED,
+  SERVER_HEARTBEAT_SUCCEEDED,
+  SERVER_OPENING,
+  TOPOLOGY_CLOSED,
+  TOPOLOGY_DESCRIPTION_CHANGED,
+  TOPOLOGY_OPENING
 } from './constants';
 export type {
   AbstractCursorEvents,
@@ -357,6 +366,9 @@ export type {
   LogConvertible,
   Loggable,
   LoggableEvent,
+  LoggableServerHeartbeatFailedEvent,
+  LoggableServerHeartbeatStartedEvent,
+  LoggableServerHeartbeatSucceededEvent,
   MongoDBLogWritable,
   MongoLoggableComponent,
   MongoLogger,

diff --git a/src/mongo_logger.ts b/src/mongo_logger.ts
@@ -1,4 +1,4 @@
-import { EJSON } from 'bson';
+import { type Document, EJSON, type EJSONOptions } from 'bson';
 import type { Writable } from 'stream';
 import { inspect } from 'util';
 
@@ -35,8 +35,23 @@ import {
   CONNECTION_POOL_CLOSED,
   CONNECTION_POOL_CREATED,
   CONNECTION_POOL_READY,
-  CONNECTION_READY
+  CONNECTION_READY,
+  SERVER_CLOSED,
+  SERVER_HEARTBEAT_FAILED,
+  SERVER_HEARTBEAT_STARTED,
+  SERVER_HEARTBEAT_SUCCEEDED,
+  SERVER_OPENING,
+  TOPOLOGY_CLOSED,
+  TOPOLOGY_DESCRIPTION_CHANGED,
+  TOPOLOGY_OPENING
 } from './constants';
+import type {
+  ServerClosedEvent,
+  ServerOpeningEvent,
+  TopologyClosedEvent,
+  TopologyDescriptionChangedEvent,
+  TopologyOpeningEvent
+} from './sdam/events';
 import { HostAddress, parseUnsignedInteger } from './utils';
 
 /** @internal */
@@ -270,6 +285,54 @@ 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 server heartbeat beginning
+ */
+export type LoggableServerHeartbeatStartedEvent = {
+  topologyId: number;
+  awaited: boolean;
+  connectionId: string;
+  name: typeof SERVER_HEARTBEAT_STARTED;
+};
+
+/**
+ * @internal
+ * Must be separate from Events API due to differences in spec requirements for logging server heartbeat success
+ */
+export type LoggableServerHeartbeatSucceededEvent = {
+  topologyId: number;
+  awaited: boolean;
+  connectionId: string;
+  reply: Document;
+  serverConnectionId: number | '<monitor>';
+  duration: number;
+  name: typeof SERVER_HEARTBEAT_SUCCEEDED;
+};
+
+/**
+ * @internal
+ * Must be separate from Events API due to differences in spec requirements for logging server heartbeat failure
+ */
+export type LoggableServerHeartbeatFailedEvent = {
+  topologyId: number;
+  awaited: boolean;
+  connectionId: string;
+  failure: Error;
+  duration: number;
+  name: typeof SERVER_HEARTBEAT_FAILED;
+};
+
+type SDAMLoggableEvent =
+  | ServerClosedEvent
+  | LoggableServerHeartbeatFailedEvent
+  | LoggableServerHeartbeatStartedEvent
+  | LoggableServerHeartbeatSucceededEvent
+  | ServerOpeningEvent
+  | TopologyClosedEvent
+  | TopologyDescriptionChangedEvent
+  | TopologyOpeningEvent;
+
 /** @internal */
 export type LoggableEvent =
   | CommandStartedEvent
@@ -285,16 +348,28 @@ export type LoggableEvent =
   | ConnectionCheckedInEvent
   | ConnectionCheckedOutEvent
   | ConnectionCheckOutStartedEvent
-  | ConnectionCheckOutFailedEvent;
+  | ConnectionCheckOutFailedEvent
+  | ServerClosedEvent
+  | LoggableServerHeartbeatFailedEvent
+  | LoggableServerHeartbeatStartedEvent
+  | LoggableServerHeartbeatSucceededEvent
+  | ServerOpeningEvent
+  | TopologyClosedEvent
+  | TopologyDescriptionChangedEvent
+  | TopologyOpeningEvent;
 
 /** @internal */
 export interface LogConvertible extends Record<string, any> {
   toLog(): Record<string, any>;
 }
 
 /** @internal */
-export function stringifyWithMaxLen(value: any, maxDocumentLength: number): string {
-  const ejson = EJSON.stringify(value);
+export function stringifyWithMaxLen(
+  value: any,
+  maxDocumentLength: number,
+  options: EJSONOptions = {}
+): string {
+  const ejson = EJSON.stringify(value, options);
 
   return maxDocumentLength !== 0 && ejson.length > maxDocumentLength
     ? `${ejson.slice(0, maxDocumentLength)}...`
@@ -329,15 +404,36 @@ function attachCommandFields(
 
 function attachConnectionFields(
   log: Record<string, any>,
-  connectionPoolEvent: ConnectionPoolMonitoringEvent
+  event: ConnectionPoolMonitoringEvent | ServerOpeningEvent | ServerClosedEvent
 ) {
-  const { host, port } = HostAddress.fromString(connectionPoolEvent.address).toHostPort();
+  const { host, port } = HostAddress.fromString(event.address).toHostPort();
   log.serverHost = host;
   log.serverPort = port;
 
   return log;
 }
 
+function attachSDAMFields(log: Record<string, any>, sdamEvent: SDAMLoggableEvent) {
+  log.topologyId = sdamEvent.topologyId;
+  return log;
+}
+
+function attachServerHeartbeatFields(
+  log: Record<string, any>,
+  serverHeartbeatEvent:
+    | LoggableServerHeartbeatFailedEvent
+    | LoggableServerHeartbeatStartedEvent
+    | LoggableServerHeartbeatSucceededEvent
+) {
+  const { awaited, connectionId } = serverHeartbeatEvent;
+  log.awaited = awaited;
+  log.driverConnectionId = serverHeartbeatEvent.connectionId;
+  const { host, port } = HostAddress.fromString(connectionId).toHostPort();
+  log.serverHost = host;
+  log.serverPort = port;
+  return log;
+}
+
 function defaultLogTransform(
   logObject: LoggableEvent | Record<string, any>,
   maxDocumentLength: number = DEFAULT_MAX_DOCUMENT_LENGTH
@@ -456,14 +552,63 @@ function defaultLogTransform(
     case CONNECTION_CHECKED_OUT:
       log = attachConnectionFields(log, logObject);
       log.message = 'Connection checked out';
-
       log.driverConnectionId = logObject.connectionId;
       return log;
     case CONNECTION_CHECKED_IN:
       log = attachConnectionFields(log, logObject);
       log.message = 'Connection checked in';
       log.driverConnectionId = logObject.connectionId;
       return log;
+    case SERVER_OPENING:
+      log = attachSDAMFields(log, logObject);
+      log = attachConnectionFields(log, logObject);
+      log.message = 'Starting server monitoring';
+      return log;
+    case SERVER_CLOSED:
+      log = attachSDAMFields(log, logObject);
+      log = attachConnectionFields(log, logObject);
+      log.message = 'Stopped server monitoring';
+      return log;
+    case SERVER_HEARTBEAT_STARTED:
+      log = attachSDAMFields(log, logObject);
+      log = attachServerHeartbeatFields(log, logObject);
+      log.message = 'Server heartbeat started';
+      return log;
+    case SERVER_HEARTBEAT_SUCCEEDED:
+      log = attachSDAMFields(log, logObject);
+      log = attachServerHeartbeatFields(log, logObject);
+      log.message = 'Server heartbeat succeeded';
+      log.durationMS = logObject.duration;
+      log.serverConnectionId = logObject.serverConnectionId;
+      log.reply = stringifyWithMaxLen(logObject.reply, maxDocumentLength, { relaxed: true });
+      return log;
+    case SERVER_HEARTBEAT_FAILED:
+      log = attachSDAMFields(log, logObject);
+      log = attachServerHeartbeatFields(log, logObject);
+      log.message = 'Server heartbeat failed';
+      log.durationMS = logObject.duration;
+      log.failure = logObject.failure.message;
+      return log;
+    case TOPOLOGY_OPENING:
+      log = attachSDAMFields(log, logObject);
+      log.message = 'Starting topology monitoring';
+      return log;
+    case TOPOLOGY_CLOSED:
+      log = attachSDAMFields(log, logObject);
+      log.message = 'Stopped topology monitoring';
+      return log;
+    case TOPOLOGY_DESCRIPTION_CHANGED:
+      log = attachSDAMFields(log, logObject);
+      log.message = 'Topology description changed';
+      log.previousDescription = log.reply = stringifyWithMaxLen(
+        logObject.previousDescription,
+        maxDocumentLength
+      );
+      log.newDescription = log.reply = stringifyWithMaxLen(
+        logObject.newDescription,
+        maxDocumentLength
+      );
+      return log;
     default:
       for (const [key, value] of Object.entries(logObject)) {
         if (value != null) log[key] = value;

diff --git a/src/mongo_types.ts b/src/mongo_types.ts
@@ -12,7 +12,13 @@ import type {
   ObjectId,
   Timestamp
 } from './bson';
-import type { MongoLoggableComponent, MongoLogger } from './mongo_logger';
+import type {
+  LoggableServerHeartbeatFailedEvent,
+  LoggableServerHeartbeatStartedEvent,
+  LoggableServerHeartbeatSucceededEvent,
+  MongoLoggableComponent,
+  MongoLogger
+} from './mongo_logger';
 import type { Sort } from './sort';
 
 /** @internal */
@@ -405,13 +411,33 @@ export class TypedEventEmitter<Events extends EventsDescription> extends EventEm
   /** @internal */
   protected component?: MongoLoggableComponent;
   /** @internal */
-  protected emitAndLog<EventKey extends keyof Events>(
+  emitAndLog<EventKey extends keyof Events>(
     event: EventKey | symbol,
     ...args: Parameters<Events[EventKey]>
   ): void {
     this.emit(event, ...args);
     if (this.component) this.mongoLogger?.debug(this.component, args[0]);
   }
+  /** @internal */
+  emitAndLogHeartbeat<EventKey extends keyof Events>(
+    event: EventKey | symbol,
+    topologyId: number,
+    serverConnectionId?: number | '<monitor>',
+    ...args: Parameters<Events[EventKey]>
+  ): void {
+    this.emit(event, ...args);
+    if (this.component) {
+      const loggableHeartbeatEvent:
+        | LoggableServerHeartbeatFailedEvent
+        | LoggableServerHeartbeatSucceededEvent
+        | LoggableServerHeartbeatStartedEvent = {
+        topologyId: topologyId,
+        serverConnectionId: serverConnectionId ?? null,
+        ...args[0]
+      };
+      this.mongoLogger?.debug(this.component, loggableHeartbeatEvent);
+    }
+  }
 }
 
 /** @public */