(core) Add new telemetry events

Summary: Adds a handful of new telemetry events, and makes a few tweaks to allow for better organization of telemetry. Test Plan: Manual. Reviewers: paulfitz Reviewed By: paulfitz Differential Revision: https://phab.getgrist.com/D4100
2026-03-02 04:09:24 +00:00 · 2023-11-01 09:54:19 -04:00
parent 51f7402297
commit 7a85aaa7a1
19 changed files with 523 additions and 129 deletions
--- a/app/server/lib/ActiveDoc.ts
+++ b/app/server/lib/ActiveDoc.ts
@@ -89,7 +89,6 @@ import {Authorizer, RequestWithLogin} from 'app/server/lib/Authorizer';
 import {checksumFile} from 'app/server/lib/checksumFile';
 import {Client} from 'app/server/lib/Client';
 import {DEFAULT_CACHE_TTL, DocManager} from 'app/server/lib/DocManager';
-import {getTemplateOrg} from 'app/server/lib/gristSettings';
 import {ICreateActiveDocOptions} from 'app/server/lib/ICreate';
 import {makeForkIds} from 'app/server/lib/idUtils';
 import {GRIST_DOC_SQL, GRIST_DOC_WITH_TABLE1_SQL} from 'app/server/lib/initialDocSql';
@@ -1420,9 +1419,7 @@ export class ActiveDoc extends EventEmitter {

      await dbManager.forkDoc(userId, doc, forkIds.forkId);

-      // TODO: Remove the right side once all template docs have their type set to "template".
-      const isTemplate = doc.type === 'template' ||
-        (doc.workspace.org.domain === getTemplateOrg() && doc.type !== 'tutorial');
+      const isTemplate = doc.type === 'template';
      this.logTelemetryEvent(docSession, 'documentForked', {
        limited: {
          forkIdDigest: forkIds.forkId,
@@ -1827,11 +1824,10 @@ export class ActiveDoc extends EventEmitter {
    event: TelemetryEvent,
    metadata?: TelemetryMetadataByLevel
  ) {
-    this._docManager.gristServer.getTelemetry().logEvent(event, merge(
+    this._docManager.gristServer.getTelemetry().logEvent(docSession, event, merge(
      this._getTelemetryMeta(docSession),
      metadata,
-    ))
-    .catch(e => this._log.error(docSession, `failed to log telemetry event ${event}`, e));
+    ));
  }

  /**
--- a/app/server/lib/AppEndpoint.ts
+++ b/app/server/lib/AppEndpoint.ts
@@ -19,7 +19,6 @@ import {customizeDocWorkerUrl, getWorker, useWorkerPool} from 'app/server/lib/Do
 import {expressWrap} from 'app/server/lib/expressWrap';
 import {DocTemplate, GristServer} from 'app/server/lib/GristServer';
 import {getCookieDomain} from 'app/server/lib/gristSessions';
-import {getTemplateOrg} from 'app/server/lib/gristSettings';
 import {getAssignmentId} from 'app/server/lib/idUtils';
 import log from 'app/server/lib/log';
 import {addOrgToPathIfNeeded, pruneAPIResult, trustOrigin} from 'app/server/lib/requestUtils';
@@ -165,11 +164,9 @@ export function attachAppEndpoint(options: AttachOptions): void {

    const isPublic = ((doc as unknown) as APIDocument).public ?? false;
    const isSnapshot = Boolean(parseUrlId(urlId).snapshotId);
-    // TODO: Remove the right side once all template docs have their type set to "template".
-    const isTemplate = doc.type === 'template' ||
-      (doc.workspace.org.domain === getTemplateOrg() && doc.type !== 'tutorial');
+    const isTemplate = doc.type === 'template';
    if (isPublic || isTemplate) {
-      gristServer.getTelemetry().logEvent('documentOpened', {
+      gristServer.getTelemetry().logEvent(mreq, 'documentOpened', {
        limited: {
          docIdDigest: docId,
          access: doc.access,
@@ -184,8 +181,7 @@ export function attachAppEndpoint(options: AttachOptions): void {
          userId: mreq.userId,
          altSessionId: mreq.altSessionId,
        },
-      })
-      .catch(e => log.error('failed to log telemetry event documentOpened', e));
+      });
    }

    if (isTemplate) {
--- a/app/server/lib/Authorizer.ts
+++ b/app/server/lib/Authorizer.ts
@@ -397,14 +397,13 @@ export async function addRequestUser(dbManager: HomeDBManager, permitStore: IPer
  };
  log.rawDebug(`Auth[${meta.method}]: ${meta.host} ${meta.path}`, meta);
  if (hasApiKey) {
-    options.gristServer.getTelemetry().logEvent('apiUsage', {
+    options.gristServer.getTelemetry().logEvent(mreq, 'apiUsage', {
      full: {
        method: mreq.method,
        userId: mreq.userId,
        userAgent: mreq.headers['user-agent'],
      },
-    })
-    .catch(e => log.error('failed to log telemetry event apiUsage', e));
+    });
  }

  return next();
--- a/app/server/lib/DocApi.ts
+++ b/app/server/lib/DocApi.ts
@@ -1044,7 +1044,7 @@ export class DocWorkerApi {
          const tutorialTrunkId = options.sourceDocId;
          await this._dbManager.connection.transaction(async (manager) => {
            // Fetch the tutorial trunk doc so we can replace the tutorial doc's name.
-            const tutorialTrunk = await this._dbManager.getRawDocById(tutorialTrunkId, manager);
+            const tutorialTrunk = await this._dbManager.getDoc({...scope, urlId: tutorialTrunkId}, manager);
            await this._dbManager.updateDocument(
              scope,
              {
@@ -1152,7 +1152,7 @@ export class DocWorkerApi {
      const userId = getUserId(req);
      const wsId = integerParam(req.params.wid, 'wid');
      const uploadId = integerParam(req.body.uploadId, 'uploadId');
-      const result = await this._docManager.importDocToWorkspace({
+      const result = await this._docManager.importDocToWorkspace(mreq, {
        userId,
        uploadId,
        workspaceId: wsId,
@@ -1284,7 +1284,7 @@ export class DocWorkerApi {
          asTemplate: optBooleanParam(parameters.asTemplate, 'asTemplate'),
        });
      } else if (uploadId !== undefined) {
-        const result = await this._docManager.importDocToWorkspace({
+        const result = await this._docManager.importDocToWorkspace(mreq, {
          userId,
          uploadId,
          documentName: optStringParam(parameters.documentName, 'documentName'),
@@ -1343,7 +1343,7 @@ export class DocWorkerApi {
    }

    // Then, import the copy to the workspace.
-    const result = await this._docManager.importDocToWorkspace({
+    const result = await this._docManager.importDocToWorkspace(mreq, {
      userId,
      uploadId: uploadResult.uploadId,
      documentName,
@@ -1419,13 +1419,12 @@ export class DocWorkerApi {

  private _logDocumentCreatedTelemetryEvent(req: Request, metadata: TelemetryMetadataByLevel) {
    const mreq = req as RequestWithLogin;
-    this._grist.getTelemetry().logEvent('documentCreated', _.merge({
+    this._grist.getTelemetry().logEvent(mreq, 'documentCreated', _.merge({
      full: {
        userId: mreq.userId,
        altSessionId: mreq.altSessionId,
      },
-    }, metadata))
-    .catch(e => log.error('failed to log telemetry event documentCreated', e));
+    }, metadata));
  }

  /**
--- a/app/server/lib/DocManager.ts
+++ b/app/server/lib/DocManager.ts
@@ -15,7 +15,8 @@ import {tbind} from 'app/common/tbind';
 import {TelemetryMetadataByLevel} from 'app/common/Telemetry';
 import {NEW_DOCUMENT_CODE} from 'app/common/UserAPI';
 import {HomeDBManager} from 'app/gen-server/lib/HomeDBManager';
-import {assertAccess, Authorizer, DocAuthorizer, DummyAuthorizer, isSingleUserMode} from 'app/server/lib/Authorizer';
+import {assertAccess, Authorizer, DocAuthorizer, DummyAuthorizer, isSingleUserMode,
+        RequestWithLogin} from 'app/server/lib/Authorizer';
 import {Client} from 'app/server/lib/Client';
 import {
  getDocSessionCachedDoc,
@@ -198,7 +199,7 @@ export class DocManager extends EventEmitter {
   *
   * Cleans up `uploadId` and returns creation info about the imported doc.
   */
-  public async importDocToWorkspace(options: {
+  public async importDocToWorkspace(mreq: RequestWithLogin, options: {
    userId: number,
    uploadId: number,
    documentName?: string,
@@ -232,14 +233,13 @@ export class DocManager extends EventEmitter {
      userId,
    });

-    this.gristServer.getTelemetry().logEvent('documentCreated', merge({
+    this.gristServer.getTelemetry().logEvent(mreq, 'documentCreated', merge({
      limited: {
        docIdDigest: docCreationInfo.id,
        fileType: uploadInfo.files[0].ext.trim().slice(1),
        isSaved: workspaceId !== undefined,
      },
-    }, telemetryMetadata))
-    .catch(e => log.error('failed to log telemetry event documentCreated', e));
+    }, telemetryMetadata));

    return docCreationInfo;
    // The imported document is associated with the worker that did the import.
--- a/app/server/lib/FlexServer.ts
+++ b/app/server/lib/FlexServer.ts
@@ -1309,6 +1309,7 @@ export class FlexServer implements GristServer {
        // to other (not public) team sites.
        const doom = await createDoom(req);
        await doom.deleteUser(userId);
+        this.getTelemetry().logEvent(req as RequestWithLogin, 'deletedAccount');
        return resp.status(200).json(true);
      }));

@@ -1341,6 +1342,14 @@ export class FlexServer implements GristServer {
        // Reuse Doom cli tool for org deletion. Note, this removes everything as a super user.
        const doom = await createDoom(req);
        await doom.deleteOrg(org.id);
+
+        this.getTelemetry().logEvent(req as RequestWithLogin, 'deletedSite', {
+          full: {
+            siteId: org.id,
+            userId: mreq.userId,
+          },
+        });
+
        return resp.status(200).send();
      }));
    }
@@ -1442,14 +1451,15 @@ export class FlexServer implements GristServer {
        // If we failed to record, at least log the data, so we could potentially recover it.
        log.rawWarn(`Failed to record new user info: ${e.message}`, {newUserQuestions: row});
      });
-      this.getTelemetry().logEvent('welcomeQuestionsSubmitted', {
-        full: {
-          userId,
-          useCases,
-          useOther,
-        },
-      })
-      .catch(e => log.error('failed to log telemetry event welcomeQuestionsSubmitted', e));
+      const nonOtherUseCases = useCases.filter(useCase => useCase !== 'Other');
+      for (const useCase of [...nonOtherUseCases, ...(useOther ? [`Other - ${useOther}`] : [])]) {
+        this.getTelemetry().logEvent(req as RequestWithLogin, 'answeredUseCaseQuestion', {
+          full: {
+            userId,
+            useCase,
+          },
+        });
+      }

      resp.status(200).send();
    }), jsonErrorHandler); // Add a final error handler that reports errors as JSON.
--- a/app/server/lib/GristServer.ts
+++ b/app/server/lib/GristServer.ts
@@ -154,7 +154,8 @@ export function createDummyTelemetry(): ITelemetry {
    addEndpoints() { /* do nothing */ },
    addPages() { /* do nothing */ },
    start() { return Promise.resolve(); },
-    logEvent() { return Promise.resolve(); },
+    logEvent() { /* do nothing */ },
+    logEventAsync() { return Promise.resolve(); },
    getTelemetryConfig() { return undefined; },
    fetchTelemetryPrefs() { return Promise.resolve(); },
  };
--- a/app/server/lib/ProcessMonitor.ts
+++ b/app/server/lib/ProcessMonitor.ts
@@ -1,4 +1,3 @@
-import log from 'app/server/lib/log';
 import { ITelemetry } from 'app/server/lib/Telemetry';

 const MONITOR_PERIOD_MS = 5_000;        // take a look at memory usage this often
@@ -67,15 +66,14 @@ function monitor(telemetry: ITelemetry) {
    Math.abs(heapUsed - _lastReportedHeapUsed) > _lastReportedHeapUsed * MEMORY_DELTA_FRACTION ||
    Math.abs(cpuAverage - _lastReportedCpuAverage) > CPU_DELTA_FRACTION
  ) {
-    telemetry.logEvent('processMonitor', {
+    telemetry.logEvent(null, 'processMonitor', {
      full: {
        heapUsedMB: Math.round(memoryUsage.heapUsed/1024/1024),
        heapTotalMB: Math.round(memoryUsage.heapTotal/1024/1024),
        cpuAverage: Math.round(cpuAverage * 100) / 100,
        intervalMs,
      },
-    })
-    .catch(e => log.error('failed to log telemetry event processMonitor', e));
+    });
    _lastReportedHeapUsed = heapUsed;
    _lastReportedCpuAverage = cpuAverage;
    _lastReportTime = now;
--- a/app/server/lib/Telemetry.ts
+++ b/app/server/lib/Telemetry.ts
@@ -19,22 +19,35 @@ import {Activation} from 'app/gen-server/entity/Activation';
 import {Activations} from 'app/gen-server/lib/Activations';
 import {HomeDBManager} from 'app/gen-server/lib/HomeDBManager';
 import {RequestWithLogin} from 'app/server/lib/Authorizer';
+import {getDocSessionUser, OptDocSession} from 'app/server/lib/DocSession';
 import {expressWrap} from 'app/server/lib/expressWrap';
 import {GristServer} from 'app/server/lib/GristServer';
 import {hashId} from 'app/server/lib/hashingUtils';
 import {LogMethods} from 'app/server/lib/LogMethods';
 import {stringParam} from 'app/server/lib/requestUtils';
+import {getLogMetaFromDocSession} from 'app/server/lib/serverUtils';
 import * as express from 'express';
 import fetch from 'node-fetch';
 import merge = require('lodash/merge');
 import pickBy = require('lodash/pickBy');

+type RequestOrSession = RequestWithLogin | OptDocSession | null;
+
 export interface ITelemetry {
  start(): Promise<void>;
-  logEvent(name: TelemetryEvent, metadata?: TelemetryMetadataByLevel): Promise<void>;
+  logEvent(
+    requestOrSession: RequestOrSession,
+    name: TelemetryEvent,
+    metadata?: TelemetryMetadataByLevel
+  ): void;
+  logEventAsync(
+    requestOrSession: RequestOrSession,
+    name: TelemetryEvent,
+    metadata?: TelemetryMetadataByLevel
+  ): Promise<void>;
  addEndpoints(app: express.Express): void;
  addPages(app: express.Express, middleware: express.RequestHandler[]): void;
-  getTelemetryConfig(): TelemetryConfig | undefined;
+  getTelemetryConfig(requestOrSession?: RequestOrSession): TelemetryConfig | undefined;
  fetchTelemetryPrefs(): Promise<void>;
 }

@@ -51,7 +64,8 @@ export class Telemetry implements ITelemetry {
  private readonly _forwardTelemetryEventsUrl = process.env.GRIST_TELEMETRY_URL ||
    'https://telemetry.getgrist.com/api/telemetry';
  private _numPendingForwardEventRequests = 0;
-  private readonly _logger = new LogMethods('Telemetry ', () => ({}));
+  private readonly _logger = new LogMethods('Telemetry ', (requestOrSession: RequestOrSession | undefined) =>
+    this._getLogMeta(requestOrSession));
  private readonly _telemetryLogger = new LogMethods<string>('Telemetry ', (eventType) => ({
    eventType,
  }));
@@ -105,34 +119,27 @@ export class Telemetry implements ITelemetry {
   * });
   * ```
   */
-  public async logEvent(
+  public async logEventAsync(
+    requestOrSession: RequestOrSession,
    event: TelemetryEvent,
    metadata?: TelemetryMetadataByLevel
  ) {
-    if (!this._checkTelemetryEvent) {
-      this._logger.error(undefined, 'logEvent called but telemetry event checker is undefined');
-      return;
-    }
+    await this._checkAndLogEvent(requestOrSession, event, metadata);
+  }

-    const prefs = this._telemetryPrefs;
-    if (!prefs) {
-      this._logger.error(undefined, 'logEvent called but telemetry preferences are undefined');
-      return;
-    }
-
-    const {telemetryLevel} = prefs;
-    if (TelemetryContracts[event] && TelemetryContracts[event].minimumTelemetryLevel > Level[telemetryLevel.value]) {
-      return;
-    }
-
-    metadata = filterMetadata(metadata, telemetryLevel.value);
-    this._checkTelemetryEvent(event, metadata);
-
-    if (this._shouldForwardTelemetryEvents) {
-      await this._forwardEvent(event, metadata);
-    } else {
-      this._logEvent(event, metadata);
-    }
+  /**
+   * Non-async variant of `logEventAsync`.
+   *
+   * Convenient for fire-and-forget usage.
+   */
+  public logEvent(
+    requestOrSession: RequestOrSession,
+    event: TelemetryEvent,
+    metadata?: TelemetryMetadataByLevel
+  ) {
+    this.logEventAsync(requestOrSession, event, metadata).catch((e) => {
+      this._logger.error(requestOrSession, `failed to log telemetry event ${event}`, e);
+    });
  }

  public addEndpoints(app: express.Application) {
@@ -151,7 +158,7 @@ export class Telemetry implements ITelemetry {
    app.post('/api/telemetry', expressWrap(async (req, resp) => {
      const mreq = req as RequestWithLogin;
      const event = stringParam(req.body.event, 'event', {allowed: TelemetryEvents.values}) as TelemetryEvent;
-      if ('eventSource' in req.body.metadata) {
+      if ('eventSource' in (req.body.metadata ?? {})) {
        this._telemetryLogger.rawLog('info', getEventType(event), event, {
          ...(removeNullishKeys(req.body.metadata)),
          eventName: event,
@@ -159,7 +166,7 @@ export class Telemetry implements ITelemetry {
      } else {
        try {
          this._assertTelemetryIsReady();
-          await this.logEvent(event, merge(
+          await this._checkAndLogEvent(mreq, event, merge(
            {
              full: {
                userId: mreq.userId,
@@ -169,7 +176,7 @@ export class Telemetry implements ITelemetry {
            req.body.metadata,
          ));
        } catch (e) {
-          this._logger.error(undefined, `failed to log telemetry event ${event}`, e);
+          this._logger.error(mreq, `failed to log telemetry event ${event}`, e);
          throw new ApiError(`Telemetry failed to log telemetry event ${event}`, 500);
        }
      }
@@ -186,10 +193,10 @@ export class Telemetry implements ITelemetry {
    }
  }

-  public getTelemetryConfig(): TelemetryConfig | undefined {
+  public getTelemetryConfig(requestOrSession?: RequestOrSession): TelemetryConfig | undefined {
    const prefs = this._telemetryPrefs;
    if (!prefs) {
-      this._logger.error(undefined, 'getTelemetryConfig called but telemetry preferences are undefined');
+      this._logger.error(requestOrSession, 'getTelemetryConfig called but telemetry preferences are undefined');
      return undefined;
    }

@@ -208,41 +215,88 @@ export class Telemetry implements ITelemetry {
    this._checkTelemetryEvent = buildTelemetryEventChecker(this._telemetryPrefs.telemetryLevel.value);
  }

+  private async _checkAndLogEvent(
+    requestOrSession: RequestOrSession,
+    event: TelemetryEvent,
+    metadata?: TelemetryMetadataByLevel
+  ) {
+    if (!this._checkTelemetryEvent) {
+      this._logger.error(null, 'logEvent called but telemetry event checker is undefined');
+      return;
+    }
+
+    const prefs = this._telemetryPrefs;
+    if (!prefs) {
+      this._logger.error(null, 'logEvent called but telemetry preferences are undefined');
+      return;
+    }
+
+    const {telemetryLevel} = prefs;
+    if (TelemetryContracts[event] && TelemetryContracts[event].minimumTelemetryLevel > Level[telemetryLevel.value]) {
+      return;
+    }
+
+    metadata = filterMetadata(metadata, telemetryLevel.value);
+    this._checkTelemetryEvent(event, metadata);
+
+    if (this._shouldForwardTelemetryEvents) {
+      await this._forwardEvent(requestOrSession, event, metadata);
+    } else {
+      this._logEvent(requestOrSession, event, metadata);
+    }
+  }
+
  private _logEvent(
+    requestOrSession: RequestOrSession,
    event: TelemetryEvent,
    metadata?: TelemetryMetadata
  ) {
+    let isInternalUser: boolean | undefined;
+    if (requestOrSession) {
+      const email = ('get' in requestOrSession)
+        ? requestOrSession.user?.loginEmail
+        : getDocSessionUser(requestOrSession)?.email;
+      if (email) {
+        isInternalUser = email !== 'anon@getgrist.com' && email.endsWith('@getgrist.com');
+      }
+    }
+    const {category: eventCategory} = TelemetryContracts[event];
    this._telemetryLogger.rawLog('info', getEventType(event), event, {
      ...metadata,
      eventName: event,
+      ...(eventCategory !== undefined ? {eventCategory} : undefined),
      eventSource: `grist-${this._deploymentType}`,
      installationId: this._activation!.id,
+      ...(isInternalUser !== undefined ? {isInternalUser} : undefined),
    });
  }

  private async _forwardEvent(
+    requestOrSession: RequestOrSession,
    event: TelemetryEvent,
    metadata?: TelemetryMetadata
  ) {
    if (this._numPendingForwardEventRequests === MAX_PENDING_FORWARD_EVENT_REQUESTS) {
-      this._logger.warn(undefined, 'exceeded the maximum number of pending forwardEvent calls '
+      this._logger.warn(requestOrSession, 'exceeded the maximum number of pending forwardEvent calls '
        + `(${MAX_PENDING_FORWARD_EVENT_REQUESTS}). Skipping forwarding of event ${event}.`);
      return;
    }

    try {
      this._numPendingForwardEventRequests += 1;
+      const {category: eventCategory} = TelemetryContracts[event];
      await this._doForwardEvent(JSON.stringify({
        event,
        metadata: {
          ...metadata,
          eventName: event,
+          ...(eventCategory !== undefined ? {eventCategory} : undefined),
          eventSource: `grist-${this._deploymentType}`,
          installationId: this._activation!.id,
-        }
+        },
      }));
    } catch (e) {
-      this._logger.error(undefined, `failed to forward telemetry event ${event}`, e);
+      this._logger.error(requestOrSession, `failed to forward telemetry event ${event}`, e);
    } finally {
      this._numPendingForwardEventRequests -= 1;
    }
@@ -266,6 +320,21 @@ export class Telemetry implements ITelemetry {
      throw new ApiError('Telemetry is not ready', 500);
    }
  }
+
+  private _getLogMeta(requestOrSession?: RequestOrSession) {
+    if (!requestOrSession) { return {}; }
+
+    if ('get' in requestOrSession) {
+      return {
+        org: requestOrSession.org,
+        email: requestOrSession.user?.loginEmail,
+        userId: requestOrSession.userId,
+        altSessionId: requestOrSession.altSessionId,
+      };
+    } else {
+      return getLogMetaFromDocSession(requestOrSession);
+    }
+  }
 }

 export async function getTelemetryPrefs(
--- a/app/server/lib/sendAppPage.ts
+++ b/app/server/lib/sendAppPage.ts
@@ -83,7 +83,7 @@ export function makeGristConfig(options: MakeGristConfigOptions): GristLoadConfi
    gristNewColumnMenu: isAffirmative(process.env.GRIST_NEW_COLUMN_MENU),
    supportEmail: SUPPORT_EMAIL,
    userLocale: (req as RequestWithLogin | undefined)?.user?.options?.locale,
-    telemetry: server?.getTelemetry().getTelemetryConfig(),
+    telemetry: server?.getTelemetry().getTelemetryConfig(req as RequestWithLogin | undefined),
    deploymentType: server?.getDeploymentType(),
    templateOrg: getTemplateOrg(),
    canCloseAccount: isAffirmative(process.env.GRIST_ACCOUNT_CLOSE),