feat: track all API calls MONGOSH-977 (#1135)

Specifically:

- Rename `mongosh:api-call` to `mongosh:api-call-with-arguments` for
  a bit more accuracy, and drop `mongosh:deprecated-api-call` in
  favor of a more generla `mongosh:api-call` event that provides
  information useful for telemetry.
- Track top-level API calls of async APIs, avoiding tracking of
  nested calls and omitting synchronous APIs since they are used
  internally fairly extensively.

Author: addaleax

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

@@ -804,6 +804,19 @@ describe('CliRepl', () => {
           expect(loadEvents[1].properties.nested).to.equal(true);
         });
 
+        it('posts analytics event for shell API calls', async() => {
+          await cliRepl.start(await testServer.connectionString(), {});
+          input.write('db.printShardingStatus()\n');
+          input.write('exit\n');
+          await waitBus(cliRepl.bus, 'mongosh:closed');
+          const apiEvents = requests.map(
+            req => JSON.parse(req.body).batch.filter(entry => entry.event === 'API Call')).flat();
+          expect(apiEvents).to.have.lengthOf(1);
+          expect(apiEvents[0].properties.class).to.equal('Database');
+          expect(apiEvents[0].properties.method).to.equal('printShardingStatus');
+          expect(apiEvents[0].properties.count).to.equal(1);
+        });
+
         context('with a 5.0+ server', () => {
           skipIfServerVersion(testServer, '<= 4.4');
 

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

@@ -364,6 +364,9 @@ class MongoshNodeRepl implements EvaluationListener {
       this.output.write(this.writer(warn) + '\n');
     }
 
+    (repl as any).on(asyncRepl.evalStart, () => {
+      this.bus.emit('mongosh:evaluate-started');
+    });
     (repl as any).on(asyncRepl.evalFinish, () => {
       this.bus.emit('mongosh:evaluate-finished');
     });

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

@@ -55,13 +55,13 @@ describe('setupLoggerAndTelemetry', () => {
     }
 
     bus.emit('mongosh:setCtx', { method: 'setCtx' });
-    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:api-call-with-arguments', { method: 'auth', class: 'Database', db: 'test-1603986682000', arguments: { } });
+    bus.emit('mongosh:api-call-with-arguments', { method: 'redactable', arguments: { filter: { email: '[email protected]' } } });
     bus.emit('mongosh:evaluate-input', { input: '1+1' });
 
     const circular: any = {};
     circular.circular = circular;
-    bus.emit('mongosh:api-call', { method: 'circulararg', arguments: { options: { circular } } });
+    bus.emit('mongosh:api-call-with-arguments', { method: 'circulararg', arguments: { options: { circular } } });
     expect(circular.circular).to.equal(circular); // Make sure the argument is still intact afterwards
 
     bus.emit('mongosh:start-loading-cli-scripts', { usesShellOption: true });
@@ -374,22 +374,26 @@ describe('setupLoggerAndTelemetry', () => {
     logOutput = [];
     analyticsOutput = [];
 
-    bus.emit('mongosh:deprecated-api-call', { method: 'cloneDatabase', class: 'Database' });
-    bus.emit('mongosh:deprecated-api-call', { method: 'cloneDatabase', class: 'Database' });
-    bus.emit('mongosh:deprecated-api-call', { method: 'copyDatabase', class: 'Database' });
-    bus.emit('mongosh:deprecated-api-call', { method: 'cloneDatabase', class: 'Database' });
+    bus.emit('mongosh:api-call', { method: 'cloneDatabase', class: 'Database', deprecated: true, callDepth: 0, isAsync: true });
+    bus.emit('mongosh:api-call', { method: 'cloneDatabase', class: 'Database', deprecated: true, callDepth: 0, isAsync: true });
+    bus.emit('mongosh:api-call', { method: 'copyDatabase', class: 'Database', deprecated: true, callDepth: 0, isAsync: true });
+    bus.emit('mongosh:api-call', { method: 'cloneDatabase', class: 'Database', deprecated: true, callDepth: 0, isAsync: true });
+    bus.emit('mongosh:api-call', { method: 'mangleDatabase', class: 'Database', deprecated: true, callDepth: 1, isAsync: true });
+    bus.emit('mongosh:api-call', { method: 'getName', class: 'Database', deprecated: false, callDepth: 0, isAsync: false });
 
     expect(logOutput).to.be.empty;
     expect(analyticsOutput).to.be.empty;
 
     bus.emit('mongosh:evaluate-finished');
-    expect(logOutput).to.have.length(2);
-    expect(analyticsOutput).to.have.length(2);
+    expect(logOutput).to.have.length(3);
+    expect(analyticsOutput).to.have.length(5);
 
     expect(logOutput[0].msg).to.equal('Deprecated API call');
     expect(logOutput[0].attr).to.deep.equal({ class: 'Database', method: 'cloneDatabase' });
     expect(logOutput[1].msg).to.equal('Deprecated API call');
     expect(logOutput[1].attr).to.deep.equal({ class: 'Database', method: 'copyDatabase' });
+    expect(logOutput[2].msg).to.equal('Deprecated API call');
+    expect(logOutput[2].attr).to.deep.equal({ class: 'Database', method: 'mangleDatabase' });
     expect(analyticsOutput).to.deep.equal([
       [
         'track',
@@ -414,14 +418,52 @@ describe('setupLoggerAndTelemetry', () => {
             method: 'copyDatabase',
           }
         }
-      ]
+      ],
+      [
+        'track',
+        {
+          userId: '53defe995fa47e6c13102d9d',
+          event: 'Deprecated Method',
+          properties: {
+            mongosh_version: '1.0.0',
+            class: 'Database',
+            method: 'mangleDatabase',
+          }
+        }
+      ],
+      [
+        'track',
+        {
+          userId: '53defe995fa47e6c13102d9d',
+          event: 'API Call',
+          properties: {
+            mongosh_version: '1.0.0',
+            class: 'Database',
+            method: 'cloneDatabase',
+            count: 3
+          }
+        }
+      ],
+      [
+        'track',
+        {
+          userId: '53defe995fa47e6c13102d9d',
+          event: 'API Call',
+          properties: {
+            mongosh_version: '1.0.0',
+            class: 'Database',
+            method: 'copyDatabase',
+            count: 1
+          }
+        }
+      ],
     ]);
 
     bus.emit('mongosh:new-user', userId, false);
     logOutput = [];
     analyticsOutput = [];
 
-    bus.emit('mongosh:deprecated-api-call', { method: 'cloneDatabase', class: 'Database' });
+    bus.emit('mongosh:api-call', { method: 'cloneDatabase', class: 'Database', deprecated: true, callDepth: 0, isAsync: true });
 
     expect(logOutput).to.be.empty;
     expect(analyticsOutput).to.be.empty;

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

@@ -3,6 +3,7 @@ import redactInfo from 'mongodb-redact';
 import { redactURICredentials } from '@mongosh/history';
 import type {
   MongoshBus,
+  ApiEventWithArguments,
   ApiEvent,
   UseEvent,
   EvaluateInputEvent,
@@ -67,6 +68,28 @@ class NoopAnalytics implements MongoshAnalytics {
   track(_info: any): void {} // eslint-disable-line @typescript-eslint/no-unused-vars
 }
 
+/**
+ * A helper class for keeping track of how often specific events occurred.
+ */
+class MultiSet<T> {
+  _entries: Map<string, number> = new Map();
+
+  add(entry: T): void {
+    const key = JSON.stringify(Object.entries(entry).sort());
+    this._entries.set(key, (this._entries.get(key) ?? 0) + 1);
+  }
+
+  clear(): void {
+    this._entries.clear();
+  }
+
+  *[Symbol.iterator](): Iterator<[T, number]> {
+    for (const [key, count] of this._entries) {
+      yield [Object.fromEntries(JSON.parse(key)) as T, count];
+    }
+  }
+}
+
 /**
  * Connect a MongoshBus instance that emits events to logging and analytics providers.
  *
@@ -194,11 +217,11 @@ export function setupLoggerAndTelemetry(
     }
   });
 
-  bus.on('mongosh:setCtx', function(args: ApiEvent) {
+  bus.on('mongosh:setCtx', function(args: ApiEventWithArguments) {
     log.info('MONGOSH', mongoLogId(1_000_000_010), 'shell-api', 'Initialized context', args);
   });
 
-  bus.on('mongosh:api-call', function(args: ApiEvent) {
+  bus.on('mongosh:api-call-with-arguments', function(args: ApiEventWithArguments) {
     // TODO: redactInfo cannot handle circular or otherwise nontrivial input
     let arg;
     try {
@@ -349,28 +372,54 @@ export function setupLoggerAndTelemetry(
     log.info('MONGOSH-SNIPPETS', mongoLogId(1_000_000_032), 'snippets', 'Rewrote error message', ev);
   });
 
-  const deprecatedApiCalls = new Set<string>();
-  bus.on('mongosh:deprecated-api-call', function(ev: ApiEvent) {
-    deprecatedApiCalls.add(`${ev.class}#${ev.method}`);
+  const deprecatedApiCalls = new MultiSet<Pick<ApiEvent, 'class' | 'method'>>();
+  const apiCalls = new MultiSet<Pick<ApiEvent, 'class' | 'method'>>();
+  bus.on('mongosh:api-call', function(ev: ApiEvent) {
+    if (ev.deprecated) {
+      deprecatedApiCalls.add({ class: ev.class, method: ev.method });
+    }
+    if (ev.callDepth === 0 && ev.isAsync) {
+      apiCalls.add({ class: ev.class, method: ev.method });
+    }
+  });
+  bus.on('mongosh:evaluate-started', function() {
+    // Clear API calls before evaluation starts. This is important because
+    // some API calls are also emitted by mongosh CLI repl internals,
+    // but we only care about those emitted from user code (i.e. during
+    // evaluation).
+    deprecatedApiCalls.clear();
+    apiCalls.clear();
   });
   bus.on('mongosh:evaluate-finished', function() {
-    deprecatedApiCalls.forEach(e => {
-      const [clazz, method] = e.split('#');
-      log.warn('MONGOSH', mongoLogId(1_000_000_033), 'shell-api', 'Deprecated API call', { class: clazz, method });
+    for (const [entry] of deprecatedApiCalls) {
+      log.warn('MONGOSH', mongoLogId(1_000_000_033), 'shell-api', 'Deprecated API call', entry);
 
       if (telemetry) {
         analytics.track({
           userId,
           event: 'Deprecated Method',
           properties: {
             mongosh_version,
-            class: clazz,
-            method
+            ...entry
           }
         });
       }
-    });
+    }
+    for (const [entry, count] of apiCalls) {
+      if (telemetry) {
+        analytics.track({
+          userId,
+          event: 'API Call',
+          properties: {
+            mongosh_version,
+            ...entry,
+            count
+          }
+        });
+      }
+    }
     deprecatedApiCalls.clear();
+    apiCalls.clear();
   });
 
   bus.on('mongosh-sp:connect-attempt-initialized', function(ev: SpConnectAttemptInitializedEvent) {

packages/node-runtime-worker-thread/src/index.spec.ts

@@ -175,7 +175,7 @@ describe('WorkerRuntime', () => {
 
       await runtime.evaluate('db.getCollectionNames()');
 
-      expect(eventEmitter.emit).to.have.been.calledWith('mongosh:api-call', {
+      expect(eventEmitter.emit).to.have.been.calledWith('mongosh:api-call-with-arguments', {
         arguments: {},
         class: 'Database',
         db: 'test',

packages/shell-api/src/bulk.ts

@@ -177,7 +177,7 @@ export default class Bulk extends ShellApiWithMongoClass {
    * @private
    */
   private _emitBulkApiCall(methodName: string, methodArguments: Document = {}): void {
-    this._mongo._instanceState.emitApiCall({
+    this._mongo._instanceState.emitApiCallWithArgs({
       method: methodName,
       class: 'Bulk',
       db: this._collection._database._name,

packages/shell-api/src/collection.spec.ts

@@ -65,14 +65,14 @@ describe('Collection', () => {
   });
   describe('.collections', () => {
     it('allows to get a collection as property if is not one of the existing methods', () => {
-      const database = new Database({ _instanceState: { emitApiCall: (): void => {} } } as any, 'db1');
+      const database = new Database({ _instanceState: { emitApiCallWithArgs: (): void => {} } } as any, 'db1');
       const coll: any = new Collection({} as any, database, 'coll');
       expect(coll.someCollection).to.have.instanceOf(Collection);
       expect(coll.someCollection._name).to.equal('coll.someCollection');
     });
 
     it('reuses collections', () => {
-      const database: any = new Database({ _instanceState: { emitApiCall: (): void => {} } } as any, 'db1');
+      const database: any = new Database({ _instanceState: { emitApiCallWithArgs: (): void => {} } } as any, 'db1');
       const coll: any = new Collection({} as any, database, 'coll');
       expect(coll.someCollection).to.equal(database.getCollection('coll.someCollection'));
       expect(coll.someCollection).to.equal(database.coll.someCollection);

packages/shell-api/src/collection.ts

@@ -130,7 +130,7 @@ export default class Collection extends ShellApiWithMongoClass {
    * @private
    */
   private _emitCollectionApiCall(methodName: string, methodArguments: Document = {}): void {
-    this._mongo._instanceState.emitApiCall({
+    this._mongo._instanceState.emitApiCallWithArgs({
       method: methodName,
       class: 'Collection',
       db: this._database._name,

packages/shell-api/src/database.ts

@@ -126,7 +126,7 @@ export default class Database extends ShellApiWithMongoClass {
    * @private
    */
   private _emitDatabaseApiCall(methodName: string, methodArguments: Document = {}): void {
-    this._mongo._instanceState.emitApiCall({
+    this._mongo._instanceState.emitApiCallWithArgs({
       method: methodName,
       class: 'Database',
       db: this._name,

packages/shell-api/src/decorators.ts

@@ -230,20 +230,26 @@ function wrapWithApiChecks<T extends(...args: any[]) => any>(fn: T, className: s
   const wrapper = (fn as any).returnsPromise ?
     markImplicitlyAwaited(async function(this: any, ...args: any[]): Promise<any> {
       const instanceState = getShellInstanceState(this);
-      checkForDeprecation(instanceState, className, fn);
+      emitApiCallTelemetry(instanceState, className, fn, true);
       const interruptFlag = instanceState?.interrupted;
       interruptFlag?.checkpoint();
       const interrupt = interruptFlag?.asPromise();
 
       let result: any;
       try {
+        if (instanceState) {
+          instanceState.apiCallDepth++;
+        }
         result = await Promise.race([
           interrupt?.promise ?? new Promise<never>(() => {}),
           fn.call(this, ...args)
         ]);
       } catch (e) {
         throw instanceState?.transformError(e) ?? e;
       } finally {
+        if (instanceState) {
+          instanceState.apiCallDepth--;
+        }
         if (interrupt) {
           interrupt.destroy();
         }
@@ -252,14 +258,21 @@ function wrapWithApiChecks<T extends(...args: any[]) => any>(fn: T, className: s
       return result;
     }) : function(this: any, ...args: any[]): any {
       const instanceState = getShellInstanceState(this);
-      checkForDeprecation(instanceState, className, fn);
+      emitApiCallTelemetry(instanceState, className, fn, false);
       const interruptFlag = instanceState?.interrupted;
       interruptFlag?.checkpoint();
       let result: any;
       try {
+        if (instanceState) {
+          instanceState.apiCallDepth++;
+        }
         result = fn.call(this, ...args);
       } catch (e) {
         throw instanceState?.transformError(e) ?? e;
+      } finally {
+        if (instanceState) {
+          instanceState.apiCallDepth--;
+        }
       }
       interruptFlag?.checkpoint();
       return result;
@@ -270,20 +283,21 @@ function wrapWithApiChecks<T extends(...args: any[]) => any>(fn: T, className: s
 }
 
 /**
- * Emit a 'mongosh:deprecated-api-call' event on the instance state's message bus
- * if the function was marked with the {@link deprecated} decorator.
+ * Emit a 'mongosh:api-call' event on the instance state's message bus,
+ * with the 'deprecated' property set if the function was marked with
+ * the {@link deprecated} decorator.
  *
  * @param instanceState A ShellInstanceState object.
  * @param className The name of the class in question.
  * @param fn The class method in question.
  */
-function checkForDeprecation(instanceState: ShellInstanceState | undefined, className: string, fn: Function) {
-  if (instanceState && typeof instanceState.emitDeprecatedApiCall === 'function' && typeof fn === 'function' && (fn as any).deprecated) {
-    instanceState.emitDeprecatedApiCall({
-      method: fn.name,
-      class: className
-    });
-  }
+function emitApiCallTelemetry(instanceState: ShellInstanceState | undefined, className: string, fn: Function, isAsync: boolean) {
+  instanceState?.emitApiCall?.({
+    method: fn.name,
+    class: className,
+    deprecated: !!(fn as any).deprecated,
+    isAsync
+  });
 }
 
 /**