gristlabs_grist-core/test/server/lib/Telemetry.ts

import {GristDeploymentType} from 'app/common/gristUrls';
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';
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;
      let forwardEventSpy: sinon.SinonSpy;
      let postJsonPayloadStub: sinon.SinonStub;

      const sandbox = sinon.createSandbox();
      const loggedEvents: [TelemetryEvent, ILogMeta][] = [];

      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]);
          });
        forwardEventSpy = sandbox
          .spy(Telemetry.prototype as any, '_forwardEvent');
        postJsonPayloadStub = sandbox
          .stub(Telemetry.prototype as any, '_postJsonPayload');
        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.equal(forwardEventSpy.callCount, 0);
          });
        } else {
          it('forwards telemetry events', async function() {
            if (telemetryLevel === 'limited') {
              await telemetry.logEvent('documentOpened', {
                limited: {
                  docIdDigest: 'digest',
                  isPublic: false,
                },
              });
              assert.deepEqual(forwardEventSpy.lastCall.args, [
                'documentOpened',
                {
                  docIdDigest: 'digest',
                  isPublic: false,
                }
              ]);
            }

            if (telemetryLevel === 'full') {
              await telemetry.logEvent('documentOpened', {
                limited: {
                  docIdDigest: 'digest',
                  isPublic: false,
                },
                full: {
                  userId: 1,
                },
              });
              assert.deepEqual(forwardEventSpy.lastCall.args, [
                'documentOpened',
                {
                  docIdDigest: 'digest',
                  isPublic: false,
                  userId: 1,
                }
              ]);
            }

            assert.equal(forwardEventSpy.callCount, 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.equal(forwardEventSpy.callCount, 0);
        });
      }

      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.equal(forwardEventSpy.callCount, 0);
          });

          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.equal(forwardEventSpy.callCount, 0);
            });
          }
        } 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] = forwardEventSpy.lastCall.args;
            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(forwardEventSpy.callCount, 2);
            } else {
              // The POST above also triggers an "apiUsage" event.
              assert.equal(forwardEventSpy.callCount, 3);
              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.equal(forwardEventSpy.callCount, 0);
        });
      }
    });
  }
});