gristlabs_grist-core/test/server/lib/Telemetry.ts
George Gevoian 0a34292536 (core) Add telemetry for AI Assistant
Summary: Also fixes a few bugs with some telemetry events not being recorded.

Test Plan: Manual.

Reviewers: paulfitz

Reviewed By: paulfitz

Differential Revision: https://phab.getgrist.com/D3960
2023-07-20 12:50:26 -04:00

524 lines
18 KiB
TypeScript

import {GristDeploymentType} from 'app/common/gristUrls';
import {PrefSource} from 'app/common/InstallAPI';
import {TelemetryEvent, TelemetryLevel} from 'app/common/Telemetry';
import {ILogMeta, LogMethods} from 'app/server/lib/LogMethods';
import {filterMetadata, 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 kiwi = configForUser('Kiwi');
const anon = configForUser('Anonymous');
describe('Telemetry', function() {
const variants: [GristDeploymentType, TelemetryLevel, PrefSource][] = [
['saas', 'off', 'environment-variable'],
['saas', 'limited', 'environment-variable'],
['saas', 'full', 'environment-variable'],
['core', 'off', 'environment-variable'],
['core', 'limited', 'environment-variable'],
['core', 'full', 'environment-variable'],
['core', 'off', 'preferences'],
['core', 'limited', 'preferences'],
['core', 'full', 'preferences'],
];
for (const [deploymentType, telemetryLevel, settingSource] of variants) {
describe(`in grist-${deploymentType} with level "${telemetryLevel}" set via ${settingSource}`, function() {
let server: TestServer;
let homeUrl: string;
let installationId: string;
let telemetry: ITelemetry;
let forwardEventSpy: sinon.SinonSpy;
let doForwardEventStub: sinon.SinonStub;
const sandbox = sinon.createSandbox();
const loggedEvents: [TelemetryEvent, ILogMeta][] = [];
before(async function() {
process.env.GRIST_TEST_SERVER_DEPLOYMENT_TYPE = deploymentType;
if (settingSource === 'environment-variable') {
process.env.GRIST_TELEMETRY_LEVEL = telemetryLevel;
}
process.env.GRIST_DEFAULT_EMAIL = 'chimpy@getgrist.com';
server = new TestServer(this);
homeUrl = await server.start();
if (settingSource ==='preferences') {
await axios.patch(`${homeUrl}/api/install/prefs`, {
telemetry: {telemetryLevel},
}, chimpy);
}
installationId = (await server.server.getActivations().current()).id;
telemetry = server.server.getTelemetry();
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');
doForwardEventStub = sandbox
.stub(Telemetry.prototype as any, '_doForwardEvent');
});
after(async function() {
delete process.env.GRIST_TEST_SERVER_DEPLOYMENT_TYPE;
delete process.env.GRIST_TELEMETRY_LEVEL;
delete process.env.GRIST_DEFAULT_EMAIL;
await server.stop();
sandbox.restore();
});
it('returns the current telemetry config', async function() {
assert.deepEqual(telemetry.getTelemetryConfig(), {
telemetryLevel,
});
});
if (deploymentType === 'core') {
it('returns the current telemetry status', async function() {
const resp = await axios.get(`${homeUrl}/api/install/prefs`, chimpy);
assert.equal(resp.status, 200);
assert.deepEqual(resp.data, {
telemetry: {
telemetryLevel: {
value: telemetryLevel,
source: settingSource,
},
},
});
});
}
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: 'dige:Vq9L3nCkeufQ8euzDkXtM2Fl1cnsALqakjEeM6QlbXQ=',
isPublic: false,
installationId,
}
]);
}
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: 'dige:Vq9L3nCkeufQ8euzDkXtM2Fl1cnsALqakjEeM6QlbXQ=',
isPublic: false,
userId: 1,
installationId,
}
]);
}
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: 'dige:Vq9L3nCkeufQ8euzDkXtM2Fl1cnsALqakjEeM6QlbXQ=',
isPublic: false,
}
]);
assert.equal(forwardEventSpy.callCount, 1);
}
if (telemetryLevel === 'full') {
await telemetry.logEvent('documentOpened', {
limited: {
docIdDigest: 'digest',
isPublic: false,
},
full: {
userId: 1,
},
});
assert.deepEqual(forwardEventSpy.lastCall.args, [
'documentOpened',
{
docIdDigest: 'dige:Vq9L3nCkeufQ8euzDkXtM2Fl1cnsALqakjEeM6QlbXQ=',
isPublic: false,
userId: 1,
}
]);
// An earlier test triggered an apiUsage event.
assert.equal(forwardEventSpy.callCount, 2);
}
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'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,
installationId,
});
} 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, {
watchTimeSeconds: 30,
});
} else {
assert.containsAllKeys(metadata, [
'watchTimeSeconds',
'userId',
'altSessionId',
]);
assert.equal(metadata.watchTimeSeconds, 30);
assert.equal(metadata.userId, 1);
}
if (telemetryLevel === 'limited') {
assert.equal(forwardEventSpy.callCount, 2);
} else {
// The count below includes 2 apiUsage events triggered as side effects.
assert.equal(forwardEventSpy.callCount, 4);
assert.equal(forwardEventSpy.thirdCall.args[0], 'apiUsage');
}
assert.isEmpty(loggedEvents);
});
it('skips forwarding events if too many requests are pending', async function() {
let numRequestsMade = 0;
doForwardEventStub.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);
});
}
});
}
describe('api', function() {
let server: TestServer;
let homeUrl: string;
const sandbox = sinon.createSandbox();
before(async function() {
process.env.GRIST_TEST_SERVER_DEPLOYMENT_TYPE = 'core';
process.env.GRIST_DEFAULT_EMAIL = 'chimpy@getgrist.com';
server = new TestServer(this);
homeUrl = await server.start();
sandbox.stub(Telemetry.prototype as any, '_doForwardEvent');
});
after(async function() {
delete process.env.GRIST_TEST_SERVER_DEPLOYMENT_TYPE;
delete process.env.GRIST_DEFAULT_EMAIL;
await server.stop();
sandbox.restore();
});
it('GET /install/prefs returns 200 for non-default users', async function() {
const resp = await axios.get(`${homeUrl}/api/install/prefs`, kiwi);
assert.equal(resp.status, 200);
assert.deepEqual(resp.data, {
telemetry: {
telemetryLevel: {
value: 'off',
source: 'preferences',
},
},
});
});
it('GET /install/prefs returns 200 for the default user', async function() {
const resp = await axios.get(`${homeUrl}/api/install/prefs`, chimpy);
assert.equal(resp.status, 200);
assert.deepEqual(resp.data, {
telemetry: {
telemetryLevel: {
value: 'off',
source: 'preferences',
},
},
});
});
it('PATCH /install/prefs returns 403 for non-default users', async function() {
const resp = await axios.patch(`${homeUrl}/api/install/prefs`, {
telemetry: {telemetryLevel: 'limited'},
}, kiwi);
assert.equal(resp.status, 403);
});
it('PATCH /install/prefs returns 200 for the default user', async function() {
let resp = await axios.patch(`${homeUrl}/api/install/prefs`, {
telemetry: {telemetryLevel: 'limited'},
}, chimpy);
assert.equal(resp.status, 200);
resp = await axios.get(`${homeUrl}/api/install/prefs`, chimpy);
assert.deepEqual(resp.data, {
telemetry: {
telemetryLevel: {
value: 'limited',
source: 'preferences',
},
},
});
});
});
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',
});
});
it('hashes keys suffixed with "Digest"', function() {
const metadata = {
limited: {
docIdDigest: 'FGWGX4S6TB6',
docId: '3WH3D68J28',
},
};
assert.deepEqual(filterMetadata(metadata, 'limited'), {
docIdDigest: 'FGWG:omhYAysWiM7coZK+FLK/tIOPW4BaowXjU7J/P9ynYcU=',
docId: '3WH3D68J28',
});
});
});
});