From f061bbf8281e8b9a69671103269b34f6353145d2 Mon Sep 17 00:00:00 2001 From: dschom Date: Mon, 19 Dec 2022 13:31:10 -0800 Subject: [PATCH] fix(content): Fix buggy timing metrics MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Because: - We could see in Sentry that various times provided to metrics endpoint were consistently off. This Commit: - Creates an abstraction around the performance API to isolate some of its complexities. - Tries to use the performance API where possible. - Address discrepancies between performance API timestamps and system time.. The assumption that the clock used by Date and the clock used by the performance API are somehow in sync is likely the reason for the generation of erroneous data. It is very likely that there is a significant clock skew found between the monotonic clock used by the performance API and current state of the system clock. There appears to be a lot of nuance here, and the exact way this plays out depends on the OS, browser, and browser version, and if the machine has been put into sleep mode. One thing is clear, mixing the performance API timestamps and Date timestamps appears to not work very well. - Adds support for using L2 timings, and uses these timings when possible. - Adds a performance fallback class that can fill in for situations where the performance API is missing. - Adds some logic around timing values that should be ignored when set to 0. - Prefers the performance API's clock when possible, since it’s resilient to skewed metrics due to a computer being put to sleep. - For browser’s that do not support the performance api, we will not produce timing data. - For browser’s that do not support the performance api, we will make a best effort to produce timing data; however, if we detect the machine enters sleep mode during data collection, the data will be deemed unreliable and will not be recorded. --- .../app/scripts/lib/metrics.js | 25 +- .../app/tests/spec/lib/metrics.js | 2027 +++++++++-------- packages/fxa-shared/speed-trap/events.js | 8 +- packages/fxa-shared/speed-trap/index.js | 8 + .../speed-trap/navigation-timing.js | 136 +- .../speed-trap/performance-factory.js | 88 + packages/fxa-shared/speed-trap/speed-trap.js | 61 +- packages/fxa-shared/speed-trap/timers.js | 19 +- .../fxa-shared/speed-trap/timing-fields.js | 40 + 9 files changed, 1337 insertions(+), 1075 deletions(-) create mode 100644 packages/fxa-shared/speed-trap/performance-factory.js create mode 100644 packages/fxa-shared/speed-trap/timing-fields.js diff --git a/packages/fxa-content-server/app/scripts/lib/metrics.js b/packages/fxa-content-server/app/scripts/lib/metrics.js index 48247de8f5..19256ae0e4 100644 --- a/packages/fxa-content-server/app/scripts/lib/metrics.js +++ b/packages/fxa-content-server/app/scripts/lib/metrics.js @@ -145,7 +145,14 @@ function marshallEmailDomain(email) { } function Metrics(options = {}) { - this._speedTrap = new SpeedTrap(); + + // Supplying a custom start time is a good way to create invalid metrics. We + // are deprecating this option. + if (options.startTime !== undefined) { + throw new Error('Supplying an external start time is no longer supported!'); + } + + this._speedTrap = new SpeedTrap(options); this._speedTrap.init(); // `timers` and `events` are part of the public API @@ -184,9 +191,7 @@ function Metrics(options = {}) { this._screenWidth = options.screenWidth || NOT_REPORTED_VALUE; this._sentryMetrics = options.sentryMetrics; this._service = options.service || NOT_REPORTED_VALUE; - // if navigationTiming is supported, the baseTime will be from - // navigationTiming.navigationStart, otherwise Date.now(). - this._startTime = options.startTime || this._speedTrap.baseTime; + this._startTime = this._speedTrap.baseTime; this._syncEngines = options.syncEngines || []; this._uid = options.uid || NOT_REPORTED_VALUE; this._metricsEnabled = options.metricsEnabled ?? true; @@ -448,7 +453,7 @@ _.extend(Metrics.prototype, Backbone.Events, { experiments: flattenHashIntoArrayOfObjects(this._activeExperiments), flowBeginTime: flowData.flowBeginTime, flowId: flowData.flowId, - flushTime: Date.now(), + flushTime: this._speedTrap.now(), initialView: this._initialViewName, isSampledUser: this._isSampledUser, lang: this._lang, @@ -529,6 +534,16 @@ _.extend(Metrics.prototype, Backbone.Events, { if (!this._metricsEnabled) { return Promise.resolve(true); } + + // This case will only be hit for legacy browsers that + // don't support the performance API and went into sleep + // state. During metrics collection. In these cases the + // metrics generated are not reliable and should not be + // reported. + if (this._speedTrap.isInSuspectState()) { + return Promise.resolve() + } + const url = `${this._collector}/metrics`; const payload = JSON.stringify(data); diff --git a/packages/fxa-content-server/app/tests/spec/lib/metrics.js b/packages/fxa-content-server/app/tests/spec/lib/metrics.js index 1dd69cb1fb..d4712ea5b7 100644 --- a/packages/fxa-content-server/app/tests/spec/lib/metrics.js +++ b/packages/fxa-content-server/app/tests/spec/lib/metrics.js @@ -15,6 +15,7 @@ import Notifier from 'lib/channels/notifier'; import sinon from 'sinon'; import SubscriptionModel from 'models/subscription'; import WindowMock from '../../mocks/window'; +import { getFallbackPerformanceApi, getRealPerformanceApi } from 'fxa-shared/speed-trap/performance-factory'; const FLOW_ID = '0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef'; @@ -23,186 +24,137 @@ const MARKETING_CAMPAIGN = 'campaign1'; const MARKETING_CAMPAIGN_URL = 'https://accounts.firefox.com'; const BAD_METRIC_ERROR_PREFIX = 'Bad metric encountered:'; -describe('lib/metrics', () => { - let environment; - let metrics; - let notifier; - let sentryMock; - let windowMock; - let xhr; - function createMetrics(options = {}) { - environment = new Environment(windowMock); +const performanceApis = [ + { name: 'real - L2', api: getRealPerformanceApi(), useL1Timings: false }, + { name: 'real - L1', api: getRealPerformanceApi(), useL1Timings: true }, + { name: 'fallback', api: getFallbackPerformanceApi() } +] - notifier = new Notifier(); - sinon.spy(notifier, 'on'); +for (const performanceApi of performanceApis) { - xhr = { ajax() {} }; + describe('lib/metrics/' + performanceApi.name, () => { + let environment; + let metrics; + let notifier; + let sentryMock; + let windowMock; + let xhr; + let startTime; - sentryMock = { - captureException: sinon.spy(), - }; + function createMetrics(options = {}) { + environment = new Environment(windowMock); - metrics = new Metrics( - _.defaults(options, { - brokerType: 'fx-desktop-v3', - clientHeight: 966, - clientWidth: 1033, - context: 'fx_desktop_v3', - devicePixelRatio: 2, - entrypoint: 'menupanel', - entrypointExperiment: 'wibble', - entrypointVariation: 'blee', - environment, - inactivityFlushMs: 50, - isSampledUser: true, - lang: 'db_LB', - notifier, - screenHeight: 1200, - screenWidth: 1600, - sentryMetrics: sentryMock, - service: 'sync', - startTime: 1439233336187, - uid: '0ae7fe2b244f4a789857dff3ae263927', - uniqueUserId: '0ae7fe2b-244f-4a78-9857-dff3ae263927', - utmCampaign: 'utm_campaign', - utmContent: 'utm_content', - utmMedium: 'utm_medium', - utmSource: 'none', - utmTerm: '', - window: windowMock, - xhr, - }) - ); - sinon.spy(metrics, '_initializeSubscriptionModel'); - } + notifier = new Notifier(); + sinon.spy(notifier, 'on'); - beforeEach(() => { - windowMock = new WindowMock(); - windowMock.document.referrer = 'https://marketplace.firefox.com'; - $(windowMock.document.body).attr('data-flow-id', FLOW_ID); - $(windowMock.document.body).attr('data-flow-begin', FLOW_BEGIN_TIME); + xhr = { ajax() {} }; - createMetrics(); - }); + sentryMock = { + captureException: sinon.spy(), + }; - afterEach(() => { - metrics.destroy(); - metrics = null; - }); + metrics = new Metrics( + _.defaults(options, { + performance: performanceApi.api, + useL1Timings: performanceApi.useL1Timings, + brokerType: 'fx-desktop-v3', + clientHeight: 966, + clientWidth: 1033, + context: 'fx_desktop_v3', + devicePixelRatio: 2, + entrypoint: 'menupanel', + entrypointExperiment: 'wibble', + entrypointVariation: 'blee', + environment, + inactivityFlushMs: 50, + isSampledUser: true, + lang: 'db_LB', + notifier, + screenHeight: 1200, + screenWidth: 1600, + sentryMetrics: sentryMock, + service: 'sync', + uid: '0ae7fe2b244f4a789857dff3ae263927', + uniqueUserId: '0ae7fe2b-244f-4a78-9857-dff3ae263927', + utmCampaign: 'utm_campaign', + utmContent: 'utm_content', + utmMedium: 'utm_medium', + utmSource: 'none', + utmTerm: '', + window: windowMock, + xhr, + }) + ); - it('has the expected notifications', () => { - assert.lengthOf(Object.keys(metrics.notifications), 8); + // Peak at start time. + startTime = metrics._startTime; + sinon.spy(metrics, '_initializeSubscriptionModel'); + } - assert.isTrue('flow.initialize' in metrics.notifications); - assert.isTrue('flow.event' in metrics.notifications); - assert.isTrue('set-email-domain' in metrics.notifications); - assert.isTrue('set-sync-engines' in metrics.notifications); - assert.equal( - metrics.notifications['subscription.initialize'], - '_initializeSubscriptionModel' - ); - assert.isTrue('set-uid' in metrics.notifications); - assert.isTrue('clear-uid' in metrics.notifications); - assert.isTrue('once!view-shown' in metrics.notifications); - }); - - it('observable flow state is correct', () => { - assert.isUndefined(metrics.getFlowModel()); - assert.deepEqual(metrics.getFlowEventMetadata(), { - deviceId: undefined, - entrypoint: 'menupanel', - entrypointExperiment: 'wibble', - entrypointVariation: 'blee', - flowBeginTime: undefined, - flowId: undefined, - planId: undefined, - productId: undefined, - utmCampaign: 'utm_campaign', - utmContent: 'utm_content', - utmMedium: 'utm_medium', - utmSource: undefined, - utmTerm: undefined, - }); - }); - - it('observable subscription state is correct', () => { - assert.equal(metrics._initializeSubscriptionModel.callCount, 0); - const subscriptionModel = metrics.getSubscriptionModel(); - assert.instanceOf(subscriptionModel, SubscriptionModel); - assert.equal(subscriptionModel.get('planId'), null); - assert.equal(subscriptionModel.get('productId'), null); - }); - - it('deviceId defaults to NOT_REPORTED_VALUE', () => { - assert.equal(metrics.getAllData().deviceId, 'none'); - }); - - describe('trigger flow.initialize event', () => { beforeEach(() => { - notifier.trigger('flow.initialize'); + windowMock = new WindowMock(); + windowMock.document.referrer = 'https://marketplace.firefox.com'; + $(windowMock.document.body).attr('data-flow-id', FLOW_ID); + $(windowMock.document.body).attr('data-flow-begin', FLOW_BEGIN_TIME); + + createMetrics(); + }); + + afterEach(() => { + metrics.destroy(); + metrics = null; + }); + + it('has the expected notifications', () => { + assert.lengthOf(Object.keys(metrics.notifications), 8); + + assert.isTrue('flow.initialize' in metrics.notifications); + assert.isTrue('flow.event' in metrics.notifications); + assert.isTrue('set-email-domain' in metrics.notifications); + assert.isTrue('set-sync-engines' in metrics.notifications); + assert.equal( + metrics.notifications['subscription.initialize'], + '_initializeSubscriptionModel' + ); + assert.isTrue('set-uid' in metrics.notifications); + assert.isTrue('clear-uid' in metrics.notifications); + assert.isTrue('once!view-shown' in metrics.notifications); }); it('observable flow state is correct', () => { - assert.equal(metrics.getFlowModel().get('flowId'), FLOW_ID); - assert.equal(metrics.getFlowModel().get('flowBegin'), FLOW_BEGIN_TIME); - const metadata = metrics.getFlowEventMetadata(); - assert.match(metadata.deviceId, /^[0-9a-f]{32}$/); - assert.equal(metadata.flowBeginTime, FLOW_BEGIN_TIME); - assert.equal(metadata.flowId, FLOW_ID); - assert.equal(metadata.utmCampaign, 'utm_campaign'); - assert.equal(metadata.utmContent, 'utm_content'); - assert.equal(metadata.utmMedium, 'utm_medium'); - assert.equal(metadata.utmSource, undefined); - assert.equal(metadata.utmTerm, undefined); + assert.isUndefined(metrics.getFlowModel()); + assert.deepEqual(metrics.getFlowEventMetadata(), { + deviceId: undefined, + entrypoint: 'menupanel', + entrypointExperiment: 'wibble', + entrypointVariation: 'blee', + flowBeginTime: undefined, + flowId: undefined, + planId: undefined, + productId: undefined, + utmCampaign: 'utm_campaign', + utmContent: 'utm_content', + utmMedium: 'utm_medium', + utmSource: undefined, + utmTerm: undefined, + }); }); - it('flow events are triggered correctly', () => { - notifier.trigger('flow.event', { event: 'foo', viewName: 'signin' }); - notifier.trigger('flow.event', { event: 'foo', viewName: 'signin' }); - notifier.trigger('flow.event', { - event: 'bar', - viewName: 'oauth.signin', - }); - notifier.trigger('flow.event', { event: 'baz' }); - - const events = metrics.getFilteredData().events; - assert.equal(events.length, 4); - assert.equal(events[0].type, 'flow.signin.foo'); - assert.equal(events[1].type, 'flow.signin.foo'); - assert.equal(events[2].type, 'flow.signin.bar'); - assert.equal(events[3].type, 'flow.baz'); + it('observable subscription state is correct', () => { + assert.equal(metrics._initializeSubscriptionModel.callCount, 0); + const subscriptionModel = metrics.getSubscriptionModel(); + assert.instanceOf(subscriptionModel, SubscriptionModel); + assert.equal(subscriptionModel.get('planId'), null); + assert.equal(subscriptionModel.get('productId'), null); }); - it('flow events are triggered correctly with once=true', () => { - notifier.trigger('flow.event', { - event: 'foo', - once: true, - viewName: 'signin', - }); - notifier.trigger('flow.event', { - event: 'foo', - once: true, - viewName: 'signin', - }); - notifier.trigger('flow.event', { - event: 'foo', - once: true, - viewName: 'signup', - }); - - const events = metrics.getFilteredData().events; - assert.equal(events[0].type, 'flow.signin.foo'); - assert.equal(events[1].type, 'flow.signup.foo'); + it('deviceId defaults to NOT_REPORTED_VALUE', () => { + assert.equal(metrics.getAllData().deviceId, 'none'); }); - describe('trigger flow.initialize event with fresh data', () => { + describe('trigger flow.initialize event', () => { beforeEach(() => { - $(windowMock.document.body).attr( - 'data-flow-id', - 'deadbeefdeadbeefdeadbeefdeadbeefdeadbeefdeadbeefdeadbeefdeadbeef' - ); - $(windowMock.document.body).attr('data-flow-begin', 1484930216699); notifier.trigger('flow.initialize'); }); @@ -219,905 +171,970 @@ describe('lib/metrics', () => { assert.equal(metadata.utmSource, undefined); assert.equal(metadata.utmTerm, undefined); }); - }); - }); - describe('trigger subscription.initialize event with explicit model', () => { - let subscriptionModel; + it('flow events are triggered correctly', () => { + notifier.trigger('flow.event', { event: 'foo', viewName: 'signin' }); + notifier.trigger('flow.event', { event: 'foo', viewName: 'signin' }); + notifier.trigger('flow.event', { + event: 'bar', + viewName: 'oauth.signin', + }); + notifier.trigger('flow.event', { event: 'baz' }); - beforeEach(() => { - subscriptionModel = new SubscriptionModel({ - planId: 'foo', - productId: 'bar', - }); - notifier.trigger('subscription.initialize', subscriptionModel); - }); - - it('observable subscription state is correct', () => { - assert.equal(metrics._initializeSubscriptionModel.callCount, 1); - assert.equal(metrics.getSubscriptionModel(), subscriptionModel); - assert.equal(subscriptionModel.get('planId'), 'foo'); - assert.equal(subscriptionModel.get('productId'), 'bar'); - }); - - it('subscription state is available in metrics metadata', () => { - const metadata = metrics.getFlowEventMetadata(); - assert.equal(metadata.planId, 'foo'); - assert.equal(metadata.productId, 'bar'); - }); - }); - - describe('trigger subscription.initialize event with url params', () => { - beforeEach(() => { - windowMock.location.search = 'foo=bar&plan=wibble'; - windowMock.location.pathname = '/subscriptions/products/prod_blee'; - notifier.trigger('subscription.initialize'); - }); - - it('observable subscription state is correct', () => { - assert.equal(metrics._initializeSubscriptionModel.callCount, 1); - const subscriptionModel = metrics.getSubscriptionModel(); - assert.instanceOf(subscriptionModel, SubscriptionModel); - assert.equal(subscriptionModel.get('planId'), 'wibble'); - assert.equal(subscriptionModel.get('productId'), 'prod_blee'); - }); - }); - - describe('getFilteredData', () => { - beforeEach(() => { - sinon.stub(metrics, 'getFlowEventMetadata').returns({ - flowBeginTime: 123, - flowId: 'flow-id', - }); - sinon.stub; - - metrics._setInitialView({ viewName: 'signup' }); - metrics.logNumStoredAccounts(1); - metrics.logUserPreferences('pref', 'value'); - notifier.trigger( - 'subscription.initialize', - new SubscriptionModel({ - planId: 'plid', - productId: 'pid', - }) - ); - }); - - it('gets data that is allowed to be sent to the server', () => { - const filteredData = metrics.getFilteredData(); - - // ensure results are filtered and no unexpected data makes it through. - assert.lengthOf( - Object.keys(_.omit(filteredData, metrics.ALLOWED_FIELDS)), - 0 - ); - }); - - it('gets non-optional fields', () => { - const filteredData = metrics.getFilteredData(); - assert.lengthOf(Object.keys(filteredData), 37); - - assert.isTrue(filteredData.hasOwnProperty('events')); - assert.isTrue(filteredData.hasOwnProperty('timers')); - assert.isTrue(filteredData.hasOwnProperty('navigationTiming')); - assert.isTrue(filteredData.hasOwnProperty('duration')); - - assert.equal(filteredData.broker, 'fx-desktop-v3'); - assert.equal(filteredData.context, 'fx_desktop_v3'); - assert.isTrue(filteredData.hasOwnProperty('deviceId')); - assert.equal(filteredData.emailDomain, 'none'); - assert.equal(filteredData.entrypoint, 'menupanel'); - assert.equal(filteredData.entrypoint_experiment, 'wibble'); - assert.equal(filteredData.entrypoint_variation, 'blee'); - assert.deepEqual(filteredData.experiments, []); - assert.equal(filteredData.flowBeginTime, 123); - assert.equal(filteredData.flowId, 'flow-id'); - assert.isNumber(filteredData.flushTime); - assert.equal(filteredData.initialView, 'signup'); - assert.isTrue(filteredData.isSampledUser); - assert.equal(filteredData.lang, 'db_LB'); - assert.deepEqual(filteredData.marketing, []); - assert.equal(filteredData.numStoredAccounts, 1); - assert.equal(filteredData.newsletters, 'none'); - - assert.equal(filteredData.planId, 'plid'); - assert.equal(filteredData.productId, 'pid'); - - assert.equal(filteredData.referrer, 'https://marketplace.firefox.com'); - assert.equal(filteredData.screen.width, 1600); - assert.equal(filteredData.screen.height, 1200); - assert.equal(filteredData.screen.devicePixelRatio, 2); - assert.equal(filteredData.screen.clientWidth, 1033); - assert.equal(filteredData.screen.clientHeight, 966); - assert.equal(filteredData.service, 'sync'); - assert.equal(filteredData.startTime, 1439233336187); - assert.deepEqual(filteredData.syncEngines, []); - - assert.equal(filteredData.uid, '0ae7fe2b244f4a789857dff3ae263927'); - assert.equal( - filteredData.uniqueUserId, - '0ae7fe2b-244f-4a78-9857-dff3ae263927' - ); - - assert.deepEqual(filteredData.userPreferences, { - pref: true, + const events = metrics.getFilteredData().events; + assert.equal(events.length, 4); + assert.equal(events[0].type, 'flow.signin.foo'); + assert.equal(events[1].type, 'flow.signin.foo'); + assert.equal(events[2].type, 'flow.signin.bar'); + assert.equal(events[3].type, 'flow.baz'); }); - assert.equal(filteredData.utm_campaign, 'utm_campaign'); - assert.equal(filteredData.utm_content, 'utm_content'); - assert.equal(filteredData.utm_medium, 'utm_medium'); - assert.equal(filteredData.utm_source, 'none'); - assert.equal(filteredData.utm_term, 'none'); - }); - }); + it('flow events are triggered correctly with once=true', () => { + notifier.trigger('flow.event', { + event: 'foo', + once: true, + viewName: 'signin', + }); + notifier.trigger('flow.event', { + event: 'foo', + once: true, + viewName: 'signin', + }); + notifier.trigger('flow.event', { + event: 'foo', + once: true, + viewName: 'signup', + }); - describe('logEvent', () => { - it('adds events to output data', () => { - sinon.stub(metrics, 'flush').resolves({}); + const events = metrics.getFilteredData().events; + assert.equal(events[0].type, 'flow.signin.foo'); + assert.equal(events[1].type, 'flow.signup.foo'); + }); - metrics.logEvent('event1'); - metrics.logEvent('event2'); - metrics.logEvent('event3'); + describe('trigger flow.initialize event with fresh data', () => { + beforeEach(() => { + $(windowMock.document.body).attr( + 'data-flow-id', + 'deadbeefdeadbeefdeadbeefdeadbeefdeadbeefdeadbeefdeadbeefdeadbeef' + ); + $(windowMock.document.body).attr('data-flow-begin', 1484930216699); + notifier.trigger('flow.initialize'); + }); - const filteredData = metrics.getFilteredData(); - assert.equal(filteredData.events.length, 3); - assert.equal(filteredData.events[0].type, 'event1'); - assert.equal(filteredData.events[1].type, 'event2'); - assert.equal(filteredData.events[2].type, 'event3'); - - assert.isFalse(metrics.flush.called); + it('observable flow state is correct', () => { + assert.equal(metrics.getFlowModel().get('flowId'), FLOW_ID); + assert.equal(metrics.getFlowModel().get('flowBegin'), FLOW_BEGIN_TIME); + const metadata = metrics.getFlowEventMetadata(); + assert.match(metadata.deviceId, /^[0-9a-f]{32}$/); + assert.equal(metadata.flowBeginTime, FLOW_BEGIN_TIME); + assert.equal(metadata.flowId, FLOW_ID); + assert.equal(metadata.utmCampaign, 'utm_campaign'); + assert.equal(metadata.utmContent, 'utm_content'); + assert.equal(metadata.utmMedium, 'utm_medium'); + assert.equal(metadata.utmSource, undefined); + assert.equal(metadata.utmTerm, undefined); + }); + }); }); - it('flushes events as soon as a screen.* event is logged', () => { - sinon.stub(metrics, 'flush').resolves({}); + describe('trigger subscription.initialize event with explicit model', () => { + let subscriptionModel; - metrics.logEvent('event1'); - metrics.logEvent('event2'); - metrics.logEvent('event3'); - metrics.logEvent('screen.signin'); + beforeEach(() => { + subscriptionModel = new SubscriptionModel({ + planId: 'foo', + productId: 'bar', + }); + notifier.trigger('subscription.initialize', subscriptionModel); + }); - assert.isTrue(metrics.flush.calledOnce); + it('observable subscription state is correct', () => { + assert.equal(metrics._initializeSubscriptionModel.callCount, 1); + assert.equal(metrics.getSubscriptionModel(), subscriptionModel); + assert.equal(subscriptionModel.get('planId'), 'foo'); + assert.equal(subscriptionModel.get('productId'), 'bar'); + }); + + it('subscription state is available in metrics metadata', () => { + const metadata = metrics.getFlowEventMetadata(); + assert.equal(metadata.planId, 'foo'); + assert.equal(metadata.productId, 'bar'); + }); }); - it('flushes events as soon as a *.complete event is logged', () => { - sinon.stub(metrics, 'flush').resolves({}); + describe('trigger subscription.initialize event with url params', () => { + beforeEach(() => { + windowMock.location.search = 'foo=bar&plan=wibble'; + windowMock.location.pathname = '/subscriptions/products/prod_blee'; + notifier.trigger('subscription.initialize'); + }); - metrics.logEvent('event1'); - metrics.logEvent('event2'); - metrics.logEvent('event3'); - metrics.logEvent('signin.complete'); - - assert.isTrue(metrics.flush.calledOnce); + it('observable subscription state is correct', () => { + assert.equal(metrics._initializeSubscriptionModel.callCount, 1); + const subscriptionModel = metrics.getSubscriptionModel(); + assert.instanceOf(subscriptionModel, SubscriptionModel); + assert.equal(subscriptionModel.get('planId'), 'wibble'); + assert.equal(subscriptionModel.get('productId'), 'prod_blee'); + }); }); - it('flushes events as soon as a *.success event is logged', () => { - sinon.stub(metrics, 'flush').resolves({}); + describe('getFilteredData', () => { + beforeEach(() => { + sinon.stub(metrics, 'getFlowEventMetadata').returns({ + flowBeginTime: 123, + flowId: 'flow-id', + }); + sinon.stub; - metrics.logEvent('event1'); - metrics.logEvent('event2'); - metrics.logEvent('event3'); - metrics.logEvent('signin.success'); + metrics._setInitialView({ viewName: 'signup' }); + metrics.logNumStoredAccounts(1); + metrics.logUserPreferences('pref', 'value'); + notifier.trigger( + 'subscription.initialize', + new SubscriptionModel({ + planId: 'plid', + productId: 'pid', + }) + ); + }); - assert.isTrue(metrics.flush.calledOnce); - }); - }); + it('gets data that is allowed to be sent to the server', () => { + const filteredData = metrics.getFilteredData(); - describe('logEventOnce', () => { - it('adds events to output data', () => { - metrics.logEventOnce('event1'); - metrics.logEventOnce('event1'); - metrics.logEventOnce('event3'); + // ensure results are filtered and no unexpected data makes it through. + assert.lengthOf( + Object.keys(_.omit(filteredData, metrics.ALLOWED_FIELDS)), + 0 + ); + }); - const filteredData = metrics.getFilteredData(); - assert.equal(filteredData.events.length, 2); - assert.equal(filteredData.events[0].type, 'event1'); - assert.equal(filteredData.events[1].type, 'event3'); - }); - }); + it('gets non-optional fields', () => { + const filteredData = metrics.getFilteredData(); + assert.lengthOf(Object.keys(filteredData), 37); - describe('markEventLogged', () => { - it('does not log an event if marked logged', () => { - metrics.markEventLogged('event2'); - metrics.logEventOnce('event1'); - metrics.logEventOnce('event2'); + assert.isTrue(filteredData.hasOwnProperty('events')); + assert.isTrue(filteredData.hasOwnProperty('timers')); + assert.isTrue(filteredData.hasOwnProperty('navigationTiming')); + assert.isTrue(filteredData.hasOwnProperty('duration')); - const filteredData = metrics.getFilteredData(); - assert.equal(filteredData.events.length, 1); - assert.equal(filteredData.events[0].type, 'event1'); - }); - }); + assert.equal(filteredData.broker, 'fx-desktop-v3'); + assert.equal(filteredData.context, 'fx_desktop_v3'); + assert.isTrue(filteredData.hasOwnProperty('deviceId')); + assert.equal(filteredData.emailDomain, 'none'); + assert.equal(filteredData.entrypoint, 'menupanel'); + assert.equal(filteredData.entrypoint_experiment, 'wibble'); + assert.equal(filteredData.entrypoint_variation, 'blee'); + assert.deepEqual(filteredData.experiments, []); + assert.equal(filteredData.flowBeginTime, 123); + assert.equal(filteredData.flowId, 'flow-id'); + assert.isNumber(filteredData.flushTime); + assert.equal(filteredData.initialView, 'signup'); + assert.isTrue(filteredData.isSampledUser); + assert.equal(filteredData.lang, 'db_LB'); + assert.deepEqual(filteredData.marketing, []); + assert.equal(filteredData.numStoredAccounts, 1); + assert.equal(filteredData.newsletters, 'none'); - describe('startTimer/stopTimer', () => { - it('adds a timer to output data', () => { - metrics.startTimer('timer1'); - metrics.stopTimer('timer1'); + assert.equal(filteredData.planId, 'plid'); + assert.equal(filteredData.productId, 'pid'); - const filteredData = metrics.getFilteredData(); - assert.equal(filteredData.timers.timer1.length, 1); + assert.equal(filteredData.referrer, 'https://marketplace.firefox.com'); + assert.equal(filteredData.screen.width, 1600); + assert.equal(filteredData.screen.height, 1200); + assert.equal(filteredData.screen.devicePixelRatio, 2); + assert.equal(filteredData.screen.clientWidth, 1033); + assert.equal(filteredData.screen.clientHeight, 966); + assert.equal(filteredData.service, 'sync'); + assert.equal(filteredData.startTime, startTime); + assert.deepEqual(filteredData.syncEngines, []); - const timerData = filteredData.timers.timer1[0]; - assert.ok(timerData.hasOwnProperty('start')); - assert.ok(timerData.hasOwnProperty('stop')); - assert.ok(timerData.hasOwnProperty('elapsed')); - }); - }); + assert.equal(filteredData.uid, '0ae7fe2b244f4a789857dff3ae263927'); + assert.equal( + filteredData.uniqueUserId, + '0ae7fe2b-244f-4a78-9857-dff3ae263927' + ); - describe('flush', () => { - beforeEach(() => { - notifier.trigger('set-uid', 'mock uid'); + assert.deepEqual(filteredData.userPreferences, { + pref: true, + }); + + assert.equal(filteredData.utm_campaign, 'utm_campaign'); + assert.equal(filteredData.utm_content, 'utm_content'); + assert.equal(filteredData.utm_medium, 'utm_medium'); + assert.equal(filteredData.utm_source, 'none'); + assert.equal(filteredData.utm_term, 'none'); + }); }); - describe('flush, no data has changed, flush again', () => { - beforeEach(async () => { - sinon.stub(environment, 'hasSendBeacon').callsFake(() => true); - sinon.stub(windowMock.navigator, 'sendBeacon').callsFake(() => true); + describe('logEvent', () => { + it('adds events to output data', () => { + sinon.stub(metrics, 'flush').resolves({}); - metrics.logEvent('event'); + metrics.logEvent('event1'); + metrics.logEvent('event2'); + metrics.logEvent('event3'); + + const filteredData = metrics.getFilteredData(); + assert.equal(filteredData.events.length, 3); + assert.equal(filteredData.events[0].type, 'event1'); + assert.equal(filteredData.events[1].type, 'event2'); + assert.equal(filteredData.events[2].type, 'event3'); + + assert.isFalse(metrics.flush.called); + }); + + it('flushes events as soon as a screen.* event is logged', () => { + sinon.stub(metrics, 'flush').resolves({}); + + metrics.logEvent('event1'); + metrics.logEvent('event2'); + metrics.logEvent('event3'); + metrics.logEvent('screen.signin'); + + assert.isTrue(metrics.flush.calledOnce); + }); + + it('flushes events as soon as a *.complete event is logged', () => { + sinon.stub(metrics, 'flush').resolves({}); + + metrics.logEvent('event1'); + metrics.logEvent('event2'); + metrics.logEvent('event3'); + metrics.logEvent('signin.complete'); + + assert.isTrue(metrics.flush.calledOnce); + }); + + it('flushes events as soon as a *.success event is logged', () => { + sinon.stub(metrics, 'flush').resolves({}); + + metrics.logEvent('event1'); + metrics.logEvent('event2'); + metrics.logEvent('event3'); + metrics.logEvent('signin.success'); + + assert.isTrue(metrics.flush.calledOnce); + }); + }); + + describe('logEventOnce', () => { + it('adds events to output data', () => { + metrics.logEventOnce('event1'); + metrics.logEventOnce('event1'); + metrics.logEventOnce('event3'); + + const filteredData = metrics.getFilteredData(); + assert.equal(filteredData.events.length, 2); + assert.equal(filteredData.events[0].type, 'event1'); + assert.equal(filteredData.events[1].type, 'event3'); + }); + }); + + describe('markEventLogged', () => { + it('does not log an event if marked logged', () => { + metrics.markEventLogged('event2'); + metrics.logEventOnce('event1'); + metrics.logEventOnce('event2'); + + const filteredData = metrics.getFilteredData(); + assert.equal(filteredData.events.length, 1); + assert.equal(filteredData.events[0].type, 'event1'); + }); + }); + + describe('startTimer/stopTimer', () => { + it('adds a timer to output data', () => { metrics.startTimer('timer1'); metrics.stopTimer('timer1'); - await metrics.flush(); - await metrics.flush(); - }); - it('sends data once', () => { - assert.equal(windowMock.navigator.sendBeacon.callCount, 1); + const filteredData = metrics.getFilteredData(); + assert.equal(filteredData.timers.timer1.length, 1); - const data = JSON.parse(windowMock.navigator.sendBeacon.args[0][1]); - assert.isUndefined(data.planId); - assert.isUndefined(data.productId); + const timerData = filteredData.timers.timer1[0]; + assert.ok(timerData.hasOwnProperty('start')); + assert.ok(timerData.hasOwnProperty('stop')); + assert.ok(timerData.hasOwnProperty('elapsed')); }); }); - describe('flush, data has changed, flush again', () => { - beforeEach(async () => { - sinon.stub(environment, 'hasSendBeacon').returns(true); - sinon.stub(windowMock.navigator, 'sendBeacon').returns(true); + describe('flush', () => { + beforeEach(() => { + notifier.trigger('set-uid', 'mock uid'); + }); + + describe('flush, no data has changed, flush again', () => { + beforeEach(async () => { + sinon.stub(environment, 'hasSendBeacon').callsFake(() => true); + sinon.stub(windowMock.navigator, 'sendBeacon').callsFake(() => true); + + metrics.logEvent('event'); + metrics.startTimer('timer1'); + metrics.stopTimer('timer1'); + await metrics.flush(); + await metrics.flush(); + }); + + it('sends data once', () => { + assert.equal(windowMock.navigator.sendBeacon.callCount, 1); + + const data = JSON.parse(windowMock.navigator.sendBeacon.args[0][1]); + assert.isUndefined(data.planId); + assert.isUndefined(data.productId); + }); + }); + + describe('flush, data has changed, flush again', () => { + beforeEach(async () => { + sinon.stub(environment, 'hasSendBeacon').returns(true); + sinon.stub(windowMock.navigator, 'sendBeacon').returns(true); + metrics.logMarketingImpression( + MARKETING_CAMPAIGN, + MARKETING_CAMPAIGN_URL + ); + await metrics.flush(); + metrics.logMarketingClick(MARKETING_CAMPAIGN, MARKETING_CAMPAIGN_URL); + metrics.logEventOnce('loaded'); + await metrics.flush(); + metrics.logEvent('anuther one'); + await metrics.flush(); + }); + + it('sends data multiple times, navigationTiming data only sent on first flush with a loaded event', () => { + assert.equal(windowMock.navigator.sendBeacon.callCount, 3); + + const firstPayload = JSON.parse( + windowMock.navigator.sendBeacon.args[0][1] + ); + assert.notProperty(firstPayload, 'navigationTiming'); + + const secondPayload = JSON.parse( + windowMock.navigator.sendBeacon.args[1][1] + ); + assert.isObject(secondPayload.navigationTiming); + + const thirdPayload = JSON.parse( + windowMock.navigator.sendBeacon.args[2][1] + ); + assert.notProperty(thirdPayload, 'navigationTiming'); + }); + }); + + describe('flush with timer', () => { + beforeEach(function (done) { + sinon.stub(environment, 'hasSendBeacon').returns(true); + sinon.stub(windowMock.navigator, 'sendBeacon').returns(true); + metrics.startTimer('foo'); + setTimeout(() => { + metrics.stopTimer('foo'); + metrics.flush().then(() => { + done(); + }); + }, 4); + }); + + it('sends data', () => { + assert.equal(windowMock.navigator.sendBeacon.callCount, 1); + const data = JSON.parse( + windowMock.navigator.sendBeacon.getCall(0).args[1] + ); + assert.isArray(data.events); + assert.lengthOf(data.events, 0); + assert.isObject(data.timers); + assert.lengthOf(Object.keys(data.timers), 1); + assert.isArray(data.timers.foo); + assert.lengthOf(data.timers.foo, 1); + assert.isObject(data.timers.foo[0]); + assert.isNumber(data.timers.foo[0].elapsed); + }); + }); + + it('flush is safely re-entrant', () => { + let sendCount = 0; + const events = []; + + sinon.stub(metrics, '_send').callsFake((data) => { + events[sendCount++] = data.events; + if (sendCount < 3) { + // Trigger re-entrant flushes the first couple of times + metrics.logEvent(`reentrant-${sendCount}`); + metrics.flush(); + } else if (sendCount === 3) { + assert.lengthOf(events[0], 1); + assert.equal(events[0][0].type, 'wibble'); + assert.lengthOf(events[1], 1); + assert.equal(events[1][0].type, 'reentrant-1'); + assert.lengthOf(events[2], 1); + assert.equal(events[2][0].type, 'reentrant-2'); + } else { + assert.notOk(sendCount); + } + + return Promise.resolve(true); + }); + + metrics.logEvent('wibble'); + metrics.flush(); + }); + }); + + describe('_send', () => { + const dataToSend = { + foo: 'bar', + }; + + describe('has sendBeacon', () => { + beforeEach(() => { + sinon.stub(environment, 'hasSendBeacon').returns(true); + }); + + it('sendBeacon succeeds resolves to true', async () => { + sinon.stub(windowMock.navigator, 'sendBeacon').returns(true); + const result = await metrics._send(dataToSend); + assert.isTrue(result); + assert.isTrue( + windowMock.navigator.sendBeacon.calledOnceWith( + '/metrics', + JSON.stringify(dataToSend) + ) + ); + }); + + it('resolves to false', async () => { + sinon.stub(windowMock.navigator, 'sendBeacon').returns(false); + const result = await metrics._send(dataToSend); + assert.isFalse(result); + assert.isTrue( + windowMock.navigator.sendBeacon.calledOnceWith( + '/metrics', + JSON.stringify(dataToSend) + ) + ); + }); + }); + + describe('does not have sendBeacon', () => { + beforeEach(() => { + sinon.stub(environment, 'hasSendBeacon').returns(false); + }); + + it('ajax succeeds synchronously', async () => { + sinon.stub(xhr, 'ajax').resolves({}); + + const result = await metrics._send(dataToSend, true); + assert.isTrue(result); + + assert.isTrue(xhr.ajax.calledOnce); + const settings = xhr.ajax.args[0][0]; + assert.isObject(settings); + assert.lengthOf(Object.keys(settings), 5); + assert.isFalse(settings.async); + assert.equal(settings.type, 'POST'); + assert.equal(settings.url, '/metrics'); + assert.equal(settings.contentType, 'application/json'); + + const data = JSON.parse(settings.data); + assert.deepEqual(data, dataToSend); + }); + + it('flush, ajax succeeds asynchronously', async () => { + sinon.stub(xhr, 'ajax').resolves({}); + + await metrics._send(dataToSend, false); + const settings = xhr.ajax.args[0][0]; + assert.isTrue(settings.async); + }); + + it('flush, ajax fails', async () => { + sinon.stub(xhr, 'ajax').rejects(new Error('uh oh')); + + const result = await metrics._send(dataToSend, false); + assert.isFalse(result); + }); + }); + }); + + describe('errorToId', () => { + it('converts an error into an id that can be used for logging', () => { + const error = AuthErrors.toError('UNEXPECTED_ERROR', 'signup'); + error.viewName = 'oauth'; // this should be ignored, context is specified + + const id = metrics.errorToId(error); + assert.equal(id, 'error.signup.auth.999'); + }); + + it('handles a viewName on the error', () => { + const error = AuthErrors.toError('UNEXPECTED_ERROR'); + error.viewName = 'oauth'; + + const id = metrics.errorToId(error); + assert.equal(id, 'error.oauth.auth.999'); + }); + + it('handles viewName prefix', () => { + const error = AuthErrors.toError('UNEXPECTED_ERROR'); + error.viewName = 'oauth'; + metrics.setViewNamePrefix('signup'); + + const id = metrics.errorToId(error); + assert.equal(id, 'error.signup.oauth.auth.999'); + }); + }); + + describe('logError', () => { + it('logs an error', () => { + sinon.stub(metrics, 'logEvent'); + sinon.stub(metrics, 'errorToId').returns('some_error_id'); + const error = AuthErrors.toError('UNEXPECTED_ERROR', 'signup'); + + metrics.logError(error); + + assert.isTrue(metrics.logEvent.calledOnceWith('some_error_id')); + assert.isTrue(metrics.errorToId.calledOnceWith(error)); + }); + }); + + describe('logView', () => { + it('logs the screen', () => { + sinon.stub(metrics, 'logEvent'); + metrics.logView('signup'); + + assert.isTrue(metrics.logEvent.calledOnceWith('screen.signup')); + }); + + it('adds the viewName prefix', () => { + sinon.stub(metrics, 'logEvent'); + metrics.setViewNamePrefix('signup'); + metrics.logView('oauth'); + assert.isTrue(metrics.logEvent.calledOnceWith('screen.signup.oauth')); + }); + }); + + describe('logViewEvent', () => { + beforeEach(() => { + sinon.stub(metrics, 'logEvent'); + }); + + it('logs an event with the view name as a prefix to the event stream', () => { + metrics.logViewEvent('view-name', 'event1'); + assert.isTrue(metrics.logEvent.calledOnceWith('view-name.event1')); + }); + + it('adds the viewName prefix', () => { + metrics.setViewNamePrefix('signup'); + metrics.logViewEvent('view-name', 'event1'); + assert.isTrue(metrics.logEvent.calledOnceWith('signup.view-name.event1')); + }); + }); + + describe('setBrokerType', function () { + it('sets the broker name', function () { + metrics.setBrokerType('fx-desktop-v3'); + const { broker } = metrics.getFilteredData(); + + assert.equal(broker, 'fx-desktop-v3'); + }); + + it('handles undefined broker type', function () { + metrics.setBrokerType(undefined); + assert.equal(metrics.getFilteredData().broker, 'none'); + }); + + it('handles null broker type', function () { + metrics.setBrokerType(null); + assert.equal(metrics.getFilteredData().broker, 'none'); + }); + + it('handles empty broker type', function () { + metrics.setBrokerType(''); + assert.equal(metrics.getFilteredData().broker, 'none'); + }); + }); + + describe('setService', function () { + it('sets the service identifier', function () { + metrics.setService('00112233445566'); + const { service } = metrics.getFilteredData(); + + assert.equal(service, '00112233445566'); + }); + }); + + describe('setService', function () { + it('sets the service identifier', function () { + metrics.setService('00112233445566'); + const { service } = metrics.getFilteredData(); + + assert.equal(service, '00112233445566'); + }); + }); + + describe('setService', function () { + it('sets the service identifier', function () { + metrics.setService('00112233445566'); + const { service } = metrics.getFilteredData(); + + assert.equal(service, '00112233445566'); + }); + }); + + describe('isCollectionEnabled', () => { + it('reports that collection is enabled if `isSampledUser===true`', () => { + assert.isTrue(metrics.isCollectionEnabled()); + }); + + it('reports that collection is disabled if `isSampledUser===false`', () => { + createMetrics({ + isSampledUser: false, + }); + assert.isFalse(metrics.isCollectionEnabled()); + }); + }); + + describe('logMarketingImpression & logMarketingClick', () => { + it('logs the marketing impression and click', () => { + assert.isUndefined( + metrics.getMarketingImpression( + MARKETING_CAMPAIGN, + MARKETING_CAMPAIGN_URL + ) + ); metrics.logMarketingImpression( MARKETING_CAMPAIGN, MARKETING_CAMPAIGN_URL ); - await metrics.flush(); + assert.isFalse( + metrics.getMarketingImpression( + MARKETING_CAMPAIGN, + MARKETING_CAMPAIGN_URL + ).clicked + ); metrics.logMarketingClick(MARKETING_CAMPAIGN, MARKETING_CAMPAIGN_URL); - metrics.logEventOnce('loaded'); - await metrics.flush(); - metrics.logEvent('anuther one'); - await metrics.flush(); - }); - - it('sends data multiple times, navigationTiming data only sent on first flush with a loaded event', () => { - assert.equal(windowMock.navigator.sendBeacon.callCount, 3); - - const firstPayload = JSON.parse( - windowMock.navigator.sendBeacon.args[0][1] + assert.isTrue( + metrics.getMarketingImpression( + MARKETING_CAMPAIGN, + MARKETING_CAMPAIGN_URL + ).clicked ); - assert.notProperty(firstPayload, 'navigationTiming'); - - const secondPayload = JSON.parse( - windowMock.navigator.sendBeacon.args[1][1] - ); - assert.isObject(secondPayload.navigationTiming); - - const thirdPayload = JSON.parse( - windowMock.navigator.sendBeacon.args[2][1] - ); - assert.notProperty(thirdPayload, 'navigationTiming'); }); }); - describe('flush with timer', () => { - beforeEach(function (done) { - sinon.stub(environment, 'hasSendBeacon').returns(true); - sinon.stub(windowMock.navigator, 'sendBeacon').returns(true); - metrics.startTimer('foo'); - setTimeout(() => { - metrics.stopTimer('foo'); - metrics.flush().then(() => { - done(); + describe('logExperiment', () => { + it('logs the experiment name and group', () => { + const experiment = 'mailcheck'; + const group = 'group'; + sinon.spy(metrics, 'logEvent'); + sinon.spy(metrics, 'logEventOnce'); + notifier.trigger('flow.initialize'); + + metrics.logExperiment(); + assert.equal(Object.keys(metrics._activeExperiments).length, 0); + assert.equal(metrics.logEventOnce.callCount, 1); + assert.equal( + metrics.logEventOnce.args[0][0], + 'flow.experiment.undefined.undefined' + ); + + metrics.logExperiment(experiment); + assert.equal(Object.keys(metrics._activeExperiments).length, 0); + assert.equal(metrics.logEventOnce.callCount, 2); + assert.equal( + metrics.logEventOnce.args[1][0], + 'flow.experiment.mailcheck.undefined' + ); + + metrics.logExperiment(experiment, group); + assert.equal(Object.keys(metrics._activeExperiments).length, 1); + assert.isDefined(metrics._activeExperiments['mailcheck']); + assert.equal(metrics.logEventOnce.callCount, 3); + assert.equal( + metrics.logEventOnce.args[2][0], + 'flow.experiment.mailcheck.group' + ); + }); + }); + + describe('logNumStoredAccounts', () => { + it('correctly stores count', () => { + assert.equal(metrics.getAllData().numStoredAccounts, ''); + metrics.logNumStoredAccounts(4); + assert.equal(metrics.getAllData().numStoredAccounts, 4); + }); + + it('correctly reports count', async () => { + sinon.stub(metrics, '_send').callsFake(() => Promise.resolve(true)); + sinon.stub(metrics, '_isFlushRequired').callsFake(() => true); + + await metrics.flush(); + // not sent if logNumStoredAccounts has not been called + assert.notProperty(metrics._send.args[0][0], 'numStoredAccounts'); + + metrics.logNumStoredAccounts(2); + + await metrics.flush(); + // a second flush! + assert.equal(metrics._send.args[1][0].numStoredAccounts, 2); + + await metrics.flush(); + assert.notProperty(metrics._send.args[0][0], 'numStoredAccounts'); + }); + }); + + describe('logUserPreferences', () => { + const userPrefMetrics = { + 'account-recovery': true, + 'two-step-authentication': false, + }; + + it('correctly stores user preference', () => { + assert.deepEqual(metrics.getAllData().userPreferences, {}); + metrics.logUserPreferences('account-recovery', true); + metrics.logUserPreferences('two-step-authentication', false); + assert.deepEqual(metrics.getAllData().userPreferences, userPrefMetrics); + }); + + it('correctly reports user preferences', async () => { + sinon.stub(metrics, '_send').callsFake(() => Promise.resolve(true)); + sinon.stub(metrics, '_isFlushRequired').callsFake(() => true); + + await metrics.flush(); + assert.deepEqual(metrics.getAllData().userPreferences, {}); + + metrics.logUserPreferences('account-recovery', true); + metrics.logUserPreferences('two-step-authentication', false); + + await metrics.flush(); + assert.deepEqual( + metrics._send.args[1][0].userPreferences, + userPrefMetrics + ); + }); + }); + + describe('notifier events', () => { + it('flow.initialize', () => { + sinon.stub(metrics, '_initializeFlowModel'); + notifier.trigger('flow.initialize'); + + assert.isTrue(metrics._initializeFlowModel.calledOnce); + }); + + it('flow.event', () => { + sinon.stub(metrics, '_logFlowEvent'); + notifier.trigger('flow.event'); + + assert.isTrue(metrics._logFlowEvent.calledOnce); + }); + + it('set-email-domain (other)', () => { + notifier.trigger('set-email-domain', 'foo@example.com'); + assert.equal(metrics.getFilteredData().emailDomain, 'other'); + }); + + it('set-email-domain (popular domain)', () => { + notifier.trigger('set-email-domain', 'pmbooth@gmail.com'); + assert.equal(metrics.getFilteredData().emailDomain, 'gmail.com'); + }); + + it('set-sync-engines', () => { + notifier.trigger('set-sync-engines', ['foo', 'bar']); + assert.deepEqual(metrics.getFilteredData().syncEngines, ['foo', 'bar']); + }); + + it('set-uid', () => { + sinon.stub(metrics, '_setUid'); + notifier.trigger('set-uid'); + + assert.isTrue(metrics._setUid.calledOnce); + }); + + it('clear-uid', () => { + sinon.stub(metrics, '_clearUid'); + notifier.trigger('clear-uid'); + + assert.isTrue(metrics._clearUid.calledOnce); + }); + + it('subscription.initialize', () => { + notifier.trigger('subscription.initialize'); + + assert.isTrue(metrics._initializeSubscriptionModel.calledOnce); + }); + + it('view-shown', () => { + sinon.stub(metrics, '_setInitialView'); + // should only call the handler once + notifier.trigger('view-shown'); + notifier.trigger('view-shown'); + notifier.trigger('view-shown'); + + assert.isTrue(metrics._setInitialView.calledOnce); + }); + }); + + describe('DOM events', () => { + it('flushes on window blur', () => { + sinon.stub(metrics, 'flush'); + metrics.logEvent('blee'); + $(windowMock).trigger('blur'); + + assert.isTrue(metrics.flush.calledOnceWith(true)); + }); + + it('flushes on window unload', () => { + sinon.stub(metrics, 'flush'); + metrics.logEvent('wibble'); + $(windowMock).trigger('unload'); + + assert.isTrue(metrics.flush.calledOnceWith(true)); + }); + + it('flushes on window visibilitychange', () => { + sinon.stub(metrics, 'flush'); + metrics.logEvent('wibble'); + $(windowMock).trigger('visibilitychange'); + + assert.isTrue(metrics.flush.calledOnceWith(true)); + }); + + it('flushes on window pagehide', () => { + sinon.stub(metrics, 'flush'); + metrics.logEvent('wibble'); + $(windowMock).trigger('pagehide'); + + assert.isTrue(metrics.flush.calledOnceWith(true)); + }); + }); + + describe('inactivity timeout', () => { + it('automatic flushes after inactivityFlushMs', () => { + return new Promise((resolve, reject) => { + sinon.stub(metrics, 'logEvent').callsFake(() => {}); + sinon.stub(metrics, 'flush').callsFake(() => { + try { + assert.equal(metrics.logEvent.callCount, 2); + assert.equal(metrics.logEvent.args[0][0], 'flism'); + assert.equal(metrics.logEvent.args[1][0], 'inactivity.flush'); + assert.isTrue(metrics.flush.calledOnce); + assert.lengthOf(metrics.flush.getCall(0).args, 0); + } catch (e) { + return reject(e); + } + + resolve(); }); - }, 4); - }); - it('sends data', () => { - assert.equal(windowMock.navigator.sendBeacon.callCount, 1); - const data = JSON.parse( - windowMock.navigator.sendBeacon.getCall(0).args[1] - ); - assert.isArray(data.events); - assert.lengthOf(data.events, 0); - assert.isObject(data.timers); - assert.lengthOf(Object.keys(data.timers), 1); - assert.isArray(data.timers.foo); - assert.lengthOf(data.timers.foo, 1); - assert.isObject(data.timers.foo[0]); - assert.isNumber(data.timers.foo[0].elapsed); + metrics.logEvent('flism'); + }); }); }); - it('flush is safely re-entrant', () => { - let sendCount = 0; - const events = []; - - sinon.stub(metrics, '_send').callsFake((data) => { - events[sendCount++] = data.events; - if (sendCount < 3) { - // Trigger re-entrant flushes the first couple of times - metrics.logEvent(`reentrant-${sendCount}`); - metrics.flush(); - } else if (sendCount === 3) { - assert.lengthOf(events[0], 1); - assert.equal(events[0][0].type, 'wibble'); - assert.lengthOf(events[1], 1); - assert.equal(events[1][0].type, 'reentrant-1'); - assert.lengthOf(events[2], 1); - assert.equal(events[2][0].type, 'reentrant-2'); - } else { - assert.notOk(sendCount); - } - - return Promise.resolve(true); - }); - - metrics.logEvent('wibble'); - metrics.flush(); - }); - }); - - describe('_send', () => { - const dataToSend = { - foo: 'bar', - }; - - describe('has sendBeacon', () => { - beforeEach(() => { - sinon.stub(environment, 'hasSendBeacon').returns(true); - }); - - it('sendBeacon succeeds resolves to true', async () => { - sinon.stub(windowMock.navigator, 'sendBeacon').returns(true); - const result = await metrics._send(dataToSend); - assert.isTrue(result); - assert.isTrue( - windowMock.navigator.sendBeacon.calledOnceWith( - '/metrics', - JSON.stringify(dataToSend) - ) - ); - }); - - it('resolves to false', async () => { - sinon.stub(windowMock.navigator, 'sendBeacon').returns(false); - const result = await metrics._send(dataToSend); - assert.isFalse(result); - assert.isTrue( - windowMock.navigator.sendBeacon.calledOnceWith( - '/metrics', - JSON.stringify(dataToSend) - ) - ); - }); - }); - - describe('does not have sendBeacon', () => { - beforeEach(() => { - sinon.stub(environment, 'hasSendBeacon').returns(false); - }); - - it('ajax succeeds synchronously', async () => { - sinon.stub(xhr, 'ajax').resolves({}); - - const result = await metrics._send(dataToSend, true); - assert.isTrue(result); - - assert.isTrue(xhr.ajax.calledOnce); - const settings = xhr.ajax.args[0][0]; - assert.isObject(settings); - assert.lengthOf(Object.keys(settings), 5); - assert.isFalse(settings.async); - assert.equal(settings.type, 'POST'); - assert.equal(settings.url, '/metrics'); - assert.equal(settings.contentType, 'application/json'); - - const data = JSON.parse(settings.data); - assert.deepEqual(data, dataToSend); - }); - - it('flush, ajax succeeds asynchronously', async () => { - sinon.stub(xhr, 'ajax').resolves({}); - - await metrics._send(dataToSend, false); - const settings = xhr.ajax.args[0][0]; - assert.isTrue(settings.async); - }); - - it('flush, ajax fails', async () => { - sinon.stub(xhr, 'ajax').rejects(new Error('uh oh')); - - const result = await metrics._send(dataToSend, false); - assert.isFalse(result); - }); - }); - }); - - describe('errorToId', () => { - it('converts an error into an id that can be used for logging', () => { - const error = AuthErrors.toError('UNEXPECTED_ERROR', 'signup'); - error.viewName = 'oauth'; // this should be ignored, context is specified - - const id = metrics.errorToId(error); - assert.equal(id, 'error.signup.auth.999'); - }); - - it('handles a viewName on the error', () => { - const error = AuthErrors.toError('UNEXPECTED_ERROR'); - error.viewName = 'oauth'; - - const id = metrics.errorToId(error); - assert.equal(id, 'error.oauth.auth.999'); - }); - - it('handles viewName prefix', () => { - const error = AuthErrors.toError('UNEXPECTED_ERROR'); - error.viewName = 'oauth'; - metrics.setViewNamePrefix('signup'); - - const id = metrics.errorToId(error); - assert.equal(id, 'error.signup.oauth.auth.999'); - }); - }); - - describe('logError', () => { - it('logs an error', () => { - sinon.stub(metrics, 'logEvent'); - sinon.stub(metrics, 'errorToId').returns('some_error_id'); - const error = AuthErrors.toError('UNEXPECTED_ERROR', 'signup'); - - metrics.logError(error); - - assert.isTrue(metrics.logEvent.calledOnceWith('some_error_id')); - assert.isTrue(metrics.errorToId.calledOnceWith(error)); - }); - }); - - describe('logView', () => { - it('logs the screen', () => { - sinon.stub(metrics, 'logEvent'); - metrics.logView('signup'); - - assert.isTrue(metrics.logEvent.calledOnceWith('screen.signup')); - }); - - it('adds the viewName prefix', () => { - sinon.stub(metrics, 'logEvent'); - metrics.setViewNamePrefix('signup'); - metrics.logView('oauth'); - assert.isTrue(metrics.logEvent.calledOnceWith('screen.signup.oauth')); - }); - }); - - describe('logViewEvent', () => { - beforeEach(() => { - sinon.stub(metrics, 'logEvent'); - }); - - it('logs an event with the view name as a prefix to the event stream', () => { - metrics.logViewEvent('view-name', 'event1'); - assert.isTrue(metrics.logEvent.calledOnceWith('view-name.event1')); - }); - - it('adds the viewName prefix', () => { - metrics.setViewNamePrefix('signup'); - metrics.logViewEvent('view-name', 'event1'); - assert.isTrue(metrics.logEvent.calledOnceWith('signup.view-name.event1')); - }); - }); - - describe('setBrokerType', function () { - it('sets the broker name', function () { - metrics.setBrokerType('fx-desktop-v3'); - const { broker } = metrics.getFilteredData(); - - assert.equal(broker, 'fx-desktop-v3'); - }); - - it('handles undefined broker type', function () { - metrics.setBrokerType(undefined); - assert.equal(metrics.getFilteredData().broker, 'none'); - }); - - it('handles null broker type', function () { - metrics.setBrokerType(null); - assert.equal(metrics.getFilteredData().broker, 'none'); - }); - - it('handles empty broker type', function () { - metrics.setBrokerType(''); - assert.equal(metrics.getFilteredData().broker, 'none'); - }); - }); - - describe('setService', function () { - it('sets the service identifier', function () { - metrics.setService('00112233445566'); - const { service } = metrics.getFilteredData(); - - assert.equal(service, '00112233445566'); - }); - }); - - describe('setService', function () { - it('sets the service identifier', function () { - metrics.setService('00112233445566'); - const { service } = metrics.getFilteredData(); - - assert.equal(service, '00112233445566'); - }); - }); - - describe('setService', function () { - it('sets the service identifier', function () { - metrics.setService('00112233445566'); - const { service } = metrics.getFilteredData(); - - assert.equal(service, '00112233445566'); - }); - }); - - describe('isCollectionEnabled', () => { - it('reports that collection is enabled if `isSampledUser===true`', () => { - assert.isTrue(metrics.isCollectionEnabled()); - }); - - it('reports that collection is disabled if `isSampledUser===false`', () => { - createMetrics({ - isSampledUser: false, - }); - assert.isFalse(metrics.isCollectionEnabled()); - }); - }); - - describe('logMarketingImpression & logMarketingClick', () => { - it('logs the marketing impression and click', () => { - assert.isUndefined( - metrics.getMarketingImpression( - MARKETING_CAMPAIGN, - MARKETING_CAMPAIGN_URL - ) - ); - metrics.logMarketingImpression( - MARKETING_CAMPAIGN, - MARKETING_CAMPAIGN_URL - ); - assert.isFalse( - metrics.getMarketingImpression( - MARKETING_CAMPAIGN, - MARKETING_CAMPAIGN_URL - ).clicked - ); - metrics.logMarketingClick(MARKETING_CAMPAIGN, MARKETING_CAMPAIGN_URL); - assert.isTrue( - metrics.getMarketingImpression( - MARKETING_CAMPAIGN, - MARKETING_CAMPAIGN_URL - ).clicked - ); - }); - }); - - describe('logExperiment', () => { - it('logs the experiment name and group', () => { - const experiment = 'mailcheck'; - const group = 'group'; - sinon.spy(metrics, 'logEvent'); - sinon.spy(metrics, 'logEventOnce'); - notifier.trigger('flow.initialize'); - - metrics.logExperiment(); - assert.equal(Object.keys(metrics._activeExperiments).length, 0); - assert.equal(metrics.logEventOnce.callCount, 1); - assert.equal( - metrics.logEventOnce.args[0][0], - 'flow.experiment.undefined.undefined' - ); - - metrics.logExperiment(experiment); - assert.equal(Object.keys(metrics._activeExperiments).length, 0); - assert.equal(metrics.logEventOnce.callCount, 2); - assert.equal( - metrics.logEventOnce.args[1][0], - 'flow.experiment.mailcheck.undefined' - ); - - metrics.logExperiment(experiment, group); - assert.equal(Object.keys(metrics._activeExperiments).length, 1); - assert.isDefined(metrics._activeExperiments['mailcheck']); - assert.equal(metrics.logEventOnce.callCount, 3); - assert.equal( - metrics.logEventOnce.args[2][0], - 'flow.experiment.mailcheck.group' - ); - }); - }); - - describe('logNumStoredAccounts', () => { - it('correctly stores count', () => { - assert.equal(metrics.getAllData().numStoredAccounts, ''); - metrics.logNumStoredAccounts(4); - assert.equal(metrics.getAllData().numStoredAccounts, 4); - }); - - it('correctly reports count', async () => { - sinon.stub(metrics, '_send').callsFake(() => Promise.resolve(true)); - sinon.stub(metrics, '_isFlushRequired').callsFake(() => true); - - await metrics.flush(); - // not sent if logNumStoredAccounts has not been called - assert.notProperty(metrics._send.args[0][0], 'numStoredAccounts'); - - metrics.logNumStoredAccounts(2); - - await metrics.flush(); - // a second flush! - assert.equal(metrics._send.args[1][0].numStoredAccounts, 2); - - await metrics.flush(); - assert.notProperty(metrics._send.args[0][0], 'numStoredAccounts'); - }); - }); - - describe('logUserPreferences', () => { - const userPrefMetrics = { - 'account-recovery': true, - 'two-step-authentication': false, - }; - - it('correctly stores user preference', () => { - assert.deepEqual(metrics.getAllData().userPreferences, {}); - metrics.logUserPreferences('account-recovery', true); - metrics.logUserPreferences('two-step-authentication', false); - assert.deepEqual(metrics.getAllData().userPreferences, userPrefMetrics); - }); - - it('correctly reports user preferences', async () => { - sinon.stub(metrics, '_send').callsFake(() => Promise.resolve(true)); - sinon.stub(metrics, '_isFlushRequired').callsFake(() => true); - - await metrics.flush(); - assert.deepEqual(metrics.getAllData().userPreferences, {}); - - metrics.logUserPreferences('account-recovery', true); - metrics.logUserPreferences('two-step-authentication', false); - - await metrics.flush(); - assert.deepEqual( - metrics._send.args[1][0].userPreferences, - userPrefMetrics - ); - }); - }); - - describe('notifier events', () => { - it('flow.initialize', () => { - sinon.stub(metrics, '_initializeFlowModel'); - notifier.trigger('flow.initialize'); - - assert.isTrue(metrics._initializeFlowModel.calledOnce); - }); - - it('flow.event', () => { - sinon.stub(metrics, '_logFlowEvent'); - notifier.trigger('flow.event'); - - assert.isTrue(metrics._logFlowEvent.calledOnce); - }); - - it('set-email-domain (other)', () => { - notifier.trigger('set-email-domain', 'foo@example.com'); - assert.equal(metrics.getFilteredData().emailDomain, 'other'); - }); - - it('set-email-domain (popular domain)', () => { - notifier.trigger('set-email-domain', 'pmbooth@gmail.com'); - assert.equal(metrics.getFilteredData().emailDomain, 'gmail.com'); - }); - - it('set-sync-engines', () => { - notifier.trigger('set-sync-engines', ['foo', 'bar']); - assert.deepEqual(metrics.getFilteredData().syncEngines, ['foo', 'bar']); - }); - - it('set-uid', () => { - sinon.stub(metrics, '_setUid'); - notifier.trigger('set-uid'); - - assert.isTrue(metrics._setUid.calledOnce); - }); - - it('clear-uid', () => { - sinon.stub(metrics, '_clearUid'); - notifier.trigger('clear-uid'); - - assert.isTrue(metrics._clearUid.calledOnce); - }); - - it('subscription.initialize', () => { - notifier.trigger('subscription.initialize'); - - assert.isTrue(metrics._initializeSubscriptionModel.calledOnce); - }); - - it('view-shown', () => { - sinon.stub(metrics, '_setInitialView'); - // should only call the handler once - notifier.trigger('view-shown'); - notifier.trigger('view-shown'); - notifier.trigger('view-shown'); - - assert.isTrue(metrics._setInitialView.calledOnce); - }); - }); - - describe('DOM events', () => { - it('flushes on window blur', () => { - sinon.stub(metrics, 'flush'); - metrics.logEvent('blee'); - $(windowMock).trigger('blur'); - - assert.isTrue(metrics.flush.calledOnceWith(true)); - }); - - it('flushes on window unload', () => { - sinon.stub(metrics, 'flush'); - metrics.logEvent('wibble'); - $(windowMock).trigger('unload'); - - assert.isTrue(metrics.flush.calledOnceWith(true)); - }); - - it('flushes on window visibilitychange', () => { - sinon.stub(metrics, 'flush'); - metrics.logEvent('wibble'); - $(windowMock).trigger('visibilitychange'); - - assert.isTrue(metrics.flush.calledOnceWith(true)); - }); - - it('flushes on window pagehide', () => { - sinon.stub(metrics, 'flush'); - metrics.logEvent('wibble'); - $(windowMock).trigger('pagehide'); - - assert.isTrue(metrics.flush.calledOnceWith(true)); - }); - }); - - describe('inactivity timeout', () => { - it('automatic flushes after inactivityFlushMs', () => { - return new Promise((resolve, reject) => { - sinon.stub(metrics, 'logEvent').callsFake(() => {}); - sinon.stub(metrics, 'flush').callsFake(() => { - try { - assert.equal(metrics.logEvent.callCount, 2); - assert.equal(metrics.logEvent.args[0][0], 'flism'); - assert.equal(metrics.logEvent.args[1][0], 'inactivity.flush'); - assert.isTrue(metrics.flush.calledOnce); - assert.lengthOf(metrics.flush.getCall(0).args, 0); - } catch (e) { - return reject(e); - } - - resolve(); + describe('sanitizes and reports invalid utm', () => { + it('flushes as expected', (done) => { + createMetrics({ + utmCampaign: '(not valid)', + utmContent: 'utm_content', + utmMedium: 'utm_medium', + utmSource: 'none', + utmTerm: '', }); - metrics.logEvent('flism'); + sinon.stub(metrics, '_send').resolves(true); + + metrics.logEvent('signin.success'); + + setTimeout(() => { + try { + assert.equal(metrics._send.callCount, 1); + + const firstPayload = metrics._send.args[0][0]; + assert.equal(firstPayload.events[0].type, 'signin.success'); + assert.equal(firstPayload.utm_campaign, 'invalid'); + assert.equal(firstPayload.utm_content, 'utm_content'); + assert.equal(firstPayload.utm_medium, 'utm_medium'); + assert.equal(firstPayload.utm_source, 'none'); + assert.equal(firstPayload.utm_term, 'none'); + + assert.equal(sentryMock.captureException.callCount, 1); + assert.include( + sentryMock.captureException.args[0][0].message, + BAD_METRIC_ERROR_PREFIX + ); + } catch (err) { + return done(err); + } + + done(); + }, 50); + }); + }); + + describe('all together now', () => { + it('flushes as expected', (done) => { + sinon.stub(metrics, '_send').resolves(true); + + notifier.trigger('set-uid', 'mock uid'); + notifier.trigger('flow.initialize'); + metrics.logEvent('foo'); + notifier.trigger('flow.event', { event: 'bar', once: true }); + metrics.logEvent('baz'); + notifier.trigger('view-shown', { viewName: 'wibble' }); + // trigger `view-shown` twice, ensure it's only logged once. + notifier.trigger('view-shown', { viewName: 'blee' }); + notifier.trigger( + 'subscription.initialize', + new SubscriptionModel({ + planId: 'plid', + productId: 'pid', + }) + ); + notifier.trigger('flow.event', { event: 'buz', once: true }); + metrics.logEvent('signin.complete'); + + metrics.logEvent('signin.password.incorrect'); + metrics.logEvent('signin.success'); + + metrics.logEvent('sent.on.timeout'); + + setTimeout(() => { + try { + assert.equal(metrics._send.callCount, 3); + + const firstPayload = metrics._send.args[0][0]; + assert.equal(firstPayload.events[0].type, 'foo'); + assert.equal(firstPayload.events[1].type, 'flow.bar'); + assert.equal(firstPayload.events[2].type, 'baz'); + assert.equal(firstPayload.events[3].type, 'loaded'); + assert.equal(firstPayload.events[4].type, 'flow.buz'); + assert.equal(firstPayload.events[5].type, 'signin.complete'); + + assert.equal(firstPayload.planId, 'plid'); + assert.equal(firstPayload.productId, 'pid'); + + assert.equal( + metrics._send.args[1][0].events[0].type, + 'signin.password.incorrect' + ); + assert.equal( + metrics._send.args[1][0].events[1].type, + 'signin.success' + ); + + assert.equal( + metrics._send.args[2][0].events[0].type, + 'sent.on.timeout' + ); + assert.equal( + metrics._send.args[2][0].events[1].type, + 'inactivity.flush' + ); + } catch (err) { + return done(err); + } + + done(); + }, 50); }); }); }); - describe('sanitizes and reports invalid utm', () => { - it('flushes as expected', (done) => { - createMetrics({ - utmCampaign: '(not valid)', - utmContent: 'utm_content', - utmMedium: 'utm_medium', - utmSource: 'none', - utmTerm: '', - }); - - sinon.stub(metrics, '_send').resolves(true); - - metrics.logEvent('signin.success'); - - setTimeout(() => { - try { - assert.equal(metrics._send.callCount, 1); - - const firstPayload = metrics._send.args[0][0]; - assert.equal(firstPayload.events[0].type, 'signin.success'); - assert.equal(firstPayload.utm_campaign, 'invalid'); - assert.equal(firstPayload.utm_content, 'utm_content'); - assert.equal(firstPayload.utm_medium, 'utm_medium'); - assert.equal(firstPayload.utm_source, 'none'); - assert.equal(firstPayload.utm_term, 'none'); - - assert.equal(sentryMock.captureException.callCount, 1); - assert.include( - sentryMock.captureException.args[0][0].message, - BAD_METRIC_ERROR_PREFIX - ); - } catch (err) { - return done(err); - } - - done(); - }, 50); - }); - }); - - describe('all together now', () => { - it('flushes as expected', (done) => { - sinon.stub(metrics, '_send').resolves(true); - - notifier.trigger('set-uid', 'mock uid'); - notifier.trigger('flow.initialize'); - metrics.logEvent('foo'); - notifier.trigger('flow.event', { event: 'bar', once: true }); - metrics.logEvent('baz'); - notifier.trigger('view-shown', { viewName: 'wibble' }); - // trigger `view-shown` twice, ensure it's only logged once. - notifier.trigger('view-shown', { viewName: 'blee' }); - notifier.trigger( - 'subscription.initialize', - new SubscriptionModel({ - planId: 'plid', - productId: 'pid', - }) - ); - notifier.trigger('flow.event', { event: 'buz', once: true }); - metrics.logEvent('signin.complete'); - - metrics.logEvent('signin.password.incorrect'); - metrics.logEvent('signin.success'); - - metrics.logEvent('sent.on.timeout'); - - setTimeout(() => { - try { - assert.equal(metrics._send.callCount, 3); - - const firstPayload = metrics._send.args[0][0]; - assert.equal(firstPayload.events[0].type, 'foo'); - assert.equal(firstPayload.events[1].type, 'flow.bar'); - assert.equal(firstPayload.events[2].type, 'baz'); - assert.equal(firstPayload.events[3].type, 'loaded'); - assert.equal(firstPayload.events[4].type, 'flow.buz'); - assert.equal(firstPayload.events[5].type, 'signin.complete'); - - assert.equal(firstPayload.planId, 'plid'); - assert.equal(firstPayload.productId, 'pid'); - - assert.equal( - metrics._send.args[1][0].events[0].type, - 'signin.password.incorrect' - ); - assert.equal( - metrics._send.args[1][0].events[1].type, - 'signin.success' - ); - - assert.equal( - metrics._send.args[2][0].events[0].type, - 'sent.on.timeout' - ); - assert.equal( - metrics._send.args[2][0].events[1].type, - 'inactivity.flush' - ); - } catch (err) { - return done(err); - } - - done(); - }, 50); - }); - }); -}); +} diff --git a/packages/fxa-shared/speed-trap/events.js b/packages/fxa-shared/speed-trap/events.js index e27b041bfd..fde8915ea6 100644 --- a/packages/fxa-shared/speed-trap/events.js +++ b/packages/fxa-shared/speed-trap/events.js @@ -5,13 +5,17 @@ class Events { init(options) { this.events = []; - this.baseTime = options.baseTime; + + if (!options || !options.performance) { + throw new Error('options.performance is required!') + } + this.performance = options.performance; } capture(name) { this.events.push({ type: name, - offset: Date.now() - this.baseTime, + offset: this.performance.now(), }); } diff --git a/packages/fxa-shared/speed-trap/index.js b/packages/fxa-shared/speed-trap/index.js index b57115379e..a4bc80a05b 100644 --- a/packages/fxa-shared/speed-trap/index.js +++ b/packages/fxa-shared/speed-trap/index.js @@ -1,2 +1,10 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ + +// Note, this code was ported back into fxa for ease of maintenance. The source originated +// from https://www.npmjs.com/package/speed-trap. The actual github repo for this package +// no longer exists. + import { default as SpeedTrap } from './speed-trap'; export default SpeedTrap; diff --git a/packages/fxa-shared/speed-trap/navigation-timing.js b/packages/fxa-shared/speed-trap/navigation-timing.js index 9680c89903..b7265f586e 100644 --- a/packages/fxa-shared/speed-trap/navigation-timing.js +++ b/packages/fxa-shared/speed-trap/navigation-timing.js @@ -2,66 +2,108 @@ * License, v. 2.0. If a copy of the MPL was not distributed with this * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ -const NAVIGATION_TIMING_FIELDS = { - navigationStart: undefined, - unloadEventStart: undefined, - unloadEventEnd: undefined, - redirectStart: undefined, - redirectEnd: undefined, - fetchStart: undefined, - domainLookupStart: undefined, - domainLookupEnd: undefined, - connectStart: undefined, - connectEnd: undefined, - secureConnectionStart: undefined, - requestStart: undefined, - responseStart: undefined, - responseEnd: undefined, - domLoading: undefined, - domInteractive: undefined, - domContentLoadedEventStart: undefined, - domContentLoadedEventEnd: undefined, - domComplete: undefined, - loadEventStart: undefined, - loadEventEnd: undefined, -}; +import {NAVIGATION_TIMING_FIELDS, OPTIONAL_NAVIGATION_TIMING_FIELDS} from './timing-fields'; -var navigationTiming; -try { - // eslint-disable-next-line no-undef - navigationTiming = window.performance.timing; -} catch (e) { - // NOOP +const L2TimingsMap = { + 'navigationStart': 'startTime', + 'domLoading': 'domContentLoadedEventStart' } -if (!navigationTiming) { - navigationTiming = Object.create(NAVIGATION_TIMING_FIELDS); +const TimingVersions = { + L2: 'L2', + L1: 'L1', + UNKNOWN: '' } -var navigationStart = navigationTiming.navigationStart || Date.now(); - class NavigationTiming { - init(options) { - options = options || {}; - this.navigationTiming = options.navigationTiming || navigationTiming; - this.baseTime = navigationStart; + init(opts) { + + // A performance api must be provided + if (!opts || !opts.performance) { + throw new Error('opts.performance is required!') + } + this.performance = opts.performance; + this.useL1Timings = opts.useL1Timings; } - get() { - return this.navigationTiming; + getTimingVersion () { + const version = this.getL2Timings() ? TimingVersions.L2 : + this.getL1Timings() ? TimingVersions.L1 : + TimingVersions.UNKNOWN; + return version; + } + + getL2Timings() { + if ( + !!this.performance && + !!this.performance.getEntriesByType && + !!this.performance.getEntriesByType('navigation')) + { + return this.performance.getEntriesByType('navigation')[0] + } + } + + getL1Timings() { + return this.performance.timing; } diff() { - var diff = {}; - var baseTime = this.baseTime; - for (var key in NAVIGATION_TIMING_FIELDS) { - var timing = this.navigationTiming[key]; + // If we are using our fallback performance api (ie window.performance + // doesn't exist), don't return anything. + if (this.performance.unreliable === true) { + return undefined; + } - if (timing >= baseTime) { - diff[key] = timing - baseTime; - } else { - diff[key] = null; + const diff = {} + const l2Timings = this.getL2Timings(); + const l1Timings = this.getL1Timings(); + + function diffL1() { + // Make navigation timings relative to navigation start. + for (const key in NAVIGATION_TIMING_FIELDS) { + const timing = l1Timings[key]; + + if (timing === 0 && OPTIONAL_NAVIGATION_TIMING_FIELDS.indexOf(key) >= 0) { + // A time value of 0 for certain fields indicates a non-applicable value. Set to null. + diff[key] = null; + } + else { + // Compute the delta relative to navigation start. This removes any + // ambiguity around what the 'start' or 'baseTime' time is. Since we + // are sure the current set of navigation timings were created using + // the same kind of clock, this seems like the safest way to do this. + diff[key] = timing - this.performance.timing.navigationStart; + } + } + } + + function diffL2 () { + // If we have level 2 timings we can almost return the timings directly. We just have massage + // a couple fields to keep it backwards compatible. + for (const key in NAVIGATION_TIMING_FIELDS) { + const mappedKey = L2TimingsMap[key] || key; + diff[key] = l2Timings[mappedKey]; + } + } + + // Case for testing. We should always try to use l2, but if explicitly requested use L1. + if (this.useL1Timings && l1Timings) { + diffL1(); + } + else if (l2Timings) { + diffL2(); + } + else if (l1Timings) { + diffL1(); + } + + // We shouldn't see any negative values. If we do something went very wrong. + // We will use -11111 as a magic number to ensure a sentry error is captured, + // and it's easy to spot. + for (const key in NAVIGATION_TIMING_FIELDS) { + if (diff[key] < 0) { + diff[key] = -11111; } } return diff; diff --git a/packages/fxa-shared/speed-trap/performance-factory.js b/packages/fxa-shared/speed-trap/performance-factory.js new file mode 100644 index 0000000000..74c20bbe0e --- /dev/null +++ b/packages/fxa-shared/speed-trap/performance-factory.js @@ -0,0 +1,88 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ + +import { NAVIGATION_TIMING_FIELDS } from './timing-fields' + +/** + * Small util for determining if a browser went to sleep. + */ +class SleepDetection { + + constructor() { + this.sleepDetected = false; + this.lastTime =Date.now(); + this.iid = ''; + } + + startSleepDetection() { + this.iid = setInterval(() => { + if (this.sleepDetected) { + clearInterval(this.iid); + return; + } + + const currentTime = Date.now(); + if (currentTime > (this.lastTime + 2000*2)) { // ignore small delays + this.sleepDetected = true; + } + this.lastTime = currentTime; + }, 2000); + } +} + +/** + * This minimal fallback api is deemed unreliable. We use this in + * the event a browser doesn't provide a performance api. In these + * cases there is not a monotonic clock for us to rely on, which can + * result in weird edge cases where a system is put into a sleep state + * and the metrics collected will be wildly off. + */ +class PerformanceFallback { + + constructor() { + this.unreliable = true; + this.timeOrigin = Date.now(); + this.timing = Object.create(NAVIGATION_TIMING_FIELDS); + this.sleepDetection = new SleepDetection(); + this.sleepDetection.startSleepDetection(); + } + + now() { + return Date.now() - this.timeOrigin; + } + + // If the machine was put to sleep during metrics collection, the values + // are invalid and cannot be used. + isInSuspectState() { + return this.sleepDetection.sleepDetected; + } +} + +/** + * Provides a fake performance api with minimal functionality. + */ +export function getFallbackPerformanceApi() { + return new PerformanceFallback(); +} + +/** + * Provides the browser's performance api. + */ +export function getRealPerformanceApi () { + // eslint-disable-next-line no-undef + return window.performance; +} + +/** + * Provides a performance api, or for browsers that don't support the performance api, a version + * of it to support minimal functionality required by speed trap. + */ +export function getPerformanceApi() { + // eslint-disable-next-line no-undef + if (!!window.performance && typeof window.performance.now === 'function') { + return getRealPerformanceApi(); + } + + return getFallbackPerformanceApi(); +} diff --git a/packages/fxa-shared/speed-trap/speed-trap.js b/packages/fxa-shared/speed-trap/speed-trap.js index c39eeceb6a..faa4ccd5ee 100644 --- a/packages/fxa-shared/speed-trap/speed-trap.js +++ b/packages/fxa-shared/speed-trap/speed-trap.js @@ -5,24 +5,29 @@ import guid from './guid'; import NavigationTiming from './navigation-timing'; import Timers from './timers'; import Events from './events'; +import { getPerformanceApi } from './performance-factory'; var SpeedTrap = { init: function (options) { options = options || {}; - this.navigationTiming = Object.create(NavigationTiming); - this.navigationTiming.init(options); - this.baseTime = this.navigationTiming.get().navigationStart || Date.now(); + // This will provide the browser's performance API, or a fallback version which has + // reduced functionality. The exact performance API can also be passed in as option + // for testing purposes. + this.performance = options.performance || getPerformanceApi(); + this.baseTime = this.performance.timeOrigin; + + this.navigationTiming = Object.create(NavigationTiming); + this.navigationTiming.init({ + performance: this.performance, + useL1Timings: options.useL1Timings + }); this.timers = Object.create(Timers); - this.timers.init({ - baseTime: this.baseTime, - }); + this.timers.init({performance: this.performance}); this.events = Object.create(Events); - this.events.init({ - baseTime: this.baseTime, - }); + this.events.init({performance: this.performance}); this.uuid = guid(); @@ -59,10 +64,12 @@ var SpeedTrap = { // if cookies are disabled, sessionStorage access will blow up. } + const navigationTiming = this.navigationTiming.diff(); + return { uuid: this.uuid, puuid: previousPageUUID, - navigationTiming: this.navigationTiming.diff(), + navigationTiming, // eslint-disable-next-line no-undef referrer: document.referrer || '', tags: this.tags, @@ -92,11 +99,43 @@ var SpeedTrap = { return { uuid: this.uuid, - duration: Date.now() - this.baseTime, + // The performance API keeps track of the current duration. The exact way this is done + // may vary depending on the browser's implementation. We will assume that as long as we + // stay within the confines of the browser's implementation, this value is reasonable. + // What is not reasonable is assuming the that we can Subtract Date.now() from + // performance.timeOrigin or performance.timings.navigationStart and get a valid value. + // It's very likely the performance API is using a monotonic clock that does not match our + // current system clock. + duration: this.performance.now(), timers: this.timers.get(), events: this.events.get(), }; }, + + /** + * Return the current time using speed trap's clock. If the performance api is available + * its monotonic clock will be used. Otherwise the system clock is used (ie Date.now()). + * + * Note: The system clock is susceptible to edge cases were a machine sleeps during a load + * operation. In this case we may result produce a very large metric. + * + * Note: performance.now() will likely differ from Date.now() and is not expected to be the real + * time. Please be aware of what underlying implementation is in use when calling this function. + */ + now: function() { + return this.performance.timeOrigin + this.performance.now(); + }, + + /** + * Legacy browsers can end up in suspect states when a machine is put into sleep mode during + * metrics collection. This flag indicates the machine is likely in an invalid state. + */ + isInSuspectState: function () { + if (this.performance.unreliable === true) { + return this.performance.isInSuspectState(); + } + return false; + } }; export default Object.create(SpeedTrap); diff --git a/packages/fxa-shared/speed-trap/timers.js b/packages/fxa-shared/speed-trap/timers.js index 11a6f18b3f..8ab27ed71c 100644 --- a/packages/fxa-shared/speed-trap/timers.js +++ b/packages/fxa-shared/speed-trap/timers.js @@ -4,22 +4,31 @@ class Timers { init(options) { + if (!options || !options.performance) { + throw new Error('options.performance required') + } + this.completed = {}; this.running = {}; - this.baseTime = options.baseTime; + this.performance = options.performance; + this.baseTime = options.performance.timeOrigin; } start(name) { - var start = Date.now(); - if (this.running[name]) throw new Error(name + ' timer already started'); + var start = this.performance.now() + if (typeof this.running[name] === 'number') { + throw new Error(name + ' timer already started'); + } this.running[name] = start; } stop(name) { - var stop = Date.now(); + var stop = this.performance.now() - if (!this.running[name]) throw new Error(name + ' timer not started'); + if (typeof this.running[name] !== 'number') { + throw new Error(name + ' timer not started'); + } if (!this.completed[name]) this.completed[name] = []; var start = this.running[name]; diff --git a/packages/fxa-shared/speed-trap/timing-fields.js b/packages/fxa-shared/speed-trap/timing-fields.js new file mode 100644 index 0000000000..957d7a3d14 --- /dev/null +++ b/packages/fxa-shared/speed-trap/timing-fields.js @@ -0,0 +1,40 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ + + /** + * Navigation Timing fields we use for metrics. + */ +export const NAVIGATION_TIMING_FIELDS = { + navigationStart: undefined, + unloadEventStart: undefined, + unloadEventEnd: undefined, + redirectStart: undefined, + redirectEnd: undefined, + fetchStart: undefined, + domainLookupStart: undefined, + domainLookupEnd: undefined, + connectStart: undefined, + connectEnd: undefined, + secureConnectionStart: undefined, + requestStart: undefined, + responseStart: undefined, + responseEnd: undefined, + domLoading: undefined, + domInteractive: undefined, + domContentLoadedEventStart: undefined, + domContentLoadedEventEnd: undefined, + domComplete: undefined, + loadEventStart: undefined, + loadEventEnd: undefined, +}; + +export const OPTIONAL_NAVIGATION_TIMING_FIELDS = [ + 'loadEventEnd', + 'loadEventStart', + 'redirectEnd', + 'redirectStart', + 'secureConnectionStart', + 'unloadEventEnd', + 'unloadEventStart' +];