diff --git a/libraries/o-tracking/src/javascript/core/send.js b/libraries/o-tracking/src/javascript/core/send.js index 41d21b7d64..41f63718af 100644 --- a/libraries/o-tracking/src/javascript/core/send.js +++ b/libraries/o-tracking/src/javascript/core/send.js @@ -129,20 +129,61 @@ function run(callback = function () { /* empty */}) { // Investigate queue lengths bug // https://jira.ft.com/browse/DTP-330 const all_events = queue.all(); + let queue_length = all_events.length; - if (all_events.length > 200) { + if (queue_length > 200) { const counts = {}; - - all_events.forEach(function (event) { - const label = [event.category, event.action].join(':'); - - if (!Object.prototype.hasOwnProperty.call(counts, label)) { - counts[label] = 0; + const isOfflineCounts = { + true: 0, + false: 0, + }; + let maxOfflineLag = 0; + let totalOfflineLag = 0; + + all_events.forEach(function ({ + queueTime, + category, + action, + context = {}, + device: {is_offline = false} = {}, + }) { + const offlineLag = new Date().getTime() - queueTime; + + // If a previously-queued event was a 'queue-bug' summary, + // extract the information and merge with the current context + if (category === 'o-tracking' && action === 'queue-bug') { + const previousCounts = context.counts || {}; + const previousOfflineCounts = context.isOfflineCounts || { + true: 0, + false: 0, + }; + const previousMaxOfflineLag = context.maxOfflineLag || 0; + const previousTotalOfflineLag = context.totalOfflineLag || 0; + + for (const [label, count] of Object.entries(previousCounts)) { + counts[label] = (counts[label] || 0) + count; + queue_length += count; + } + + isOfflineCounts[true] += previousOfflineCounts.true; + isOfflineCounts[false] += previousOfflineCounts.false; + + maxOfflineLag = Math.max(maxOfflineLag, previousMaxOfflineLag); + totalOfflineLag += previousTotalOfflineLag; + + // Data from this old 'queue-bug' event has been exported, + // so the event can now be forgotten + queue_length -= 1; + } else { + const label = [category, action].join(':'); + counts[label] = (counts[label] || 0) + 1; + isOfflineCounts[is_offline] += 1; + maxOfflineLag = Math.max(maxOfflineLag, offlineLag); + totalOfflineLag += offlineLag; } - - counts[label] += 1; }); + const averageOfflineLag = Math.round(totalOfflineLag / queue_length); queue.replace([]); queue.add({ @@ -150,10 +191,14 @@ function run(callback = function () { /* empty */}) { action: 'queue-bug', context: { url: document.URL, - queue_length: all_events.length, + queue_length, counts: counts, - storage: queue.storage.storage._type - } + isOfflineCounts, + maxOfflineLag, + averageOfflineLag, + totalOfflineLag, + storage: queue.storage.storage._type, + }, }); } @@ -202,9 +247,4 @@ function init() { return queue; } -export { - init, - add, - run, - addAndRun -}; +export {init, addAndRun}; diff --git a/libraries/o-tracking/test/core.test.js b/libraries/o-tracking/test/core.test.js index a2f178fb0a..dd08c23d37 100644 --- a/libraries/o-tracking/test/core.test.js +++ b/libraries/o-tracking/test/core.test.js @@ -5,7 +5,7 @@ import sinon from 'sinon/pkg/sinon-esm.js'; import {set, destroy} from '../src/javascript/core/settings.js'; import {Queue} from '../src/javascript/core/queue.js'; import {session, init} from '../src/javascript/core/session.js'; -import {init as initSend, run} from '../src/javascript/core/send.js'; +import {init as initSend} from '../src/javascript/core/send.js'; import core from '../src/javascript/core.js'; import { errorNextSend } from './setup.js'; @@ -100,7 +100,7 @@ describe('Core', function () { proclaim.equal(callback.called, 1, 'Callback called once.'); // Try again - run(); + initSend(); proclaim.ok(callback.calledOnce, 'Callback should only be called once as next send could be on a different page.'); }); diff --git a/libraries/o-tracking/test/core/send.test.js b/libraries/o-tracking/test/core/send.test.js index cf5dcffd4c..3a81c8b607 100644 --- a/libraries/o-tracking/test/core/send.test.js +++ b/libraries/o-tracking/test/core/send.test.js @@ -4,11 +4,10 @@ import proclaim from 'proclaim'; import sinon from 'sinon/pkg/sinon-esm.js'; import { init, - add, addAndRun } from '../../src/javascript/core/send.js'; import {Queue} from "../../src/javascript/core/queue.js"; -import {unmockTransport, mockTransport, sendSpy} from '../setup.js'; +import {unmockTransport, mockTransport, sendSpy, errorNextSend} from '../setup.js'; import {set, destroy} from '../../src/javascript/core/settings.js'; const request = { @@ -52,13 +51,6 @@ describe('Core.Send', function () { }); }); - it('should add a request', function () { - proclaim.doesNotThrow(function () { - add(request); - }); - }); - - describe('fallback transports', function () { before(function () { unmockTransport(); @@ -252,41 +244,164 @@ describe('Core.Send', function () { }); }); - it('should cope with the huge queue bug', function (done) { - const server = sinon.fakeServer.create(); // Catch AJAX requests - let queue = new Queue('requests'); + describe('queue bug', function () { + let queue; - queue.replace([]); + beforeEach(function () { + set('config', {queue: true}); + queue = init(); + }); - for (let i=0; i<201; i++) { - queue.add({}); - } + afterEach(function () { + queue.storage.destroy(); + }); - queue.save(); + it('should summarise large numbers of offline events to avoid the huge queue bug', function () { + // queue up 200 'offline' events + for (let i = 0; i < 200; i++) { + errorNextSend(); + addAndRun({ + category: 'page', + action: 'view', + }); + } - server.respondWith([200, { "Content-Type": "plain/text", "Content-Length": 2 }, "OK"]); + // Go online, and send the events with a clean sinon.spy history + sendSpy.resetHistory(); + addAndRun({ + category: 'button', + action: 'click', + }); + + // Only one event should be sent + proclaim.equal(sendSpy.callCount, 1); + + const payload = JSON.parse(sendSpy.firstCall.args[1]); + proclaim.equal(payload.category, 'o-tracking'); + proclaim.equal(payload.action, 'queue-bug'); + proclaim.equal(payload.context.queue_length, 201); + proclaim.deepEqual(payload.context.counts, { + 'page:view': 200, + 'button:click': 1, + }); + + proclaim.equal(queue.all().length, 0); + }); - // Run the queue - init(); + it('should summarise all offline events rather than discard previous summaries', function () { + // queue up 200 'offline' events + for (let i = 0; i < 200; i++) { + errorNextSend(); + addAndRun({ + category: 'page', + action: 'view', + }); + } - server.respond(); + // this failure will generate a queue-bug event which fails to be sent + errorNextSend(); + addAndRun({ + category: 'button', + action: 'click', + }); + + // queue up 200 more 'offline' events + for (let i = 0; i < 200; i++) { + errorNextSend(); + addAndRun({ + category: 'page', + action: 'view', + }); + } - // Wait for localStorage - setTimeout(() => { - try { - // Refresh our queue as it's kept in memory - queue = new Queue('requests'); + // Go online, and send the events with a clean sinon.spy history + sendSpy.resetHistory(); + addAndRun({ + category: 'button', + action: 'click', + }); + + // Two send events should have been attempted + proclaim.equal(sendSpy.callCount, 2); + + // NB: our mockTransport completes synchronously, so the last click event is + // sent before the queue-bug event. It'll be the other way around with + // a real HTTP call, but harder to observe the test framework. + const firstEvent = JSON.parse(sendSpy.firstCall.args[1]); + proclaim.equal(firstEvent.category, 'button'); + proclaim.equal(firstEvent.action, 'click'); + + const secondEvent = JSON.parse(sendSpy.secondCall.args[1]); + proclaim.equal(secondEvent.category, 'o-tracking'); + proclaim.equal(secondEvent.action, 'queue-bug'); + proclaim.equal(secondEvent.context.queue_length, 401); + proclaim.deepEqual(secondEvent.context.counts, { + 'page:view': 400, + 'button:click': 1, + }); + + proclaim.equal(queue.all().length, 0); + }); - // Event added for the debugging info - proclaim.equal(queue.all().length, 0); + it('should summarise offline status and queue time', async function () { + const clock = sinon.useFakeTimers({ + now: new Date(0), + toFake: ['Date'], + }); + + // queue up 100 'online' events which fail to send + for (let i = 0; i < 100; i++) { + errorNextSend(); + addAndRun({ + category: 'page', + action: 'view', + }); + clock.tick(1); + } - // console.log(queue.all()); - server.restore(); - done(); - } catch (error) { - done(error); + // queue up 301 'offline' events with a queue lag + for (let i = 0; i < 301; i++) { + errorNextSend(); + addAndRun({ + category: 'page', + action: 'view', + device: { + is_offline: true, + }, + }); + clock.tick(1); } - }, 200); + + // Go online, and send the events with a clean sinon.spy history + sendSpy.resetHistory(); + addAndRun({ + category: 'button', + action: 'click', + }); + + // Two send events should have been attempted + proclaim.equal(sendSpy.callCount, 2); + + // NB: our mockTransport completes synchronously, so the last click event is + // sent before the queue-bug event. It'll be the other way around with + // a real HTTP call, but harder to observe the test framework. + const firstEvent = JSON.parse(sendSpy.firstCall.args[1]); + proclaim.equal(firstEvent.category, 'button'); + proclaim.equal(firstEvent.action, 'click'); + + const secondEvent = JSON.parse(sendSpy.secondCall.args[1]); + proclaim.equal(secondEvent.category, 'o-tracking'); + proclaim.equal(secondEvent.action, 'queue-bug'); + proclaim.equal(secondEvent.context.maxOfflineLag, 200); + proclaim.equal(secondEvent.context.averageOfflineLag, 100); + proclaim.equal(secondEvent.context.totalOfflineLag, 40000); + proclaim.deepEqual(secondEvent.context.isOfflineCounts, { + true: 301, + false: 100, + }); + + clock.restore(); + }); }); it('should replace circular references with warning strings', function (done) { @@ -329,6 +444,4 @@ describe('Core.Send', function () { } }, 100); }); - - });