From a460563dafd1e73097241d5088cbf00a4d5e30bd Mon Sep 17 00:00:00 2001 From: George Gevoian Date: Fri, 9 Jun 2023 12:32:40 -0400 Subject: [PATCH] (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/common/Telemetry.ts | 496 +++++++++--------------------- app/gen-server/entity/Document.ts | 8 +- app/server/lib/DocApi.ts | 1 + app/server/lib/Telemetry.ts | 66 ++-- test/server/lib/Telemetry.ts | 65 ++-- 5 files changed, 227 insertions(+), 409 deletions(-) diff --git a/app/common/Telemetry.ts b/app/common/Telemetry.ts index ba6f529f..38fc6b57 100644 --- a/app/common/Telemetry.ts +++ b/app/common/Telemetry.ts @@ -23,764 +23,546 @@ export enum Level { * level. */ export const TelemetryContracts: TelemetryContracts = { - /** - * Triggered when an HTTP request with an API key is made. - */ apiUsage: { + description: 'Triggered when an HTTP request with an API key is made.', minimumTelemetryLevel: Level.full, metadataContracts: { - /** - * The HTTP request method (e.g. GET, POST, PUT). - */ method: { + description: 'The HTTP request method (e.g. GET, POST, PUT).', dataType: 'string', }, - /** - * The id of the user that triggered this event. - */ userId: { + description: 'The id of the user that triggered this event.', dataType: 'number', }, - /** - * The User-Agent HTTP request header. - */ userAgent: { + description: 'The User-Agent HTTP request header.', dataType: 'string', }, }, }, - /** - * Triggered when HelpScout Beacon is opened. - */ beaconOpen: { + description: 'Triggered when HelpScout Beacon is opened.', minimumTelemetryLevel: Level.full, metadataContracts: { - /** - * The id of the user that triggered this event. - */ userId: { + description: 'The id of the user that triggered this event.', dataType: 'number', }, - /** - * A random, session-based identifier for the user that triggered this event. - */ altSessionId: { + description: 'A random, session-based identifier for the user that triggered this event.', dataType: 'string', }, }, }, - /** - * Triggered when an article is opened in HelpScout Beacon. - */ beaconArticleViewed: { + description: 'Triggered when an article is opened in HelpScout Beacon.', minimumTelemetryLevel: Level.full, metadataContracts: { - /** - * The id of the article. - */ articleId: { + description: 'The id of the article.', dataType: 'string', }, - /** - * The id of the user that triggered this event. - */ userId: { + description: 'The id of the user that triggered this event.', dataType: 'number', }, - /** - * A random, session-based identifier for the user that triggered this event. - */ altSessionId: { + description: 'A random, session-based identifier for the user that triggered this event.', dataType: 'string', }, }, }, - /** - * Triggered when an email is sent in HelpScout Beacon. - */ beaconEmailSent: { + description: 'Triggered when an email is sent in HelpScout Beacon.', minimumTelemetryLevel: Level.full, metadataContracts: { - /** - * The id of the user that triggered this event. - */ userId: { + description: 'The id of the user that triggered this event.', dataType: 'number', }, - /** - * A random, session-based identifier for the user that triggered this event. - */ altSessionId: { + description: 'A random, session-based identifier for the user that triggered this event.', dataType: 'string', }, }, }, - /** - * Triggered when a search is made in HelpScout Beacon. - */ beaconSearch: { + description: 'Triggered when a search is made in HelpScout Beacon.', minimumTelemetryLevel: Level.full, metadataContracts: { - /** - * The search query. - */ searchQuery: { + description: 'The search query.', dataType: 'string', }, - /** - * The id of the user that triggered this event. - */ userId: { + description: 'The id of the user that triggered this event.', dataType: 'number', }, - /** - * A random, session-based identifier for the user that triggered this event. - */ altSessionId: { + description: 'A random, session-based identifier for the user that triggered this event.', dataType: 'string', }, }, }, - /** - * Triggered when a document is forked. - */ documentForked: { + description: 'Triggered when a document is forked.', minimumTelemetryLevel: Level.limited, metadataContracts: { - /** - * A hash of the doc id. - */ docIdDigest: { + description: 'A hash of the doc id.', dataType: 'string', }, - /** - * The id of the site containing the forked document. - */ siteId: { + description: 'The id of the site containing the forked document.', dataType: 'number', minimumTelemetryLevel: Level.full, }, - /** - * The type of the site. - */ siteType: { + description: 'The type of the site.', dataType: 'string', minimumTelemetryLevel: Level.full, }, - /** - * A random, session-based identifier for the user that triggered this event. - */ altSessionId: { + description: 'A random, session-based identifier for the user that triggered this event.', dataType: 'string', minimumTelemetryLevel: Level.full, }, - /** - * The id of the user that triggered this event. - */ + access: { + description: 'The document access level of the user that triggered this event.', + dataType: 'string', + }, userId: { + description: 'The id of the user that triggered this event.', dataType: 'number', minimumTelemetryLevel: Level.full, }, - /** - * A hash of the fork id. - */ forkIdDigest: { + description: 'A hash of the fork id.', dataType: 'string', }, - /** - * A hash of the full id of the fork, including the trunk id and fork id. - */ forkDocIdDigest: { + description: 'A hash of the full id of the fork, including the trunk id and fork id.', dataType: 'string', }, - /** - * A hash of the trunk id. - */ trunkIdDigest: { + description: 'A hash of the trunk id.', dataType: 'string', }, - /** - * Whether the trunk is a template. - */ isTemplate: { + description: 'Whether the trunk is a template.', dataType: 'boolean', }, - /** - * Timestamp of the last update to the trunk document. - */ lastActivity: { + description: 'Timestamp of the last update to the trunk document.', dataType: 'date', }, }, }, - /** - * Triggered when a public document or template is opened. - */ documentOpened: { + description: 'Triggered when a public document or template is opened.', minimumTelemetryLevel: Level.limited, metadataContracts: { - /** - * A hash of the doc id. - */ docIdDigest: { + description: 'A hash of the doc id.', dataType: 'string', }, - /** - * The site id. - */ siteId: { + description: 'The site id.', dataType: 'number', minimumTelemetryLevel: Level.full, }, - /** - * The site type. - */ siteType: { + description: 'The site type.', dataType: 'string', minimumTelemetryLevel: Level.full, }, - /** - * The id of the user that triggered this event. - */ userId: { + description: 'The id of the user that triggered this event.', dataType: 'number', minimumTelemetryLevel: Level.full, }, - /** - * A random, session-based identifier for the user that triggered this event. - */ altSessionId: { + description: 'A random, session-based identifier for the user that triggered this event.', dataType: 'string', minimumTelemetryLevel: Level.full, }, - /** - * The document access level of the user that triggered this event. - */ access: { - dataType: 'boolean', + description: 'The document access level of the user that triggered this event.', + dataType: 'string', }, - /** - * Whether the document is public. - */ isPublic: { + description: 'Whether the document is public.', dataType: 'boolean', }, - /** - * Whether a snapshot was opened. - */ isSnapshot: { + description: 'Whether a snapshot was opened.', dataType: 'boolean', }, - /** - * Whether the document is a template. - */ isTemplate: { + description: 'Whether the document is a template.', dataType: 'boolean', }, - /** - * Timestamp of when the document was last updated. - */ lastUpdated: { + description: 'Timestamp of when the document was last updated.', dataType: 'date', }, }, }, - /** - * Triggered on doc open and close, as well as hourly while a document is open. - */ documentUsage: { + description: 'Triggered on doc open and close, as well as hourly while a document is open.', minimumTelemetryLevel: Level.limited, metadataContracts: { - /** - * A hash of the doc id. - */ docIdDigest: { + description: 'A hash of the doc id.', dataType: 'string', }, - /** - * The site id. - */ siteId: { + description: 'The site id.', dataType: 'number', minimumTelemetryLevel: Level.full, }, - /** - * The site type. - */ siteType: { + description: 'The site type.', dataType: 'string', minimumTelemetryLevel: Level.full, }, - /** - * A random, session-based identifier for the user that triggered this event. - */ altSessionId: { + description: 'A random, session-based identifier for the user that triggered this event.', dataType: 'string', minimumTelemetryLevel: Level.full, }, - /** - * The id of the user that triggered this event. - */ + access: { + description: 'The document access level of the user that triggered this event.', + dataType: 'string', + }, userId: { + description: 'The id of the user that triggered this event.', dataType: 'number', minimumTelemetryLevel: Level.full, }, - /** - * What caused this event to trigger. - * - * May be either "docOpen", "interval", or "docClose". - */ triggeredBy: { + description: 'What caused this event to trigger. May be either "docOpen", "interval", or "docClose".', dataType: 'string', }, - /** - * Whether the document is public. - */ isPublic: { + description: 'Whether the document is public.', dataType: 'boolean', }, - /** - * The number of rows in the document. - */ rowCount: { + description: 'The number of rows in the document.', dataType: 'number', }, - /** - * The total size of all data in the document, excluding attachments. - */ dataSizeBytes: { + description: 'The total size of all data in the document, excluding attachments.', dataType: 'number', }, - /** - * The total size of all attachments in the document. - */ attachmentsSize: { + description: 'The total size of all attachments in the document.', dataType: 'number', }, - /** - * The number of access rules in the document. - */ numAccessRules: { + description: 'The number of access rules in the document.', dataType: 'number', }, - /** - * The number of user attributes in the document. - */ numUserAttributes: { + description: 'The number of user attributes in the document.', dataType: 'number', }, - /** - * The number of attachments in the document. - */ numAttachments: { + description: 'The number of attachments in the document.', dataType: 'number', }, - /** - * A list of unique file extensions compiled from all of the document's attachments. - */ attachmentTypes: { + description: "A list of unique file extensions compiled from all of the document's attachments.", dataType: 'string[]', }, - /** - * The number of charts in the document. - */ numCharts: { + description: 'The number of charts in the document.', dataType: 'number', }, - /** - * A list of chart types of every chart in the document. - */ chartTypes: { + description: 'A list of chart types of every chart in the document.', dataType: 'string[]', }, - /** - * The number of linked charts in the document. - */ numLinkedCharts: { + description: 'The number of linked charts in the document.', dataType: 'number', }, - /** - * The number of linked widgets in the document. - */ numLinkedWidgets: { + description: 'The number of linked widgets in the document.', dataType: 'number', }, - /** - * The number of columns in the document. - */ numColumns: { + description: 'The number of columns in the document.', dataType: 'number', }, - /** - * The number of columns with conditional formatting in the document. - */ numColumnsWithConditionalFormatting: { + description: 'The number of columns with conditional formatting in the document.', dataType: 'number', }, - /** - * The number of formula columns in the document. - */ numFormulaColumns: { + description: 'The number of formula columns in the document.', dataType: 'number', }, - /** - * The number of trigger formula columns in the document. - */ numTriggerFormulaColumns: { + description: 'The number of trigger formula columns in the document.', dataType: 'number', }, - /** - * The number of summary formula columns in the document. - */ numSummaryFormulaColumns: { + description: 'The number of summary formula columns in the document.', dataType: 'number', }, - /** - * The number of fields with conditional formatting in the document. - */ numFieldsWithConditionalFormatting: { + description: 'The number of fields with conditional formatting in the document.', dataType: 'number', }, - /** - * The number of tables in the document. - */ numTables: { + description: 'The number of tables in the document.', dataType: 'number', }, - /** - * The number of on-demand tables in the document. - */ numOnDemandTables: { + description: 'The number of on-demand tables in the document.', dataType: 'number', }, - /** - * The number of tables with conditional formatting in the document. - */ numTablesWithConditionalFormatting: { + description: 'The number of tables with conditional formatting in the document.', dataType: 'number', }, - /** - * The number of summary tables in the document. - */ numSummaryTables: { + description: 'The number of summary tables in the document.', dataType: 'number', }, - /** - * The number of custom widgets in the document. - */ numCustomWidgets: { + description: 'The number of custom widgets in the document.', dataType: 'number', }, - /** - * A list of plugin ids for every custom widget in the document. - * - * The ids of widgets not created by Grist Labs are replaced with "externalId". - */ customWidgetIds: { + description: 'A list of plugin ids for every custom widget in the document. ' + + 'The ids of widgets not created by Grist Labs are replaced with "externalId".', dataType: 'string[]', }, }, }, - /** - * Triggered every 5 seconds. - */ processMonitor: { + description: 'Triggered every 5 seconds.', minimumTelemetryLevel: Level.full, metadataContracts: { - /** Size of JS heap in use, in MiB. */ heapUsedMB: { + description: 'Size of JS heap in use, in MiB.', dataType: 'number', }, - /** Total heap size, in MiB, allocated for JS by V8. */ heapTotalMB: { + description: 'Total heap size, in MiB, allocated for JS by V8. ', dataType: 'number', }, - /** Fraction (typically between 0 and 1) of CPU usage. Includes all threads, so may exceed 1. */ cpuAverage: { + description: 'Fraction (typically between 0 and 1) of CPU usage. Includes all threads, so may exceed 1.', dataType: 'number', }, - /** Interval (in milliseconds) over which `cpuAverage` is reported. */ intervalMs: { + description: 'Interval (in milliseconds) over which `cpuAverage` is reported.', dataType: 'number', }, }, }, - /** - * Triggered when sending webhooks. - */ sendingWebhooks: { + description: 'Triggered when sending webhooks.', minimumTelemetryLevel: Level.limited, metadataContracts: { - /** - * The number of events in the batch of webhooks being sent. - */ numEvents: { + description: 'The number of events in the batch of webhooks being sent.', dataType: 'number', }, - /** - * A hash of the doc id. - */ docIdDigest: { + description: 'A hash of the doc id.', dataType: 'string', }, - /** - * The site id. - */ siteId: { + description: 'The site id.', dataType: 'number', minimumTelemetryLevel: Level.full, }, - /** - * The site type. - */ siteType: { + description: 'The site type.', dataType: 'string', minimumTelemetryLevel: Level.full, }, - /** - * A random, session-based identifier for the user that triggered this event. - */ altSessionId: { + description: 'A random, session-based identifier for the user that triggered this event.', dataType: 'string', minimumTelemetryLevel: Level.full, }, - /** - * The id of the user that triggered this event. - */ + access: { + description: 'The document access level of the user that triggered this event.', + dataType: 'string', + }, userId: { + description: 'The id of the user that triggered this event.', dataType: 'number', minimumTelemetryLevel: Level.full, }, }, }, - /** - * Triggered after a user successfully verifies their account during sign-up. - * - * Not triggered in grist-core. - */ signupVerified: { + description: 'Triggered after a user successfully verifies their account during sign-up. ' + + 'Not triggered in grist-core.', minimumTelemetryLevel: Level.full, metadataContracts: { - /** - * Whether the user viewed any templates before signing up. - */ isAnonymousTemplateSignup: { + description: 'Whether the user viewed any templates before signing up.', dataType: 'boolean', }, - /** - * The doc id of the template the user last viewed before signing up, if any. - */ templateId: { + description: 'The doc id of the template the user last viewed before signing up, if any.', dataType: 'string', }, }, }, - /** - * Triggered daily. - */ siteMembership: { + description: 'Triggered daily.', minimumTelemetryLevel: Level.limited, metadataContracts: { - /** - * The site id. - */ siteId: { + description: 'The site id.', dataType: 'number', }, - /** - * The site type. - */ siteType: { + description: 'The site type.', dataType: 'string', }, - /** - * The number of users with an owner role in this site. - */ numOwners: { + description: 'The number of users with an owner role in this site.', dataType: 'number', }, - /** - * The number of users with an editor role in this site. - */ numEditors: { + description: 'The number of users with an editor role in this site.', dataType: 'number', }, - /** - * The number of users with a viewer role in this site. - */ numViewers: { + description: 'The number of users with a viewer role in this site.', dataType: 'number', }, }, }, - /** - * Triggered daily. - */ siteUsage: { + description: 'Triggered daily.', minimumTelemetryLevel: Level.limited, metadataContracts: { - /** - * The site id. - */ siteId: { + description: 'The site id.', dataType: 'number', }, - /** - * The site type. - */ siteType: { + description: 'The site type.', dataType: 'string', }, - /** - * Whether the site's subscription is in good standing. - */ inGoodStanding: { + description: "Whether the site's subscription is in good standing.", dataType: 'boolean', }, - /** - * The Stripe Plan id associated with this site. - */ stripePlanId: { + description: 'The Stripe Plan id associated with this site.', dataType: 'string', minimumTelemetryLevel: Level.full, }, - /** - * The number of docs in this site. - */ numDocs: { + description: 'The number of docs in this site.', dataType: 'number', }, - /** - * The number of workspaces in this site. - */ numWorkspaces: { + description: 'The number of workspaces in this site.', dataType: 'number', }, - /** - * The number of site members. - */ numMembers: { + description: 'The number of site members.', dataType: 'number', }, - /** - * A timestamp of the most recent update made to a site document. - */ lastActivity: { + description: 'A timestamp of the most recent update made to a site document.', dataType: 'date', }, }, }, - /** - * Triggered on changes to tutorial progress. - */ tutorialProgressChanged: { + description: 'Triggered on changes to tutorial progress.', minimumTelemetryLevel: Level.full, metadataContracts: { - /** - * A hash of the tutorial fork id. - */ tutorialForkIdDigest: { + description: 'A hash of the tutorial fork id.', dataType: 'string', }, - /** - * A hash of the tutorial trunk id. - */ tutorialTrunkIdDigest: { + description: 'A hash of the tutorial trunk id.', dataType: 'string', }, - /** - * The 0-based index of the last tutorial slide the user had open. - */ lastSlideIndex: { + description: 'The 0-based index of the last tutorial slide the user had open.', dataType: 'number', }, - /** - * The total number of slides in the tutorial. - */ numSlides: { + description: 'The total number of slides in the tutorial.', dataType: 'number', }, - /** - * Percentage of tutorial completion. - */ percentComplete: { + description: 'Percentage of tutorial completion.', dataType: 'number', }, }, }, - /** - * Triggered when a tutorial is restarted. - */ tutorialRestarted: { + description: 'Triggered when a tutorial is restarted.', minimumTelemetryLevel: Level.full, metadataContracts: { - /** - * A hash of the tutorial fork id. - */ tutorialForkIdDigest: { + description: 'A hash of the tutorial fork id.', dataType: 'string', }, - /** - * A hash of the tutorial trunk id. - */ tutorialTrunkIdDigest: { + description: 'A hash of the tutorial trunk id.', dataType: 'string', }, - /** - * A hash of the doc id. - */ docIdDigest: { + description: 'A hash of the doc id.', dataType: 'string', }, - /** - * The site id. - */ siteId: { + description: 'The site id.', dataType: 'number', }, - /** - * The site type. - */ siteType: { + description: 'The site type.', dataType: 'string', }, - /** - * A random, session-based identifier for the user that triggered this event. - */ altSessionId: { + description: 'A random, session-based identifier for the user that triggered this event.', + dataType: 'string', + }, + access: { + description: 'The document access level of the user that triggered this event.', dataType: 'string', }, - /** - * The id of the user that triggered this event. - */ userId: { + description: 'The id of the user that triggered this event.', dataType: 'number', }, }, }, - /** - * Triggered when the video tour is closed. - */ watchedVideoTour: { + description: 'Triggered when the video tour is closed.', minimumTelemetryLevel: Level.limited, metadataContracts: { - /** - * The number of seconds elapsed in the video player. - */ watchTimeSeconds: { + description: 'The number of seconds elapsed in the video player.', dataType: 'number', }, - /** - * The id of the user that triggered this event. - */ userId: { + description: 'The id of the user that triggered this event.', dataType: 'number', minimumTelemetryLevel: Level.full, }, - /** - * A random, session-based identifier for the user that triggered this event. - */ altSessionId: { + description: 'A random, session-based identifier for the user that triggered this event.', dataType: 'string', minimumTelemetryLevel: Level.full, }, @@ -811,11 +593,13 @@ export const TelemetryEvents = StringUnion( export type TelemetryEvent = typeof TelemetryEvents.type; interface TelemetryEventContract { + description: string; minimumTelemetryLevel: Level; metadataContracts?: Record; } interface MetadataContract { + description: string; dataType: 'boolean' | 'number' | 'string' | 'string[]' | 'date'; minimumTelemetryLevel?: Level; } diff --git a/app/gen-server/entity/Document.ts b/app/gen-server/entity/Document.ts index 859864c0..2e0a67d9 100644 --- a/app/gen-server/entity/Document.ts +++ b/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); } } diff --git a/app/server/lib/DocApi.ts b/app/server/lib/DocApi.ts index f60645aa..afcc8e1b 100644 --- a/app/server/lib/DocApi.ts +++ b/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, }, diff --git a/app/server/lib/Telemetry.ts b/app/server/lib/Telemetry.ts index 1a559cc8..65fbf38c 100644 --- a/app/server/lib/Telemetry.ts +++ b/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, + }); + } } diff --git a/test/server/lib/Telemetry.ts b/test/server/lib/Telemetry.ts index cf065155..5555b67c 100644 --- a/test/server/lib/Telemetry.ts +++ b/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 - .stub(Telemetry.prototype, 'forwardEvent') - .callsFake((event: TelemetryEvent, metadata?: TelemetryMetadata) => { - forwardedEvents.push([event, metadata]); - }); + forwardEventSpy = sandbox + .spy(Telemetry.prototype as any, '_forwardEvent'); + postJsonPayloadStub = sandbox + .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!.userId, 1); + assert.equal(metadata.watchTimeSeconds, 30); + 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(forwardedEvents[1][0], 'apiUsage'); + 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.isEmpty(forwardedEvents); + assert.equal(forwardEventSpy.callCount, 0); }); } });