chore(data-service): add a log whenever connecting throws and include connection id COMPASS-9404 (#6953)

Author: nbbeeken

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

@@ -206,10 +206,11 @@ describe('Logging and Telemetry integration', function () {
           c: 'COMPASS-DATA-SERVICE',
           id: 1_001_000_014,
           ctx: 'Connection 0',
-          msg: 'Connecting',
+          msg: 'Connecting Started',
           attr: (actual: any) => {
             expect(actual.url).to.match(/^mongodb:\/\/127.0.0.1:27091/);
             expect(actual.csfle).to.equal(null);
+            expect(actual).to.have.property('connectionId', 0);
           },
         },
         {
@@ -284,8 +285,9 @@ describe('Logging and Telemetry integration', function () {
           c: 'COMPASS-DATA-SERVICE',
           id: 1_001_000_015,
           ctx: 'Connection 0',
-          msg: 'Connected',
+          msg: 'Connecting Succeeded',
           attr: {
+            connectionId: 0,
             isMongos: false,
             isWritable: true,
           },

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

@@ -23,6 +23,7 @@ import { mochaTestServer } from '@mongodb-js/compass-test-server';
 import type { SearchIndex } from './search-index-detail-helper';
 import { range } from 'lodash';
 import ConnectionString from 'mongodb-connection-string-url';
+import type { DataServiceImplLogger, MongoLogId } from './logger';
 
 const { expect } = chai;
 chai.use(chaiAsPromised);
@@ -93,6 +94,118 @@ describe('DataService', function () {
         .drop();
     });
 
+    describe('#connect', function () {
+      const connectionStartedId = 1_001_000_014;
+      const connectionSucceededId = 1_001_000_015;
+      const connectionFailedId = 1_001_000_359;
+      const logs: {
+        info: [
+          component: string,
+          id: MongoLogId,
+          context: string,
+          message: string,
+          attr?: unknown
+        ];
+      }[] = [];
+      const logCollector: DataServiceImplLogger = {
+        error: () => {},
+        info: (...args) => logs.push({ info: args }),
+        debug: () => {},
+        warn: () => {},
+        fatal: () => {},
+      };
+
+      let dataServiceLogTest;
+
+      beforeEach(function () {
+        logs.length = 0;
+      });
+
+      afterEach(async function () {
+        await dataServiceLogTest?.disconnect();
+        dataServiceLogTest = undefined;
+      });
+
+      // The log and connection ids in this test are used by CompassWeb to measure connect time metrics.
+      // The intention of these tests is not to restrict any changes to the logs or ids.
+      // If a change to the ids is necessary please inform the appropriate team and they can adjust before pulling in the change.
+      it('when connecting succeeds there is a start and success log with a connectionId', async function () {
+        dataServiceLogTest = new DataServiceImpl(
+          connectionOptions,
+          logCollector
+        );
+        await dataServiceLogTest.connect();
+
+        expect(logs.map(({ info: [, id] }) => id.__value)).to.include(
+          connectionStartedId
+        );
+        expect(logs.map(({ info: [, id] }) => id.__value)).to.include(
+          connectionSucceededId
+        );
+
+        const startedLog = logs.find(
+          ({ info: [, id] }) => id.__value === connectionStartedId
+        );
+        const succeededLog = logs.find(
+          ({ info: [, id] }) => id.__value === connectionSucceededId
+        );
+
+        const { info: [, , , , startedAttr] = [] } = startedLog ?? {};
+        expect(startedAttr).to.have.property(
+          'connectionId',
+          dataServiceLogTest._id
+        );
+        const { info: [, , , , succeededAttr] = [] } = succeededLog ?? {};
+        expect(succeededAttr).to.have.property(
+          'connectionId',
+          dataServiceLogTest._id
+        );
+      });
+
+      it('when connecting fails there is a start and failure log with a connectionId', async function () {
+        dataServiceLogTest = new DataServiceImpl(
+          {
+            connectionString:
+              'mongodb://iLoveJavascript?serverSelectionTimeoutMS=5',
+            lookup: () => {
+              throw new Error('test error');
+            },
+          },
+          logCollector
+        );
+
+        const result = await dataServiceLogTest
+          .connect()
+          .catch((error) => error);
+        expect(result).to.be.instanceOf(Error);
+
+        expect(logs.map(({ info: [, id] }) => id.__value)).to.include(
+          connectionStartedId
+        );
+        expect(logs.map(({ info: [, id] }) => id.__value)).to.include(
+          connectionFailedId
+        );
+
+        const startedLog = logs.find(
+          ({ info: [, id] }) => id.__value === connectionStartedId
+        );
+        const failedLog = logs.find(
+          ({ info: [, id] }) => id.__value === connectionFailedId
+        );
+
+        const { info: [, , , , startedAttr] = [] } = startedLog ?? {};
+        expect(startedAttr).to.have.property(
+          'connectionId',
+          dataServiceLogTest._id
+        );
+        const { info: [, , , , succeededAttr] = [] } = failedLog ?? {};
+        expect(succeededAttr).to.have.property(
+          'connectionId',
+          dataServiceLogTest._id
+        );
+      });
+    });
+
     describe('#isConnected', function () {
       let dataServiceIsConnected: DataService;
 

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

@@ -1579,7 +1579,8 @@ class DataServiceImpl extends WithLogContext implements DataService {
     debug('connecting...');
     this._isConnecting = true;
 
-    this._logger.info(mongoLogId(1_001_000_014), 'Connecting', {
+    this._logger.info(mongoLogId(1_001_000_014), 'Connecting Started', {
+      connectionId: this._id,
       url: redactConnectionString(this._connectionOptions.connectionString),
       csfle: this._csfleLogInformation(this._connectionOptions.fleOptions),
     });
@@ -1599,11 +1600,16 @@ class DataServiceImpl extends WithLogContext implements DataService {
         });
 
       const attr = {
+        connectionId: this._id,
         isWritable: this.isWritable(),
         isMongos: this.isMongos(),
       };
 
-      this._logger.info(mongoLogId(1_001_000_015), 'Connected', attr);
+      this._logger.info(
+        mongoLogId(1_001_000_015),
+        'Connecting Succeeded',
+        attr
+      );
       debug('connected!', attr);
 
       state.oidcPlugin.logger.on('mongodb-oidc-plugin:state-updated', () => {
@@ -1626,6 +1632,15 @@ class DataServiceImpl extends WithLogContext implements DataService {
         this,
         this._crudClient
       );
+    } catch (error) {
+      this._logger.info(mongoLogId(1_001_000_359), 'Connecting Failed', {
+        connectionId: this._id,
+        error:
+          error && typeof error === 'object' && 'message' in error
+            ? error?.message
+            : 'unknown error',
+      });
+      throw error;
     } finally {
       this._isConnecting = false;
     }