chore: try to make sure we always have reasonable log file names (#5331)

* try to make sure we always have reasonable log file names

* more extra logging improvements

* more pauses at initial load and after saving a favourite

* more waits, better test output

* clean up the waiting

* ignore subprocess errors, but log them

* comments

packages/compass-e2e-tests/helpers/compass.ts

@@ -5,6 +5,7 @@ import type Mocha from 'mocha';
 import path from 'path';
 import os from 'os';
 import { execFile } from 'child_process';
+import type { ExecFileOptions, ExecFileException } from 'child_process';
 import { promisify } from 'util';
 import zlib from 'zlib';
 import { remote } from 'webdriverio';
@@ -318,7 +319,7 @@ export class Compass {
     }
   }
 
-  async stop(test?: Mocha.Hook | Mocha.Test): Promise<void> {
+  async stop(test?: Mocha.Hook | Mocha.Test, step?: string): Promise<void> {
     // TODO: we don't have main logs to write :(
     /*
     const mainLogs = [];
@@ -333,7 +334,11 @@ export class Compass {
     const nowFormatted = formattedDate();
 
     // name the log files after the closest test if possible to make it easier to find
-    const name = test ? pathName(test.fullTitle()) : nowFormatted;
+    let name = test ? pathName(test.fullTitle()) : nowFormatted;
+
+    if (step) {
+      name = `${name}-${step}`;
+    }
 
     const renderLogPath = path.join(
       LOG_PATH,
@@ -429,6 +434,26 @@ async function getCompassExecutionParameters(): Promise<{
   return { testPackagedApp, binary };
 }
 
+function execFileIgnoreError(
+  path: string,
+  args: readonly string[],
+  opts: ExecFileOptions
+): Promise<{
+  error: ExecFileException | null;
+  stdout: string;
+  stderr: string;
+}> {
+  return new Promise((resolve) => {
+    execFile(path, args, opts, function (error, stdout, stderr) {
+      resolve({
+        error,
+        stdout,
+        stderr,
+      });
+    });
+  });
+}
+
 export async function runCompassOnce(args: string[], timeout = 30_000) {
   const { binary } = await getCompassExecutionParameters();
   debug('spawning compass...', {
@@ -438,7 +463,12 @@ export async function runCompassOnce(args: string[], timeout = 30_000) {
     args,
     timeout,
   });
-  const { stdout, stderr } = await promisify(execFile)(
+  // For whatever reason, running the compass CLI frequently completes what it
+  // was set to do and then exits the process with error code 1 and no other
+  // output. So while figuring out what's going on, don't ever throw but do log
+  // the error. Assertions that follow runCompassOnce() can then check if it did
+  // what it was supposed to do and fail if it didn't.
+  const { error, stdout, stderr } = await execFileIgnoreError(
     binary,
     [
       COMPASS_PATH,
@@ -452,11 +482,12 @@ export async function runCompassOnce(args: string[], timeout = 30_000) {
       timeout,
       env: {
         ...process.env,
-        DE: 'generic', // for xdg-settings: unknown desktop environment
+        // prevent xdg-settings: unknown desktop environment error logs
+        DE: 'generic',
       },
     }
   );
-  debug('Ran compass with args', { args, stdout, stderr });
+  debug('Ran compass with args', { args, error, stdout, stderr });
   return { stdout, stderr };
 }
 
@@ -894,7 +925,8 @@ export async function beforeTests(
 
 export async function afterTests(
   compass?: Compass,
-  test?: Mocha.Hook | Mocha.Test
+  test?: Mocha.Hook | Mocha.Test,
+  step?: string
 ): Promise<void> {
   if (!compass) {
     return;
@@ -916,7 +948,7 @@ export async function afterTests(
 
   const closePromise = (async function close(): Promise<void> {
     try {
-      await compass.stop(test);
+      await compass.stop(test, step);
     } catch (err) {
       debug('An error occurred while stopping compass:');
       debug(err);

packages/compass-e2e-tests/tests/connection.test.ts

@@ -640,7 +640,7 @@ describe('SRV connectivity', function () {
       );
     } finally {
       // make sure the browser gets closed otherwise if this fails the process wont exit
-      await afterTests(compass);
+      await afterTests(compass, this.currentTest, 'no-connect');
     }
 
     const { logs } = compass;
@@ -706,7 +706,7 @@ describe('System CA access', function () {
       expect(result).to.have.property('ok', 1);
     } finally {
       // make sure the browser gets closed otherwise if this fails the process wont exit
-      await afterTests(compass);
+      await afterTests(compass, this.currentTest, 'no-connect');
     }
 
     const { logs } = compass;
@@ -745,7 +745,7 @@ describe('FLE2', function () {
   });
 
   after(async function () {
-    await afterTests(compass, this.currentTest);
+    await afterTests(compass, undefined, 'FLE2');
   });
 
   it('can connect using local KMS', async function () {

packages/compass-e2e-tests/tests/import-export-connections.test.ts

@@ -13,6 +13,16 @@ import type { CompassBrowser } from '../helpers/compass-browser';
 import Debug from 'debug';
 const debug = Debug('import-export-connections');
 
+function waitForConnections() {
+  // The connection list UI does not handle concurrent modifications to the
+  // connections list well. Unfortunately, this includes the initial load,
+  // which can realistically take longer than the startup time + the time
+  // it takes to save a favorite in e2e tests, and so the result of that
+  // initial load would override the favorite saving (from the point of view
+  // of the connection sidebar at least). Add a timeout to make this less flaky. :(
+  return new Promise((resolve) => setTimeout(resolve, 5000));
+}
+
 describe('Connection Import / Export', function () {
   let tmpdir: string;
   let i = 0;
@@ -79,19 +89,19 @@ describe('Connection Import / Export', function () {
     await browser.selectFavorite(favoriteName);
     await browser.clickVisible(Selectors.EditConnectionStringToggle);
     await browser.clickVisible(Selectors.ConfirmationModalConfirmButton());
-    await browser.waitUntil(async () => {
-      const cs = await browser.getConnectFormConnectionString(true);
-      const expected =
-        variant === 'protected'
-          ? connectionStringWithoutCredentials
-          : connectionString;
-      return cs === expected;
-    });
+    const cs = await browser.getConnectFormConnectionString(true);
+    const expected =
+      variant === 'protected'
+        ? connectionStringWithoutCredentials
+        : connectionString;
+    expect(cs).to.equal(expected);
     await browser.selectFavorite(favoriteName);
     await browser.selectConnectionMenuItem(
       favoriteName,
       Selectors.RemoveConnectionItem
     );
+
+    await waitForConnections();
   }
 
   for (const variant of variants) {
@@ -119,8 +129,11 @@ describe('Connection Import / Export', function () {
           connectionString
         );
 
+        await waitForConnections();
         await browser.saveFavorite(favoriteName, 'color3');
-        await afterTests(compass);
+        await waitForConnections();
+
+        await afterTests(compass, this.currentTest, 'favorite');
       }
 
       debug('Exporting connection via CLI');
@@ -154,7 +167,8 @@ describe('Connection Import / Export', function () {
           favoriteName,
           Selectors.RemoveConnectionItem
         );
-        await afterTests(compass);
+        await waitForConnections();
+        await afterTests(compass, this.currentTest, 'remove');
       }
 
       debug('Importing connection via CLI');
@@ -181,7 +195,7 @@ describe('Connection Import / Export', function () {
         const compass = await beforeTests();
         const { browser } = compass;
         await verifyAndRemoveImportedFavorite(browser, favoriteName, variant);
-        await afterTests(compass);
+        await afterTests(compass, this.currentTest, 'verify');
       }
     });
   }
@@ -200,23 +214,20 @@ describe('Connection Import / Export', function () {
         connectionString
       );
 
-      // The connection list UI does not handle concurrent modifications to the
-      // connections list well. Unfortunately, this includes the initial load,
-      // which can realistically take longer than the startup time + the time
-      // it takes to save a favorite in e2e tests, and so the result of that
-      // initial load would override the favorite saving (from the point of view
-      // of the connection sidebar at least). Add a timeout to make this less flaky. :(
-      await new Promise((resolve) => setTimeout(resolve, 5000));
+      await waitForConnections();
 
       await browser.saveFavorite(favoriteName, 'color3');
+
+      // again: make sure the new favourite is there
+      await waitForConnections();
     });
 
     afterEach(async function () {
       await afterTest(compass, this.currentTest);
     });
 
     after(async function () {
-      await afterTests(compass);
+      await afterTests(compass, undefined, 'import-export-connections');
     });
 
     for (const variant of variants) {

packages/compass-e2e-tests/tests/in-use-encryption.test.ts

@@ -63,7 +63,7 @@ describe('CSFLE / QE', function () {
 
     after(async function () {
       if (compass) {
-        await afterTests(compass, this.currentTest);
+        await afterTests(compass, undefined, 'CSFLE / QE');
       }
     });
 

packages/compass-e2e-tests/tests/logging.test.ts

@@ -19,7 +19,7 @@ describe('Logging and Telemetry integration', function () {
         await browser.shellEval('use test');
         await browser.shellEval('db.runCommand({ connectionStatus: 1 })');
       } finally {
-        await afterTests(compass);
+        await afterTests(compass, undefined, 'before-hook-example');
         await telemetry.stop();
       }
 
@@ -389,7 +389,7 @@ describe('Logging and Telemetry integration', function () {
     });
 
     after(async function name() {
-      await afterTests(compass);
+      await afterTests(compass, undefined, 'after-subsequent-run');
       await telemetry.stop();
     });
 
@@ -415,12 +415,12 @@ describe('Logging and Telemetry integration', function () {
         delete process.env.MONGODB_COMPASS_TEST_UNCAUGHT_EXCEPTION;
       }
 
-      await afterTests(compass);
+      await afterTests(compass, undefined, 'before-uncaught-exceptions');
     });
 
     after(async function () {
       // clean up if it failed during the before hook
-      await afterTests(compass, this.currentTest);
+      await afterTests(compass, undefined, 'after-uncaught-exceptions');
     });
 
     it('provides logging information for uncaught exceptions', function () {

packages/compass-e2e-tests/tests/no-network-traffic.test.ts

@@ -64,7 +64,7 @@ describe('networkTraffic: false / Isolated Edition', function () {
     try {
       await browser.connectWithConnectionString();
     } finally {
-      await afterTests(compass, this.currentTest);
+      await afterTests(compass, this.currentTest, 'connect');
     }
 
     const straceLog = await fs.readFile(outfile, 'utf8');

packages/compass-e2e-tests/tests/oidc.test.ts

@@ -366,8 +366,7 @@ describe('OIDC integration', function () {
 
     {
       // Restart Compass
-      await afterTest(compass);
-      await afterTests(compass);
+      await afterTests(compass, this.currentTest, 'restart');
       compass = await beforeTests();
       browser = compass.browser;
     }

packages/compass-e2e-tests/tests/protect-connection-strings.test.ts

@@ -40,7 +40,7 @@ describe('protectConnectionStrings', function () {
 
   after(async function () {
     await browser.setFeature('protectConnectionStrings', false);
-    await afterTests(compass, this.currentTest);
+    await afterTests(compass, undefined, 'protectConnectionStrings');
   });
 
   afterEach(async function () {

packages/compass-e2e-tests/tests/search-indexes.test.ts

@@ -166,7 +166,7 @@ describe.skip('Search Indexes', function () {
   });
 
   after(async function () {
-    await afterTests(compass, this.currentTest);
+    await afterTests(compass, undefined, 'search-indexes');
   });
 
   beforeEach(async function () {

packages/compass-e2e-tests/tests/shell.test.ts

@@ -18,7 +18,7 @@ describe('Shell', function () {
   });
 
   after(async function () {
-    await afterTests(compass, this.currentTest);
+    await afterTests(compass, undefined, 'shell');
     await telemetry.stop();
   });
 

packages/compass-e2e-tests/tests/show-kerberos-password-field.test.ts

@@ -19,7 +19,7 @@ describe('showKerberosPasswordField', function () {
   });
 
   after(async function () {
-    await afterTests(compass, this.currentTest);
+    await afterTests(compass, undefined, 'showKerberosPasswordField');
   });
 
   afterEach(async function () {

packages/compass-e2e-tests/tests/time-to-first-query.test.ts

@@ -16,7 +16,7 @@ describe('Time to first query', function () {
     if (compass) {
       // even though this is after (not afterEach) currentTest points to the last test
       await afterTest(compass, this.currentTest);
-      await afterTests(compass);
+      await afterTests(compass, this.currentTest);
       compass = undefined;
     }
   });