Merge pull request #1949 from matrix-org/luke/track-uisis-piwik

Track decryption success/failure rate with piwik

src/DecryptionFailureTracker.js

@@ -0,0 +1,169 @@
+/*
+Copyright 2018 New Vector Ltd
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+class DecryptionFailure {
+    constructor(failedEventId) {
+        this.failedEventId = failedEventId;
+        this.ts = Date.now();
+    }
+}
+
+export default 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`.
+    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 = [];
+
+    // Event IDs of failures that were tracked previously
+    trackedEventHashMap = {
+        // [eventId]: true
+    };
+
+    // Set to an interval ID when `start` is called
+    checkInterval = null;
+    trackInterval = null;
+
+    // Spread the load on `Analytics` by sending at most 1 event per
+    // `TRACK_INTERVAL_MS`.
+    static TRACK_INTERVAL_MS = 1000;
+
+    // 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`.
+    static GRACE_PERIOD_MS = 5000;
+
+    constructor(fn) {
+        if (!fn || typeof fn !== 'function') {
+            throw new Error('DecryptionFailureTracker requires tracking function');
+        }
+
+        this.trackDecryptionFailure = fn;
+    }
+
+    // loadTrackedEventHashMap() {
+    //     this.trackedEventHashMap = JSON.parse(localStorage.getItem('mx-decryption-failure-event-id-hashes')) || {};
+    // }
+
+    // saveTrackedEventHashMap() {
+    //     localStorage.setItem('mx-decryption-failure-event-id-hashes', JSON.stringify(this.trackedEventHashMap));
+    // }
+
+    eventDecrypted(e) {
+        if (e.isDecryptionFailure()) {
+            this.addDecryptionFailureForEvent(e);
+        } else {
+            // Could be an event in the failures, remove it
+            this.removeDecryptionFailuresForEvent(e);
+        }
+    }
+
+    addDecryptionFailureForEvent(e) {
+        this.failures.push(new DecryptionFailure(e.getId()));
+    }
+
+    removeDecryptionFailuresForEvent(e) {
+        this.failures = this.failures.filter((f) => f.failedEventId !== e.getId());
+    }
+
+    /**
+     * Start checking for and tracking failures.
+     */
+    start() {
+        this.checkInterval = setInterval(
+            () => this.checkFailures(Date.now()),
+            DecryptionFailureTracker.CHECK_INTERVAL_MS,
+        );
+
+        this.trackInterval = setInterval(
+            () => this.trackFailure(),
+            DecryptionFailureTracker.TRACK_INTERVAL_MS,
+        );
+    }
+
+    /**
+     * Clear state and stop checking for and tracking failures.
+     */
+    stop() {
+        clearInterval(this.checkInterval);
+        clearInterval(this.trackInterval);
+
+        this.failures = [];
+        this.failuresToTrack = [];
+    }
+
+    /**
+     * Mark failures that occured before nowTs - GRACE_PERIOD_MS as failures that should be
+     * tracked. Only mark one failure per event ID.
+     * @param {number} nowTs the timestamp that represents the time now.
+     */
+    checkFailures(nowTs) {
+        const failuresGivenGrace = [];
+        const failuresNotReady = [];
+        while (this.failures.length > 0) {
+            const f = this.failures.shift();
+            if (nowTs > f.ts + DecryptionFailureTracker.GRACE_PERIOD_MS) {
+                failuresGivenGrace.push(f);
+            } else {
+                failuresNotReady.push(f);
+            }
+        }
+        this.failures = failuresNotReady;
+
+        // Only track one failure per event
+        const dedupedFailuresMap = failuresGivenGrace.reduce(
+            (map, failure) => {
+                if (!this.trackedEventHashMap[failure.failedEventId]) {
+                    return map.set(failure.failedEventId, failure);
+                } else {
+                    return map;
+                }
+            },
+            // Use a map to preseve key ordering
+            new Map(),
+        );
+
+        const trackedEventIds = [...dedupedFailuresMap.keys()];
+
+        this.trackedEventHashMap = trackedEventIds.reduce(
+            (result, eventId) => ({...result, [eventId]: true}),
+            this.trackedEventHashMap,
+        );
+
+        // Commented out for now for expediency, we need to consider unbound nature of storing
+        // this in localStorage
+        // this.saveTrackedEventHashMap();
+
+        const dedupedFailures = dedupedFailuresMap.values();
+
+        this.failuresToTrack = [...this.failuresToTrack, ...dedupedFailures];
+    }
+
+    /**
+     * If there is a failure that should be tracked, call the given trackDecryptionFailure
+     * function with the first failure in the FIFO of failures that should be tracked.
+     */
+    trackFailure() {
+        if (this.failuresToTrack.length > 0) {
+            this.trackDecryptionFailure(this.failuresToTrack.shift());
+        }
+    }
+}

src/components/structures/MatrixChat.js

@@ -23,6 +23,7 @@ import PropTypes from 'prop-types';
 import Matrix from "matrix-js-sdk";
 
 import Analytics from "../../Analytics";
+import DecryptionFailureTracker from "../../DecryptionFailureTracker";
 import MatrixClientPeg from "../../MatrixClientPeg";
 import PlatformPeg from "../../PlatformPeg";
 import SdkConfig from "../../SdkConfig";
@@ -1303,6 +1304,21 @@ export default React.createClass({
             }
         });
 
+        const dft = new DecryptionFailureTracker((failure) => {
+            // TODO: Pass reason for failure as third argument to trackEvent
+            Analytics.trackEvent('E2E', 'Decryption failure');
+        });
+
+        // Shelved for later date when we have time to think about persisting history of
+        // tracked events across sessions.
+        // dft.loadTrackedEventHashMap();
+
+        dft.start();
+
+        // When logging out, stop tracking failures and destroy state
+        cli.on("Session.logged_out", () => dft.stop());
+        cli.on("Event.decrypted", (e) => dft.eventDecrypted(e));
+
         const krh = new KeyRequestHandler(cli);
         cli.on("crypto.roomKeyRequest", (req) => {
             krh.handleKeyRequest(req);

test/DecryptionFailureTracker-test.js

@@ -0,0 +1,185 @@
+/*
+Copyright 2018 New Vector Ltd
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+import expect from 'expect';
+
+import DecryptionFailureTracker from '../src/DecryptionFailureTracker';
+
+import { MatrixEvent } from 'matrix-js-sdk';
+
+function createFailedDecryptionEvent() {
+    const event = new MatrixEvent({
+        event_id: "event-id-" + Math.random().toString(16).slice(2),
+    });
+    event._setClearData(
+        event._badEncryptedMessage(":("),
+    );
+    return event;
+}
+
+describe('DecryptionFailureTracker', function() {
+    it('tracks a failed decryption', function(done) {
+        const failedDecryptionEvent = createFailedDecryptionEvent();
+        let trackedFailure = null;
+        const tracker = new DecryptionFailureTracker((failure) => {
+            trackedFailure = failure;
+        });
+
+        tracker.eventDecrypted(failedDecryptionEvent);
+
+        // Pretend "now" is Infinity
+        tracker.checkFailures(Infinity);
+
+        // Immediately track the newest failure, if there is one
+        tracker.trackFailure();
+
+        expect(trackedFailure).toNotBe(null, 'should track a failure for an event that failed decryption');
+
+        done();
+    });
+
+    it('does not track a failed decryption where the event is subsequently successfully decrypted', (done) => {
+        const decryptedEvent = createFailedDecryptionEvent();
+        const tracker = new DecryptionFailureTracker((failure) => {
+            expect(true).toBe(false, 'should not track an event that has since been decrypted correctly');
+        });
+
+        tracker.eventDecrypted(decryptedEvent);
+
+        // Indicate successful decryption: clear data can be anything where the msgtype is not m.bad.encrypted
+        decryptedEvent._setClearData({});
+        tracker.eventDecrypted(decryptedEvent);
+
+        // Pretend "now" is Infinity
+        tracker.checkFailures(Infinity);
+
+        // Immediately track the newest failure, if there is one
+        tracker.trackFailure();
+        done();
+    });
+
+    it('only tracks a single failure per event, despite multiple failed decryptions for multiple events', (done) => {
+        const decryptedEvent = createFailedDecryptionEvent();
+        const decryptedEvent2 = createFailedDecryptionEvent();
+
+        let count = 0;
+        const tracker = new DecryptionFailureTracker((failure) => count++);
+
+        // 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);
+
+        // Pretend "now" is Infinity
+        tracker.checkFailures(Infinity);
+
+        // Simulated polling of `trackFailure`, an arbitrary number ( > 2 ) times
+        tracker.trackFailure();
+        tracker.trackFailure();
+        tracker.trackFailure();
+        tracker.trackFailure();
+
+        expect(count).toBe(2, count + ' failures tracked, should only track a single failure per event');
+
+        done();
+    });
+
+    it('track failures in the order they occured', (done) => {
+        const decryptedEvent = createFailedDecryptionEvent();
+        const decryptedEvent2 = createFailedDecryptionEvent();
+
+        const failures = [];
+        const tracker = new DecryptionFailureTracker((failure) => failures.push(failure));
+
+        // Indicate decryption
+        tracker.eventDecrypted(decryptedEvent);
+        tracker.eventDecrypted(decryptedEvent2);
+
+        // Pretend "now" is Infinity
+        tracker.checkFailures(Infinity);
+
+        // Simulated polling of `trackFailure`, an arbitrary number ( > 2 ) times
+        tracker.trackFailure();
+        tracker.trackFailure();
+
+        expect(failures.length).toBe(2, 'expected 2 failures to be tracked, got ' + failures.length);
+        expect(failures[0].failedEventId).toBe(decryptedEvent.getId(), 'the first failure should be tracked first');
+        expect(failures[1].failedEventId).toBe(decryptedEvent2.getId(), 'the second failure should be tracked second');
+
+        done();
+    });
+
+    it('should not track a failure for an event that was tracked previously', (done) => {
+        const decryptedEvent = createFailedDecryptionEvent();
+
+        const failures = [];
+        const tracker = new DecryptionFailureTracker((failure) => failures.push(failure));
+
+        // Indicate decryption
+        tracker.eventDecrypted(decryptedEvent);
+
+        // Pretend "now" is Infinity
+        tracker.checkFailures(Infinity);
+
+        tracker.trackFailure();
+
+        // Indicate a second decryption, after having tracked the failure
+        tracker.eventDecrypted(decryptedEvent);
+
+        tracker.trackFailure();
+
+        expect(failures.length).toBe(1, 'should only track a single failure per event');
+
+        done();
+    });
+
+    xit('should not track a failure for an event that was tracked in a previous session', (done) => {
+        // This test uses localStorage, clear it beforehand
+        localStorage.clear();
+
+        const decryptedEvent = createFailedDecryptionEvent();
+
+        const failures = [];
+        const tracker = new DecryptionFailureTracker((failure) => failures.push(failure));
+
+        // Indicate decryption
+        tracker.eventDecrypted(decryptedEvent);
+
+        // Pretend "now" is Infinity
+        // NB: This saves to localStorage specific to DFT
+        tracker.checkFailures(Infinity);
+
+        tracker.trackFailure();
+
+        // Simulate the browser refreshing by destroying tracker and creating a new tracker
+        const secondTracker = new DecryptionFailureTracker((failure) => failures.push(failure));
+
+        //secondTracker.loadTrackedEventHashMap();
+
+        secondTracker.eventDecrypted(decryptedEvent);
+        secondTracker.checkFailures(Infinity);
+        secondTracker.trackFailure();
+
+        expect(failures.length).toBe(1, 'should track a single failure per event per session, got ' + failures.length);
+
+        done();
+    });
+});