Merge pull request #2045 from matrix-org/luke/track-decryption-failures-specific

Implement aggregation by error type for tracked decryption failures
pull/21833/head
David Baker 2018-07-06 15:48:22 +01:00 committed by GitHub
commit 983ea950be
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 156 additions and 60 deletions

View File

@ -14,22 +14,25 @@ See the License for the specific language governing permissions and
limitations under the License. limitations under the License.
*/ */
class DecryptionFailure { export class DecryptionFailure {
constructor(failedEventId) { constructor(failedEventId, errorCode) {
this.failedEventId = failedEventId; this.failedEventId = failedEventId;
this.errorCode = errorCode;
this.ts = Date.now(); this.ts = Date.now();
} }
} }
export default class DecryptionFailureTracker { export class DecryptionFailureTracker {
// Array of items of type DecryptionFailure. Every `CHECK_INTERVAL_MS`, this list // 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 // is checked for failures that happened > `GRACE_PERIOD_MS` ago. Those that did
// are added to `failuresToTrack`. // are accumulated in `failureCounts`.
failures = []; failures = [];
// Every TRACK_INTERVAL_MS (so as to spread the number of hits done on Analytics), // A histogram of the number of failures that will be tracked at the next tracking
// one DecryptionFailure of this FIFO is removed and tracked. // interval, split by failure error code.
failuresToTrack = []; failureCounts = {
// [errorCode]: 42
};
// Event IDs of failures that were tracked previously // Event IDs of failures that were tracked previously
trackedEventHashMap = { trackedEventHashMap = {
@ -46,16 +49,35 @@ export default class DecryptionFailureTracker {
// Call `checkFailures` every `CHECK_INTERVAL_MS`. // Call `checkFailures` every `CHECK_INTERVAL_MS`.
static CHECK_INTERVAL_MS = 5000; static CHECK_INTERVAL_MS = 5000;
// Give events a chance to be decrypted by waiting `GRACE_PERIOD_MS` before moving // Give events a chance to be decrypted by waiting `GRACE_PERIOD_MS` before counting
// the failure to `failuresToTrack`. // the failure in `failureCounts`.
static GRACE_PERIOD_MS = 60000; 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') { if (!fn || typeof fn !== 'function') {
throw new Error('DecryptionFailureTracker requires tracking 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() { // loadTrackedEventHashMap() {
@ -66,17 +88,17 @@ export default class DecryptionFailureTracker {
// localStorage.setItem('mx-decryption-failure-event-id-hashes', JSON.stringify(this.trackedEventHashMap)); // localStorage.setItem('mx-decryption-failure-event-id-hashes', JSON.stringify(this.trackedEventHashMap));
// } // }
eventDecrypted(e) { eventDecrypted(e, err) {
if (e.isDecryptionFailure()) { if (err) {
this.addDecryptionFailureForEvent(e); this.addDecryptionFailure(new DecryptionFailure(e.getId(), err.code));
} else { } else {
// Could be an event in the failures, remove it // Could be an event in the failures, remove it
this.removeDecryptionFailuresForEvent(e); this.removeDecryptionFailuresForEvent(e);
} }
} }
addDecryptionFailureForEvent(e) { addDecryptionFailure(failure) {
this.failures.push(new DecryptionFailure(e.getId())); this.failures.push(failure);
} }
removeDecryptionFailuresForEvent(e) { removeDecryptionFailuresForEvent(e) {
@ -93,7 +115,7 @@ export default class DecryptionFailureTracker {
); );
this.trackInterval = setInterval( this.trackInterval = setInterval(
() => this.trackFailure(), () => this.trackFailures(),
DecryptionFailureTracker.TRACK_INTERVAL_MS, DecryptionFailureTracker.TRACK_INTERVAL_MS,
); );
} }
@ -106,7 +128,7 @@ export default class DecryptionFailureTracker {
clearInterval(this.trackInterval); clearInterval(this.trackInterval);
this.failures = []; this.failures = [];
this.failuresToTrack = []; this.failureCounts = {};
} }
/** /**
@ -153,20 +175,28 @@ export default class DecryptionFailureTracker {
const dedupedFailures = dedupedFailuresMap.values(); 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 * If there are failures that should be tracked, call the given trackDecryptionFailure
* function with the number of failures that should be tracked. * function with the number of failures that should be tracked.
*/ */
trackFailure() { trackFailures() {
if (this.failuresToTrack.length > 0) { for (const errorCode of Object.keys(this.failureCounts)) {
// Remove all failures, and expose the number of failures for now. if (this.failureCounts[errorCode] > 0) {
// const trackedErrorCode = this._mapErrorCode ? this._mapErrorCode(errorCode) : errorCode;
// TODO: Track a histogram of error types to cardinailty to allow for
// aggregation by error type. this._trackDecryptionFailure(this.failureCounts[errorCode], trackedErrorCode);
this.trackDecryptionFailure(this.failuresToTrack.splice(0).length); this.failureCounts[errorCode] = 0;
}
} }
} }
} }

View File

@ -23,7 +23,7 @@ import PropTypes from 'prop-types';
import Matrix from "matrix-js-sdk"; import Matrix from "matrix-js-sdk";
import Analytics from "../../Analytics"; import Analytics from "../../Analytics";
import DecryptionFailureTracker from "../../DecryptionFailureTracker"; import { DecryptionFailureTracker } from "../../DecryptionFailureTracker";
import MatrixClientPeg from "../../MatrixClientPeg"; import MatrixClientPeg from "../../MatrixClientPeg";
import PlatformPeg from "../../PlatformPeg"; import PlatformPeg from "../../PlatformPeg";
import SdkConfig from "../../SdkConfig"; import SdkConfig from "../../SdkConfig";
@ -1304,9 +1304,20 @@ export default React.createClass({
} }
}); });
const dft = new DecryptionFailureTracker((total) => { const dft = new DecryptionFailureTracker((total, errorCode) => {
// TODO: Pass reason for failure as third argument to trackEvent Analytics.trackEvent('E2E', 'Decryption failure', errorCode, total);
Analytics.trackEvent('E2E', 'Decryption failure', 'unspecified_error', 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 // 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 // When logging out, stop tracking failures and destroy state
cli.on("Session.logged_out", () => dft.stop()); 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); const krh = new KeyRequestHandler(cli);
cli.on("crypto.roomKeyRequest", (req) => { cli.on("crypto.roomKeyRequest", (req) => {

View File

@ -16,10 +16,18 @@ limitations under the License.
import expect from 'expect'; import expect from 'expect';
import DecryptionFailureTracker from '../src/DecryptionFailureTracker'; import { DecryptionFailure, DecryptionFailureTracker } from '../src/DecryptionFailureTracker';
import { MatrixEvent } from 'matrix-js-sdk'; import { MatrixEvent } from 'matrix-js-sdk';
class MockDecryptionError extends Error {
constructor(code) {
super();
this.code = code || 'MOCK_DECRYPTION_ERROR';
}
}
function createFailedDecryptionEvent() { function createFailedDecryptionEvent() {
const event = new MatrixEvent({ const event = new MatrixEvent({
event_id: "event-id-" + Math.random().toString(16).slice(2), event_id: "event-id-" + Math.random().toString(16).slice(2),
@ -37,13 +45,14 @@ describe('DecryptionFailureTracker', function() {
let count = 0; let count = 0;
const tracker = new DecryptionFailureTracker((total) => count += total); const tracker = new DecryptionFailureTracker((total) => count += total);
tracker.eventDecrypted(failedDecryptionEvent); const err = new MockDecryptionError();
tracker.eventDecrypted(failedDecryptionEvent, err);
// Pretend "now" is Infinity // Pretend "now" is Infinity
tracker.checkFailures(Infinity); tracker.checkFailures(Infinity);
// Immediately track the newest failure, if there is one // Immediately track the newest failures
tracker.trackFailure(); tracker.trackFailures();
expect(count).toNotBe(0, 'should track a failure for an event that failed decryption'); 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'); 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 // Indicate successful decryption: clear data can be anything where the msgtype is not m.bad.encrypted
decryptedEvent._setClearData({}); decryptedEvent._setClearData({});
tracker.eventDecrypted(decryptedEvent); tracker.eventDecrypted(decryptedEvent, null);
// Pretend "now" is Infinity // Pretend "now" is Infinity
tracker.checkFailures(Infinity); tracker.checkFailures(Infinity);
// Immediately track the newest failure, if there is one // Immediately track the newest failures
tracker.trackFailure(); tracker.trackFailures();
done(); done();
}); });
@ -78,23 +88,24 @@ describe('DecryptionFailureTracker', function() {
const tracker = new DecryptionFailureTracker((total) => count += total); const tracker = new DecryptionFailureTracker((total) => count += total);
// Arbitrary number of failed decryptions for both events // Arbitrary number of failed decryptions for both events
tracker.eventDecrypted(decryptedEvent); const err = new MockDecryptionError();
tracker.eventDecrypted(decryptedEvent); tracker.eventDecrypted(decryptedEvent, err);
tracker.eventDecrypted(decryptedEvent); tracker.eventDecrypted(decryptedEvent, err);
tracker.eventDecrypted(decryptedEvent); tracker.eventDecrypted(decryptedEvent, err);
tracker.eventDecrypted(decryptedEvent); tracker.eventDecrypted(decryptedEvent, err);
tracker.eventDecrypted(decryptedEvent2); tracker.eventDecrypted(decryptedEvent, err);
tracker.eventDecrypted(decryptedEvent2); tracker.eventDecrypted(decryptedEvent2, err);
tracker.eventDecrypted(decryptedEvent2); tracker.eventDecrypted(decryptedEvent2, err);
tracker.eventDecrypted(decryptedEvent2, err);
// Pretend "now" is Infinity // Pretend "now" is Infinity
tracker.checkFailures(Infinity); tracker.checkFailures(Infinity);
// Simulated polling of `trackFailure`, an arbitrary number ( > 2 ) times // Simulated polling of `trackFailures`, an arbitrary number ( > 2 ) times
tracker.trackFailure(); tracker.trackFailures();
tracker.trackFailure(); tracker.trackFailures();
tracker.trackFailure(); tracker.trackFailures();
tracker.trackFailure(); tracker.trackFailures();
expect(count).toBe(2, count + ' failures tracked, should only track a single failure per event'); 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); const tracker = new DecryptionFailureTracker((total) => count += total);
// Indicate decryption // Indicate decryption
tracker.eventDecrypted(decryptedEvent); const err = new MockDecryptionError();
tracker.eventDecrypted(decryptedEvent, err);
// Pretend "now" is Infinity // Pretend "now" is Infinity
tracker.checkFailures(Infinity); tracker.checkFailures(Infinity);
tracker.trackFailure(); tracker.trackFailures();
// Indicate a second decryption, after having tracked the failure // 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'); 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); const tracker = new DecryptionFailureTracker((total) => count += total);
// Indicate decryption // Indicate decryption
tracker.eventDecrypted(decryptedEvent); const err = new MockDecryptionError();
tracker.eventDecrypted(decryptedEvent, err);
// Pretend "now" is Infinity // Pretend "now" is Infinity
// NB: This saves to localStorage specific to DFT // NB: This saves to localStorage specific to DFT
tracker.checkFailures(Infinity); tracker.checkFailures(Infinity);
tracker.trackFailure(); tracker.trackFailures();
// Simulate the browser refreshing by destroying tracker and creating a new tracker // Simulate the browser refreshing by destroying tracker and creating a new tracker
const secondTracker = new DecryptionFailureTracker((total) => count += total); const secondTracker = new DecryptionFailureTracker((total) => count += total);
//secondTracker.loadTrackedEventHashMap(); //secondTracker.loadTrackedEventHashMap();
secondTracker.eventDecrypted(decryptedEvent); secondTracker.eventDecrypted(decryptedEvent, err);
secondTracker.checkFailures(Infinity); secondTracker.checkFailures(Infinity);
secondTracker.trackFailure(); secondTracker.trackFailures();
expect(count).toBe(1, count + ' failures tracked, should only track a single failure per event'); expect(count).toBe(1, count + ' failures tracked, should only track a single failure per event');
done(); 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']);
});
}); });