Project import generated by Copybara.
GitOrigin-RevId: d9e9e3fb4e31372ec1fb43b178994ca78fa8fe70
diff --git a/static_src/monitoring/client-logger.test.js b/static_src/monitoring/client-logger.test.js
new file mode 100644
index 0000000..5c88355
--- /dev/null
+++ b/static_src/monitoring/client-logger.test.js
@@ -0,0 +1,627 @@
+import {assert} from 'chai';
+import sinon from 'sinon';
+
+import ClientLogger from './client-logger.js';
+import MonorailTSMon from './monorail-ts-mon.js';
+
+describe('ClientLogger', () => {
+ const startedKey = 'ClientLogger.rutabaga.started';
+ let c;
+
+ beforeEach(() => {
+ window.CS_env = {
+ token: 'rutabaga-token',
+ tokenExpiresSec: 1234,
+ app_version: 'rutabaga-version',
+ };
+ window.chops = {rpc: {PrpcClient: sinon.spy()}};
+ window.ga = sinon.spy();
+ MonorailTSMon.prototype.disableAfterNextFlush = sinon.spy();
+ c = new ClientLogger('rutabaga');
+ });
+
+ afterEach(() => {
+ sessionStorage.clear();
+ });
+
+ describe('constructor', () => {
+ it('assigns this.category', () => {
+ assert.equal(c.category, 'rutabaga');
+ });
+
+ it('gets started events from sessionStorage', () => {
+ const startedEvents = {
+ event1: {
+ time: 12345678,
+ labels: ['label1', 'label2'],
+ },
+ event2: {
+ time: 87654321,
+ labels: ['label2'],
+ },
+ };
+ sessionStorage[startedKey] = JSON.stringify(startedEvents);
+
+ c = new ClientLogger('rutabaga');
+ assert.deepEqual(startedEvents, c.startedEvents);
+ });
+ });
+
+ describe('records ts_mon metrics', () => {
+ let issueCreateMetric;
+ let issueUpdateMetric;
+ let autocompleteMetric;
+ let c;
+
+ beforeEach(() => {
+ window.ga = sinon.spy();
+ c = new ClientLogger('issues');
+ issueCreateMetric = c.tsMon._userTimingMetrics[0].metric;
+ issueCreateMetric.add = sinon.spy();
+
+ issueUpdateMetric = c.tsMon._userTimingMetrics[1].metric;
+ issueUpdateMetric.add = sinon.spy();
+
+ autocompleteMetric = c.tsMon._userTimingMetrics[2].metric;
+ autocompleteMetric.add = sinon.spy();
+ });
+
+ it('bogus', () => {
+ c.logStart('rutabaga');
+ c.logEnd('rutabaga');
+ sinon.assert.notCalled(issueCreateMetric.add);
+ sinon.assert.notCalled(issueUpdateMetric.add);
+ sinon.assert.notCalled(autocompleteMetric.add);
+ });
+
+ it('new-issue', () => {
+ c.logStart('new-issue', 'server-time');
+ c.logEnd('new-issue', 'server-time');
+ sinon.assert.notCalled(issueUpdateMetric.add);
+ sinon.assert.notCalled(autocompleteMetric.add);
+
+ sinon.assert.calledOnce(issueCreateMetric.add);
+ assert.isNumber(issueCreateMetric.add.getCall(0).args[0]);
+ assert.isString(issueCreateMetric.add.getCall(0).args[1].get('client_id'));
+ assert.equal(issueCreateMetric.add.getCall(0).args[1].get('host_name'),
+ 'rutabaga-version');
+ });
+
+ it('issue-update', () => {
+ c.logStart('issue-update', 'computer-time');
+ c.logEnd('issue-update', 'computer-time');
+ sinon.assert.notCalled(issueCreateMetric.add);
+ sinon.assert.notCalled(autocompleteMetric.add);
+
+ sinon.assert.calledOnce(issueUpdateMetric.add);
+ assert.isNumber(issueUpdateMetric.add.getCall(0).args[0]);
+ assert.isString(issueUpdateMetric.add.getCall(0).args[1].get('client_id'));
+ assert.equal(issueUpdateMetric.add.getCall(0).args[1].get('host_name'),
+ 'rutabaga-version');
+ });
+
+ it('populate-options', () => {
+ c.logStart('populate-options');
+ c.logEnd('populate-options');
+ sinon.assert.notCalled(issueCreateMetric.add);
+ sinon.assert.notCalled(issueUpdateMetric.add);
+ // Autocomplete is not called in issues category.
+ sinon.assert.notCalled(autocompleteMetric.add);
+
+ c = new ClientLogger('autocomplete');
+ autocompleteMetric = c.tsMon._userTimingMetrics[2].metric;
+ autocompleteMetric.add = sinon.spy();
+
+ c.logStart('populate-options', 'user-time');
+ c.logEnd('populate-options', 'user-time');
+ sinon.assert.notCalled(issueCreateMetric.add);
+ sinon.assert.notCalled(issueUpdateMetric.add);
+
+ sinon.assert.calledOnce(autocompleteMetric.add);
+ assert.isNumber(autocompleteMetric.add.getCall(0).args[0]);
+ assert.isString(autocompleteMetric.add.getCall(0).args[1].get('client_id'));
+ assert.equal(autocompleteMetric.add.getCall(0).args[1].get('host_name'),
+ 'rutabaga-version');
+ });
+ });
+
+ describe('logStart', () => {
+ let c;
+ let clock;
+ const currentTime = 5000;
+
+ beforeEach(() => {
+ c = new ClientLogger('rutabaga');
+ clock = sinon.useFakeTimers(currentTime);
+ });
+
+ afterEach(() => {
+ clock.restore();
+ sessionStorage.clear();
+ });
+
+ it('creates a new startedEvent if none', () => {
+ c.logStart('event-name', 'event-label');
+
+ sinon.assert.calledOnce(ga);
+ sinon.assert.calledWith(ga, 'send', 'event', 'rutabaga',
+ 'event-name-start', 'event-label');
+
+ const expectedStartedEvents = {
+ 'event-name': {
+ time: currentTime,
+ labels: {
+ 'event-label': currentTime,
+ },
+ },
+ };
+ assert.deepEqual(c.startedEvents, expectedStartedEvents);
+ assert.deepEqual(JSON.parse(sessionStorage[startedKey]),
+ expectedStartedEvents);
+ });
+
+ it('uses an existing startedEvent', () => {
+ c.startedEvents['event-name'] = {
+ time: 1234,
+ labels: {
+ 'event-label': 1000,
+ },
+ };
+ c.logStart('event-name', 'event-label');
+
+ sinon.assert.calledOnce(ga);
+ sinon.assert.calledWith(ga, 'send', 'event', 'rutabaga',
+ 'event-name-start', 'event-label');
+
+ // TODO(jeffcarp): Audit is this wanted behavior? Replacing event time
+ // but not label time?
+ const expectedStartedEvents = {
+ 'event-name': {
+ time: 1234,
+ labels: {
+ 'event-label': currentTime,
+ },
+ },
+ };
+ assert.deepEqual(c.startedEvents, expectedStartedEvents);
+ assert.deepEqual(JSON.parse(sessionStorage[startedKey]),
+ expectedStartedEvents);
+ });
+ });
+
+ describe('logPause', () => {
+ const startTime = 1234;
+ const currentTime = 5000;
+ let c;
+ let clock;
+
+ beforeEach(() => {
+ clock = sinon.useFakeTimers(currentTime);
+ c = new ClientLogger('rutabaga');
+ c.startedEvents['event-name'] = {
+ time: startTime,
+ labels: {
+ 'event-label': startTime,
+ },
+ };
+ });
+
+ afterEach(() => {
+ clock.restore();
+ sessionStorage.clear();
+ });
+
+ it('throws if no label given', () => {
+ assert.throws(() => {
+ c.logPause('bogus');
+ }, 'event with no label');
+ });
+
+ it('exits early if no start event exists', () => {
+ const originalStartedEvents = Object.assign(c.startedEvents, {});
+ c.logPause('bogus', 'fogus');
+ assert.deepEqual(c.startedEvents, originalStartedEvents);
+ });
+
+ it('exits early if no label exists', () => {
+ const originalStartedEvents = Object.assign(c.startedEvents, {});
+ c.logPause('event-name', 'fogus');
+ assert.deepEqual(c.startedEvents, originalStartedEvents);
+ });
+
+ it('adds elapsed time to start event', () => {
+ c.logPause('event-name', 'event-label');
+
+ const expectedStartedEvents = {
+ 'event-name': {
+ time: startTime,
+ labels: {
+ 'event-label': startTime,
+ },
+ elapsed: {
+ 'event-label': currentTime - startTime,
+ },
+ },
+ };
+ assert.deepEqual(c.startedEvents, expectedStartedEvents);
+ assert.deepEqual(
+ JSON.parse(sessionStorage['ClientLogger.rutabaga.started']),
+ expectedStartedEvents);
+ });
+ });
+
+ describe('logResume', () => {
+ let c;
+ let clock;
+ const startTimeEvent = 1234;
+ const startTimeLabel = 2345;
+ const labelElapsed = 4321;
+ const currentTime = 6000;
+
+ beforeEach(() => {
+ clock = sinon.useFakeTimers(currentTime);
+ c = new ClientLogger('rutabaga');
+ c.startedEvents['event-name'] = {
+ time: startTimeEvent,
+ labels: {
+ 'event-label': startTimeLabel,
+ },
+ elapsed: {
+ 'event-label': labelElapsed,
+ },
+ };
+ });
+
+ afterEach(() => {
+ clock.restore();
+ sessionStorage.clear();
+ });
+
+ it('throws if no label given', () => {
+ assert.throws(() => {
+ c.logResume('bogus');
+ }, 'no label');
+ });
+
+ it('exits early if no start event exists', () => {
+ const originalStartedEvents = Object.assign(c.startedEvents, {});
+ c.logResume('bogus', 'fogus');
+ assert.deepEqual(c.startedEvents, originalStartedEvents);
+ });
+
+ it('exits early if the label was never paused', () => {
+ c.startedEvents['event-name'] = {
+ time: startTimeEvent,
+ labels: {
+ 'event-label': startTimeLabel,
+ },
+ elapsed: {},
+ };
+
+ const originalStartedEvents = Object.assign(c.startedEvents, {});
+ c.logResume('event-name', 'event-label');
+ assert.deepEqual(c.startedEvents, originalStartedEvents);
+ });
+
+ it('sets start event time to current time', () => {
+ c.logResume('event-name', 'event-label');
+
+ const expectedStartedEvents = {
+ 'event-name': {
+ time: startTimeEvent,
+ labels: {
+ 'event-label': currentTime,
+ },
+ elapsed: {
+ 'event-label': labelElapsed,
+ },
+ },
+ };
+ assert.deepEqual(c.startedEvents, expectedStartedEvents);
+ assert.deepEqual(
+ JSON.parse(sessionStorage['ClientLogger.rutabaga.started']),
+ expectedStartedEvents);
+ });
+ });
+
+ describe('logEnd', () => {
+ let c;
+ let clock;
+ const startTimeEvent = 1234;
+ const startTimeLabel1 = 2345;
+ const startTimeLabel2 = 3456;
+ const currentTime = 10000;
+
+ beforeEach(() => {
+ c = new ClientLogger('rutabaga');
+ clock = sinon.useFakeTimers(currentTime);
+ c.tsMon.recordUserTiming = sinon.spy();
+ c.startedEvents = {
+ someEvent: {
+ time: startTimeEvent,
+ labels: {
+ label1: startTimeLabel1,
+ label2: startTimeLabel2,
+ },
+ },
+ };
+ });
+
+ afterEach(() => {
+ clock.restore();
+ });
+
+ it('returns early if no event was started', () => {
+ c.startedEvents = {someEvent: {}};
+ const originalStartedEvents = Object.assign(c.startedEvents, {});
+ c.logEnd('bogus');
+ sinon.assert.notCalled(window.ga);
+ assert.isNull(sessionStorage.getItem(startedKey));
+ assert.deepEqual(c.startedEvents, originalStartedEvents);
+ });
+
+ it('returns early if label was not started', () => {
+ c.startedEvents = {someEvent: {labels: {}}};
+ const originalStartedEvents = Object.assign(c.startedEvents, {});
+ c.logEnd('someEvent', 'bogus');
+ sinon.assert.notCalled(window.ga);
+ assert.isNull(sessionStorage.getItem(startedKey));
+ assert.deepEqual(c.startedEvents, originalStartedEvents);
+ });
+
+ it('does not log non-labeled events over threshold', () => {
+ c.startedEvents = {someEvent: {time: currentTime - 1000}};
+ c.logEnd('someEvent', null, 999);
+
+ sinon.assert.calledOnce(window.ga);
+ sinon.assert.calledWith(window.ga, 'send', 'event', 'rutabaga',
+ 'someEvent-end', null, undefined);
+ sinon.assert.notCalled(c.tsMon.recordUserTiming);
+ assert.equal(sessionStorage.getItem(startedKey), '{}');
+ });
+
+ it('does not log labeled events over threshold', () => {
+ const elapsedLabel2 = 2000;
+ c.startedEvents.someEvent.elapsed = {
+ label1: currentTime - 1000,
+ label2: elapsedLabel2,
+ };
+ c.logEnd('someEvent', 'label1', 999);
+
+ sinon.assert.calledOnce(window.ga);
+ sinon.assert.calledWith(window.ga, 'send', 'event', 'rutabaga',
+ 'someEvent-end', 'label1', undefined);
+ // TODO(jeffcarp): Feature: add GA event if over threshold.
+ sinon.assert.notCalled(c.tsMon.recordUserTiming);
+
+ const expectedStartedEvents = {
+ someEvent: {
+ time: startTimeEvent,
+ labels: {
+ label2: startTimeLabel2,
+ },
+ elapsed: {
+ label2: elapsedLabel2,
+ },
+ },
+ };
+ assert.deepEqual(c.startedEvents, expectedStartedEvents);
+ assert.deepEqual(JSON.parse(sessionStorage[startedKey]),
+ expectedStartedEvents);
+ });
+
+ it('calls ga() with timing and event info for all labels', () => {
+ const label1Elapsed = 1000;
+ const label2Elapsed = 2500;
+ c.startedEvents.someEvent.elapsed = {
+ label1: label1Elapsed,
+ label2: label2Elapsed,
+ };
+ c.logEnd('someEvent');
+
+ assert.deepEqual(ga.getCall(0).args, [
+ 'send', 'timing', {
+ timingCategory: 'rutabaga',
+ timingValue: currentTime - startTimeEvent,
+ timingVar: 'someEvent',
+ }]);
+
+ assert.deepEqual(ga.getCall(1).args, [
+ 'send', 'timing', {
+ timingCategory: 'rutabaga',
+ timingValue: (currentTime - startTimeLabel1) + label1Elapsed,
+ timingVar: 'someEvent',
+ timingLabel: 'label1',
+ }]);
+ assert.deepEqual(ga.getCall(2).args, [
+ 'send', 'timing', {
+ timingCategory: 'rutabaga',
+ timingValue: (currentTime - startTimeLabel2) + label2Elapsed,
+ timingVar: 'someEvent',
+ timingLabel: 'label2',
+ }]);
+ assert.deepEqual(ga.getCall(3).args, [
+ 'send', 'event', 'rutabaga', 'someEvent-end', undefined, undefined,
+ ]);
+ assert.deepEqual(c.tsMon.recordUserTiming.getCall(0).args, [
+ 'rutabaga', 'someEvent', null, currentTime - startTimeEvent,
+ ]);
+ assert.deepEqual(c.tsMon.recordUserTiming.getCall(1).args, [
+ 'rutabaga', 'someEvent', 'label1',
+ (currentTime - startTimeLabel1) + label1Elapsed,
+ ]);
+ assert.deepEqual(c.tsMon.recordUserTiming.getCall(2).args, [
+ 'rutabaga', 'someEvent', 'label2',
+ (currentTime - startTimeLabel2) + label2Elapsed,
+ ]);
+
+ assert.deepEqual(c.startedEvents, {});
+ assert.equal(sessionStorage.getItem(startedKey), '{}');
+ });
+
+ it('calling with a label calls ga() only for that label', () => {
+ const label1Elapsed = 1000;
+ const label2Elapsed = 2500;
+ c.startedEvents.someEvent.elapsed = {
+ label1: label1Elapsed,
+ label2: label2Elapsed,
+ };
+ c.logEnd('someEvent', 'label2');
+
+ assert.deepEqual(ga.getCall(0).args, [
+ 'send', 'timing', {
+ timingCategory: 'rutabaga',
+ timingValue: (currentTime - startTimeLabel2) + label2Elapsed,
+ timingVar: 'someEvent',
+ timingLabel: 'label2',
+ }]);
+ assert.deepEqual(window.ga.getCall(1).args, [
+ 'send', 'event', 'rutabaga', 'someEvent-end', 'label2', undefined,
+ ]);
+ sinon.assert.calledOnce(c.tsMon.recordUserTiming);
+ sinon.assert.calledWith(c.tsMon.recordUserTiming, 'rutabaga',
+ 'someEvent', 'label2', (currentTime - startTimeLabel2) + label2Elapsed);
+
+ const expectedStartedEvents = {
+ someEvent: {
+ time: startTimeEvent,
+ labels: {
+ label1: startTimeLabel1,
+ },
+ elapsed: {
+ label1: label1Elapsed,
+ },
+ },
+ };
+ assert.deepEqual(c.startedEvents, expectedStartedEvents);
+ assert.deepEqual(JSON.parse(sessionStorage[startedKey]),
+ expectedStartedEvents);
+ });
+
+ it('calling logStart, logPause, logResume, and logEnd works for labels',
+ () => {
+ let countedElapsedTime = 0;
+ c.logStart('someEvent', 'label1');
+ clock.tick(1000);
+ countedElapsedTime += 1000;
+ c.logPause('someEvent', 'label1');
+ clock.tick(1000);
+ c.logResume('someEvent', 'label1');
+ clock.tick(1000);
+ countedElapsedTime += 1000;
+ c.logEnd('someEvent', 'label1');
+
+ assert.deepEqual(ga.getCall(0).args, [
+ 'send', 'event', 'rutabaga', 'someEvent-start', 'label1', undefined,
+ ]);
+ assert.deepEqual(ga.getCall(1).args, [
+ 'send', 'timing', {
+ timingCategory: 'rutabaga',
+ timingValue: countedElapsedTime,
+ timingVar: 'someEvent',
+ timingLabel: 'label1',
+ }]);
+ assert.deepEqual(window.ga.getCall(2).args, [
+ 'send', 'event', 'rutabaga', 'someEvent-end', 'label1', undefined,
+ ]);
+ sinon.assert.calledOnce(c.tsMon.recordUserTiming);
+ sinon.assert.calledWith(c.tsMon.recordUserTiming, 'rutabaga',
+ 'someEvent', 'label1', countedElapsedTime);
+
+ const expectedStartedEvents = {
+ someEvent: {
+ time: startTimeEvent,
+ labels: {
+ label2: startTimeLabel2,
+ },
+ elapsed: {},
+ },
+ };
+ assert.deepEqual(c.startedEvents, expectedStartedEvents);
+ assert.deepEqual(JSON.parse(sessionStorage[startedKey]),
+ expectedStartedEvents);
+ });
+
+ it('logs some events when others are above threshold', () => {
+ c.startedEvents = {
+ someEvent: {
+ time: 9500,
+ labels: {
+ overThresholdWithoutElapsed: 8000,
+ overThresholdWithElapsed: 9500,
+ underThresholdWithoutElapsed: 9750,
+ underThresholdWithElapsed: 9650,
+ exactlyOnThresholdWithoutElapsed: 9001,
+ exactlyOnThresholdWithElapsed: 9002,
+ },
+ elapsed: {
+ overThresholdWithElapsed: 1000,
+ underThresholdWithElapsed: 100,
+ exactlyOnThresholdWithElapsed: 1,
+ },
+ },
+ };
+ c.logEnd('someEvent', null, 999);
+
+ // Verify ga() calls.
+ assert.equal(window.ga.getCalls().length, 6);
+ assert.deepEqual(ga.getCall(0).args, [
+ 'send', 'timing', {
+ timingCategory: 'rutabaga',
+ timingValue: 500,
+ timingVar: 'someEvent',
+ }]);
+ assert.deepEqual(ga.getCall(1).args, [
+ 'send', 'timing', {
+ timingCategory: 'rutabaga',
+ timingValue: 250,
+ timingVar: 'someEvent',
+ timingLabel: 'underThresholdWithoutElapsed',
+ }]);
+ assert.deepEqual(ga.getCall(2).args, [
+ 'send', 'timing', {
+ timingCategory: 'rutabaga',
+ timingValue: 450,
+ timingVar: 'someEvent',
+ timingLabel: 'underThresholdWithElapsed',
+ }]);
+ assert.deepEqual(ga.getCall(3).args, [
+ 'send', 'timing', {
+ timingCategory: 'rutabaga',
+ timingValue: 999,
+ timingVar: 'someEvent',
+ timingLabel: 'exactlyOnThresholdWithoutElapsed',
+ }]);
+ assert.deepEqual(ga.getCall(4).args, [
+ 'send', 'timing', {
+ timingCategory: 'rutabaga',
+ timingValue: 999,
+ timingVar: 'someEvent',
+ timingLabel: 'exactlyOnThresholdWithElapsed',
+ }]);
+ assert.deepEqual(ga.getCall(5).args, [
+ 'send', 'event', 'rutabaga', 'someEvent-end', null, undefined,
+ ]);
+
+ // Verify ts_mon.recordUserTiming() calls.
+ assert.equal(c.tsMon.recordUserTiming.getCalls().length, 5);
+ assert.deepEqual(c.tsMon.recordUserTiming.getCall(0).args, [
+ 'rutabaga', 'someEvent', null, 500,
+ ]);
+ assert.deepEqual(c.tsMon.recordUserTiming.getCall(1).args, [
+ 'rutabaga', 'someEvent', 'underThresholdWithoutElapsed', 250,
+ ]);
+ assert.deepEqual(c.tsMon.recordUserTiming.getCall(2).args, [
+ 'rutabaga', 'someEvent', 'underThresholdWithElapsed', 450,
+ ]);
+ assert.deepEqual(c.tsMon.recordUserTiming.getCall(3).args, [
+ 'rutabaga', 'someEvent', 'exactlyOnThresholdWithoutElapsed', 999,
+ ]);
+ assert.deepEqual(c.tsMon.recordUserTiming.getCall(4).args, [
+ 'rutabaga', 'someEvent', 'exactlyOnThresholdWithElapsed', 999,
+ ]);
+ assert.deepEqual(c.startedEvents, {});
+ assert.deepEqual(JSON.parse(sessionStorage[startedKey]), {});
+ });
+ });
+});