(core) Add optional telemetry to grist-core

Summary:
Adds support for optional telemetry to grist-core.

A new environment variable, GRIST_TELEMETRY_LEVEL, controls the level of telemetry collected.

Test Plan: Server and unit tests.

Reviewers: paulfitz

Reviewed By: paulfitz

Subscribers: dsagal, anaisconce

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

test/common/Telemetry.ts

@@ -0,0 +1,215 @@
+import {buildTelemetryEventChecker, filterMetadata, TelemetryEvent} from 'app/common/Telemetry';
+import {assert} from 'chai';
+
+describe('Telemetry', function() {
+  describe('buildTelemetryEventChecker', function() {
+    it('returns a function that checks telemetry data', function() {
+      assert.isFunction(buildTelemetryEventChecker('full'));
+    });
+
+    it('does not throw if event and metadata are valid', function() {
+      const checker = buildTelemetryEventChecker('full');
+      assert.doesNotThrow(() => checker('apiUsage', {
+        method: 'GET',
+        userId: 1,
+        userAgent: 'node-fetch/1.0',
+      }));
+      assert.doesNotThrow(() => checker('siteUsage', {
+        siteId: 1,
+        siteType: 'team',
+        inGoodStanding: true,
+        stripePlanId: 'stripePlanId',
+        numDocs: 1,
+        numWorkspaces: 1,
+        numMembers: 1,
+        lastActivity: new Date('2022-12-30T01:23:45'),
+      }));
+      assert.doesNotThrow(() => checker('watchedVideoTour', {
+        watchTimeSeconds: 30,
+        userId: 1,
+        altSessionId: 'altSessionId',
+      }));
+    });
+
+    it("does not throw when metadata is a subset of what's expected", function() {
+      const checker = buildTelemetryEventChecker('full');
+      assert.doesNotThrow(() => checker('documentUsage', {
+        docIdDigest: 'docIdDigest',
+        siteId: 1,
+        rowCount: 123,
+        attachmentTypes: ['pdf'],
+      }));
+    });
+
+    it('does not throw if all metadata is less than or equal to the expected telemetry level', function() {
+      const checker = buildTelemetryEventChecker('limited');
+      assert.doesNotThrow(() => checker('documentUsage', {
+        rowCount: 123,
+      }));
+      assert.doesNotThrow(() => checker('siteUsage', {
+        siteId: 1,
+        siteType: 'team',
+        inGoodStanding: true,
+        numDocs: 1,
+        numWorkspaces: 1,
+        numMembers: 1,
+        lastActivity: new Date('2022-12-30T01:23:45'),
+      }));
+      assert.doesNotThrow(() => checker('watchedVideoTour', {
+        watchTimeSeconds: 30,
+      }));
+    });
+
+    it('throws if event is invalid', function() {
+      const checker = buildTelemetryEventChecker('full');
+      assert.throws(
+        () => checker('invalidEvent' as TelemetryEvent, {}),
+        /Unknown telemetry event: invalidEvent/
+      );
+    });
+
+    it('throws if metadata is invalid', function() {
+      const checker = buildTelemetryEventChecker('full');
+      assert.throws(
+        () => checker('apiUsage', {invalidMetadata: '123'}),
+        /Unknown metadata for telemetry event apiUsage: invalidMetadata/
+      );
+    });
+
+    it('throws if metadata types do not match expected types', function() {
+      const checker = buildTelemetryEventChecker('full');
+      assert.throws(
+        () => checker('siteUsage', {siteId: '1'}),
+        // eslint-disable-next-line max-len
+        /Telemetry metadata siteId of event siteUsage expected a value of type number but received a value of type string/
+      );
+      assert.throws(
+        () => checker('siteUsage', {lastActivity: 1234567890}),
+        // eslint-disable-next-line max-len
+        /Telemetry metadata lastActivity of event siteUsage expected a value of type Date or string but received a value of type number/
+      );
+      assert.throws(
+        () => checker('siteUsage', {inGoodStanding: 'true'}),
+        // eslint-disable-next-line max-len
+        /Telemetry metadata inGoodStanding of event siteUsage expected a value of type boolean but received a value of type string/
+      );
+      assert.throws(
+        () => checker('siteUsage', {numDocs: '1'}),
+        // eslint-disable-next-line max-len
+        /Telemetry metadata numDocs of event siteUsage expected a value of type number but received a value of type string/
+      );
+      assert.throws(
+        () => checker('documentUsage', {attachmentTypes: '1,2,3'}),
+        // eslint-disable-next-line max-len
+        /Telemetry metadata attachmentTypes of event documentUsage expected a value of type array but received a value of type string/
+      );
+      assert.throws(
+        () => checker('documentUsage', {attachmentTypes: ['.txt', 1, true]}),
+        // eslint-disable-next-line max-len
+        /Telemetry metadata attachmentTypes of event documentUsage expected a value of type string\[\] but received a value of type object\[\]/
+      );
+    });
+
+    it('throws if event requires an elevated telemetry level', function() {
+      const checker = buildTelemetryEventChecker('limited');
+      assert.throws(
+        () => checker('signupVerified', {}),
+        // eslint-disable-next-line max-len
+        /Telemetry event signupVerified requires a minimum telemetry level of 2 but the current level is 1/
+      );
+    });
+
+    it('throws if metadata requires an elevated telemetry level', function() {
+      const checker = buildTelemetryEventChecker('limited');
+      assert.throws(
+        () => checker('watchedVideoTour', {
+          watchTimeSeconds: 30,
+          userId: 1,
+          altSessionId: 'altSessionId',
+        }),
+        // eslint-disable-next-line max-len
+        /Telemetry metadata userId of event watchedVideoTour requires a minimum telemetry level of 2 but the current level is 1/
+      );
+    });
+  });
+
+  describe('filterMetadata', function() {
+    it('returns filtered and flattened metadata when maxLevel is "full"', function() {
+      const metadata = {
+        limited: {
+          foo: 'abc',
+        },
+        full: {
+          bar: '123',
+        },
+      };
+      assert.deepEqual(filterMetadata(metadata, 'full'), {
+        foo: 'abc',
+        bar: '123',
+      });
+    });
+
+    it('returns filtered and flattened metadata when maxLevel is "limited"', function() {
+      const metadata = {
+        limited: {
+          foo: 'abc',
+        },
+        full: {
+          bar: '123',
+        },
+      };
+      assert.deepEqual(filterMetadata(metadata, 'limited'), {
+        foo: 'abc',
+      });
+    });
+
+    it('returns undefined when maxLevel is "off"', function() {
+      assert.isUndefined(filterMetadata(undefined, 'off'));
+    });
+
+    it('returns an empty object when metadata is empty', function() {
+      assert.isEmpty(filterMetadata({}, 'full'));
+    });
+
+    it('returns undefined when metadata is undefined', function() {
+      assert.isUndefined(filterMetadata(undefined, 'full'));
+    });
+
+    it('does not mutate metadata', function() {
+      const metadata = {
+        limited: {
+          foo: 'abc',
+        },
+        full: {
+          bar: '123',
+        },
+      };
+      filterMetadata(metadata, 'limited');
+      assert.deepEqual(metadata, {
+        limited: {
+          foo: 'abc',
+        },
+        full: {
+          bar: '123',
+        },
+      });
+    });
+
+    it('excludes keys with nullish values', function() {
+      const metadata = {
+        limited: {
+          foo1: null,
+          foo2: 'abc',
+        },
+        full: {
+          bar1: undefined,
+          bar2: '123',
+        },
+      };
+      assert.deepEqual(filterMetadata(metadata, 'full'), {
+        foo2: 'abc',
+        bar2: '123',
+      });
+    });
+  });
+});

test/nbrowser/testServer.ts

@@ -205,7 +205,11 @@ export class TestServerMerged implements IMochaServer {
     }
     const state: IGristUrlState = { org: team };
     const baseDomain = parseSubdomain(new URL(this.getHost()).hostname).base;
-    const gristConfig = makeGristConfig(this.getHost(), {}, baseDomain);
+    const gristConfig = makeGristConfig({
+      homeUrl: this.getHost(),
+      extra: {},
+      baseDomain,
+    });
     const url = encodeUrl(gristConfig, state, new URL(this.getHost())).replace(/\/$/, "");
     return `${url}${relPath}`;
   }

test/server/lib/Authorizer.ts

@@ -34,7 +34,7 @@ async function activateServer(home: FlexServer, docManager: DocManager) {
   home.addJsonSupport();
   await home.addLandingPages();
   home.addHomeApi();
-  home.addTelemetryEndpoint();
+  home.addTelemetry();
   await home.addDoc();
   home.addApiErrorHandlers();
   serverUrl = home.getOwnUrl();

test/server/lib/Telemetry.ts

@@ -0,0 +1,309 @@
+import {GristDeploymentType} from 'app/common/gristUrls';
+import {TelemetryEvent, TelemetryLevel, TelemetryMetadata} from 'app/common/Telemetry';
+import {ILogMeta, LogMethods} from 'app/server/lib/LogMethods';
+import {ITelemetry, Telemetry} from 'app/server/lib/Telemetry';
+import axios from 'axios';
+import {assert} from 'chai';
+import * as sinon from 'sinon';
+import {TestServer} from 'test/gen-server/apiUtils';
+import {configForUser} from 'test/gen-server/testUtils';
+
+const chimpy = configForUser('Chimpy');
+const anon = configForUser('Anonymous');
+
+describe('Telemetry', function() {
+  const deploymentTypesAndTelemetryLevels: [GristDeploymentType, TelemetryLevel][] = [
+    ['saas', 'off'],
+    ['saas', 'limited'],
+    ['saas', 'full'],
+    ['core', 'off'],
+    ['core', 'limited'],
+    ['core', 'full'],
+  ];
+
+  for (const [deploymentType, telemetryLevel] of deploymentTypesAndTelemetryLevels) {
+    describe(`in grist-${deploymentType} with a telemetry level of "${telemetryLevel}"`, function() {
+      let homeUrl: string;
+      let installationId: string;
+      let server: TestServer;
+      let telemetry: ITelemetry;
+
+      const sandbox = sinon.createSandbox();
+      const loggedEvents: [TelemetryEvent, ILogMeta][] = [];
+      const forwardedEvents: [TelemetryEvent, TelemetryMetadata | undefined][] = [];
+
+      before(async function() {
+        process.env.GRIST_TEST_SERVER_DEPLOYMENT_TYPE = deploymentType;
+        process.env.GRIST_TELEMETRY_LEVEL = telemetryLevel;
+        server = new TestServer(this);
+        homeUrl = await server.start();
+        installationId = (await server.server.getActivations().current()).id;
+        sandbox
+          .stub(LogMethods.prototype, 'rawLog')
+          .callsFake((_level: string, _info: unknown, name: string, meta: ILogMeta) => {
+            loggedEvents.push([name as TelemetryEvent, meta]);
+          });
+        sandbox
+          .stub(Telemetry.prototype, 'forwardEvent')
+          .callsFake((event: TelemetryEvent, metadata?: TelemetryMetadata) => {
+            forwardedEvents.push([event, metadata]);
+          });
+        telemetry = server.server.getTelemetry();
+      });
+
+      after(async function() {
+        await server.stop();
+        sandbox.restore();
+        delete process.env.GRIST_TEST_SERVER_DEPLOYMENT_TYPE;
+        delete process.env.GRIST_TELEMETRY_LEVEL;
+      });
+
+      it('returns the current telemetry level', async function() {
+        assert.equal(telemetry.getTelemetryLevel(), telemetryLevel);
+      });
+
+      if (telemetryLevel !== 'off') {
+        if (deploymentType === 'saas') {
+          it('logs telemetry events', async function() {
+            if (telemetryLevel === 'limited') {
+              await telemetry.logEvent('documentOpened', {
+                limited: {
+                  docIdDigest: 'digest',
+                  isPublic: false,
+                },
+              });
+              assert.deepEqual(loggedEvents[loggedEvents.length - 1], [
+                'documentOpened',
+                {
+                  eventName: 'documentOpened',
+                  eventSource: `grist-${deploymentType}`,
+                  docIdDigest: 'digest',
+                  isPublic: false,
+                }
+              ]);
+            }
+
+            if (telemetryLevel === 'full') {
+              await telemetry.logEvent('documentOpened', {
+                limited: {
+                  docIdDigest: 'digest',
+                  isPublic: false,
+                },
+                full: {
+                  userId: 1,
+                },
+              });
+              assert.deepEqual(loggedEvents[loggedEvents.length - 1], [
+                'documentOpened',
+                {
+                  eventName: 'documentOpened',
+                  eventSource: `grist-${deploymentType}`,
+                  docIdDigest: 'digest',
+                  isPublic: false,
+                  userId: 1,
+                }
+              ]);
+            }
+
+            assert.equal(loggedEvents.length, 1);
+            assert.isEmpty(forwardedEvents);
+          });
+        } else {
+          it('forwards telemetry events', async function() {
+            if (telemetryLevel === 'limited') {
+              await telemetry.logEvent('documentOpened', {
+                limited: {
+                  docIdDigest: 'digest',
+                  isPublic: false,
+                },
+              });
+              assert.deepEqual(forwardedEvents[forwardedEvents.length - 1], [
+                'documentOpened',
+                {
+                  docIdDigest: 'digest',
+                  isPublic: false,
+                }
+              ]);
+            }
+
+            if (telemetryLevel === 'full') {
+              await telemetry.logEvent('documentOpened', {
+                limited: {
+                  docIdDigest: 'digest',
+                  isPublic: false,
+                },
+                full: {
+                  userId: 1,
+                },
+              });
+              assert.deepEqual(forwardedEvents[forwardedEvents.length - 1], [
+                'documentOpened',
+                {
+                  docIdDigest: 'digest',
+                  isPublic: false,
+                  userId: 1,
+                }
+              ]);
+            }
+
+            assert.equal(forwardedEvents.length, 1);
+            assert.isEmpty(loggedEvents);
+          });
+        }
+      } else {
+        it('does not log telemetry events', async function() {
+          await telemetry.logEvent('documentOpened', {
+            limited: {
+              docIdDigest: 'digest',
+              isPublic: false,
+            },
+          });
+          assert.isEmpty(loggedEvents);
+          assert.isEmpty(forwardedEvents);
+        });
+      }
+
+      if (telemetryLevel !== 'off') {
+        it('throws an error when an event is invalid', async function() {
+          await assert.isRejected(
+            telemetry.logEvent('invalidEvent' as TelemetryEvent, {limited: {method: 'GET'}}),
+            /Unknown telemetry event: invalidEvent/
+          );
+        });
+
+        it("throws an error when an event's metadata is invalid", async function() {
+          await assert.isRejected(
+            telemetry.logEvent('documentOpened', {limited: {invalidMetadata: 'GET'}}),
+            /Unknown metadata for telemetry event documentOpened: invalidMetadata/
+          );
+        });
+
+        if (telemetryLevel === 'limited') {
+          it('throws an error when an event requires an elevated telemetry level', async function() {
+            await assert.isRejected(
+              telemetry.logEvent('signupVerified', {}),
+              /Telemetry event signupVerified requires a minimum telemetry level of 2 but the current level is 1/
+            );
+          });
+
+          it("throws an error when an event's metadata requires an elevated telemetry level", async function() {
+            await assert.isRejected(
+              telemetry.logEvent('documentOpened', {limited: {userId: 1}}),
+              // eslint-disable-next-line max-len
+              /Telemetry metadata userId of event documentOpened requires a minimum telemetry level of 2 but the current level is 1/
+            );
+          });
+        }
+      }
+
+      if (telemetryLevel !== 'off') {
+        if (deploymentType === 'saas') {
+          it('logs telemetry events sent to /api/telemetry', async function() {
+            await axios.post(`${homeUrl}/api/telemetry`, {
+              event: 'watchedVideoTour',
+              metadata: {
+                limited: {watchTimeSeconds: 30},
+              },
+            }, chimpy);
+            const [event, metadata] = loggedEvents[loggedEvents.length - 1];
+            assert.equal(event, 'watchedVideoTour');
+            if (telemetryLevel === 'limited') {
+              assert.deepEqual(metadata, {
+                eventName: 'watchedVideoTour',
+                eventSource: `grist-${deploymentType}`,
+                watchTimeSeconds: 30,
+              });
+            } else {
+              assert.containsAllKeys(metadata, [
+                'eventSource',
+                'watchTimeSeconds',
+                'userId',
+                'altSessionId',
+              ]);
+              assert.equal(metadata.watchTimeSeconds, 30);
+              assert.equal(metadata.userId, 1);
+            }
+
+            if (telemetryLevel === 'limited') {
+              assert.equal(loggedEvents.length, 2);
+            } else {
+              // The POST above also triggers an "apiUsage" event.
+              assert.equal(loggedEvents.length, 3);
+              assert.equal(loggedEvents[1][0], 'apiUsage');
+            }
+            assert.isEmpty(forwardedEvents);
+          });
+
+          if (telemetryLevel === 'limited') {
+            it('skips checks if event sent to /api/telemetry is from an external source', async function() {
+              await axios.post(`${homeUrl}/api/telemetry`, {
+                event: 'watchedVideoTour',
+                metadata: {
+                  eventSource: 'grist-core',
+                  watchTimeSeconds: 60,
+                  userId: 123,
+                  altSessionId: 'altSessionId',
+                },
+              }, anon);
+              const [event, metadata] = loggedEvents[loggedEvents.length - 1];
+              assert.equal(event, 'watchedVideoTour');
+              assert.containsAllKeys(metadata, [
+                'eventSource',
+                'watchTimeSeconds',
+                'userId',
+                'altSessionId',
+              ]);
+              assert.equal(metadata.watchTimeSeconds, 60);
+              assert.equal(metadata.userId, 123);
+              assert.equal(loggedEvents.length, 3);
+              assert.isEmpty(forwardedEvents);
+            });
+          }
+        } else {
+          it('forwards telemetry events sent to /api/telemetry', async function() {
+            await axios.post(`${homeUrl}/api/telemetry`, {
+              event: 'watchedVideoTour',
+              metadata: {
+                limited: {watchTimeSeconds: 30},
+              },
+            }, chimpy);
+            const [event, metadata] = forwardedEvents[forwardedEvents.length - 1];
+            assert.equal(event, 'watchedVideoTour');
+            if (telemetryLevel === 'limited') {
+              assert.deepEqual(metadata, {
+                eventSource: `grist-${deploymentType}`,
+                installationId,
+                watchTimeSeconds: 30,
+              });
+            } else {
+              assert.containsAllKeys(metadata, [
+                'eventSource',
+                'installationId',
+                'watchTimeSeconds',
+                'userId',
+                'altSessionId',
+              ]);
+              assert.equal(metadata!.watchTimeSeconds, 30);
+              assert.equal(metadata!.userId, 1);
+            }
+
+            if (telemetryLevel === 'limited') {
+              assert.equal(forwardedEvents.length, 2);
+            } else {
+              // The POST above also triggers an "apiUsage" event.
+              assert.equal(forwardedEvents.length, 3);
+              assert.equal(forwardedEvents[1][0], 'apiUsage');
+            }
+            assert.isEmpty(loggedEvents);
+          });
+        }
+      } 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);
+        });
+      }
+    });
+  }
+});