(core) Tweak telemetry

Summary: Adjusts the level of telemetry collected from Grist SaaS.

Test Plan: Tested manually.

Reviewers: paulfitz

Reviewed By: paulfitz

Subscribers: paulfitz

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

app/client/lib/telemetry.ts

@@ -2,10 +2,10 @@ import {logError} from 'app/client/models/errors';
 import {TelemetryEventName} from 'app/common/Telemetry';
 import {fetchFromHome, pageHasHome} from 'app/common/urlUtils';
 
-export async function logTelemetryEvent(name: TelemetryEventName, metadata?: Record<string, any>) {
+export function logTelemetryEvent(name: TelemetryEventName, metadata?: Record<string, any>) {
   if (!pageHasHome()) { return; }
 
-  await fetchFromHome('/api/telemetry', {
+  fetchFromHome('/api/telemetry', {
     method: 'POST',
     body: JSON.stringify({
       name,

app/client/ui/OpenVideoTour.ts

@@ -36,7 +36,7 @@ const VIDEO_TOUR_YOUTUBE_EMBED_ID = 'qnr2Pfnxdlc';
       owner.onDispose(async () => {
         if (youtubePlayer.isLoading()) { return; }
 
-        await logTelemetryEvent('watchedVideoTour', {
+        logTelemetryEvent('watchedVideoTour', {
           watchTimeSeconds: Math.floor(youtubePlayer.getCurrentTime()),
         });
       });

app/common/hashingUtils.ts

@@ -0,0 +1,12 @@
+import {createHash} from 'crypto';
+
+/**
+ * Returns a hash of `id` prefixed with the first 4 characters of `id`.
+ *
+ * Useful for situations where potentially sensitive identifiers are logged, such as
+ * doc ids (like those that have public link sharing enabled). The first 4 characters
+ * are included to assist with troubleshooting.
+ */
+export function hashId(id: string): string {
+  return `${id.slice(0, 4)}:${createHash('sha256').update(id.slice(4)).digest('base64')}`;
+}

app/gen-server/entity/Document.ts

@@ -1,5 +1,6 @@
 import {ApiError} from 'app/common/ApiError';
 import {DocumentUsage} from 'app/common/DocUsage';
+import {hashId} from 'app/common/hashingUtils';
 import {Role} from 'app/common/roles';
 import {DocumentOptions, DocumentProperties, documentPropertyKeys,
         DocumentType, NEW_DOCUMENT_CODE, TutorialMetadata} from "app/common/UserAPI";
@@ -164,8 +165,8 @@ export class Document extends Resource {
       ? Math.floor((lastSlideIndex / numSlides) * 100)
       : undefined;
     dbManager?.emit('tutorialProgressChange', {
-      tutorialForkId: this.id,
-      tutorialTrunkId: this.trunkId,
+      tutorialForkIdDigest: hashId(this.id),
+      tutorialTrunkIdDigest: this.trunkId ? hashId(this.trunkId) : undefined,
       lastSlideIndex,
       numSlides,
       percentComplete,

app/gen-server/lib/Housekeeper.ts

@@ -17,7 +17,8 @@ import fetch from 'node-fetch';
 import * as Fetch from 'node-fetch';
 import { EntityManager } from 'typeorm';
 
-const HOUSEKEEPER_PERIOD_MS = 1 * 60 * 60 * 1000;   // operate every 1 hour
+const DELETE_TRASH_PERIOD_MS = 1 * 60 * 60 * 1000;  // operate every 1 hour
+const LOG_METRICS_PERIOD_MS = 24 * 60 * 60 * 1000;  // operate every day
 const AGE_THRESHOLD_OFFSET = '-30 days';            // should be an interval known by postgres + sqlite
 
 /**
@@ -33,7 +34,8 @@ const AGE_THRESHOLD_OFFSET = '-30 days';            // should be an interval kno
  * multiple home servers, there will be no competition or duplication of effort.
  */
 export class Housekeeper {
-  private _interval?: NodeJS.Timeout;
+  private _deleteTrashinterval?: NodeJS.Timeout;
+  private _logMetricsInterval?: NodeJS.Timeout;
   private _electionKey?: string;
 
   public constructor(private _dbManager: HomeDBManager, private _server: GristServer,
@@ -45,34 +47,35 @@ export class Housekeeper {
    */
   public async start() {
     await this.stop();
-    this._interval = setInterval(() => {
-      this.doHousekeepingExclusively().catch(log.warn.bind(log));
-    }, HOUSEKEEPER_PERIOD_MS);
+    this._deleteTrashinterval = setInterval(() => {
+      this.deleteTrashExclusively().catch(log.warn.bind(log));
+    }, DELETE_TRASH_PERIOD_MS);
+    this._logMetricsInterval = setInterval(() => {
+      this.logMetricsExclusively().catch(log.warn.bind(log));
+    }, LOG_METRICS_PERIOD_MS);
   }
 
   /**
    * Stop scheduling housekeeping tasks.  Note: doesn't wait for any housekeeping task in progress.
    */
   public async stop() {
-    if (this._interval) {
-      clearInterval(this._interval);
-      this._interval = undefined;
+    for (const interval of ['_deleteTrashinterval', '_logMetricsInterval'] as const) {
+      clearInterval(this[interval]);
+      this[interval] = undefined;
     }
   }
 
   /**
-   * Deletes old trash and logs metrics if no other server is working on it or worked on it
-   * recently.
+   * Deletes old trash if no other server is working on it or worked on it recently.
    */
-  public async doHousekeepingExclusively(): Promise<boolean> {
-    const electionKey = await this._electionStore.getElection('housekeeping', HOUSEKEEPER_PERIOD_MS / 2.0);
+  public async deleteTrashExclusively(): Promise<boolean> {
+    const electionKey = await this._electionStore.getElection('housekeeping', DELETE_TRASH_PERIOD_MS / 2.0);
     if (!electionKey) {
-      log.info('Skipping housekeeping since another server is working on it or worked on it recently');
+      log.info('Skipping deleteTrash since another server is working on it or worked on it recently');
       return false;
     }
     this._electionKey = electionKey;
     await this.deleteTrash();
-    await this.logMetrics();
     return true;
   }
 
@@ -152,6 +155,20 @@ export class Housekeeper {
     }
   }
 
+  /**
+   * Logs metrics if no other server is working on it or worked on it recently.
+   */
+  public async logMetricsExclusively(): Promise<boolean> {
+    const electionKey = await this._electionStore.getElection('logMetrics', LOG_METRICS_PERIOD_MS / 2.0);
+    if (!electionKey) {
+      log.info('Skipping logMetrics since another server is working on it or worked on it recently');
+      return false;
+    }
+    this._electionKey = electionKey;
+    await this.logMetrics();
+    return true;
+  }
+
   /**
    * Logs metrics regardless of what other servers may be doing.
    */
@@ -163,7 +180,7 @@ export class Housekeeper {
         telemetryManager?.logEvent('siteUsage', {
           siteId: summary.site_id,
           siteType: summary.site_type,
-          inGoodStanding: summary.in_good_standing,
+          inGoodStanding: Boolean(summary.in_good_standing),
           stripePlanId: summary.stripe_plan_id,
           numDocs: Number(summary.num_docs),
           numWorkspaces: Number(summary.num_workspaces),

app/server/lib/ActiveDoc.ts

@@ -68,6 +68,7 @@ import {FormulaProperties, getFormulaProperties} from 'app/common/GranularAccess
 import {isHiddenCol} from 'app/common/gristTypes';
 import {commonUrls, parseUrlId} from 'app/common/gristUrls';
 import {byteString, countIf, retryOnce, safeJsonParse} from 'app/common/gutil';
+import {hashId} from 'app/common/hashingUtils';
 import {InactivityTimer} from 'app/common/InactivityTimer';
 import {Interval} from 'app/common/Interval';
 import * as roles from 'app/common/roles';
@@ -131,10 +132,12 @@ import {createAttachmentsIndex, DocStorage, REMOVE_UNUSED_ATTACHMENTS_DELAY} fro
 import {expandQuery} from './ExpandedQuery';
 import {GranularAccess, GranularAccessForBundle} from './GranularAccess';
 import {OnDemandActions} from './OnDemandActions';
-import {getLogMetaFromDocSession, getPubSubPrefix, timeoutReached} from './serverUtils';
+import {getLogMetaFromDocSession, getPubSubPrefix, getTelemetryMetaFromDocSession,
+        timeoutReached} from './serverUtils';
 import {findOrAddAllEnvelope, Sharing} from './Sharing';
 import cloneDeep = require('lodash/cloneDeep');
 import flatten = require('lodash/flatten');
+import merge = require('lodash/merge');
 import pick = require('lodash/pick');
 import remove = require('lodash/remove');
 import sum = require('lodash/sum');
@@ -1389,10 +1392,9 @@ export class ActiveDoc extends EventEmitter implements AssistanceDoc {
       // TODO: Need a more precise way to identify a template. (This org now also has tutorials.)
       const isTemplate = TEMPLATES_ORG_DOMAIN === doc.workspace.org.domain && doc.type !== 'tutorial';
       this.logTelemetryEvent(docSession, 'documentForked', {
-        forkId: forkIds.forkId,
-        forkDocId: forkIds.docId,
-        forkUrlId: forkIds.urlId,
-        trunkId: doc.trunkId,
+        forkIdDigest: hashId(forkIds.forkId),
+        forkDocIdDigest: hashId(forkIds.docId),
+        trunkIdDigest: doc.trunkId ? hashId(doc.trunkId) : undefined,
         isTemplate,
         lastActivity: doc.updatedAt,
       });
@@ -2314,7 +2316,6 @@ export class ActiveDoc extends EventEmitter implements AssistanceDoc {
   private _logDocMetrics(docSession: OptDocSession, triggeredBy: 'docOpen' | 'interval'| 'docClose') {
     this.logTelemetryEvent(docSession, 'documentUsage', {
       triggeredBy,
-      access: this._doc?.access,
       isPublic: ((this._doc as unknown) as APIDocument)?.public ?? false,
       rowCount: this._docUsage?.rowCount?.total,
       dataSizeBytes: this._docUsage?.dataSizeBytes,
@@ -2434,22 +2435,22 @@ export class ActiveDoc extends EventEmitter implements AssistanceDoc {
   private _getCustomWidgetMetrics() {
     const viewSections = this.docData?.getMetaTable('_grist_Views_section');
     const viewSectionRecords = viewSections?.getRecords() ?? [];
-    const customWidgetUrls: string[] = [];
+    const customWidgetIds: string[] = [];
     for (const r of viewSectionRecords) {
       const {customView} = safeJsonParse(r.options, {});
       if (!customView) { continue; }
 
-      const {url} = safeJsonParse(customView, {});
+      const {pluginId, url} = safeJsonParse(customView, {});
       if (!url) { continue; }
 
-      const isGristUrl = url.startsWith(commonUrls.gristLabsCustomWidgets);
-      customWidgetUrls.push(isGristUrl ? url : 'externalURL');
+      const isGristLabsWidget = url.startsWith(commonUrls.gristLabsCustomWidgets);
+      customWidgetIds.push(isGristLabsWidget ? pluginId : 'externalId');
     }
-    const numCustomWidgets = customWidgetUrls.length;
+    const numCustomWidgets = customWidgetIds.length;
 
     return {
       numCustomWidgets,
-      customWidgetUrls,
+      customWidgetIds,
     };
   }
 
@@ -2511,15 +2512,16 @@ export class ActiveDoc extends EventEmitter implements AssistanceDoc {
   }
 
   private _getTelemetryMeta(docSession: OptDocSession|null) {
-    return {
-      ...(docSession ? {
-          ...getLogMetaFromDocSession(docSession),
-          altSessionId: getDocSessionAltSessionId(docSession),
-        } : {}),
-      docId: this._docName,
+    const altSessionId = docSession ? getDocSessionAltSessionId(docSession) : undefined;
+    return merge(
+      docSession ? getTelemetryMetaFromDocSession(docSession) : {},
+      altSessionId ? {altSessionId} : undefined,
+      {
+        docIdDigest: hashId(this._docName),
         siteId: this._doc?.workspace.org.id,
         siteType: this._product?.name,
-    };
+      },
+    );
   }
 
   /**

app/server/lib/AppEndpoint.ts

@@ -9,6 +9,7 @@ import fetch, {Response as FetchResponse, RequestInit} from 'node-fetch';
 import {ApiError} from 'app/common/ApiError';
 import {getSlugIfNeeded, parseSubdomainStrictly, parseUrlId} from 'app/common/gristUrls';
 import {removeTrailingSlash} from 'app/common/gutil';
+import {hashId} from 'app/common/hashingUtils';
 import {LocalPlugin} from "app/common/plugin";
 import {TelemetryTemplateSignupCookieName} from 'app/common/Telemetry';
 import {Document as APIDocument} from 'app/common/UserAPI';
@@ -308,7 +309,7 @@ export function attachAppEndpoint(options: AttachOptions): void {
     const isTemplate = TEMPLATES_ORG_DOMAIN === doc.workspace.org.domain && doc.type !== 'tutorial';
     if (isPublic || isTemplate) {
       gristServer.getTelemetryManager()?.logEvent('documentOpened', {
-        docId,
+        docIdDigest: hashId(docId),
         siteId: doc.workspace.org.id,
         siteType: doc.workspace.org.billingAccount.product.name,
         userId: mreq.userId,

app/server/lib/Authorizer.ts

@@ -397,7 +397,8 @@ export async function addRequestUser(dbManager: HomeDBManager, permitStore: IPer
   log.rawDebug(`Auth[${meta.method}]: ${meta.host} ${meta.path}`, meta);
   if (hasApiKey) {
     options.gristServer.getTelemetryManager()?.logEvent('apiUsage', {
-      ...meta,
+      method: mreq.method,
+      userId: mreq.userId,
       userAgent: req.headers['user-agent'],
     });
   }

app/server/lib/Client.ts

@@ -433,6 +433,16 @@ export class Client {
     return meta;
   }
 
+  public getFullTelemetryMeta() {
+    const meta: Record<string, any> = {};
+    // We assume the _userId has already been cached, which will be true always (for all practical
+    // purposes) because it's set when the Authorizer checks this client.
+    if (this._userId) { meta.userId = this._userId; }
+    const altSessionId = this.getAltSessionId();
+    if (altSessionId) { meta.altSessionId = altSessionId; }
+    return meta;
+  }
+
   private async _refreshUser(dbManager: HomeDBManager) {
     if (this._profile) {
       const user = await this._fetchUser(dbManager);

app/server/lib/DocApi.ts

@@ -11,6 +11,7 @@ import {
 import {isRaisedException} from "app/common/gristTypes";
 import {buildUrlId, parseUrlId} from "app/common/gristUrls";
 import {isAffirmative} from "app/common/gutil";
+import {hashId} from "app/common/hashingUtils";
 import {SchemaTypes} from "app/common/schema";
 import {SortFunc} from 'app/common/SortFunc';
 import {Sort} from 'app/common/SortSpec';
@@ -915,9 +916,8 @@ export class DocWorkerApi {
           });
           const {forkId} = parseUrlId(scope.urlId);
           activeDoc.logTelemetryEvent(docSession, 'tutorialRestarted', {
-            tutorialForkId: forkId,
-            tutorialForkUrlId: scope.urlId,
-            tutorialTrunkId,
+            tutorialForkIdDigest: forkId ? hashId(forkId) : undefined,
+            tutorialTrunkIdDigest: hashId(tutorialTrunkId),
           });
         }
       }

app/server/lib/FlexServer.ts

@@ -697,9 +697,7 @@ export class FlexServer implements GristServer {
       const name = stringParam(req.body.name, 'name', TelemetryEventNames);
       this._telemetryManager?.logEvent(name as TelemetryEventName, {
         userId: mreq.userId,
-        email: mreq.user?.loginEmail,
         altSessionId: mreq.altSessionId,
-        site: mreq.org,
         ...req.body.metadata,
       });
       return resp.status(200).send();

app/server/lib/Triggers.ts

@@ -619,7 +619,9 @@ export class DocTriggers {
         await this._stats.logStatus(id, 'sending');
         meta = {numEvents: batch.length, webhookId: id, host: new URL(url).host};
         this._log("Sending batch of webhook events", meta);
-        this._activeDoc.logTelemetryEvent(null, 'sendingWebhooks', meta);
+        this._activeDoc.logTelemetryEvent(null, 'sendingWebhooks', {
+          numEvents: batch.length,
+        });
         success = await this._sendWebhookWithRetries(id, url, body, batch.length, this._loopAbort.signal);
         if (this._loopAbort.signal.aborted) {
           continue;

app/server/lib/serverUtils.ts

@@ -163,6 +163,20 @@ export function getLogMetaFromDocSession(docSession: OptDocSession) {
   };
 }
 
+/**
+ * Extract telemetry metadata from session.
+ */
+export function getTelemetryMetaFromDocSession(docSession: OptDocSession) {
+  const client = docSession.client;
+  const access = getDocSessionAccessOrNull(docSession);
+  const user = getDocSessionUser(docSession);
+  return {
+    access,
+    ...(user ? {userId: user.id} : {}),
+    ...(client ? client.getFullTelemetryMeta() : {}),   // Client if present will repeat and add to user info.
+  };
+}
+
 /**
  * Only offer choices of engine on experimental deployments (staging/dev).
  */