static_src/monitoring/client-logger.test.js

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]), {});
    });
  });
});