chore(logging): provide driver version for every connection MONGOSH-1000 (#1113)

TS requested that we provide a driver version for connection
attempts from the embedded shell in Compass. This moves the
driver version reporting to the service-provider-server package,
which is a more natural place for it anyway.

Author: addaleax

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

@@ -363,9 +363,7 @@ class CliRepl {
     if (!this.cliOptions.nodb && !this.cliOptions.quiet) {
       this.output.write(i18n.__(CONNECTING) + '\t\t' + this.clr(redactURICredentials(driverUri), ['bold', 'green']) + '\n');
     }
-    const provider = await CliServiceProvider.connect(driverUri, driverOptions, this.cliOptions, this.bus);
-    this.bus.emit('mongosh:driver-initialized', provider.driverMetadata);
-    return provider;
+    return await CliServiceProvider.connect(driverUri, driverOptions, this.cliOptions, this.bus);
   }
 
   /** Return the file path used for the REPL history. */

packages/cli-repl/test/e2e.spec.ts

@@ -871,11 +871,11 @@ describe('e2e', function() {
         });
 
         it('includes information about the driver version', async() => {
-          await eventually(async() => {
-            const log = await readLogfile();
-            expect(log.filter(logEntry => /Driver initialized/.test(logEntry.msg)))
-              .to.have.lengthOf(1);
-          });
+          const connectionString = await testServer.connectionString();
+          expect(await shell.executeLine(`connect(${JSON.stringify(connectionString)})`)).to.include('test');
+          const log = await readLogfile();
+          expect(log.filter(logEntry => typeof logEntry.attr?.driver?.version === 'string'))
+            .to.have.lengthOf(1);
         });
       });
 

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

@@ -57,7 +57,6 @@ describe('setupLoggerAndTelemetry', () => {
     bus.emit('mongosh:api-call', { method: 'auth', class: 'Database', db: 'test-1603986682000', arguments: { } });
     bus.emit('mongosh:api-call', { method: 'redactable', arguments: { filter: { email: '[email protected]' } } });
     bus.emit('mongosh:evaluate-input', { input: '1+1' });
-    bus.emit('mongosh:driver-initialized', { driver: { name: 'nodejs', version: '3.6.1' } });
 
     const circular: any = {};
     circular.circular = circular;
@@ -87,6 +86,12 @@ describe('setupLoggerAndTelemetry', () => {
     bus.emit('mongosh-snippets:snippet-command', { args: ['install', 'foo'] });
     bus.emit('mongosh-snippets:transform-error', { error: 'failed', addition: 'oh no', name: 'foo' });
 
+    const connAttemptData = {
+      driver: { name: 'nodejs', version: '3.6.1' },
+      serviceProviderVersion: '1.0.0',
+      host: 'localhost'
+    };
+    bus.emit('mongosh-sp:connect-attempt-initialized', connAttemptData);
     bus.emit('mongosh-sp:connect-heartbeat-failure', { connectionId: 'localhost', failure: new Error('cause'), isFailFast: true, isKnownServer: true });
     bus.emit('mongosh-sp:connect-heartbeat-succeeded', { connectionId: 'localhost' });
     bus.emit('mongosh-sp:connect-fail-early');
@@ -128,8 +133,6 @@ describe('setupLoggerAndTelemetry', () => {
     expect(logOutput[i++].attr.arguments.filter.email).to.equal('<email>');
     expect(logOutput[i].msg).to.equal('Evaluating input');
     expect(logOutput[i++].attr.input).to.equal('1+1');
-    expect(logOutput[i].msg).to.equal('Driver initialized');
-    expect(logOutput[i++].attr.driver.version).to.equal('3.6.1');
     expect(logOutput[i].msg).to.equal('Performed API call');
     expect(logOutput[i++].attr._inspected).to.match(/circular/);
     expect(logOutput[i++].msg).to.equal('Start loading CLI scripts');
@@ -169,6 +172,8 @@ describe('setupLoggerAndTelemetry', () => {
     expect(logOutput[i++].attr).to.deep.equal({ args: ['install', 'foo'] });
     expect(logOutput[i].msg).to.equal('Rewrote error message');
     expect(logOutput[i++].attr).to.deep.equal({ error: 'failed', addition: 'oh no', name: 'foo' });
+    expect(logOutput[i].msg).to.equal('Initiating connection attempt');
+    expect(logOutput[i++].attr).to.deep.equal(connAttemptData);
     expect(logOutput[i].msg).to.equal('Server heartbeat failure');
     expect(logOutput[i++].attr).to.deep.equal({ connectionId: 'localhost', failure: 'cause', isFailFast: true, isKnownServer: true });
     expect(logOutput[i].msg).to.equal('Server heartbeat succeeded');

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

@@ -25,6 +25,7 @@ import type {
   SnippetsNpmLookupEvent,
   SnippetsRunNpmEvent,
   SnippetsTransformErrorEvent,
+  SpConnectAttemptInitializedEvent,
   SpConnectHeartbeatFailureEvent,
   SpConnectHeartbeatSucceededEvent,
   SpResolveSrvErrorEvent,
@@ -125,10 +126,6 @@ export function setupLoggerAndTelemetry(
     }
   });
 
-  bus.on('mongosh:driver-initialized', function(driverMetadata: any) {
-    log.info('MONGOSH', mongoLogId(1_000_000_004), 'connect', 'Driver initialized', driverMetadata);
-  });
-
   bus.on('mongosh:new-user', function(id: string, enableTelemetry: boolean) {
     userId = id;
     telemetry = enableTelemetry;
@@ -373,6 +370,10 @@ export function setupLoggerAndTelemetry(
     deprecatedApiCalls.clear();
   });
 
+  bus.on('mongosh-sp:connect-attempt-initialized', function(ev: SpConnectAttemptInitializedEvent) {
+    log.info('MONGOSH-SP', mongoLogId(1_000_000_042), 'connect', 'Initiating connection attempt', ev);
+  });
+
   bus.on('mongosh-sp:connect-heartbeat-failure', function(ev: SpConnectHeartbeatFailureEvent) {
     log.warn('MONGOSH-SP', mongoLogId(1_000_000_034), 'connect', 'Server heartbeat failure', {
       ...ev,

packages/service-provider-server/src/cli-service-provider.spec.ts

@@ -47,6 +47,12 @@ describe('CliServiceProvider', () => {
       db() {}
       close() {}
       topology: any;
+      get options(): any {
+        return {
+          metadata: { driver: { name: 'nodejs', version: '3.6.1' } },
+          hosts: ['localhost']
+        };
+      }
     }
 
     it('connects once when no AutoEncryption set', async() => {
@@ -850,7 +856,8 @@ describe('CliServiceProvider', () => {
       const info = await serviceProvider.getConnectionInfo();
       expect(info.extraInfo.is_atlas).to.equal(false);
       expect(info.extraInfo.is_localhost).to.equal(true);
-      expect(dbStub.command).to.have.callCount(4);
+      expect(info.extraInfo.fcv).to.equal(undefined);
+      expect(dbStub.command).to.have.callCount(5);
     });
   });
 });

packages/service-provider-server/src/cli-service-provider.ts

@@ -118,7 +118,7 @@ type ConnectionInfo = {
   topology: any;
   extraInfo: ExtraConnectionInfo;
 };
-type ExtraConnectionInfo = ReturnType<typeof getConnectInfo>;
+type ExtraConnectionInfo = ReturnType<typeof getConnectInfo> & { fcv?: string };
 
 /**
  * Default driver options we always use.
@@ -149,6 +149,11 @@ const DEFAULT_BASE_OPTIONS: OperationOptions = Object.freeze({
 async function connectWithFailFast(client: MongoClient, bus: MongoshBus): Promise<void> {
   const failedConnections = new Map<string, Error>();
   let failEarlyClosePromise: Promise<void> | null = null;
+  bus.emit('mongosh-sp:connect-attempt-initialized', {
+    driver: client.options.metadata.driver,
+    serviceProviderVersion: require('../package.json').version,
+    host: client.options.srvHost ?? client.options.hosts.join(',')
+  });
 
   const heartbeatFailureListener = ({ failure, connectionId }: ServerHeartbeatFailedEvent) => {
     const topologyDescription: TopologyDescription | undefined = (client as any).topology?.description;
@@ -407,9 +412,10 @@ class CliServiceProvider extends ServiceProviderCore implements ServiceProvider
     }
     const topology = this.getTopology();
     const { version } = require('../package.json');
-    const [cmdLineOpts = null, atlasVersion = null] = await Promise.all([
+    const [cmdLineOpts = null, atlasVersion = null, fcv = null] = await Promise.all([
       this.runCommandWithCheck('admin', { getCmdLineOpts: 1 }, this.baseCmdOptions).catch(() => {}),
-      this.runCommandWithCheck('admin', { atlasVersion: 1 }, this.baseCmdOptions).catch(() => {})
+      this.runCommandWithCheck('admin', { atlasVersion: 1 }, this.baseCmdOptions).catch(() => {}),
+      this.runCommandWithCheck('admin', { getParameter: 1, featureCompatibilityVersion: 1 }, this.baseCmdOptions).catch(() => {})
     ]);
 
     const extraConnectionInfo = getConnectInfo(
@@ -424,7 +430,10 @@ class CliServiceProvider extends ServiceProviderCore implements ServiceProvider
     return {
       buildInfo: buildInfo,
       topology: topology,
-      extraInfo: extraConnectionInfo
+      extraInfo: {
+        ...extraConnectionInfo,
+        fcv: fcv?.featureCompatibilityVersion?.version
+      }
     };
   }
 

packages/types/src/index.ts

@@ -134,6 +134,12 @@ export interface SnippetsTransformErrorEvent {
   name: string;
 }
 
+export interface SpConnectAttemptInitializedEvent {
+  driver: { name: string, version: string };
+  serviceProviderVersion: string;
+  host: string;
+}
+
 export interface SpConnectHeartbeatFailureEvent {
   connectionId: string;
   failure: Error;
@@ -188,11 +194,6 @@ export interface MongoshBusEventsMap {
    * or the used database changed.
    */
   'mongosh:connect': (ev: ConnectEvent) => void;
-  /**
-   * Signals the creation of a new Mongo client with metadata provided
-   * by the underlying driver implementation.
-   */
-  'mongosh:driver-initialized': (driverMetadata: any) => void;
   /**
    * Signals that the shell is started by a new user.
    */
@@ -338,6 +339,8 @@ export interface MongoshBusEventsMap {
   /** Signals that a snippet has modified an error message. */
   'mongosh-snippets:transform-error': (ev: SnippetsTransformErrorEvent) => void;
 
+  /** Signals that a connection attempt is about to be performed. */
+  'mongosh-sp:connect-attempt-initialized': (ev: SpConnectAttemptInitializedEvent) => void;
   /** Signals that communicating to a specific server during connection did not succeed. */
   'mongosh-sp:connect-heartbeat-failure': (ev: SpConnectHeartbeatFailureEvent) => void;
   /** Signals that communicating to a specific server during connection succeeded. */