From d53c836fd7740cc3a3035b294514ff4bf5383b58 Mon Sep 17 00:00:00 2001 From: Luke Barnard Date: Thu, 5 Jul 2018 13:54:44 +0100 Subject: [PATCH 1/3] Implement aggregation by error type for tracked decryption failures --- src/DecryptionFailureTracker.js | 82 +++++++++++------ src/components/structures/MatrixChat.js | 19 +++- test/DecryptionFailureTracker-test.js | 115 +++++++++++++++++------- 3 files changed, 156 insertions(+), 60 deletions(-) diff --git a/src/DecryptionFailureTracker.js b/src/DecryptionFailureTracker.js index e7809d2f6c..b02a5e937b 100644 --- a/src/DecryptionFailureTracker.js +++ b/src/DecryptionFailureTracker.js @@ -14,22 +14,25 @@ See the License for the specific language governing permissions and limitations under the License. */ -class DecryptionFailure { - constructor(failedEventId) { +export class DecryptionFailure { + constructor(failedEventId, errorCode) { this.failedEventId = failedEventId; + this.errorCode = errorCode; this.ts = Date.now(); } } -export default class DecryptionFailureTracker { +export class DecryptionFailureTracker { // Array of items of type DecryptionFailure. Every `CHECK_INTERVAL_MS`, this list // is checked for failures that happened > `GRACE_PERIOD_MS` ago. Those that did - // are added to `failuresToTrack`. + // are accumulated in `failureCounts`. failures = []; - // Every TRACK_INTERVAL_MS (so as to spread the number of hits done on Analytics), - // one DecryptionFailure of this FIFO is removed and tracked. - failuresToTrack = []; + // A histogram of the number of failures that will be tracked at the next tracking + // interval, split by failure error code. + failureCounts = { + // [errorCode]: 42 + }; // Event IDs of failures that were tracked previously trackedEventHashMap = { @@ -46,16 +49,35 @@ export default class DecryptionFailureTracker { // Call `checkFailures` every `CHECK_INTERVAL_MS`. static CHECK_INTERVAL_MS = 5000; - // Give events a chance to be decrypted by waiting `GRACE_PERIOD_MS` before moving - // the failure to `failuresToTrack`. + // Give events a chance to be decrypted by waiting `GRACE_PERIOD_MS` before counting + // the failure in `failureCounts`. static GRACE_PERIOD_MS = 60000; - constructor(fn) { + /** + * Create a new DecryptionFailureTracker. + * + * Call `eventDecrypted(event, err)` on this instance when an event is decrypted. + * + * Call `start()` to start the tracker, and `stop()` to stop tracking. + * + * @param {function} fn The tracking function, which will be called when failures + * are tracked. The function should have a signature `(count, trackedErrorCode) => {...}`, + * where `count` is the number of failures and `errorCode` matches the `.code` of + * provided DecryptionError errors (by default, unless `errorCodeMapFn` is specified. + * @param {function?} errorCodeMapFn The function used to map error codes to the + * trackedErrorCode. If not provided, the `.code` of errors will be used. + */ + constructor(fn, errorCodeMapFn) { if (!fn || typeof fn !== 'function') { throw new Error('DecryptionFailureTracker requires tracking function'); } - this.trackDecryptionFailure = fn; + if (errorCodeMapFn && typeof errorCodeMapFn !== 'function') { + throw new Error('DecryptionFailureTracker second constructor argument should be a function'); + } + + this._trackDecryptionFailure = fn; + this._mapErrorCode = errorCodeMapFn; } // loadTrackedEventHashMap() { @@ -66,17 +88,17 @@ export default class DecryptionFailureTracker { // localStorage.setItem('mx-decryption-failure-event-id-hashes', JSON.stringify(this.trackedEventHashMap)); // } - eventDecrypted(e) { - if (e.isDecryptionFailure()) { - this.addDecryptionFailureForEvent(e); + eventDecrypted(e, err) { + if (err) { + this.addDecryptionFailure(new DecryptionFailure(e.getId(), err.code)); } else { // Could be an event in the failures, remove it this.removeDecryptionFailuresForEvent(e); } } - addDecryptionFailureForEvent(e) { - this.failures.push(new DecryptionFailure(e.getId())); + addDecryptionFailure(failure) { + this.failures.push(failure); } removeDecryptionFailuresForEvent(e) { @@ -93,7 +115,7 @@ export default class DecryptionFailureTracker { ); this.trackInterval = setInterval( - () => this.trackFailure(), + () => this.trackFailures(), DecryptionFailureTracker.TRACK_INTERVAL_MS, ); } @@ -106,7 +128,7 @@ export default class DecryptionFailureTracker { clearInterval(this.trackInterval); this.failures = []; - this.failuresToTrack = []; + this.failureCounts = {}; } /** @@ -153,20 +175,28 @@ export default class DecryptionFailureTracker { const dedupedFailures = dedupedFailuresMap.values(); - this.failuresToTrack = [...this.failuresToTrack, ...dedupedFailures]; + this._aggregateFailures(dedupedFailures); + } + + _aggregateFailures(failures) { + for (const failure of failures) { + const errorCode = failure.errorCode; + this.failureCounts[errorCode] = (this.failureCounts[errorCode] || 0) + 1; + } } /** * If there are failures that should be tracked, call the given trackDecryptionFailure * function with the number of failures that should be tracked. */ - trackFailure() { - if (this.failuresToTrack.length > 0) { - // Remove all failures, and expose the number of failures for now. - // - // TODO: Track a histogram of error types to cardinailty to allow for - // aggregation by error type. - this.trackDecryptionFailure(this.failuresToTrack.splice(0).length); + trackFailures() { + for (const errorCode of Object.keys(this.failureCounts)) { + if (this.failureCounts[errorCode] > 0) { + const trackedErrorCode = this._mapErrorCode ? this._mapErrorCode(errorCode) : errorCode; + + this._trackDecryptionFailure(this.failureCounts[errorCode], trackedErrorCode); + this.failureCounts[errorCode] = 0; + } } } } diff --git a/src/components/structures/MatrixChat.js b/src/components/structures/MatrixChat.js index 9ea0cb42c8..7150c661ed 100644 --- a/src/components/structures/MatrixChat.js +++ b/src/components/structures/MatrixChat.js @@ -1304,9 +1304,20 @@ export default React.createClass({ } }); - const dft = new DecryptionFailureTracker((total) => { - // TODO: Pass reason for failure as third argument to trackEvent - Analytics.trackEvent('E2E', 'Decryption failure', 'unspecified_error', total); + const dft = new DecryptionFailureTracker((total, errorCode) => { + Analytics.trackEvent('E2E', 'Decryption failure', errorCode, total); + }, (errorCode) => { + // Map JS-SDK error codes to tracker codes for aggregation + switch (errorCode) { + case 'MEGOLM_UNKNOWN_INBOUND_SESSION_ID': + return 'olm_keys_not_sent_error'; + case 'OLM_UNKNOWN_MESSAGE_INDEX': + return 'olm_index_error'; + case undefined: + return 'unexpected_error'; + default: + return 'unspecified_error'; + } }); // Shelved for later date when we have time to think about persisting history of @@ -1317,7 +1328,7 @@ export default React.createClass({ // When logging out, stop tracking failures and destroy state cli.on("Session.logged_out", () => dft.stop()); - cli.on("Event.decrypted", (e) => dft.eventDecrypted(e)); + cli.on("Event.decrypted", (e, err) => dft.eventDecrypted(e, err)); const krh = new KeyRequestHandler(cli); cli.on("crypto.roomKeyRequest", (req) => { diff --git a/test/DecryptionFailureTracker-test.js b/test/DecryptionFailureTracker-test.js index 4979fb9bb4..99922276c5 100644 --- a/test/DecryptionFailureTracker-test.js +++ b/test/DecryptionFailureTracker-test.js @@ -16,10 +16,18 @@ limitations under the License. import expect from 'expect'; -import DecryptionFailureTracker from '../src/DecryptionFailureTracker'; +import { DecryptionFailure, DecryptionFailureTracker } from '../src/DecryptionFailureTracker'; import { MatrixEvent } from 'matrix-js-sdk'; +class MockDecryptionError extends Error { + constructor(code) { + super(); + + this.code = code || 'MOCK_DECRYPTION_ERROR'; + } +} + function createFailedDecryptionEvent() { const event = new MatrixEvent({ event_id: "event-id-" + Math.random().toString(16).slice(2), @@ -30,20 +38,21 @@ function createFailedDecryptionEvent() { return event; } -describe('DecryptionFailureTracker', function() { +describe.only('DecryptionFailureTracker', function() { it('tracks a failed decryption', function(done) { const failedDecryptionEvent = createFailedDecryptionEvent(); let count = 0; const tracker = new DecryptionFailureTracker((total) => count += total); - tracker.eventDecrypted(failedDecryptionEvent); + const err = new MockDecryptionError(); + tracker.eventDecrypted(failedDecryptionEvent, err); // Pretend "now" is Infinity tracker.checkFailures(Infinity); - // Immediately track the newest failure, if there is one - tracker.trackFailure(); + // Immediately track the newest failures + tracker.trackFailures(); expect(count).toNotBe(0, 'should track a failure for an event that failed decryption'); @@ -56,17 +65,18 @@ describe('DecryptionFailureTracker', function() { expect(true).toBe(false, 'should not track an event that has since been decrypted correctly'); }); - tracker.eventDecrypted(decryptedEvent); + const err = new MockDecryptionError(); + tracker.eventDecrypted(decryptedEvent, err); // Indicate successful decryption: clear data can be anything where the msgtype is not m.bad.encrypted decryptedEvent._setClearData({}); - tracker.eventDecrypted(decryptedEvent); + tracker.eventDecrypted(decryptedEvent, null); // Pretend "now" is Infinity tracker.checkFailures(Infinity); - // Immediately track the newest failure, if there is one - tracker.trackFailure(); + // Immediately track the newest failures + tracker.trackFailures(); done(); }); @@ -78,23 +88,24 @@ describe('DecryptionFailureTracker', function() { const tracker = new DecryptionFailureTracker((total) => count += total); // Arbitrary number of failed decryptions for both events - tracker.eventDecrypted(decryptedEvent); - tracker.eventDecrypted(decryptedEvent); - tracker.eventDecrypted(decryptedEvent); - tracker.eventDecrypted(decryptedEvent); - tracker.eventDecrypted(decryptedEvent); - tracker.eventDecrypted(decryptedEvent2); - tracker.eventDecrypted(decryptedEvent2); - tracker.eventDecrypted(decryptedEvent2); + const err = new MockDecryptionError(); + tracker.eventDecrypted(decryptedEvent, err); + tracker.eventDecrypted(decryptedEvent, err); + tracker.eventDecrypted(decryptedEvent, err); + tracker.eventDecrypted(decryptedEvent, err); + tracker.eventDecrypted(decryptedEvent, err); + tracker.eventDecrypted(decryptedEvent2, err); + tracker.eventDecrypted(decryptedEvent2, err); + tracker.eventDecrypted(decryptedEvent2, err); // Pretend "now" is Infinity tracker.checkFailures(Infinity); - // Simulated polling of `trackFailure`, an arbitrary number ( > 2 ) times - tracker.trackFailure(); - tracker.trackFailure(); - tracker.trackFailure(); - tracker.trackFailure(); + // Simulated polling of `trackFailures`, an arbitrary number ( > 2 ) times + tracker.trackFailures(); + tracker.trackFailures(); + tracker.trackFailures(); + tracker.trackFailures(); expect(count).toBe(2, count + ' failures tracked, should only track a single failure per event'); @@ -108,17 +119,18 @@ describe('DecryptionFailureTracker', function() { const tracker = new DecryptionFailureTracker((total) => count += total); // Indicate decryption - tracker.eventDecrypted(decryptedEvent); + const err = new MockDecryptionError(); + tracker.eventDecrypted(decryptedEvent, err); // Pretend "now" is Infinity tracker.checkFailures(Infinity); - tracker.trackFailure(); + tracker.trackFailures(); // Indicate a second decryption, after having tracked the failure - tracker.eventDecrypted(decryptedEvent); + tracker.eventDecrypted(decryptedEvent, err); - tracker.trackFailure(); + tracker.trackFailures(); expect(count).toBe(1, 'should only track a single failure per event'); @@ -135,25 +147,68 @@ describe('DecryptionFailureTracker', function() { const tracker = new DecryptionFailureTracker((total) => count += total); // Indicate decryption - tracker.eventDecrypted(decryptedEvent); + const err = new MockDecryptionError(); + tracker.eventDecrypted(decryptedEvent, err); // Pretend "now" is Infinity // NB: This saves to localStorage specific to DFT tracker.checkFailures(Infinity); - tracker.trackFailure(); + tracker.trackFailures(); // Simulate the browser refreshing by destroying tracker and creating a new tracker const secondTracker = new DecryptionFailureTracker((total) => count += total); //secondTracker.loadTrackedEventHashMap(); - secondTracker.eventDecrypted(decryptedEvent); + secondTracker.eventDecrypted(decryptedEvent, err); secondTracker.checkFailures(Infinity); - secondTracker.trackFailure(); + secondTracker.trackFailures(); expect(count).toBe(1, count + ' failures tracked, should only track a single failure per event'); done(); }); + + it('should count different error codes separately for multiple failures with different error codes', () => { + const counts = {}; + const tracker = new DecryptionFailureTracker( + (total, errorCode) => counts[errorCode] = (counts[errorCode] || 0) + total, + ); + + // One failure of ERROR_CODE_1, and effectively two for ERROR_CODE_2 + tracker.addDecryptionFailure(new DecryptionFailure('$event_id1', 'ERROR_CODE_1')); + tracker.addDecryptionFailure(new DecryptionFailure('$event_id2', 'ERROR_CODE_2')); + tracker.addDecryptionFailure(new DecryptionFailure('$event_id2', 'ERROR_CODE_2')); + tracker.addDecryptionFailure(new DecryptionFailure('$event_id3', 'ERROR_CODE_2')); + + // Pretend "now" is Infinity + tracker.checkFailures(Infinity); + + tracker.trackFailures(); + + expect(counts['ERROR_CODE_1']).toBe(1, 'should track one ERROR_CODE_1'); + expect(counts['ERROR_CODE_2']).toBe(2, 'should track two ERROR_CODE_2'); + }); + + it('should map error codes correctly', () => { + const counts = {}; + const tracker = new DecryptionFailureTracker( + (total, errorCode) => counts[errorCode] = (counts[errorCode] || 0) + total, + (errorCode) => 'MY_NEW_ERROR_CODE', + ); + + // One failure of ERROR_CODE_1, and effectively two for ERROR_CODE_2 + tracker.addDecryptionFailure(new DecryptionFailure('$event_id1', 'ERROR_CODE_1')); + tracker.addDecryptionFailure(new DecryptionFailure('$event_id2', 'ERROR_CODE_2')); + tracker.addDecryptionFailure(new DecryptionFailure('$event_id3', 'ERROR_CODE_3')); + + // Pretend "now" is Infinity + tracker.checkFailures(Infinity); + + tracker.trackFailures(); + + expect(counts['MY_NEW_ERROR_CODE']) + .toBe(3, 'should track three MY_NEW_ERROR_CODE, got ' + counts['MY_NEW_ERROR_CODE']); + }); }); From 15bd2e157faa4128d78872a8a5fa15e5f9869f35 Mon Sep 17 00:00:00 2001 From: Luke Barnard Date: Thu, 5 Jul 2018 14:55:29 +0100 Subject: [PATCH 2/3] Test everything --- test/DecryptionFailureTracker-test.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/DecryptionFailureTracker-test.js b/test/DecryptionFailureTracker-test.js index 99922276c5..617c9d5d68 100644 --- a/test/DecryptionFailureTracker-test.js +++ b/test/DecryptionFailureTracker-test.js @@ -38,7 +38,7 @@ function createFailedDecryptionEvent() { return event; } -describe.only('DecryptionFailureTracker', function() { +describe('DecryptionFailureTracker', function() { it('tracks a failed decryption', function(done) { const failedDecryptionEvent = createFailedDecryptionEvent(); From 5af8ddcf107b30ec1583648f4d2e5143aa8df3f1 Mon Sep 17 00:00:00 2001 From: Luke Barnard Date: Fri, 6 Jul 2018 11:00:39 +0100 Subject: [PATCH 3/3] Fix import --- src/components/structures/MatrixChat.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/components/structures/MatrixChat.js b/src/components/structures/MatrixChat.js index 7150c661ed..e0bbf50d5a 100644 --- a/src/components/structures/MatrixChat.js +++ b/src/components/structures/MatrixChat.js @@ -23,7 +23,7 @@ import PropTypes from 'prop-types'; import Matrix from "matrix-js-sdk"; import Analytics from "../../Analytics"; -import DecryptionFailureTracker from "../../DecryptionFailureTracker"; +import { DecryptionFailureTracker } from "../../DecryptionFailureTracker"; import MatrixClientPeg from "../../MatrixClientPeg"; import PlatformPeg from "../../PlatformPeg"; import SdkConfig from "../../SdkConfig";