refactor(NODE-4685): unified spec runner to support logging tests (#3578)

Author: W-A-James

src/connection_string.ts

@@ -531,7 +531,8 @@ export function parseOptions(
       MONGODB_LOG_CONNECTION: process.env.MONGODB_LOG_CONNECTION,
       MONGODB_LOG_ALL: process.env.MONGODB_LOG_ALL,
       MONGODB_LOG_MAX_DOCUMENT_LENGTH: process.env.MONGODB_LOG_MAX_DOCUMENT_LENGTH,
-      MONGODB_LOG_PATH: process.env.MONGODB_LOG_PATH
+      MONGODB_LOG_PATH: process.env.MONGODB_LOG_PATH,
+      ...mongoOptions[Symbol.for('@@mdb.internalLoggerConfig')]
     };
     loggerClientOptions = {
       mongodbLogPath: mongoOptions.mongodbLogPath
@@ -1282,7 +1283,10 @@ export const OPTIONS = {
   index: { type: 'any' },
   // Legacy Options, these are unused but left here to avoid errors with CSFLE lib
   useNewUrlParser: { type: 'boolean' } as OptionDescriptor,
-  useUnifiedTopology: { type: 'boolean' } as OptionDescriptor
+  useUnifiedTopology: { type: 'boolean' } as OptionDescriptor,
+  // MongoLogger
+  // TODO(NODE-4849): Tighten the type of mongodbLogPath
+  mongodbLogPath: { type: 'any' }
 } as Record<keyof MongoClientOptions, OptionDescriptor>;
 
 export const DEFAULT_OPTIONS = new CaseInsensitiveMap(

src/mongo_logger.ts

@@ -19,6 +19,24 @@ export const SeverityLevel = Object.freeze({
 /** @internal */
 export type SeverityLevel = (typeof SeverityLevel)[keyof typeof SeverityLevel];
 
+/** @internal */
+export const SeverityLevelMap: Map<string | number, string | number> = new Map([
+  [SeverityLevel.OFF, -Infinity],
+  [SeverityLevel.EMERGENCY, 0],
+  [SeverityLevel.ALERT, 1],
+  [SeverityLevel.CRITICAL, 2],
+  [SeverityLevel.ERROR, 3],
+  [SeverityLevel.WARNING, 4],
+  [SeverityLevel.NOTICE, 5],
+  [SeverityLevel.INFORMATIONAL, 6],
+  [SeverityLevel.DEBUG, 7],
+  [SeverityLevel.TRACE, 8]
+]);
+
+for (const [level, value] of SeverityLevelMap) {
+  SeverityLevelMap.set(value, level);
+}
+
 /** @internal */
 export const MongoLoggableComponent = Object.freeze({
   COMMAND: 'command',

test/integration/command-logging-and-monitoring/command_monitoring.spec.test.ts renamed to test/integration/command-logging-and-monitoring/command_logging_and_monitoring.spec.test.ts

@@ -11,10 +11,18 @@ import { runUnifiedSuite } from '../../tools/unified-spec-runner/runner';
 // the server. There's nothing we can change here.
 const SKIP = ['A successful unordered bulk write with an unacknowledged write concern'];
 
-describe('Command Monitoring Spec (unified)', () => {
-  runUnifiedSuite(
-    loadSpecTests(path.join('command-logging-and-monitoring', 'monitoring')),
-    ({ description }) =>
-      SKIP.includes(description) ? `TODO(NODE-4261): support skip reasons in unified tests` : false
-  );
+describe('Command Logging and Monitoring Spec', function () {
+  describe('Command Monitoring Spec (unified)', () => {
+    runUnifiedSuite(
+      loadSpecTests(path.join('command-logging-and-monitoring', 'monitoring')),
+      ({ description }) =>
+        SKIP.includes(description)
+          ? `TODO(NODE-4261): support skip reasons in unified tests`
+          : false
+    );
+  });
+
+  describe.skip('Command Logging Spec', () => {
+    runUnifiedSuite(loadSpecTests(path.join('command-logging-and-monitoring', 'logging')));
+  }).skipReason = 'TODO(NODE-4686): Unskip these tests';
 });

test/tools/unified-spec-runner/entities.ts

@@ -1,6 +1,7 @@
 /* eslint-disable @typescript-eslint/no-non-null-assertion */
 import { expect } from 'chai';
 import { EventEmitter } from 'events';
+import { Writable } from 'stream';
 
 import {
   AbstractCursor,
@@ -37,7 +38,12 @@ import {
 import { ejson, getEnvironmentalOptions } from '../../tools/utils';
 import type { TestConfiguration } from '../runner/config';
 import { trace } from './runner';
-import type { ClientEncryption, ClientEntity, EntityDescription } from './schema';
+import type {
+  ClientEncryption,
+  ClientEntity,
+  EntityDescription,
+  ExpectedLogMessage
+} from './schema';
 import {
   createClientEncryption,
   makeConnectionString,
@@ -95,16 +101,40 @@ export type CmapEvent =
   | ConnectionCheckedInEvent
   | ConnectionPoolClearedEvent;
 export type SdamEvent = ServerDescriptionChangedEvent;
+export type LogMessage = Omit<ExpectedLogMessage, 'failureIsRedacted'>;
 
 function getClient(address) {
   return new MongoClient(`mongodb://${address}`, getEnvironmentalOptions());
 }
 
+// TODO(NODE-4813): Remove this class in favour of a simple object with a write method
+/* TODO(NODE-4813): Ensure that the object that we replace this with has logic to convert the
+ * collected log into the format require by the unified spec runner
+ * (see ExpectedLogMessage type in schema.ts) */
+export class UnifiedLogCollector extends Writable {
+  collectedLogs: LogMessage[] = [];
+
+  constructor() {
+    super({ objectMode: true });
+  }
+
+  _write(
+    log: LogMessage,
+    _: string,
+    callback: (e: Error | null, l: LogMessage | undefined) => void
+  ) {
+    this.collectedLogs.push(log);
+    callback(null, log);
+  }
+}
+
 export class UnifiedMongoClient extends MongoClient {
   commandEvents: CommandEvent[] = [];
   cmapEvents: CmapEvent[] = [];
   sdamEvents: SdamEvent[] = [];
   failPoints: Document[] = [];
+  logCollector: UnifiedLogCollector;
+
   ignoredEvents: string[];
   observedCommandEvents: ('commandStarted' | 'commandSucceeded' | 'commandFailed')[];
   observedCmapEvents: (
@@ -148,13 +178,35 @@ export class UnifiedMongoClient extends MongoClient {
     serverDescriptionChangedEvent: 'serverDescriptionChanged'
   } as const;
 
+  static LOGGING_COMPONENT_TO_ENV_VAR_NAME = {
+    command: 'MONGODB_LOG_COMMAND',
+    serverSelection: 'MONGODB_LOG_SERVER_SELECTION',
+    connection: 'MONGODB_LOG_CONNECTION',
+    topology: 'MONGODB_LOG_TOPOLOGY'
+  } as const;
+
   constructor(uri: string, description: ClientEntity) {
+    const logCollector = new UnifiedLogCollector();
+    const componentSeverities = {
+      MONGODB_LOG_ALL: 'off'
+    };
+
+    // NOTE: this is done to override the logger environment variables
+    for (const key in description.observeLogMessages) {
+      componentSeverities[UnifiedMongoClient.LOGGING_COMPONENT_TO_ENV_VAR_NAME[key]] =
+        description.observeLogMessages[key];
+    }
+
     super(uri, {
       monitorCommands: true,
       [Symbol.for('@@mdb.skipPingOnConnect')]: true,
+      [Symbol.for('@@mdb.enableMongoLogger')]: true,
+      [Symbol.for('@@mdb.internalMongoLoggerConfig')]: componentSeverities,
+      mongodbLogPath: logCollector,
       ...getEnvironmentalOptions(),
       ...(description.serverApi ? { serverApi: description.serverApi } : {})
     });
+    this.logCollector = logCollector;
 
     this.ignoredEvents = [
       ...(description.ignoreCommandMonitoringEvents ?? []),
@@ -242,6 +294,10 @@ export class UnifiedMongoClient extends MongoClient {
       this.off(eventName, this.pushSdamEvent);
     }
   }
+
+  get collectedLogs(): LogMessage[] {
+    return this.logCollector.collectedLogs;
+  }
 }
 
 export class FailPointMap extends Map<string, Document> {

test/tools/unified-spec-runner/match.ts

@@ -1,4 +1,5 @@
 /* eslint-disable @typescript-eslint/no-non-null-assertion */
+import { EJSON } from 'bson';
 import { expect } from 'chai';
 import { inspect } from 'util';
 
@@ -34,6 +35,7 @@ import {
   ExpectedCommandEvent,
   ExpectedError,
   ExpectedEventsForClient,
+  ExpectedLogMessage,
   ExpectedSdamEvent
 } from './schema';
 
@@ -73,12 +75,26 @@ export interface SessionLsidOperator {
 export function isSessionLsidOperator(value: unknown): value is SessionLsidOperator {
   return typeof value === 'object' && value != null && '$$sessionLsid' in value;
 }
+export interface MatchAsDocumentOperator {
+  $$matchAsDocument: unknown;
+}
+export function isMatchAsDocumentOperator(value: unknown): value is MatchAsDocumentOperator {
+  return typeof value === 'object' && value != null && '$$matchAsDocument' in value;
+}
+export interface MatchAsRootOperator {
+  $$matchAsRoot: unknown;
+}
+export function isMatchAsRootOperator(value: unknown): value is MatchAsRootOperator {
+  return typeof value === 'object' && value != null && '$$matchAsRoot' in value;
+}
 
 export const SpecialOperatorKeys = [
   '$$exists',
   '$$type',
   '$$matchesEntity',
   '$$matchesHexBytes',
+  '$$matchAsRoot',
+  '$$matchAsDocument',
   '$$unsetOrMatches',
   '$$sessionLsid'
 ];
@@ -89,7 +105,9 @@ export type SpecialOperator =
   | MatchesEntityOperator
   | MatchesHexBytesOperator
   | UnsetOrMatchesOperator
-  | SessionLsidOperator;
+  | SessionLsidOperator
+  | MatchAsDocumentOperator
+  | MatchAsRootOperator;
 
 type KeysOfUnion<T> = T extends object ? keyof T : never;
 export type SpecialOperatorKey = KeysOfUnion<SpecialOperator>;
@@ -100,7 +118,9 @@ export function isSpecialOperator(value: unknown): value is SpecialOperator {
     isMatchesEntityOperator(value) ||
     isMatchesHexBytesOperator(value) ||
     isUnsetOrMatchesOperator(value) ||
-    isSessionLsidOperator(value)
+    isSessionLsidOperator(value) ||
+    isMatchAsRootOperator(value) ||
+    isMatchAsDocumentOperator(value)
   );
 }
 
@@ -199,6 +219,10 @@ export function resultCheck(
       return;
     }
 
+    if (typeof actual !== 'object') {
+      expect.fail('Expected actual value to be an object');
+    }
+
     const expectedEntries = Object.entries(expected);
 
     if (Array.isArray(expected)) {
@@ -294,8 +318,9 @@ export function specialCheck(
     // $$sessionLsid
     const session = entities.getEntity('session', expected.$$sessionLsid, false);
     expect(session, `Session ${expected.$$sessionLsid} does not exist in entities`).to.exist;
-    const entitySessionHex = session.id!.id.buffer.toString('hex').toUpperCase();
-    const actualSessionHex = actual.id.buffer.toString('hex').toUpperCase();
+    const entitySessionHex = session.id!.id.toString('hex').toUpperCase();
+    const actualSessionHex = actual.id!.toString('hex').toUpperCase();
+
     expect(
       entitySessionHex,
       `Session entity ${expected.$$sessionLsid} does not match lsid`
@@ -323,6 +348,25 @@ export function specialCheck(
         ejson`expected value at path ${path.join('')} NOT to exist, but received ${actual}`
       ).to.be.false;
     }
+  } else if (isMatchAsDocumentOperator(expected)) {
+    if (typeof actual === 'string') {
+      const actualDoc = EJSON.parse(actual, { relaxed: false });
+      resultCheck(actualDoc, expected.$$matchAsDocument as any, entities, path, true);
+    } else {
+      expect.fail(
+        `Expected value at path '${path.join('')}' to be string, but received ${inspect(actual)}`
+      );
+    }
+  } else if (isMatchAsRootOperator(expected)) {
+    expect(
+      typeof actual,
+      `Expected value at path '${path.join('')}' to be object, but received ${inspect(actual)}`
+    ).to.equal('object');
+    expect(typeof expected.$$matchAsRoot, 'Value of $$matchAsRoot must be an object').to.equal(
+      'object'
+    );
+
+    resultCheck(actual, expected.$$matchAsRoot as any, entities, path, false);
   } else {
     expect.fail(`Unknown special operator: ${JSON.stringify(expected)}`);
   }
@@ -523,6 +567,44 @@ export function matchesEvents(
   }
 }
 
+export function compareLogs(
+  expected: ExpectedLogMessage[],
+  actual: ExpectedLogMessage[],
+  entities: EntitiesMap
+): void {
+  expect(actual).to.have.lengthOf(expected.length);
+
+  for (const [index, actualLog] of actual.entries()) {
+    const rootPrefix = `expectLogMessages[${index}]`;
+    const expectedLog = expected[index];
+
+    // Check that log levels match
+    expect(actualLog).to.have.property('level', expectedLog.level);
+
+    // Check that components match
+    expect(actualLog).to.have.property('component', expectedLog.component);
+
+    // NOTE: The spec states that if the failureIsRedacted flag is present, we
+    // must assert that a failure occurred.
+    if (expectedLog.failureIsRedacted !== undefined) {
+      expect(expectedLog.failureIsRedacted).to.be.a('boolean');
+      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({});
+      } else {
+        // Assert that failure has not been redacted
+        expect(
+          actualLog.data.failure,
+          'Expected failure to have not been redacted'
+        ).to.not.deep.equal({});
+      }
+    }
+
+    resultCheck(actualLog.data, expectedLog.data, entities, [rootPrefix], false);
+  }
+}
+
 function isMongoCryptError(err): boolean {
   if (err.constructor.name === 'MongoCryptError') {
     return true;

test/tools/unified-spec-runner/operations.ts

@@ -23,7 +23,7 @@ import { getSymbolFrom, sleep } from '../../tools/utils';
 import { TestConfiguration } from '../runner/config';
 import { EntitiesMap, UnifiedChangeStream } from './entities';
 import { expectErrorCheck, resultCheck } from './match';
-import type { ExpectedEvent, OperationDescription } from './schema';
+import type { ExpectedEvent, ExpectedLogMessage, OperationDescription } from './schema';
 import { getMatchingEventCount, translateOptions } from './unified-utils';
 
 interface OperationFunctionParams {

test/tools/unified-spec-runner/runner.ts

@@ -6,7 +6,7 @@ import type { MongoClient } from '../../mongodb';
 import { MONGODB_ERROR_CODES, ns, ReadPreference, TopologyType } from '../../mongodb';
 import { ejson } from '../utils';
 import { EntitiesMap, UnifiedMongoClient } from './entities';
-import { matchesEvents } from './match';
+import { compareLogs, matchesEvents } from './match';
 import { executeOperationAndCheck } from './operations';
 import * as uni from './schema';
 import { isAnyRequirementSatisfied, patchVersion, zip } from './unified-utils';
@@ -219,6 +219,16 @@ async function runUnifiedTest(
       }
     }
 
+    if (test.expectLogMessages) {
+      for (const expectedLogsForClient of test.expectLogMessages) {
+        const clientId = expectedLogsForClient.client;
+        const testClient = clientList.get(clientId);
+
+        expect(testClient, `No client entity found with id ${clientId}`).to.exist;
+        compareLogs(expectedLogsForClient.messages, testClient!.collectedLogs, entities);
+      }
+    }
+
     if (test.outcome) {
       for (const collectionData of test.outcome) {
         const collection = utilClient