(core) Polish telemetry code

Summary: Also fixes a few small bugs with telemetry collection.

Test Plan: Server and manual tests.

Reviewers: paulfitz

Reviewed By: paulfitz

Differential Revision: https://phab.getgrist.com/D3915

app/gen-server/entity/Document.ts

@@ -130,12 +130,12 @@ export class Document extends Resource {
             this.options.tutorial = null;
           } else {
             this.options.tutorial = this.options.tutorial || {};
-            if (props.options.tutorial.lastSlideIndex !== undefined) {
-              this.options.tutorial.lastSlideIndex = props.options.tutorial.lastSlideIndex;
-            }
             if (props.options.tutorial.numSlides !== undefined) {
               this.options.tutorial.numSlides = props.options.tutorial.numSlides;
-              if (dbManager && props.options?.tutorial?.lastSlideIndex !== undefined) {
+            }
+            if (props.options.tutorial.lastSlideIndex !== undefined) {
+              this.options.tutorial.lastSlideIndex = props.options.tutorial.lastSlideIndex;
+              if (dbManager && this.options.tutorial.numSlides) {
                 this._emitTutorialProgressChangeEvent(dbManager, this.options.tutorial);
               }
             }

app/server/lib/DocApi.ts

@@ -906,6 +906,7 @@ export class DocWorkerApi {
                 name: tutorialTrunk.name,
                 options: {
                   tutorial: {
+                    ...tutorialTrunk.options?.tutorial,
                     // For now, the only state we need to reset is the slide position.
                     lastSlideIndex: 0,
                   },

app/server/lib/Telemetry.ts

@@ -25,6 +25,8 @@ export interface ITelemetry {
   getTelemetryLevel(): TelemetryLevel;
 }
 
+const MAX_PENDING_FORWARD_EVENT_REQUESTS = 25;
+
 /**
  * Manages telemetry for Grist.
  */
@@ -34,10 +36,11 @@ export class Telemetry implements ITelemetry {
   private _shouldForwardTelemetryEvents = this._deploymentType !== 'saas';
   private _forwardTelemetryEventsUrl = process.env.GRIST_TELEMETRY_URL ||
   'https://telemetry.getgrist.com/api/telemetry';
+  private _numPendingForwardEventRequests = 0;
 
   private _installationId: string | undefined;
 
-  private _errorLogger = new LogMethods('Telemetry ', () => ({}));
+  private _logger = new LogMethods('Telemetry ', () => ({}));
   private _telemetryLogger = new LogMethods('Telemetry ', () => ({
     eventType: 'telemetry',
   }));
@@ -46,7 +49,7 @@ export class Telemetry implements ITelemetry {
 
   constructor(private _dbManager: HomeDBManager, private _gristServer: GristServer) {
     this._initialize().catch((e) => {
-      this._errorLogger.error(undefined, 'failed to initialize', e);
+      this._logger.error(undefined, 'failed to initialize', e);
     });
   }
 
@@ -99,7 +102,7 @@ export class Telemetry implements ITelemetry {
     this._checkTelemetryEvent(event, metadata);
 
     if (this._shouldForwardTelemetryEvents) {
-      await this.forwardEvent(event, metadata);
+      await this._forwardEvent(event, metadata);
     } else {
       this._telemetryLogger.rawLog('info', null, event, {
         eventName: event,
@@ -109,29 +112,6 @@ export class Telemetry implements ITelemetry {
     }
   }
 
-  /**
-   * Forwards a telemetry event and its metadata to another server.
-   */
-  public async forwardEvent(
-    event: TelemetryEvent,
-    metadata?: TelemetryMetadata
-  ) {
-    try {
-      await fetch(this._forwardTelemetryEventsUrl, {
-        method: 'POST',
-        headers: {
-          'Content-Type': 'application/json',
-        },
-        body: JSON.stringify({
-          event,
-          metadata,
-        }),
-      });
-    } catch (e) {
-      this._errorLogger.error(undefined, `failed to forward telemetry event ${event}`, e);
-    }
-  }
-
   public addEndpoints(app: express.Application) {
     /**
      * Logs telemetry events and their metadata.
@@ -169,7 +149,7 @@ export class Telemetry implements ITelemetry {
             req.body.metadata,
           ));
         } catch (e) {
-          this._errorLogger.error(undefined, `failed to log telemetry event ${event}`, e);
+          this._logger.error(undefined, `failed to log telemetry event ${event}`, e);
           throw new ApiError(`Telemetry failed to log telemetry event ${event}`, 500);
         }
       }
@@ -195,7 +175,7 @@ export class Telemetry implements ITelemetry {
     for (const event of HomeDBTelemetryEvents.values) {
       this._dbManager.on(event, async (metadata) => {
         this.logEvent(event, metadata).catch(e =>
-          this._errorLogger.error(undefined, `failed to log telemetry event ${event}`, e));
+          this._logger.error(undefined, `failed to log telemetry event ${event}`, e));
       });
     }
   }
@@ -207,4 +187,34 @@ export class Telemetry implements ITelemetry {
 
     this._checkEvent(event, metadata);
   }
+
+  private async _forwardEvent(
+    event: TelemetryEvent,
+    metadata?: TelemetryMetadata
+  ) {
+    if (this._numPendingForwardEventRequests === MAX_PENDING_FORWARD_EVENT_REQUESTS) {
+      this._logger.warn(undefined, 'exceeded the maximum number of pending forwardEvent calls '
+        + `(${MAX_PENDING_FORWARD_EVENT_REQUESTS}). Skipping forwarding of event ${event}.`);
+      return;
+    }
+
+    try {
+      this._numPendingForwardEventRequests += 1;
+      await this._postJsonPayload(JSON.stringify({event, metadata}));
+    } catch (e) {
+      this._logger.error(undefined, `failed to forward telemetry event ${event}`, e);
+    } finally {
+      this._numPendingForwardEventRequests -= 1;
+    }
+  }
+
+  private async _postJsonPayload(payload: string) {
+    await fetch(this._forwardTelemetryEventsUrl, {
+      method: 'POST',
+      headers: {
+        'Content-Type': 'application/json',
+      },
+      body: payload,
+    });
+  }
 }

test/server/lib/Telemetry.ts

@@ -1,5 +1,5 @@
 import {GristDeploymentType} from 'app/common/gristUrls';
-import {TelemetryEvent, TelemetryLevel, TelemetryMetadata} from 'app/common/Telemetry';
+import {TelemetryEvent, TelemetryLevel} from 'app/common/Telemetry';
 import {ILogMeta, LogMethods} from 'app/server/lib/LogMethods';
 import {ITelemetry, Telemetry} from 'app/server/lib/Telemetry';
 import axios from 'axios';
@@ -27,10 +27,11 @@ describe('Telemetry', function() {
       let installationId: string;
       let server: TestServer;
       let telemetry: ITelemetry;
+      let forwardEventSpy: sinon.SinonSpy;
+      let postJsonPayloadStub: sinon.SinonStub;
 
       const sandbox = sinon.createSandbox();
       const loggedEvents: [TelemetryEvent, ILogMeta][] = [];
-      const forwardedEvents: [TelemetryEvent, TelemetryMetadata | undefined][] = [];
 
       before(async function() {
         process.env.GRIST_TEST_SERVER_DEPLOYMENT_TYPE = deploymentType;
@@ -43,11 +44,10 @@ describe('Telemetry', function() {
           .callsFake((_level: string, _info: unknown, name: string, meta: ILogMeta) => {
             loggedEvents.push([name as TelemetryEvent, meta]);
           });
-        sandbox
+        forwardEventSpy = sandbox
-          .stub(Telemetry.prototype, 'forwardEvent')
+          .spy(Telemetry.prototype as any, '_forwardEvent');
-          .callsFake((event: TelemetryEvent, metadata?: TelemetryMetadata) => {
+        postJsonPayloadStub = sandbox
-            forwardedEvents.push([event, metadata]);
+          .stub(Telemetry.prototype as any, '_postJsonPayload');
-          });
         telemetry = server.server.getTelemetry();
       });
 
@@ -106,7 +106,7 @@ describe('Telemetry', function() {
             }
 
             assert.equal(loggedEvents.length, 1);
-            assert.isEmpty(forwardedEvents);
+            assert.equal(forwardEventSpy.callCount, 0);
           });
         } else {
           it('forwards telemetry events', async function() {
@@ -117,7 +117,7 @@ describe('Telemetry', function() {
                   isPublic: false,
                 },
               });
-              assert.deepEqual(forwardedEvents[forwardedEvents.length - 1], [
+              assert.deepEqual(forwardEventSpy.lastCall.args, [
                 'documentOpened',
                 {
                   docIdDigest: 'digest',
@@ -136,7 +136,7 @@ describe('Telemetry', function() {
                   userId: 1,
                 },
               });
-              assert.deepEqual(forwardedEvents[forwardedEvents.length - 1], [
+              assert.deepEqual(forwardEventSpy.lastCall.args, [
                 'documentOpened',
                 {
                   docIdDigest: 'digest',
@@ -146,7 +146,7 @@ describe('Telemetry', function() {
               ]);
             }
 
-            assert.equal(forwardedEvents.length, 1);
+            assert.equal(forwardEventSpy.callCount, 1);
             assert.isEmpty(loggedEvents);
           });
         }
@@ -159,7 +159,7 @@ describe('Telemetry', function() {
             },
           });
           assert.isEmpty(loggedEvents);
-          assert.isEmpty(forwardedEvents);
+          assert.equal(forwardEventSpy.callCount, 0);
         });
       }
 
@@ -231,7 +231,7 @@ describe('Telemetry', function() {
               assert.equal(loggedEvents.length, 3);
               assert.equal(loggedEvents[1][0], 'apiUsage');
             }
-            assert.isEmpty(forwardedEvents);
+            assert.equal(forwardEventSpy.callCount, 0);
           });
 
           if (telemetryLevel === 'limited') {
@@ -256,7 +256,7 @@ describe('Telemetry', function() {
               assert.equal(metadata.watchTimeSeconds, 60);
               assert.equal(metadata.userId, 123);
               assert.equal(loggedEvents.length, 3);
-              assert.isEmpty(forwardedEvents);
+              assert.equal(forwardEventSpy.callCount, 0);
             });
           }
         } else {
@@ -267,7 +267,7 @@ describe('Telemetry', function() {
                 limited: {watchTimeSeconds: 30},
               },
             }, chimpy);
-            const [event, metadata] = forwardedEvents[forwardedEvents.length - 1];
+            const [event, metadata] = forwardEventSpy.lastCall.args;
             assert.equal(event, 'watchedVideoTour');
             if (telemetryLevel === 'limited') {
               assert.deepEqual(metadata, {
@@ -283,25 +283,48 @@ describe('Telemetry', function() {
                 'userId',
                 'altSessionId',
               ]);
-              assert.equal(metadata!.watchTimeSeconds, 30);
+              assert.equal(metadata.watchTimeSeconds, 30);
-              assert.equal(metadata!.userId, 1);
+              assert.equal(metadata.userId, 1);
             }
 
             if (telemetryLevel === 'limited') {
-              assert.equal(forwardedEvents.length, 2);
+              assert.equal(forwardEventSpy.callCount, 2);
             } else {
               // The POST above also triggers an "apiUsage" event.
-              assert.equal(forwardedEvents.length, 3);
+              assert.equal(forwardEventSpy.callCount, 3);
-              assert.equal(forwardedEvents[1][0], 'apiUsage');
+              assert.equal(forwardEventSpy.secondCall.args[0], 'apiUsage');
             }
             assert.isEmpty(loggedEvents);
           });
+
+          it('skips forwarding events if too many requests are pending', async function() {
+            let numRequestsMade = 0;
+            postJsonPayloadStub.callsFake(async () => {
+              numRequestsMade += 1;
+              await new Promise(resolve => setTimeout(resolve, 1000));
+            });
+            forwardEventSpy.resetHistory();
+
+            // Log enough events simultaneously to cause some to be skipped. (The limit is 25.)
+            for (let i = 0; i < 30; i++) {
+              void telemetry.logEvent('documentOpened', {
+                limited: {
+                  docIdDigest: 'digest',
+                  isPublic: false,
+                },
+              });
+            }
+
+            // Check that out of the 30 forwardEvent calls, only 25 made POST requests.
+            assert.equal(forwardEventSpy.callCount, 30);
+            assert.equal(numRequestsMade, 25);
+          });
         }
       } else {
         it('does not log telemetry events sent to /api/telemetry', async function() {
           await telemetry.logEvent('apiUsage', {limited: {method: 'GET'}});
           assert.isEmpty(loggedEvents);
-          assert.isEmpty(forwardedEvents);
+          assert.equal(forwardEventSpy.callCount, 0);
         });
       }
     });