diff --git a/test/integration/client-side-encryption/client_side_encryption.prose.test.js b/test/integration/client-side-encryption/client_side_encryption.prose.test.js index 9009bc94aff..a937c542a0d 100644 --- a/test/integration/client-side-encryption/client_side_encryption.prose.test.js +++ b/test/integration/client-side-encryption/client_side_encryption.prose.test.js @@ -2310,7 +2310,10 @@ describe('Client Side Encryption Prose Tests', metadata, function () { kmip: {}, local: undefined }; - let client1, client2; + /** @type {import('../../mongodb').MongoClient} */ + let client1; + /** @type {import('../../mongodb').MongoClient} */ + let client2; describe('Case 1: Rewrap with separate ClientEncryption', function () { /** @@ -2341,12 +2344,16 @@ describe('Client Side Encryption Prose Tests', metadata, function () { `should rewrap data key from ${srcProvider} to ${dstProvider}`, metadata, async function () { + client1.mongoLogger?.trace('client', 'dropping datakeys collection'); + // Step 1. Drop the collection ``keyvault.datakeys`` await client1 .db('keyvault') .dropCollection('datakeys') .catch(() => null); + client1.mongoLogger?.trace('client', 'dropped datakeys collection'); + // Step 2. Create a ``ClientEncryption`` object named ``clientEncryption1`` const clientEncryption1 = new ClientEncryption(client1, { keyVaultNamespace: 'keyvault.datakeys', @@ -2361,17 +2368,24 @@ describe('Client Side Encryption Prose Tests', metadata, function () { bson: BSON }); + client1.mongoLogger?.trace('client', 'clientEncryption1.createDataKey started'); + // Step 3. Call ``clientEncryption1.createDataKey`` with ``srcProvider`` const keyId = await clientEncryption1.createDataKey(srcProvider, { masterKey: masterKeys[srcProvider] }); + client1.mongoLogger?.trace('client', 'clientEncryption1.createDataKey finished'); + client1.mongoLogger?.trace('client', 'clientEncryption1.encrypt started'); + // Step 4. Call ``clientEncryption1.encrypt`` with the value "test" const cipherText = await clientEncryption1.encrypt('test', { keyId, algorithm: 'AEAD_AES_256_CBC_HMAC_SHA_512-Deterministic' }); + client1.mongoLogger?.trace('client', 'clientEncryption1.encrypt finished'); + // Step 5. Create a ``ClientEncryption`` object named ``clientEncryption2`` const clientEncryption2 = new ClientEncryption(client2, { keyVaultNamespace: 'keyvault.datakeys', @@ -2386,6 +2400,8 @@ describe('Client Side Encryption Prose Tests', metadata, function () { bson: BSON }); + client2.mongoLogger?.trace('client', 'clientEncryption2.rewrapManyDataKey started'); + // Step 6. Call ``clientEncryption2.rewrapManyDataKey`` with an empty ``filter`` const rewrapManyDataKeyResult = await clientEncryption2.rewrapManyDataKey( {}, @@ -2395,16 +2411,25 @@ describe('Client Side Encryption Prose Tests', metadata, function () { } ); + client2.mongoLogger?.trace('client', 'clientEncryption2.rewrapManyDataKey finished'); + expect(rewrapManyDataKeyResult).to.have.property('bulkWriteResult'); expect(rewrapManyDataKeyResult.bulkWriteResult).to.have.property('modifiedCount', 1); + client1.mongoLogger?.trace('client', 'clientEncryption1.decrypt started'); + // 7. Call ``clientEncryption1.decrypt`` with the ``ciphertext``. Assert the return value is "test". const decryptResult1 = await clientEncryption1.decrypt(cipherText); expect(decryptResult1).to.equal('test'); + client1.mongoLogger?.trace('client', 'clientEncryption1.decrypt finished'); + client2.mongoLogger?.trace('client', 'clientEncryption2.decrypt started'); + // 8. Call ``clientEncryption2.decrypt`` with the ``ciphertext``. Assert the return value is "test". const decryptResult2 = await clientEncryption2.decrypt(cipherText); expect(decryptResult2).to.equal('test'); + + client2.mongoLogger?.trace('client', 'clientEncryption2.decrypt finished'); } ); } diff --git a/test/integration/client-side-encryption/client_side_encryption.spec.test.ts b/test/integration/client-side-encryption/client_side_encryption.spec.test.ts index 7d43268ef39..58fe5bb19bc 100644 --- a/test/integration/client-side-encryption/client_side_encryption.spec.test.ts +++ b/test/integration/client-side-encryption/client_side_encryption.spec.test.ts @@ -149,14 +149,6 @@ describe('Client Side Encryption (Unified)', function () { if (typeof shouldSkip === 'string') return shouldSkip; } - const flakyTests = { - 'rewrap to azure:name1': 'TODO(NODE-6860): fix flaky tests' - }; - - const skipReason = flakyTests[description]; - - if (skipReason) return skipReason; - return isServerless ? 'Unified CSFLE tests to not run on serverless' : false; } ); diff --git a/test/integration/server-discovery-and-monitoring/server_discovery_and_monitoring.prose.test.ts b/test/integration/server-discovery-and-monitoring/server_discovery_and_monitoring.prose.test.ts index 3549d580c69..ad8ade8c7dd 100644 --- a/test/integration/server-discovery-and-monitoring/server_discovery_and_monitoring.prose.test.ts +++ b/test/integration/server-discovery-and-monitoring/server_discovery_and_monitoring.prose.test.ts @@ -146,40 +146,37 @@ describe('Server Discovery and Monitoring Prose Tests', function () { await client.close(); }); - it.skip( - 'ensure monitors properly create and unpause connection pools when they discover servers', - { - metadata: { requires: { mongodb: '>=4.2.9', topology: '!load-balanced' } }, - test: async function () { - await client.connect(); - expect(events.shift()).to.equal(SERVER_HEARTBEAT_SUCCEEDED); - expect(events.shift()).to.equal(CONNECTION_POOL_READY); - - expect(events).to.be.empty; - - const heartBeatFailedEvent = once(client, SERVER_HEARTBEAT_FAILED); - await client.db('admin').command({ - configureFailPoint: 'failCommand', - mode: { times: 2 }, - data: { - failCommands: ['hello'], - errorCode: 1234, - appName: 'SDAMPoolManagementTest' - } - }); - await heartBeatFailedEvent; - expect(events.shift()).to.equal(SERVER_HEARTBEAT_FAILED); - expect(events.shift()).to.equal(CONNECTION_POOL_CLEARED); - - expect(events).to.be.empty; - - await once(client, SERVER_HEARTBEAT_SUCCEEDED); - expect(events.shift()).to.equal(SERVER_HEARTBEAT_SUCCEEDED); - expect(events.shift()).to.equal(CONNECTION_POOL_READY); - - expect(events).to.be.empty; - } + it('ensure monitors properly create and unpause connection pools when they discover servers', { + metadata: { requires: { mongodb: '>=4.2.9', topology: '!load-balanced' } }, + test: async function () { + await client.connect(); + expect(events.shift()).to.equal(SERVER_HEARTBEAT_SUCCEEDED); + expect(events.shift()).to.equal(CONNECTION_POOL_READY); + + expect(events).to.be.empty; + + const heartBeatFailedEvent = once(client, SERVER_HEARTBEAT_FAILED); + await client.db('admin').command({ + configureFailPoint: 'failCommand', + mode: { times: 2 }, + data: { + failCommands: ['hello'], + errorCode: 1234, + appName: 'SDAMPoolManagementTest' + } + }); + await heartBeatFailedEvent; + expect(events.shift()).to.equal(SERVER_HEARTBEAT_FAILED); + expect(events.shift()).to.equal(CONNECTION_POOL_CLEARED); + + expect(events).to.be.empty; + + await once(client, SERVER_HEARTBEAT_SUCCEEDED); + expect(events.shift()).to.equal(SERVER_HEARTBEAT_SUCCEEDED); + expect(events.shift()).to.equal(CONNECTION_POOL_READY); + + expect(events).to.be.empty; } - ).skipReason = 'TODO(NODE-5206): fix flaky test'; + }); }); }); diff --git a/test/tools/runner/config.ts b/test/tools/runner/config.ts index 5385ace8cc2..477e758f620 100644 --- a/test/tools/runner/config.ts +++ b/test/tools/runner/config.ts @@ -1,19 +1,27 @@ +import * as util from 'node:util'; +import * as types from 'node:util/types'; + import { expect } from 'chai'; +import { type Context } from 'mocha'; import ConnectionString from 'mongodb-connection-string-url'; import * as qs from 'querystring'; import * as url from 'url'; import { type AuthMechanism, + Double, HostAddress, + Long, MongoClient, type MongoClientOptions, + ObjectId, type ServerApi, TopologyType, type WriteConcernSettings } from '../../mongodb'; import { getEnvironmentalOptions } from '../utils'; import { type Filter } from './filters/filter'; +import { flakyTests } from './flaky'; interface ProxyParams { proxyHost?: string; @@ -205,6 +213,11 @@ export class TestConfiguration { newClient(urlOrQueryOptions?: string | Record, serverOptions?: MongoClientOptions) { serverOptions = Object.assign({}, getEnvironmentalOptions(), serverOptions); + + if (this.loggingEnabled && !Object.hasOwn(serverOptions, 'mongodbLogPath')) { + serverOptions = this.setupLogging(serverOptions); + } + // Support MongoClient constructor form (url, options) for `newClient`. if (typeof urlOrQueryOptions === 'string') { if (Reflect.has(serverOptions, 'host') || Reflect.has(serverOptions, 'port')) { @@ -427,6 +440,59 @@ export class TestConfiguration { makeAtlasTestConfiguration(): AtlasTestConfiguration { return new AtlasTestConfiguration(this.uri, this.context); } + + loggingEnabled = false; + logs = []; + /** + * Known flaky tests that we want to turn on logging for + * so that we can get a better idea of what is failing when it fails + */ + testsToEnableLogging = flakyTests; + + setupLogging(options: MongoClientOptions, id?: string) { + id ??= new ObjectId().toString(); + this.logs = []; + const write = log => this.logs.push({ t: log.t, id, ...log }); + options.mongodbLogPath = { write }; + options.mongodbLogComponentSeverities = { default: 'trace' }; + options.mongodbLogMaxDocumentLength = 300; + return options; + } + + beforeEachLogging(ctx: Context) { + this.loggingEnabled = this.testsToEnableLogging.includes(ctx.currentTest.fullTitle()); + } + + afterEachLogging(ctx: Context) { + if (this.loggingEnabled && ctx.currentTest.state === 'failed') { + for (const log of this.logs) { + console.error( + JSON.stringify( + log, + function (_, value) { + if (types.isMap(value)) return { Map: Array.from(value.entries()) }; + if (types.isSet(value)) return { Set: Array.from(value.values()) }; + if (types.isNativeError(value)) return { [value.name]: util.inspect(value) }; + if (typeof value === 'bigint') return { bigint: new Long(value).toExtendedJSON() }; + if (typeof value === 'symbol') return `Symbol(${value.description})`; + if (typeof value === 'number') { + if (Number.isNaN(value) || !Number.isFinite(value) || Object.is(value, -0)) + // @ts-expect-error: toExtendedJSON internal on double but not on long + return { number: new Double(value).toExtendedJSON() }; + } + if (Buffer.isBuffer(value)) + return { [value.constructor.name]: Buffer.prototype.base64Slice.call(value) }; + if (value === undefined) return { undefined: 'key was set but equal to undefined' }; + return value; + }, + 0 + ) + ); + } + } + this.loggingEnabled = false; + this.logs = []; + } } /** diff --git a/test/tools/runner/flaky.ts b/test/tools/runner/flaky.ts new file mode 100644 index 00000000000..32f299559ed --- /dev/null +++ b/test/tools/runner/flaky.ts @@ -0,0 +1,31 @@ +export const flakyTests = [ + 'Client Side Encryption (Unified) namedKMS-rewrapManyDataKey rewrap to azure:name1', + 'Server Discovery and Monitoring Prose Tests Connection Pool Management ensure monitors properly create and unpause connection pools when they discover servers', + 'CSOT spec tests legacy timeouts behave correctly for retryable operations operation succeeds after one socket timeout - aggregate on collection', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from aws to aws', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from aws to azure', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from aws to gcp', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from aws to kmip', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from aws to local', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from azure to aws', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from azure to azure', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from azure to gcp', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from azure to kmip', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from azure to local', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from gcp to aws', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from gcp to azure', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from gcp to gcp', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from gcp to kmip', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from gcp to local', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from kmip to aws', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from kmip to azure', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from kmip to gcp', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from kmip to kmip', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from kmip to local', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from local to aws', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from local to azure', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from local to gcp', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from local to kmip', + 'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from local to local', + 'Client Side Encryption Prose Tests 16. Rewrap Case 2: RewrapManyDataKeyOpts.provider is not optional when provider field is missing raises an error' +]; diff --git a/test/tools/runner/hooks/configuration.ts b/test/tools/runner/hooks/configuration.ts index d6c4100f339..a5aa8c7f5dc 100644 --- a/test/tools/runner/hooks/configuration.ts +++ b/test/tools/runner/hooks/configuration.ts @@ -22,6 +22,8 @@ import { NodeVersionFilter } from '../filters/node_version_filter'; import { OSFilter } from '../filters/os_filter'; import { ServerlessFilter } from '../filters/serverless_filter'; import { type Filter } from '../filters/filter'; +import { type Context } from 'mocha'; +import { flakyTests } from '../flaky'; // Default our tests to have auth enabled // A better solution will be tackled in NODE-3714 @@ -211,8 +213,42 @@ const beforeAllPluginImports = () => { require('mocha-sinon'); }; +async function beforeEachLogging(this: Context) { + if (this.currentTest == null) return; + this.configuration.beforeEachLogging(this); +} + +async function afterEachLogging(this: Context) { + if (this.currentTest == null) return; + this.configuration.afterEachLogging(this); +} + +function checkFlakyTestList(this: Context) { + const allTests: string[] = []; + + const stack = [this.test.parent]; + while (stack.length) { + const suite = stack.pop(); + allTests.push(...suite.tests.map(test => test.fullTitle())); + stack.push(...suite.suites); + } + allTests.reverse(); // Doesn't matter but when debugging easier to see this in the expected order. + + const flakyTestDoesNotExist = flakyTests.find(testName => !allTests.includes(testName)); + if (flakyTestDoesNotExist != null) { + console.error( + '\n' + '='.repeat(100) + '\n', + 'Flaky test:', + JSON.stringify(flakyTestDoesNotExist), + 'is not run at all', + '\n' + '='.repeat(100) + '\n' + ); + } +} + export const mochaHooks = { - beforeAll: [beforeAllPluginImports, testConfigBeforeHook], - beforeEach: [testSkipBeforeEachHook], + beforeAll: [beforeAllPluginImports, testConfigBeforeHook, checkFlakyTestList], + beforeEach: [testSkipBeforeEachHook, beforeEachLogging], + afterEach: [afterEachLogging], afterAll: [cleanUpMocksAfterHook] }; diff --git a/test/tools/unified-spec-runner/entities.ts b/test/tools/unified-spec-runner/entities.ts index 759d7fb8a17..b228c0669a0 100644 --- a/test/tools/unified-spec-runner/entities.ts +++ b/test/tools/unified-spec-runner/entities.ts @@ -28,6 +28,7 @@ import { type HostAddress, type Log, MongoClient, + type MongoClientOptions, type MongoCredentials, ReadConcern, ReadPreference, @@ -126,7 +127,7 @@ export class UnifiedMongoClient extends MongoClient { cmapEvents: CmapEvent[] = []; sdamEvents: SdamEvent[] = []; failPoints: Document[] = []; - logCollector: { buffer: LogMessage[]; write: (log: Log) => void }; + logCollector?: { buffer: LogMessage[]; write: (log: Log) => void }; ignoredEvents: string[]; observeSensitiveCommands: boolean; @@ -197,32 +198,45 @@ export class UnifiedMongoClient extends MongoClient { topology: 'MONGODB_LOG_TOPOLOGY' } as const; - constructor(uri: string, description: ClientEntity) { - const logCollector: { buffer: LogMessage[]; write: (log: Log) => void } = { - buffer: [], - write(log: Log): void { - const transformedLog = { - level: log.s, - component: log.c, - data: { ...log } - }; - - this.buffer.push(transformedLog); - } - }; - const mongodbLogComponentSeverities = description.observeLogMessages; - - super(uri, { + constructor( + uri: string, + description: ClientEntity, + config: { + loggingEnabled?: boolean; + setupLogging?: (options: Record, id: string) => Record; + } + ) { + const options: MongoClientOptions = { monitorCommands: true, __skipPingOnConnect: true, - mongodbLogComponentSeverities, ...getEnvironmentalOptions(), ...(description.serverApi ? { serverApi: description.serverApi } : {}), - mongodbLogPath: logCollector, // TODO(NODE-5785): We need to increase the truncation length because signature.hash is a Buffer making hellos too long mongodbLogMaxDocumentLength: 1250 - } as any); + }; + + let logCollector: { buffer: LogMessage[]; write: (log: Log) => void } | undefined; + if (description.observeLogMessages != null) { + options.mongodbLogComponentSeverities = description.observeLogMessages; + logCollector = { + buffer: [], + write(log: Log): void { + const transformedLog = { + level: log.s, + component: log.c, + data: { ...log } + }; + + this.buffer.push(transformedLog); + } + }; + options.mongodbLogPath = logCollector; + } else if (config.loggingEnabled) { + config.setupLogging?.(options, description.id); + } + + super(uri, options); this.observedEventEmitter.on('error', () => null); this.logCollector = logCollector; this.observeSensitiveCommands = description.observeSensitiveCommands ?? false; @@ -337,7 +351,7 @@ export class UnifiedMongoClient extends MongoClient { } get collectedLogs(): LogMessage[] { - return this.logCollector.buffer; + return this.logCollector?.buffer ?? []; } } @@ -578,7 +592,8 @@ export class EntitiesMap extends Map { } else { uri = makeConnectionString(config.url({ useMultipleMongoses }), entity.client.uriOptions); } - const client = new UnifiedMongoClient(uri, entity.client); + + const client = new UnifiedMongoClient(uri, entity.client, config); try { new EntityEventRegistry(client, entity.client, map).register(); await client.connect(); diff --git a/test/unit/tools/unified_spec_runner/entity_event_registry.test.ts b/test/unit/tools/unified_spec_runner/entity_event_registry.test.ts index f807ab5b9c0..8457ff4026b 100644 --- a/test/unit/tools/unified_spec_runner/entity_event_registry.test.ts +++ b/test/unit/tools/unified_spec_runner/entity_event_registry.test.ts @@ -48,7 +48,7 @@ describe('EntityEventRegistry', function () { }; const entitesMap = new EntitiesMap(); const uri = 'mongodb://127.0.0.1:27017'; - const client = new UnifiedMongoClient(uri, clientEntity); + const client = new UnifiedMongoClient(uri, clientEntity, {}); const registry = new EntityEventRegistry(client, clientEntity, entitesMap); before(function () { @@ -120,7 +120,7 @@ describe('EntityEventRegistry', function () { const clientEntity = { id: 'client0' }; const entitesMap = new EntitiesMap(); const uri = 'mongodb://127.0.0.1:27017'; - const client = new UnifiedMongoClient(uri, clientEntity); + const client = new UnifiedMongoClient(uri, clientEntity, {}); const registry = new EntityEventRegistry(client, clientEntity, entitesMap); before(function () {