Large queue bug

libraries/o-tracking/src/javascript/core/send.js

@@ -129,31 +129,76 @@ 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({
 			category: 'o-tracking',
 			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};

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.');
 		});

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);
 	});
-
-
 });