fix(logger): replace PassThrough with Writable for log handling COMPASS-9736 (#7222)

* fix(logger): replace PassThrough with Writable for log handling CLOUDP-332732

* fix(logger): replace PassThrough with Writable for log handling CLOUDP-332732

* test: synchronous log call

---------

Co-authored-by: Simon Zhu <[email protected]>

Author: nbbeeken

packages/compass-connections/src/stores/connections-store-redux.ts

@@ -1635,6 +1635,17 @@ const connectWithOptions = (
           );
         }
 
+        // This is used for Data Explorer connection latency tracing
+        log.info(
+          mongoLogId(1_001_000_005),
+          'Compass Connection Attempt Started',
+          'Connection attempt started',
+          {
+            clusterName: connectionInfo.atlasMetadata?.clusterName,
+            connectionId: connectionInfo.id,
+          }
+        );
+
         const connectionAttempt = createConnectionAttempt({
           logger: log.unbound,
           proxyOptions: proxyPreferenceToProxyOptions(
@@ -1655,6 +1666,16 @@ const connectWithOptions = (
         // This is how connection attempt indicates that the connection was
         // aborted
         if (!dataService || connectionAttempt.isClosed()) {
+          // This is used for Data Explorer connection latency tracing
+          log.info(
+            mongoLogId(1_001_000_007),
+            'Compass Connection Attempt Cancelled',
+            'Connection attempt cancelled',
+            {
+              clusterName: connectionInfo.atlasMetadata?.clusterName,
+              connectionId: connectionInfo.id,
+            }
+          );
           dispatch({
             type: ActionTypes.ConnectionAttemptCancelled,
             connectionId: connectionInfo.id,
@@ -1821,6 +1842,17 @@ const connectWithOptions = (
           connectionInfo
         );
 
+        // This is used for Data Explorer connection latency tracing
+        log.info(
+          mongoLogId(1_001_000_006),
+          'Compass Connection Attempt Succeeded',
+          'Connection attempt succeeded',
+          {
+            clusterName: connectionInfo.atlasMetadata?.clusterName,
+            connectionId: connectionInfo.id,
+          }
+        );
+
         connectionProgress.openConnectionSucceededToast(connectionInfo);
 
         // Emit before changing state because some plugins rely on this
@@ -1856,6 +1888,16 @@ const connectWithOptions = (
           );
         }
       } catch (err) {
+        log.info(
+          mongoLogId(1_001_000_008),
+          'Compass Connection Attempt Failed',
+          'Connection attempt failed',
+          {
+            clusterName: connectionInfo.atlasMetadata?.clusterName,
+            connectionId: connectionInfo.id,
+            error: (err as Error).message,
+          }
+        );
         dispatch(connectionAttemptError(connectionInfo, err));
       } finally {
         deviceAuthAbortController.abort();

packages/compass-web/src/logger.spec.tsx

@@ -59,4 +59,25 @@ describe('useCompassWebLogger', function () {
       },
     ]);
   });
+
+  it('should call onLog hook synchronously', function () {
+    let callbackExecuted = false;
+    const onLog = Sinon.stub().callsFake(() => {
+      callbackExecuted = true;
+    });
+
+    const {
+      result: { current: logger },
+    } = renderLoggerHook({ onLog });
+
+    // Callback should not have been called yet
+    expect(callbackExecuted).to.be.false;
+
+    // Call the logger
+    logger.log.info(mongoLogId(456), 'Test', 'sync test');
+
+    // Callback should have been called synchronously before this assertion
+    expect(callbackExecuted).to.be.true;
+    expect(onLog).to.have.been.calledOnce;
+  });
 });

packages/compass-web/src/logger.tsx

@@ -1,6 +1,6 @@
 import type { Logger } from '@mongodb-js/compass-logging/provider';
 import { MongoLogWriter } from 'mongodb-log-writer/mongo-log-writer';
-import { PassThrough } from 'stream';
+import type { Writable } from 'stream';
 import { mongoLogId } from '@mongodb-js/compass-logging/provider';
 import { useRef } from 'react';
 
@@ -62,13 +62,17 @@ export class CompassWebLogger implements Logger {
       };
     }
   ) {
-    const passThrough = new PassThrough({ objectMode: true });
-    this.log = new MongoLogWriter('', '', passThrough).bindComponent(
-      this.component
-    );
-    passThrough.on('data', (line) => {
-      callbackRef.current.onLog?.(JSON.parse(line));
-    });
+    const target = {
+      write(line: string, callback: () => void) {
+        callbackRef.current.onLog?.(JSON.parse(line));
+        callback();
+      },
+      end(callback: () => void) {
+        callback();
+      },
+    } as Writable;
+
+    this.log = new MongoLogWriter('', '', target).bindComponent(this.component);
 
     this.debug = createCompassWebDebugger(this.component, this.callbackRef);
   }

packages/data-service/src/data-service.spec.ts

@@ -167,9 +167,10 @@ describe('DataService', function () {
           {
             connectionString:
               'mongodb://iLoveJavascript?serverSelectionTimeoutMS=5',
-            lookup: () => {
-              throw new Error('test error');
-            },
+            lookup: () => ({
+              wsURL: 'ws://localhost:12345/mongodb/atlas/websocket',
+              clusterName: 'iLoveJavascript',
+            }),
           },
           logCollector
         );

packages/data-service/src/data-service.ts

@@ -53,6 +53,8 @@ import type {
   ClientEncryptionCreateDataKeyProviderOptions,
   SearchIndexDescription,
   ReadPreferenceMode,
+  CommandStartedEvent,
+  ConnectionCreatedEvent,
 } from 'mongodb';
 import { ReadPreference } from 'mongodb';
 import ConnectionStringUrl from 'mongodb-connection-string-url';
@@ -1604,10 +1606,12 @@ class DataServiceImpl extends WithLogContext implements DataService {
     debug('connecting...');
     this._isConnecting = true;
 
+    const clusterName = this._connectionOptions.lookup?.().clusterName;
     this._logger.info(mongoLogId(1_001_000_014), 'Connecting Started', {
       connectionId: this._id,
       url: redactConnectionString(this._connectionOptions.connectionString),
       csfle: this._csfleLogInformation(this._connectionOptions.fleOptions),
+      ...(clusterName && { clusterName }),
     });
 
     try {
@@ -1628,6 +1632,7 @@ class DataServiceImpl extends WithLogContext implements DataService {
         connectionId: this._id,
         isWritable: this.isWritable(),
         isMongos: this.isMongos(),
+        ...(clusterName && { clusterName }),
       };
 
       this._logger.info(
@@ -1664,6 +1669,7 @@ class DataServiceImpl extends WithLogContext implements DataService {
           error && typeof error === 'object' && 'message' in error
             ? error?.message
             : 'unknown error',
+        ...(clusterName && { clusterName }),
       });
       throw error;
     } finally {
@@ -2474,6 +2480,18 @@ class DataServiceImpl extends WithLogContext implements DataService {
 
   private _setupListeners(client: MongoClient): void {
     if (client) {
+      client.on('connectionCreated', (evt: ConnectionCreatedEvent) => {
+        const { address, connectionId } = evt;
+        this._logger.info(
+          mongoLogId(1_001_000_027),
+          'Driver connection created',
+          {
+            address,
+            serverConnectionId: connectionId,
+          }
+        );
+      });
+
       client.on(
         'serverDescriptionChanged',
         (evt: ServerDescriptionChangedEvent) => {
@@ -2595,13 +2613,30 @@ class DataServiceImpl extends WithLogContext implements DataService {
         this._emitter.emit('serverHeartbeatFailed', evt);
       });
 
+      client.on('commandStarted', (evt: CommandStartedEvent) => {
+        const { address, connectionId, requestId, commandName, databaseName } =
+          evt;
+        this._logger.debug(
+          mongoLogId(1_001_000_028),
+          'Driver command started',
+          {
+            address,
+            databaseName,
+            serverConnectionId: connectionId,
+            requestId,
+            commandName,
+          }
+        );
+      });
+
       client.on('commandSucceeded', (evt: CommandSucceededEvent) => {
-        const { address, connectionId, duration, commandName } = evt;
+        const { address, connectionId, duration, requestId, commandName } = evt;
         this._logger.debug(
           mongoLogId(1_001_000_029),
           'Driver command succeeded',
           {
             address,
+            requestId,
             serverConnectionId: connectionId,
             duration,
             commandName,
@@ -2610,11 +2645,19 @@ class DataServiceImpl extends WithLogContext implements DataService {
       });
 
       client.on('commandFailed', (evt: CommandFailedEvent) => {
-        const { address, connectionId, duration, commandName, failure } = evt;
+        const {
+          address,
+          connectionId,
+          duration,
+          requestId,
+          commandName,
+          failure,
+        } = evt;
         this._logger.debug(mongoLogId(1_001_000_030), 'Driver command failed', {
           address,
           serverConnectionId: connectionId,
           duration,
+          requestId,
           commandName,
           failure: failure.message,
         });