From 110e9a455b95c063f451e72e1ae2511f38fb75b6 Mon Sep 17 00:00:00 2001 From: Sam Date: Fri, 16 Oct 2020 09:49:55 +1100 Subject: [PATCH] FEATURE: when we fail to ship topic timings attempt to retry (#10916) * FEATURE: when we fail to ship topic timings attempt to retry This change amends it so 1. Topic timings are treated as background requests and subject to more aggressive rate limits. 2. If we notice an error when we ship timings we back off exponentially The commit allows 405, 429, 500, 501, 502, 503 and 504 errors to be retried. 500+ errors usually happen when self hosters are rebuilding or some other weird condition. 405 happens when site is in readonly. 429 happens when user is rate limited. The retry cadence is hardcoded in AJAX_FAILURE_DELAYS, longest delay is 40 seconds, we may consider enlarging it. After the last delay passes we give up and do not write timings to the server. * Address feedback - Omit promise, no need to use promises in sendNextConsolidatedTiming - Correct issue where >= -1 was used and > -1 was intended - Use objects for consolidated timings instead of Array - Stop using shift/unshift and instead use push / pop which are faster * Move consolidated timing initialization to constructor * Remove TODO and just console.warn if we have an issue --- .../discourse/app/lib/screen-track.js | 145 +++++++++++++----- .../tests/unit/lib/screen-track-test.js | 21 +++ 2 files changed, 130 insertions(+), 36 deletions(-) create mode 100644 app/assets/javascripts/discourse/tests/unit/lib/screen-track-test.js diff --git a/app/assets/javascripts/discourse/app/lib/screen-track.js b/app/assets/javascripts/discourse/app/lib/screen-track.js index 028d63e3a74..5ef5798967a 100644 --- a/app/assets/javascripts/discourse/app/lib/screen-track.js +++ b/app/assets/javascripts/discourse/app/lib/screen-track.js @@ -7,6 +7,9 @@ const PAUSE_UNLESS_SCROLLED = 1000 * 60 * 3; const MAX_TRACKING_TIME = 1000 * 60 * 6; const ANON_MAX_TOPIC_IDS = 5; +const AJAX_FAILURE_DELAYS = [5000, 10000, 20000, 40000]; +const ALLOWED_AJAX_FAILURES = [405, 429, 500, 501, 502, 503, 504]; + export default class { constructor(topicTrackingState, siteSettings, session, currentUser) { this.topicTrackingState = topicTrackingState; @@ -14,6 +17,7 @@ export default class { this.session = session; this.currentUser = currentUser; this.reset(); + this._consolidatedTimings = []; } start(topicId, topicController) { @@ -85,6 +89,104 @@ export default class { this._anonCallback = cb; } + consolidateTimings(timings, topicTime, topicId) { + let foundIndex = this._consolidatedTimings.findIndex( + (elem) => elem.topicId === topicId + ); + + if (foundIndex > -1) { + let found = this._consolidatedTimings[foundIndex]; + + const lastIndex = this._consolidatedTimings.length - 1; + + if (foundIndex !== lastIndex) { + const last = this._consolidatedTimings[lastIndex]; + this._consolidatedTimings[lastIndex] = found; + this._consolidatedTimings[lastIndex - 1] = last; + } + + const oldTimings = found.timings; + Object.keys(oldTimings).forEach((id) => { + if (timings[id]) { + oldTimings[id] += timings[id]; + } + }); + found.topicTime += topicTime; + found.timings = Object.assign({}, timings, found.timings); + } else { + this._consolidatedTimings.push({ timings, topicTime, topicId }); + } + + return this._consolidatedTimings; + } + + sendNextConsolidatedTiming() { + if (this._consolidatedTimings.length === 0) { + return; + } + + if (this._inProgress) { + return; + } + + if ( + this._blockSendingToServerTill && + this._blockSendingToServerTill > Date.now() + ) { + return; + } + + this._ajaxFailures = this._ajaxFailures || 0; + + const { timings, topicTime, topicId } = this._consolidatedTimings.pop(); + + this._inProgress = true; + + ajax("/topics/timings", { + data: { + timings: timings, + topic_time: topicTime, + topic_id: topicId, + }, + cache: false, + type: "POST", + headers: { + "X-SILENCE-LOGGER": "true", + "Discourse-Background": "true", + }, + }) + .then(() => { + this._ajaxFailures = 0; + const topicController = this._topicController; + if (topicController) { + const postNumbers = Object.keys(timings).map((v) => parseInt(v, 10)); + topicController.readPosts(topicId, postNumbers); + } + }) + .catch((e) => { + if (ALLOWED_AJAX_FAILURES.indexOf(e.jqXHR.status) > -1) { + const delay = AJAX_FAILURE_DELAYS[this._ajaxFailures]; + this._ajaxFailures += 1; + + if (delay) { + this._blockSendingToServerTill = Date.now() + delay; + // we did not send to the server, got to re-queue it + this.consolidateTimings(timings, topicTime, topicId); + } + } + + if (window.console && window.console.warn) { + window.console.warn( + `Failed to update topic times for topic ${topicId} due to ${e.jqXHR.status} error` + ); + } + }) + .finally(() => { + this._inProgress = false; + this._lastFlush = 0; + }); + } + flush() { const newTimings = {}; const totalTimings = this._totalTimings; @@ -140,42 +242,8 @@ export default class { if (!$.isEmptyObject(newTimings)) { if (this.currentUser && !isTesting()) { - this._inProgress = true; - - ajax("/topics/timings", { - data: { - timings: newTimings, - topic_time: this._topicTime, - topic_id: topicId, - }, - cache: false, - type: "POST", - headers: { - "X-SILENCE-LOGGER": "true", - }, - }) - .then(() => { - const topicController = this._topicController; - if (topicController) { - const postNumbers = Object.keys(newTimings).map((v) => - parseInt(v, 10) - ); - topicController.readPosts(topicId, postNumbers); - } - }) - .catch((e) => { - const error = e.jqXHR; - if ( - error.status === 405 && - error.responseJSON.error_type === "read_only" - ) { - return; - } - }) - .finally(() => { - this._inProgress = false; - this._lastFlush = 0; - }); + this.consolidateTimings(newTimings, this._topicTime, topicId); + this.sendNextConsolidatedTiming(); } else if (this._anonCallback) { // Anonymous viewer - save to localStorage const storage = this.keyValueStore; @@ -240,6 +308,11 @@ export default class { this.flush(); } + if (!this._inProgress) { + // handles retries so there is no situation where we are stuck with a backlog + this.sendNextConsolidatedTiming(); + } + if (this.session.hasFocus) { this._topicTime += diff; diff --git a/app/assets/javascripts/discourse/tests/unit/lib/screen-track-test.js b/app/assets/javascripts/discourse/tests/unit/lib/screen-track-test.js new file mode 100644 index 00000000000..178bca44681 --- /dev/null +++ b/app/assets/javascripts/discourse/tests/unit/lib/screen-track-test.js @@ -0,0 +1,21 @@ +import { test, module } from "qunit"; +import ScreenTrack from "discourse/lib/screen-track"; + +module("lib:screen-track"); + +test("consolidateTimings", (assert) => { + const tracker = new ScreenTrack(); + + tracker.consolidateTimings({ 1: 10, 2: 5 }, 10, 1); + tracker.consolidateTimings({ 1: 5, 3: 1 }, 3, 1); + const consolidated = tracker.consolidateTimings({ 1: 5, 3: 1 }, 3, 2); + + assert.deepEqual( + consolidated, + [ + { timings: { 1: 15, 2: 5, 3: 1 }, topicTime: 13, topicId: 1 }, + { timings: { 1: 5, 3: 1 }, topicTime: 3, topicId: 2 }, + ], + "expecting consolidated timings to match correctly" + ); +});