fix(logging): fix log flushing on exit MONGOSH-2883

packages/cli-repl/src/cli-repl.ts

@@ -323,6 +323,18 @@ export class CliRepl implements MongoshIOProvider {
   async start(
     driverUri: string,
     driverOptions: DevtoolsConnectOptions
+  ): Promise<void> {
+    try {
+      return await this._start(driverUri, driverOptions);
+    } catch (err) {
+      await this.close();
+      throw err;
+    }
+  }
+
+  private async _start(
+    driverUri: string,
+    driverOptions: DevtoolsConnectOptions
   ): Promise<void> {
     // eslint-disable-next-line @typescript-eslint/no-var-requires
     const { version }: { version: string } = require('../package.json');
@@ -659,7 +671,7 @@ export class CliRepl implements MongoshIOProvider {
     if (enabled) {
       await this.startLogging();
     } else {
-      this.loggingAndTelemetry?.detachLogger();
+      await this.loggingAndTelemetry?.detachLogger();
     }
   }
 
@@ -1172,7 +1184,7 @@ export class CliRepl implements MongoshIOProvider {
       const analytics = this.toggleableAnalytics;
       let flushError: string | null = null;
       let flushDuration: number | null = null;
-      this.loggingAndTelemetry?.flush();
+      await this.loggingAndTelemetry?.flush();
 
       if (analytics) {
         const flushStart = Date.now();

packages/e2e-tests/test/e2e.spec.ts

@@ -2142,12 +2142,7 @@ describe('e2e', function () {
           await shell.executeLine("log.info('This is a custom entry')");
           expect(shell.assertNoErrors());
           await eventually(async () => {
-            const log = await readLogFile<
-              MongoLogEntryFromFile & {
-                c: string;
-                ctx: string;
-              }
-            >();
+            const log = await readLogFile<MongoLogEntryFromFile>();
             const customLogEntry = log.filter((logEntry) =>
               logEntry.msg.includes('This is a custom entry')
             );
@@ -2182,6 +2177,46 @@ describe('e2e', function () {
             ).to.have.lengthOf(1);
           });
         });
+
+        it('flushes log file (normal exit)', async function () {
+          const shell = this.startTestShell({
+            args: [
+              '--nodb',
+              '--eval',
+              'for(let i=0; i < 10; i++) log.info("logging", {i}); log.getPath();',
+            ],
+          });
+          expect(await shell.waitForAnyExit()).to.equal(0);
+          const log = await readReplLogFile(shell.output.trim());
+          for (let i = 0; i < 10; i++) {
+            expect(
+              log.some(
+                (entry) => entry.msg === 'logging' && entry.attr?.i === i
+              )
+            ).to.be.true;
+          }
+        });
+
+        it('flushes log file (exception thrown)', async function () {
+          const shell = this.startTestShell({
+            args: [
+              '--nodb',
+              '--eval',
+              'for(let i=0; i < 10; i++) log.info("logging", {i}); print(log.getPath()); throw new Error("uh oh")',
+            ],
+          });
+          expect(await shell.waitForAnyExit()).to.equal(1);
+          const log = await readReplLogFile(
+            shell.output.replace(/Error: uh oh/g, '').trim()
+          );
+          for (let i = 0; i < 10; i++) {
+            expect(
+              log.some(
+                (entry) => entry.msg === 'logging' && entry.attr?.i === i
+              )
+            ).to.be.true;
+          }
+        });
       });
 
       describe('history file', function () {

packages/logging/src/logging-and-telemetry.spec.ts

@@ -61,7 +61,9 @@ describe('MongoshLoggingAndTelemetry', function () {
 
     logger = new MongoLogWriter(logId, `/tmp/${logId}_log`, {
       write(chunk: string, cb: () => void) {
-        logOutput.push(JSON.parse(chunk));
+        if (chunk.trim()) {
+          logOutput.push(JSON.parse(chunk));
+        }
         cb();
       },
       end(cb: () => void) {
@@ -70,8 +72,8 @@ describe('MongoshLoggingAndTelemetry', function () {
     } as Writable);
   });
 
-  afterEach(function () {
-    loggingAndTelemetry.detachLogger();
+  afterEach(async function () {
+    await loggingAndTelemetry.detachLogger();
     logger.destroy();
   });
 
@@ -82,9 +84,9 @@ describe('MongoshLoggingAndTelemetry', function () {
     );
   });
 
-  it('does not throw when attaching and detaching loggers', function () {
+  it('does not throw when attaching and detaching loggers', async function () {
     loggingAndTelemetry.attachLogger(logger);
-    loggingAndTelemetry.detachLogger();
+    await loggingAndTelemetry.detachLogger();
     expect(() => loggingAndTelemetry.attachLogger(logger)).does.not.throw();
   });
 
@@ -308,7 +310,7 @@ describe('MongoshLoggingAndTelemetry', function () {
         .setupTelemetryPromise;
 
       // Flush before it completes
-      loggingAndTelemetry.flush();
+      await loggingAndTelemetry.flush();
 
       // Emit an event that would trigger analytics
       bus.emit('mongosh:new-user', { userId, anonymousId: userId });
@@ -377,7 +379,7 @@ describe('MongoshLoggingAndTelemetry', function () {
     expect(logOutput).to.have.lengthOf(0);
     expect(analyticsOutput).to.have.lengthOf(0);
 
-    loggingAndTelemetry.detachLogger();
+    await loggingAndTelemetry.detachLogger();
 
     // This event has both analytics and logging
     bus.emit('mongosh:use', { db: '' });
@@ -386,7 +388,7 @@ describe('MongoshLoggingAndTelemetry', function () {
     expect(analyticsOutput).to.have.lengthOf(1);
   });
 
-  it('detaching logger applies to devtools-connect events', function () {
+  it('detaching logger applies to devtools-connect events', async function () {
     loggingAndTelemetry.attachLogger(logger);
 
     bus.emit('devtools-connect:connect-fail-early');
@@ -396,7 +398,7 @@ describe('MongoshLoggingAndTelemetry', function () {
     // No analytics event attached to this
     expect(analyticsOutput).to.have.lengthOf(0);
 
-    loggingAndTelemetry.detachLogger();
+    await loggingAndTelemetry.detachLogger();
     bus.emit('devtools-connect:connect-fail-early');
 
     expect(logOutput).to.have.lengthOf(2);
@@ -423,7 +425,7 @@ describe('MongoshLoggingAndTelemetry', function () {
     await (loggingAndTelemetry as LoggingAndTelemetry).setupTelemetryPromise;
     expect(analyticsOutput).to.have.lengthOf(1);
 
-    loggingAndTelemetry.detachLogger();
+    await loggingAndTelemetry.detachLogger();
 
     bus.emit('mongosh:use', { db: '' });
 
@@ -446,7 +448,7 @@ describe('MongoshLoggingAndTelemetry', function () {
 
     expect(analyticsOutput).to.have.lengthOf(1);
 
-    loggingAndTelemetry.detachLogger();
+    await loggingAndTelemetry.detachLogger();
 
     bus.emit('mongosh:use', { db: '' });
 

packages/logging/src/logging-and-telemetry.ts

@@ -126,13 +126,15 @@ export class LoggingAndTelemetry implements MongoshLoggingAndTelemetry {
     this.isSetup = true;
   }
 
-  public flush(): void {
+  public async flush(): Promise<void> {
     // Run any other pending events with the set or dummy log for telemetry purposes.
     this.runAndClearPendingBusEvents();
 
     // Abort setup, which will cause the device ID to be set to 'unknown'
     // and run any remaining telemetry events
     this.telemetrySetupAbort.abort();
+
+    await this.log.flush();
   }
 
   private async setupTelemetry(): Promise<void> {
@@ -177,10 +179,10 @@ export class LoggingAndTelemetry implements MongoshLoggingAndTelemetry {
     this.bus.emit('mongosh:log-initialized');
   }
 
-  public detachLogger() {
+  public async detachLogger(): Promise<void> {
     this.log = LoggingAndTelemetry.dummyLogger;
 
-    this.flush();
+    await this.flush();
   }
 
   private runAndClearPendingBusEvents() {

packages/logging/src/types.ts

@@ -5,9 +5,9 @@ import type { MultiSet } from './helpers';
 
 export interface MongoshLoggingAndTelemetry {
   attachLogger(logger: MongoLogWriter): void;
-  detachLogger(): void;
+  detachLogger(): Promise<void>;
   /** Flush any remaining log or telemetry events. */
-  flush(): void;
+  flush(): Promise<void>;
 }
 
 export type MongoshLoggingAndTelemetryArguments = {