Skip to content

Commit 46cb56d

Browse files
nbbeekennbbeeken
authored
ci(NODE-6860): add logging for known flaky tests (#4496)
1 parent 6dddde7 commit 46cb56d

File tree

8 files changed

+231
-69
lines changed

8 files changed

+231
-69
lines changed

‎test/integration/client-side-encryption/client_side_encryption.prose.test.js

Lines changed: 26 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2317,7 +2317,10 @@ describe('Client Side Encryption Prose Tests', metadata, function () {
23172317
kmip: {},
23182318
local: undefined
23192319
};
2320-
let client1, client2;
2320+
/** @type {import('../../mongodb').MongoClient} */
2321+
let client1;
2322+
/** @type {import('../../mongodb').MongoClient} */
2323+
let client2;
23212324

23222325
describe('Case 1: Rewrap with separate ClientEncryption', function () {
23232326
/**
@@ -2348,12 +2351,16 @@ describe('Client Side Encryption Prose Tests', metadata, function () {
23482351
`should rewrap data key from ${srcProvider} to ${dstProvider}`,
23492352
metadata,
23502353
async function () {
2354+
client1.mongoLogger?.trace('client', 'dropping datakeys collection');
2355+
23512356
// Step 1. Drop the collection ``keyvault.datakeys``
23522357
await client1
23532358
.db('keyvault')
23542359
.dropCollection('datakeys')
23552360
.catch(() => null);
23562361

2362+
client1.mongoLogger?.trace('client', 'dropped datakeys collection');
2363+
23572364
// Step 2. Create a ``ClientEncryption`` object named ``clientEncryption1``
23582365
const clientEncryption1 = new ClientEncryption(client1, {
23592366
keyVaultNamespace: 'keyvault.datakeys',
@@ -2368,17 +2375,24 @@ describe('Client Side Encryption Prose Tests', metadata, function () {
23682375
bson: BSON
23692376
});
23702377

2378+
client1.mongoLogger?.trace('client', 'clientEncryption1.createDataKey started');
2379+
23712380
// Step 3. Call ``clientEncryption1.createDataKey`` with ``srcProvider``
23722381
const keyId = await clientEncryption1.createDataKey(srcProvider, {
23732382
masterKey: masterKeys[srcProvider]
23742383
});
23752384

2385+
client1.mongoLogger?.trace('client', 'clientEncryption1.createDataKey finished');
2386+
client1.mongoLogger?.trace('client', 'clientEncryption1.encrypt started');
2387+
23762388
// Step 4. Call ``clientEncryption1.encrypt`` with the value "test"
23772389
const cipherText = await clientEncryption1.encrypt('test', {
23782390
keyId,
23792391
algorithm: 'AEAD_AES_256_CBC_HMAC_SHA_512-Deterministic'
23802392
});
23812393

2394+
client1.mongoLogger?.trace('client', 'clientEncryption1.encrypt finished');
2395+
23822396
// Step 5. Create a ``ClientEncryption`` object named ``clientEncryption2``
23832397
const clientEncryption2 = new ClientEncryption(client2, {
23842398
keyVaultNamespace: 'keyvault.datakeys',
@@ -2393,6 +2407,8 @@ describe('Client Side Encryption Prose Tests', metadata, function () {
23932407
bson: BSON
23942408
});
23952409

2410+
client2.mongoLogger?.trace('client', 'clientEncryption2.rewrapManyDataKey started');
2411+
23962412
// Step 6. Call ``clientEncryption2.rewrapManyDataKey`` with an empty ``filter``
23972413
const rewrapManyDataKeyResult = await clientEncryption2.rewrapManyDataKey(
23982414
{},
@@ -2402,16 +2418,25 @@ describe('Client Side Encryption Prose Tests', metadata, function () {
24022418
}
24032419
);
24042420

2421+
client2.mongoLogger?.trace('client', 'clientEncryption2.rewrapManyDataKey finished');
2422+
24052423
expect(rewrapManyDataKeyResult).to.have.property('bulkWriteResult');
24062424
expect(rewrapManyDataKeyResult.bulkWriteResult).to.have.property('modifiedCount', 1);
24072425

2426+
client1.mongoLogger?.trace('client', 'clientEncryption1.decrypt started');
2427+
24082428
// 7. Call ``clientEncryption1.decrypt`` with the ``ciphertext``. Assert the return value is "test".
24092429
const decryptResult1 = await clientEncryption1.decrypt(cipherText);
24102430
expect(decryptResult1).to.equal('test');
24112431

2432+
client1.mongoLogger?.trace('client', 'clientEncryption1.decrypt finished');
2433+
client2.mongoLogger?.trace('client', 'clientEncryption2.decrypt started');
2434+
24122435
// 8. Call ``clientEncryption2.decrypt`` with the ``ciphertext``. Assert the return value is "test".
24132436
const decryptResult2 = await clientEncryption2.decrypt(cipherText);
24142437
expect(decryptResult2).to.equal('test');
2438+
2439+
client2.mongoLogger?.trace('client', 'clientEncryption2.decrypt finished');
24152440
}
24162441
);
24172442
}

‎test/integration/client-side-encryption/client_side_encryption.spec.test.ts

Lines changed: 0 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -149,14 +149,6 @@ describe('Client Side Encryption (Unified)', function () {
149149
if (typeof shouldSkip === 'string') return shouldSkip;
150150
}
151151

152-
const flakyTests = {
153-
'rewrap to azure:name1': 'TODO(NODE-6860): fix flaky tests'
154-
};
155-
156-
const skipReason = flakyTests[description];
157-
158-
if (skipReason) return skipReason;
159-
160152
return isServerless ? 'Unified CSFLE tests to not run on serverless' : false;
161153
}
162154
);

‎test/integration/server-discovery-and-monitoring/server_discovery_and_monitoring.prose.test.ts

Lines changed: 31 additions & 34 deletions
Original file line numberDiff line numberDiff line change
@@ -146,40 +146,37 @@ describe('Server Discovery and Monitoring Prose Tests', function () {
146146
await client.close();
147147
});
148148

149-
it.skip(
150-
'ensure monitors properly create and unpause connection pools when they discover servers',
151-
{
152-
metadata: { requires: { mongodb: '>=4.2.9', topology: '!load-balanced' } },
153-
test: async function () {
154-
await client.connect();
155-
expect(events.shift()).to.equal(SERVER_HEARTBEAT_SUCCEEDED);
156-
expect(events.shift()).to.equal(CONNECTION_POOL_READY);
157-
158-
expect(events).to.be.empty;
159-
160-
const heartBeatFailedEvent = once(client, SERVER_HEARTBEAT_FAILED);
161-
await client.db('admin').command({
162-
configureFailPoint: 'failCommand',
163-
mode: { times: 2 },
164-
data: {
165-
failCommands: ['hello'],
166-
errorCode: 1234,
167-
appName: 'SDAMPoolManagementTest'
168-
}
169-
});
170-
await heartBeatFailedEvent;
171-
expect(events.shift()).to.equal(SERVER_HEARTBEAT_FAILED);
172-
expect(events.shift()).to.equal(CONNECTION_POOL_CLEARED);
173-
174-
expect(events).to.be.empty;
175-
176-
await once(client, SERVER_HEARTBEAT_SUCCEEDED);
177-
expect(events.shift()).to.equal(SERVER_HEARTBEAT_SUCCEEDED);
178-
expect(events.shift()).to.equal(CONNECTION_POOL_READY);
179-
180-
expect(events).to.be.empty;
181-
}
149+
it('ensure monitors properly create and unpause connection pools when they discover servers', {
150+
metadata: { requires: { mongodb: '>=4.2.9', topology: '!load-balanced' } },
151+
test: async function () {
152+
await client.connect();
153+
expect(events.shift()).to.equal(SERVER_HEARTBEAT_SUCCEEDED);
154+
expect(events.shift()).to.equal(CONNECTION_POOL_READY);
155+
156+
expect(events).to.be.empty;
157+
158+
const heartBeatFailedEvent = once(client, SERVER_HEARTBEAT_FAILED);
159+
await client.db('admin').command({
160+
configureFailPoint: 'failCommand',
161+
mode: { times: 2 },
162+
data: {
163+
failCommands: ['hello'],
164+
errorCode: 1234,
165+
appName: 'SDAMPoolManagementTest'
166+
}
167+
});
168+
await heartBeatFailedEvent;
169+
expect(events.shift()).to.equal(SERVER_HEARTBEAT_FAILED);
170+
expect(events.shift()).to.equal(CONNECTION_POOL_CLEARED);
171+
172+
expect(events).to.be.empty;
173+
174+
await once(client, SERVER_HEARTBEAT_SUCCEEDED);
175+
expect(events.shift()).to.equal(SERVER_HEARTBEAT_SUCCEEDED);
176+
expect(events.shift()).to.equal(CONNECTION_POOL_READY);
177+
178+
expect(events).to.be.empty;
182179
}
183-
).skipReason = 'TODO(NODE-5206): fix flaky test';
180+
});
184181
});
185182
});

‎test/tools/runner/config.ts

Lines changed: 66 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,19 +1,27 @@
1+
import * as util from 'node:util';
2+
import * as types from 'node:util/types';
3+
14
import { expect } from 'chai';
5+
import { type Context } from 'mocha';
26
import ConnectionString from 'mongodb-connection-string-url';
37
import * as qs from 'querystring';
48
import * as url from 'url';
59

610
import {
711
type AuthMechanism,
12+
Double,
813
HostAddress,
14+
Long,
915
MongoClient,
1016
type MongoClientOptions,
17+
ObjectId,
1118
type ServerApi,
1219
TopologyType,
1320
type WriteConcernSettings
1421
} from '../../mongodb';
1522
import { getEnvironmentalOptions } from '../utils';
1623
import { type Filter } from './filters/filter';
24+
import { flakyTests } from './flaky';
1725

1826
interface ProxyParams {
1927
proxyHost?: string;
@@ -205,6 +213,11 @@ export class TestConfiguration {
205213

206214
newClient(urlOrQueryOptions?: string | Record<string, any>, serverOptions?: MongoClientOptions) {
207215
serverOptions = Object.assign({}, getEnvironmentalOptions(), serverOptions);
216+
217+
if (this.loggingEnabled && !Object.hasOwn(serverOptions, 'mongodbLogPath')) {
218+
serverOptions = this.setupLogging(serverOptions);
219+
}
220+
208221
// Support MongoClient constructor form (url, options) for `newClient`.
209222
if (typeof urlOrQueryOptions === 'string') {
210223
if (Reflect.has(serverOptions, 'host') || Reflect.has(serverOptions, 'port')) {
@@ -427,6 +440,59 @@ export class TestConfiguration {
427440
makeAtlasTestConfiguration(): AtlasTestConfiguration {
428441
return new AtlasTestConfiguration(this.uri, this.context);
429442
}
443+
444+
loggingEnabled = false;
445+
logs = [];
446+
/**
447+
* Known flaky tests that we want to turn on logging for
448+
* so that we can get a better idea of what is failing when it fails
449+
*/
450+
testsToEnableLogging = flakyTests;
451+
452+
setupLogging(options: MongoClientOptions, id?: string) {
453+
id ??= new ObjectId().toString();
454+
this.logs = [];
455+
const write = log => this.logs.push({ t: log.t, id, ...log });
456+
options.mongodbLogPath = { write };
457+
options.mongodbLogComponentSeverities = { default: 'trace' };
458+
options.mongodbLogMaxDocumentLength = 300;
459+
return options;
460+
}
461+
462+
beforeEachLogging(ctx: Context) {
463+
this.loggingEnabled = this.testsToEnableLogging.includes(ctx.currentTest.fullTitle());
464+
}
465+
466+
afterEachLogging(ctx: Context) {
467+
if (this.loggingEnabled && ctx.currentTest.state === 'failed') {
468+
for (const log of this.logs) {
469+
console.error(
470+
JSON.stringify(
471+
log,
472+
function (_, value) {
473+
if (types.isMap(value)) return { Map: Array.from(value.entries()) };
474+
if (types.isSet(value)) return { Set: Array.from(value.values()) };
475+
if (types.isNativeError(value)) return { [value.name]: util.inspect(value) };
476+
if (typeof value === 'bigint') return { bigint: new Long(value).toExtendedJSON() };
477+
if (typeof value === 'symbol') return `Symbol(${value.description})`;
478+
if (typeof value === 'number') {
479+
if (Number.isNaN(value) || !Number.isFinite(value) || Object.is(value, -0))
480+
// @ts-expect-error: toExtendedJSON internal on double but not on long
481+
return { number: new Double(value).toExtendedJSON() };
482+
}
483+
if (Buffer.isBuffer(value))
484+
return { [value.constructor.name]: Buffer.prototype.base64Slice.call(value) };
485+
if (value === undefined) return { undefined: 'key was set but equal to undefined' };
486+
return value;
487+
},
488+
0
489+
)
490+
);
491+
}
492+
}
493+
this.loggingEnabled = false;
494+
this.logs = [];
495+
}
430496
}
431497

432498
/**

‎test/tools/runner/flaky.ts

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,31 @@
1+
export const flakyTests = [
2+
'Client Side Encryption (Unified) namedKMS-rewrapManyDataKey rewrap to azure:name1',
3+
'Server Discovery and Monitoring Prose Tests Connection Pool Management ensure monitors properly create and unpause connection pools when they discover servers',
4+
'CSOT spec tests legacy timeouts behave correctly for retryable operations operation succeeds after one socket timeout - aggregate on collection',
5+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from aws to aws',
6+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from aws to azure',
7+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from aws to gcp',
8+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from aws to kmip',
9+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from aws to local',
10+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from azure to aws',
11+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from azure to azure',
12+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from azure to gcp',
13+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from azure to kmip',
14+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from azure to local',
15+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from gcp to aws',
16+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from gcp to azure',
17+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from gcp to gcp',
18+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from gcp to kmip',
19+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from gcp to local',
20+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from kmip to aws',
21+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from kmip to azure',
22+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from kmip to gcp',
23+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from kmip to kmip',
24+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from kmip to local',
25+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from local to aws',
26+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from local to azure',
27+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from local to gcp',
28+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from local to kmip',
29+
'Client Side Encryption Prose Tests 16. Rewrap Case 1: Rewrap with separate ClientEncryption should rewrap data key from local to local',
30+
'Client Side Encryption Prose Tests 16. Rewrap Case 2: RewrapManyDataKeyOpts.provider is not optional when provider field is missing raises an error'
31+
];

‎test/tools/runner/hooks/configuration.ts

Lines changed: 38 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,8 @@ import { NodeVersionFilter } from '../filters/node_version_filter';
2222
import { OSFilter } from '../filters/os_filter';
2323
import { ServerlessFilter } from '../filters/serverless_filter';
2424
import { type Filter } from '../filters/filter';
25+
import { type Context } from 'mocha';
26+
import { flakyTests } from '../flaky';
2527

2628
// Default our tests to have auth enabled
2729
// A better solution will be tackled in NODE-3714
@@ -211,8 +213,42 @@ const beforeAllPluginImports = () => {
211213
require('mocha-sinon');
212214
};
213215

216+
async function beforeEachLogging(this: Context) {
217+
if (this.currentTest == null) return;
218+
this.configuration.beforeEachLogging(this);
219+
}
220+
221+
async function afterEachLogging(this: Context) {
222+
if (this.currentTest == null) return;
223+
this.configuration.afterEachLogging(this);
224+
}
225+
226+
function checkFlakyTestList(this: Context) {
227+
const allTests: string[] = [];
228+
229+
const stack = [this.test.parent];
230+
while (stack.length) {
231+
const suite = stack.pop();
232+
allTests.push(...suite.tests.map(test => test.fullTitle()));
233+
stack.push(...suite.suites);
234+
}
235+
allTests.reverse(); // Doesn't matter but when debugging easier to see this in the expected order.
236+
237+
const flakyTestDoesNotExist = flakyTests.find(testName => !allTests.includes(testName));
238+
if (flakyTestDoesNotExist != null) {
239+
console.error(
240+
'\n' + '='.repeat(100) + '\n',
241+
'Flaky test:',
242+
JSON.stringify(flakyTestDoesNotExist),
243+
'is not run at all',
244+
'\n' + '='.repeat(100) + '\n'
245+
);
246+
}
247+
}
248+
214249
export const mochaHooks = {
215-
beforeAll: [beforeAllPluginImports, testConfigBeforeHook],
216-
beforeEach: [testSkipBeforeEachHook],
250+
beforeAll: [beforeAllPluginImports, testConfigBeforeHook, checkFlakyTestList],
251+
beforeEach: [testSkipBeforeEachHook, beforeEachLogging],
252+
afterEach: [afterEachLogging],
217253
afterAll: [cleanUpMocksAfterHook]
218254
};

0 commit comments

Comments
 (0)