From 3e103941d67b8f7e11637ed11caf839217857afb Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Fri, 17 May 2024 17:19:31 +0100 Subject: [PATCH] Cleanup work on `DecryptionFailureTracker` (#12546) * Inline `DecryptionFailureTracker.addDecryptionFailure` * Remove redundant TRACK_INTERVAL There really doesn't seem to be much point to this batching up of decryption failure reports. We still call the analytics callback the same number of times. * Rename `trackedEvents` to `reportedEvents` * Fix incorrect documentation on `visibleEvents` This *does* overlap with `failures`. * Combine `addFailure` and `reportFailure` * Calculate client properties before starting reporting --- src/DecryptionFailureTracker.ts | 111 +++++++++-------------- src/components/structures/MatrixChat.tsx | 2 +- test/DecryptionFailureTracker-test.ts | 51 +---------- 3 files changed, 51 insertions(+), 113 deletions(-) diff --git a/src/DecryptionFailureTracker.ts b/src/DecryptionFailureTracker.ts index 91e5a3f6205..e8628f5d66f 100644 --- a/src/DecryptionFailureTracker.ts +++ b/src/DecryptionFailureTracker.ts @@ -93,33 +93,24 @@ export class DecryptionFailureTracker { * Every `CHECK_INTERVAL_MS`, this map is checked for failures that happened > * `MAXIMUM_LATE_DECRYPTION_PERIOD` ago (considered undecryptable), or * decryptions that took > `GRACE_PERIOD_MS` (considered late decryptions). - * These are accumulated in `failuresToReport`. + * + * Any such events are then reported via the `TrackingFn`. */ public failures: Map = new Map(); /** Set of event IDs that have been visible to the user. * - * This will only contain events that are not already in `failures` or in - * `trackedEvents`. + * This will only contain events that are not already in `reportedEvents`. */ public visibleEvents: Set = new Set(); - /** The failures that will be reported at the next tracking interval. These are - * events that we have decided are undecryptable due to exceeding the - * `MAXIMUM_LATE_DECRYPTION_PERIOD`, or that we decrypted but we consider as late - * decryptions. */ - public failuresToReport: Set = new Set(); - - /** Event IDs of failures that were tracked previously */ - public trackedEvents: Set = new Set(); + /** Event IDs of failures that were reported previously */ + private reportedEvents: Set = new Set(); /** Set to an interval ID when `start` is called */ public checkInterval: number | null = null; public trackInterval: number | null = null; - /** Spread the load on `Analytics` by tracking at a low frequency, `TRACK_INTERVAL_MS`. */ - public static TRACK_INTERVAL_MS = 60000; - /** Call `checkFailures` every `CHECK_INTERVAL_MS`. */ public static CHECK_INTERVAL_MS = 40000; @@ -181,12 +172,12 @@ export class DecryptionFailureTracker { return DecryptionFailureTracker.internalInstance; } - // loadTrackedEvents() { - // this.trackedEvents = new Set(JSON.parse(localStorage.getItem('mx-decryption-failure-event-ids')) || []); + // loadReportedEvents() { + // this.reportedEvents = new Set(JSON.parse(localStorage.getItem('mx-decryption-failure-event-ids')) || []); // } - // saveTrackedEvents() { - // localStorage.setItem('mx-decryption-failure-event-ids', JSON.stringify([...this.trackedEvents])); + // saveReportedEvents() { + // localStorage.setItem('mx-decryption-failure-event-ids', JSON.stringify([...this.reportedEvents])); // } /** Callback for when an event is decrypted. @@ -195,7 +186,7 @@ export class DecryptionFailureTracker { * handler after a decryption attempt on an event, whether the decryption * is successful or not. * - * @param matrixEvent the event that was decrypted + * @param e the event that was decrypted * * @param nowTs the current timestamp */ @@ -213,6 +204,11 @@ export class DecryptionFailureTracker { const eventId = e.getId()!; + // if it's already reported, we don't need to do anything + if (this.reportedEvents.has(eventId)) { + return; + } + // if we already have a record of this event, use the previously-recorded timestamp const failure = this.failures.get(eventId); const ts = failure ? failure.ts : nowTs; @@ -223,8 +219,10 @@ export class DecryptionFailureTracker { if (this.userDomain !== undefined && senderDomain !== undefined) { isFederated = this.userDomain !== senderDomain; } + const wasVisibleToUser = this.visibleEvents.has(eventId); - this.addDecryptionFailure( + this.failures.set( + eventId, new DecryptionFailure(eventId, errCode, ts, isFederated, wasVisibleToUser, this.userTrustsOwnIdentity), ); } @@ -233,7 +231,7 @@ export class DecryptionFailureTracker { const eventId = e.getId()!; // if it's already reported, we don't need to do anything - if (this.trackedEvents.has(eventId)) { + if (this.reportedEvents.has(eventId)) { return; } @@ -247,16 +245,6 @@ export class DecryptionFailureTracker { this.visibleEvents.add(eventId); } - public addDecryptionFailure(failure: DecryptionFailure): void { - const eventId = failure.failedEventId; - - if (this.trackedEvents.has(eventId)) { - return; - } - - this.failures.set(eventId, failure); - } - public removeDecryptionFailuresForEvent(e: MatrixEvent, nowTs: number): void { const eventId = e.getId()!; const failure = this.failures.get(eventId); @@ -274,7 +262,7 @@ export class DecryptionFailureTracker { // undecryptable, and leave timeToDecryptMillis undefined failure.timeToDecryptMillis = timeToDecryptMillis; } - this.failuresToReport.add(failure); + this.reportFailure(failure); } } @@ -301,15 +289,13 @@ export class DecryptionFailureTracker { /** * Start checking for and tracking failures. */ - public start(client: MatrixClient): void { - this.calculateClientProperties(client); + public async start(client: MatrixClient): Promise { + await this.calculateClientProperties(client); this.registerHandlers(client); this.checkInterval = window.setInterval( () => this.checkFailures(Date.now()), DecryptionFailureTracker.CHECK_INTERVAL_MS, ); - - this.trackInterval = window.setInterval(() => this.trackFailures(), DecryptionFailureTracker.TRACK_INTERVAL_MS); } private async calculateClientProperties(client: MatrixClient): Promise { @@ -370,7 +356,6 @@ export class DecryptionFailureTracker { this.userTrustsOwnIdentity = undefined; this.failures = new Map(); this.visibleEvents = new Set(); - this.failuresToReport = new Set(); } /** @@ -392,7 +377,7 @@ export class DecryptionFailureTracker { // - we haven't decrypted yet and it's past the time for it to be // considered a "late" decryption, so we count it as // undecryptable. - this.addFailure(eventId, failure); + this.reportFailure(failure); } else { // the event isn't old enough, so we still need to keep track of it failuresNotReady.set(eventId, failure); @@ -402,40 +387,34 @@ export class DecryptionFailureTracker { // Commented out for now for expediency, we need to consider unbound nature of storing // this in localStorage - // this.saveTrackedEvents(); - } - - private addFailure(eventId: string, failure: DecryptionFailure): void { - this.failuresToReport.add(failure); - this.trackedEvents.add(eventId); - // once we've added it to trackedEvents, we won't check - // visibleEvents for it any more - this.visibleEvents.delete(eventId); + // this.saveReportedEvents(); } /** * If there are failures that should be tracked, call the given trackDecryptionFailure * function with the failures that should be tracked. */ - public trackFailures(): void { - for (const failure of this.failuresToReport) { - const errorCode = failure.errorCode; - const trackedErrorCode = this.errorCodeMapFn(errorCode); - const properties: ErrorProperties = { - timeToDecryptMillis: failure.timeToDecryptMillis ?? -1, - wasVisibleToUser: failure.wasVisibleToUser, - }; - if (failure.isFederated !== undefined) { - properties.isFederated = failure.isFederated; - } - if (failure.userTrustsOwnIdentity !== undefined) { - properties.userTrustsOwnIdentity = failure.userTrustsOwnIdentity; - } - if (this.baseProperties) { - Object.assign(properties, this.baseProperties); - } - this.fn(trackedErrorCode, errorCode, properties); + private reportFailure(failure: DecryptionFailure): void { + const errorCode = failure.errorCode; + const trackedErrorCode = this.errorCodeMapFn(errorCode); + const properties: ErrorProperties = { + timeToDecryptMillis: failure.timeToDecryptMillis ?? -1, + wasVisibleToUser: failure.wasVisibleToUser, + }; + if (failure.isFederated !== undefined) { + properties.isFederated = failure.isFederated; + } + if (failure.userTrustsOwnIdentity !== undefined) { + properties.userTrustsOwnIdentity = failure.userTrustsOwnIdentity; } - this.failuresToReport = new Set(); + if (this.baseProperties) { + Object.assign(properties, this.baseProperties); + } + this.fn(trackedErrorCode, errorCode, properties); + + this.reportedEvents.add(failure.failedEventId); + // once we've added it to reportedEvents, we won't check + // visibleEvents for it any more + this.visibleEvents.delete(failure.failedEventId); } } diff --git a/src/components/structures/MatrixChat.tsx b/src/components/structures/MatrixChat.tsx index b755f42692c..29a3a2a7792 100644 --- a/src/components/structures/MatrixChat.tsx +++ b/src/components/structures/MatrixChat.tsx @@ -1591,7 +1591,7 @@ export default class MatrixChat extends React.PureComponent { // tracked events across sessions. // dft.loadTrackedEventHashMap(); - dft.start(cli); + dft.start(cli).catch((e) => logger.error("Unable to start DecryptionFailureTracker", e)); cli.on(ClientEvent.Room, (room) => { if (cli.isCryptoEnabled()) { diff --git a/test/DecryptionFailureTracker-test.ts b/test/DecryptionFailureTracker-test.ts index 74dfd5b7245..ef5e01719f9 100644 --- a/test/DecryptionFailureTracker-test.ts +++ b/test/DecryptionFailureTracker-test.ts @@ -55,9 +55,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - // Immediately track the newest failures - tracker.trackFailures(); - // should track a failure for an event that failed decryption expect(count).not.toBe(0); }); @@ -84,9 +81,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - // Immediately track the newest failures - tracker.trackFailures(); - // should track a failure for an event that failed decryption expect(count).not.toBe(0); @@ -110,9 +104,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - // Immediately track the newest failures - tracker.trackFailures(); - // should track a failure for an event that failed decryption expect(count).not.toBe(0); }); @@ -151,8 +142,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - tracker.trackFailures(); - expect(propertiesByErrorCode[error1].wasVisibleToUser).toBe(true); expect(propertiesByErrorCode[error2].wasVisibleToUser).toBe(true); expect(propertiesByErrorCode[error3].wasVisibleToUser).toBe(false); @@ -181,9 +170,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - - // Immediately track the newest failures - tracker.trackFailures(); }); it( @@ -213,9 +199,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - - // Immediately track the newest failures - tracker.trackFailures(); }, ); @@ -247,11 +230,9 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - // Simulated polling of `trackFailures`, an arbitrary number ( > 2 ) times - tracker.trackFailures(); - tracker.trackFailures(); - tracker.trackFailures(); - tracker.trackFailures(); + // Simulated polling of `checkFailures`, an arbitrary number ( > 2 ) times + tracker.checkFailures(Infinity); + tracker.checkFailures(Infinity); // should only track a single failure per event expect(count).toBe(2); @@ -275,12 +256,9 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - tracker.trackFailures(); - // Indicate a second decryption, after having tracked the failure eventDecrypted(tracker, decryptedEvent, Date.now()); - - tracker.trackFailures(); + tracker.checkFailures(Infinity); // should only track a single failure per event expect(count).toBe(1); @@ -308,8 +286,6 @@ describe("DecryptionFailureTracker", function () { // NB: This saves to localStorage specific to DFT tracker.checkFailures(Infinity); - tracker.trackFailures(); - // Simulate the browser refreshing by destroying tracker and creating a new tracker // @ts-ignore access to private constructor const secondTracker = new DecryptionFailureTracker( @@ -323,7 +299,6 @@ describe("DecryptionFailureTracker", function () { eventDecrypted(secondTracker, decryptedEvent, Date.now()); secondTracker.checkFailures(Infinity); - secondTracker.trackFailures(); // should only track a single failure per event expect(count).toBe(1); @@ -363,8 +338,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - tracker.trackFailures(); - //expect(counts['UnknownError']).toBe(1, 'should track one UnknownError'); expect(counts["OlmKeysNotSentError"]).toBe(2); }); @@ -400,8 +373,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - tracker.trackFailures(); - expect(counts["OlmUnspecifiedError"]).toBe(3); }); @@ -423,8 +394,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - tracker.trackFailures(); - // should track remapped error code expect(counts["XEDNI_EGASSEM_NWONKNU_MLO"]).toBe(1); }); @@ -488,8 +457,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - tracker.trackFailures(); - expect(errorCodes).toEqual([ "OlmKeysNotSentError", "OlmIndexError", @@ -546,8 +513,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - tracker.trackFailures(); - expect(propertiesByErrorCode[error1].timeToDecryptMillis).toEqual(40000); expect(propertiesByErrorCode[error2].timeToDecryptMillis).toEqual(-1); expect(propertiesByErrorCode[error3].timeToDecryptMillis).toEqual(-1); @@ -576,14 +541,13 @@ describe("DecryptionFailureTracker", function () { // long enough for the timers to fire, but we'll use fake timers just // to be safe. jest.useFakeTimers(); - tracker.start(client); + await tracker.start(client); // If the client fails to decrypt, it should get tracked const failedDecryption = await createFailedDecryptionEvent(); client.emit(MatrixEventEvent.Decrypted, failedDecryption); tracker.checkFailures(Infinity); - tracker.trackFailures(); expect(errorCount).toEqual(1); @@ -597,7 +561,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - tracker.trackFailures(); expect(errorCount).toEqual(1); @@ -655,8 +618,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - tracker.trackFailures(); - expect(propertiesByErrorCode[error1].isMatrixDotOrg).toBe(true); expect(propertiesByErrorCode[error1].cryptoSDK).toEqual("Rust"); @@ -677,7 +638,6 @@ describe("DecryptionFailureTracker", function () { tracker.addVisibleEvent(anotherFailure); eventDecrypted(tracker, anotherFailure, now); tracker.checkFailures(Infinity); - tracker.trackFailures(); expect(propertiesByErrorCode[error3].isMatrixDotOrg).toBe(false); expect(propertiesByErrorCode[error3].cryptoSDK).toEqual("Legacy"); }); @@ -707,7 +667,6 @@ describe("DecryptionFailureTracker", function () { // Pretend "now" is Infinity tracker.checkFailures(Infinity); - tracker.trackFailures(); // the time to decrypt should be relative to the first time we failed // to decrypt, not the second