From eed8d1538b8c564b0842eee9cd3696388ee4b46c Mon Sep 17 00:00:00 2001 From: Hubert Chathi Date: Wed, 15 May 2024 20:25:58 -0400 Subject: [PATCH] Add more encryption properties to PostHog (#12415) * report time to decrypt an event if it's slow * add more stats * fix some tests * keep original timestamp, and report non-visible decryption failures * add statistic for whether the user trusts their own device * revert local playwright docker changes * apply changes from review * also remove logout event handler on logout * apply changes from review * make eventDecrypted callback private --- src/DecryptionFailureTracker.ts | 356 ++++++++++---- src/components/structures/MatrixChat.tsx | 7 +- test/DecryptionFailureTracker-test.ts | 441 ++++++++++++++---- .../components/structures/MatrixChat-test.tsx | 1 + test/test-utils/client.ts | 1 + 5 files changed, 626 insertions(+), 180 deletions(-) diff --git a/src/DecryptionFailureTracker.ts b/src/DecryptionFailureTracker.ts index c842e55ec4..91e5a3f620 100644 --- a/src/DecryptionFailureTracker.ts +++ b/src/DecryptionFailureTracker.ts @@ -14,38 +14,60 @@ See the License for the specific language governing permissions and limitations under the License. */ -import { MatrixEvent } from "matrix-js-sdk/src/matrix"; +import { CryptoEvent, HttpApiEvent, MatrixClient, MatrixEventEvent, MatrixEvent } from "matrix-js-sdk/src/matrix"; import { Error as ErrorEvent } from "@matrix-org/analytics-events/types/typescript/Error"; import { DecryptionFailureCode } from "matrix-js-sdk/src/crypto-api"; import { PosthogAnalytics } from "./PosthogAnalytics"; export class DecryptionFailure { - public readonly ts: number; + /** + * The time between our initial failure to decrypt and our successful + * decryption (if we managed to decrypt). + */ + public timeToDecryptMillis?: number; public constructor( public readonly failedEventId: string, public readonly errorCode: DecryptionFailureCode, - ) { - this.ts = Date.now(); - } + /** + * The time that we failed to decrypt the event. If we failed to decrypt + * multiple times, this will be the time of the first failure. + */ + public readonly ts: number, + /** + * Is the sender on a different server from us? + */ + public readonly isFederated: boolean | undefined, + /** + * Was the failed event ever visible to the user? + */ + public wasVisibleToUser: boolean, + /** + * Has the user verified their own cross-signing identity, as of the most + * recent decryption attempt for this event? + */ + public userTrustsOwnIdentity: boolean | undefined, + ) {} } type ErrorCode = ErrorEvent["name"]; -type TrackingFn = (count: number, trackedErrCode: ErrorCode, rawError: string) => void; +/** Properties associated with decryption errors, for classifying the error. */ +export type ErrorProperties = Omit; +type TrackingFn = (trackedErrCode: ErrorCode, rawError: string, properties: ErrorProperties) => void; export type ErrCodeMapFn = (errcode: DecryptionFailureCode) => ErrorCode; export class DecryptionFailureTracker { private static internalInstance = new DecryptionFailureTracker( - (total, errorCode, rawError) => { - for (let i = 0; i < total; i++) { - PosthogAnalytics.instance.trackEvent({ - eventName: "Error", - domain: "E2EE", - name: errorCode, - context: `mxc_crypto_error_type_${rawError}`, - }); - } + (errorCode, rawError, properties) => { + const event: ErrorEvent = { + eventName: "Error", + domain: "E2EE", + name: errorCode, + context: `mxc_crypto_error_type_${rawError}`, + ...properties, + }; + PosthogAnalytics.instance.trackEvent(event); }, (errorCode) => { // Map JS-SDK error codes to tracker codes for aggregation @@ -66,51 +88,78 @@ export class DecryptionFailureTracker { }, ); - // Map of event IDs to DecryptionFailure items. + /** Map of event IDs to `DecryptionFailure` items. + * + * 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`. + */ public failures: Map = new Map(); - // Set of event IDs that have been visible to the user. + /** 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`. + */ public visibleEvents: Set = new Set(); - // Map of visible event IDs to `DecryptionFailure`s. Every - // `CHECK_INTERVAL_MS`, this map is checked for failures that - // happened > `GRACE_PERIOD_MS` ago. Those that did are - // accumulated in `failureCounts`. - public visibleFailures: Map = new Map(); + /** 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(); - /** - * A histogram of the number of failures that will be tracked at the next tracking - * interval, split by failure error code. - */ - private failureCounts: Map = new Map(); - - // Event IDs of failures that were tracked previously + /** Event IDs of failures that were tracked previously */ public trackedEvents: Set = new Set(); - // Set to an interval ID when `start` is called + /** 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`. + /** 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`. + /** Call `checkFailures` every `CHECK_INTERVAL_MS`. */ public static CHECK_INTERVAL_MS = 40000; - // Give events a chance to be decrypted by waiting `GRACE_PERIOD_MS` before counting - // the failure in `failureCounts`. - public static GRACE_PERIOD_MS = 30000; + /** If the event is successfully decrypted in less than 4s, we don't report. */ + public static GRACE_PERIOD_MS = 4000; + + /** Maximum time for an event to be decrypted to be considered a late + * decryption. If it takes longer, we consider it undecryptable. */ + public static MAXIMUM_LATE_DECRYPTION_PERIOD = 60000; + + /** Properties that will be added to all reported events (mainly reporting + * information about the Matrix client). */ + private baseProperties?: ErrorProperties = {}; + + /** The user's domain (homeserver name). */ + private userDomain?: string; + + /** Whether the user has verified their own cross-signing keys. */ + private userTrustsOwnIdentity: boolean | undefined = undefined; + + /** Whether we are currently checking our own verification status. */ + private checkingVerificationStatus: boolean = false; + + /** Whether we should retry checking our own verification status after we're + * done our current check. i.e. we got notified that our keys changed while + * we were already checking, so the result could be out of date. */ + private retryVerificationStatus: boolean = false; /** * 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. + * Call `start(client)` to start the tracker. The tracker will listen for + * decryption events on the client and track decryption failures, and will + * automatically stop tracking when the client logs out. * * @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 output of `errorCodeMapFn`. + * are tracked. The function should have a signature `(trackedErrorCode, rawError, properties) => {...}`, + * where `errorCode` matches the output of `errorCodeMapFn`, `rawError` is the original + * error (that is, the input to `errorCodeMapFn`), and `properties` is a map of the + * error properties for classifying the error. * * @param {function} errorCodeMapFn The function used to map decryption failure reason codes to the * `trackedErrorCode`. @@ -140,32 +189,62 @@ export class DecryptionFailureTracker { // localStorage.setItem('mx-decryption-failure-event-ids', JSON.stringify([...this.trackedEvents])); // } - public eventDecrypted(e: MatrixEvent): void { + /** Callback for when an event is decrypted. + * + * This function is called by our `MatrixEventEvent.Decrypted` event + * handler after a decryption attempt on an event, whether the decryption + * is successful or not. + * + * @param matrixEvent the event that was decrypted + * + * @param nowTs the current timestamp + */ + private eventDecrypted(e: MatrixEvent, nowTs: number): void { // for now we only track megolm decryption failures if (e.getWireContent().algorithm != "m.megolm.v1.aes-sha2") { return; } - const errCode = e.decryptionFailureReason; - if (errCode !== null) { - this.addDecryptionFailure(new DecryptionFailure(e.getId()!, errCode)); - } else { + if (errCode === null) { // Could be an event in the failures, remove it - this.removeDecryptionFailuresForEvent(e); + this.removeDecryptionFailuresForEvent(e, nowTs); + return; } + + const eventId = e.getId()!; + + // 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; + + const sender = e.getSender(); + const senderDomain = sender?.replace(/^.*?:/, ""); + let isFederated: boolean | undefined; + if (this.userDomain !== undefined && senderDomain !== undefined) { + isFederated = this.userDomain !== senderDomain; + } + const wasVisibleToUser = this.visibleEvents.has(eventId); + this.addDecryptionFailure( + new DecryptionFailure(eventId, errCode, ts, isFederated, wasVisibleToUser, this.userTrustsOwnIdentity), + ); } public addVisibleEvent(e: MatrixEvent): void { const eventId = e.getId()!; + // if it's already reported, we don't need to do anything if (this.trackedEvents.has(eventId)) { return; } - this.visibleEvents.add(eventId); - if (this.failures.has(eventId) && !this.visibleFailures.has(eventId)) { - this.visibleFailures.set(eventId, this.failures.get(eventId)!); + // if we've already marked the event as a failure, mark it as visible + // in the failure object + const failure = this.failures.get(eventId); + if (failure) { + failure.wasVisibleToUser = true; } + + this.visibleEvents.add(eventId); } public addDecryptionFailure(failure: DecryptionFailure): void { @@ -176,21 +255,55 @@ export class DecryptionFailureTracker { } this.failures.set(eventId, failure); - if (this.visibleEvents.has(eventId) && !this.visibleFailures.has(eventId)) { - this.visibleFailures.set(eventId, failure); + } + + public removeDecryptionFailuresForEvent(e: MatrixEvent, nowTs: number): void { + const eventId = e.getId()!; + const failure = this.failures.get(eventId); + if (failure) { + this.failures.delete(eventId); + + const timeToDecryptMillis = nowTs - failure.ts; + if (timeToDecryptMillis < DecryptionFailureTracker.GRACE_PERIOD_MS) { + // the event decrypted on time, so we don't need to report it + return; + } else if (timeToDecryptMillis <= DecryptionFailureTracker.MAXIMUM_LATE_DECRYPTION_PERIOD) { + // The event is a late decryption, so store the time it took. + // If the time to decrypt is longer than + // MAXIMUM_LATE_DECRYPTION_PERIOD, we consider the event as + // undecryptable, and leave timeToDecryptMillis undefined + failure.timeToDecryptMillis = timeToDecryptMillis; + } + this.failuresToReport.add(failure); } } - public removeDecryptionFailuresForEvent(e: MatrixEvent): void { - const eventId = e.getId()!; - this.failures.delete(eventId); - this.visibleFailures.delete(eventId); + private async handleKeysChanged(client: MatrixClient): Promise { + if (this.checkingVerificationStatus) { + // Flag that we'll need to do another check once the current check completes. + this.retryVerificationStatus = true; + return; + } + + this.checkingVerificationStatus = true; + try { + do { + this.retryVerificationStatus = false; + this.userTrustsOwnIdentity = ( + await client.getCrypto()!.getUserVerificationStatus(client.getUserId()!) + ).isCrossSigningVerified(); + } while (this.retryVerificationStatus); + } finally { + this.checkingVerificationStatus = false; + } } /** * Start checking for and tracking failures. */ - public start(): void { + public start(client: MatrixClient): void { + this.calculateClientProperties(client); + this.registerHandlers(client); this.checkInterval = window.setInterval( () => this.checkFailures(Date.now()), DecryptionFailureTracker.CHECK_INTERVAL_MS, @@ -199,63 +312,130 @@ export class DecryptionFailureTracker { this.trackInterval = window.setInterval(() => this.trackFailures(), DecryptionFailureTracker.TRACK_INTERVAL_MS); } - /** - * Clear state and stop checking for and tracking failures. - */ - public stop(): void { - if (this.checkInterval) clearInterval(this.checkInterval); - if (this.trackInterval) clearInterval(this.trackInterval); + private async calculateClientProperties(client: MatrixClient): Promise { + const baseProperties: ErrorProperties = {}; + this.baseProperties = baseProperties; - this.failures = new Map(); - this.visibleEvents = new Set(); - this.visibleFailures = new Map(); - this.failureCounts = new Map(); + this.userDomain = client.getDomain() ?? undefined; + if (this.userDomain === "matrix.org") { + baseProperties.isMatrixDotOrg = true; + } else if (this.userDomain !== undefined) { + baseProperties.isMatrixDotOrg = false; + } + + const crypto = client.getCrypto(); + if (crypto) { + const version = crypto.getVersion(); + if (version.startsWith("Rust SDK")) { + baseProperties.cryptoSDK = "Rust"; + } else { + baseProperties.cryptoSDK = "Legacy"; + } + this.userTrustsOwnIdentity = ( + await crypto.getUserVerificationStatus(client.getUserId()!) + ).isCrossSigningVerified(); + } + } + + private registerHandlers(client: MatrixClient): void { + // After the client attempts to decrypt an event, we examine it to see + // if it needs to be reported. + const decryptedHandler = (e: MatrixEvent): void => this.eventDecrypted(e, Date.now()); + // When our keys change, we check if the cross-signing keys are now trusted. + const keysChangedHandler = (): void => { + this.handleKeysChanged(client).catch((e) => { + console.log("Error handling KeysChanged event", e); + }); + }; + // When logging out, remove our handlers and destroy state + const loggedOutHandler = (): void => { + client.removeListener(MatrixEventEvent.Decrypted, decryptedHandler); + client.removeListener(CryptoEvent.KeysChanged, keysChangedHandler); + client.removeListener(HttpApiEvent.SessionLoggedOut, loggedOutHandler); + this.stop(); + }; + + client.on(MatrixEventEvent.Decrypted, decryptedHandler); + client.on(CryptoEvent.KeysChanged, keysChangedHandler); + client.on(HttpApiEvent.SessionLoggedOut, loggedOutHandler); } /** - * Mark failures that occurred before nowTs - GRACE_PERIOD_MS as failures that should be - * tracked. Only mark one failure per event ID. + * Clear state and stop checking for and tracking failures. + */ + private stop(): void { + if (this.checkInterval) clearInterval(this.checkInterval); + if (this.trackInterval) clearInterval(this.trackInterval); + + this.userTrustsOwnIdentity = undefined; + this.failures = new Map(); + this.visibleEvents = new Set(); + this.failuresToReport = new Set(); + } + + /** + * Mark failures as undecryptable or late. Only mark one failure per event ID. + * * @param {number} nowTs the timestamp that represents the time now. */ public checkFailures(nowTs: number): void { - const failuresGivenGrace: Set = new Set(); const failuresNotReady: Map = new Map(); - for (const [eventId, failure] of this.visibleFailures) { - if (nowTs > failure.ts + DecryptionFailureTracker.GRACE_PERIOD_MS) { - failuresGivenGrace.add(failure); - this.trackedEvents.add(eventId); + for (const [eventId, failure] of this.failures) { + if ( + failure.timeToDecryptMillis !== undefined || + nowTs > failure.ts + DecryptionFailureTracker.MAXIMUM_LATE_DECRYPTION_PERIOD + ) { + // we report failures under two conditions: + // - if `timeToDecryptMillis` is set, we successfully decrypted + // the event, but we got the key late. We report it so that we + // have the late decrytion stats. + // - 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); } else { + // the event isn't old enough, so we still need to keep track of it failuresNotReady.set(eventId, failure); } } - this.visibleFailures = failuresNotReady; + this.failures = failuresNotReady; // Commented out for now for expediency, we need to consider unbound nature of storing // this in localStorage // this.saveTrackedEvents(); - - this.aggregateFailures(failuresGivenGrace); } - private aggregateFailures(failures: Set): void { - for (const failure of failures) { - const errorCode = failure.errorCode; - this.failureCounts.set(errorCode, (this.failureCounts.get(errorCode) ?? 0) + 1); - } + 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); } /** * 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 failures that should be tracked. */ public trackFailures(): void { - for (const [errorCode, count] of this.failureCounts.entries()) { - if (count > 0) { - const trackedErrorCode = this.errorCodeMapFn(errorCode); - - this.fn(count, trackedErrorCode, errorCode); - this.failureCounts.set(errorCode, 0); + 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); } + this.failuresToReport = new Set(); } } diff --git a/src/components/structures/MatrixChat.tsx b/src/components/structures/MatrixChat.tsx index 2574156279..b755f42692 100644 --- a/src/components/structures/MatrixChat.tsx +++ b/src/components/structures/MatrixChat.tsx @@ -21,7 +21,6 @@ import { EventType, HttpApiEvent, MatrixClient, - MatrixEventEvent, MatrixEvent, RoomType, SyncStateData, @@ -1592,11 +1591,7 @@ export default class MatrixChat extends React.PureComponent { // tracked events across sessions. // dft.loadTrackedEventHashMap(); - dft.start(); - - // When logging out, stop tracking failures and destroy state - cli.on(HttpApiEvent.SessionLoggedOut, () => dft.stop()); - cli.on(MatrixEventEvent.Decrypted, (e) => dft.eventDecrypted(e)); + dft.start(cli); cli.on(ClientEvent.Room, (room) => { if (cli.isCryptoEnabled()) { diff --git a/test/DecryptionFailureTracker-test.ts b/test/DecryptionFailureTracker-test.ts index 305692fce8..74dfd5b724 100644 --- a/test/DecryptionFailureTracker-test.ts +++ b/test/DecryptionFailureTracker-test.ts @@ -14,20 +14,30 @@ See the License for the specific language governing permissions and limitations under the License. */ +import { mocked, Mocked } from "jest-mock"; +import { CryptoEvent, HttpApiEvent, MatrixEvent, MatrixEventEvent } from "matrix-js-sdk/src/matrix"; import { decryptExistingEvent, mkDecryptionFailureMatrixEvent } from "matrix-js-sdk/src/testing"; -import { DecryptionFailureCode } from "matrix-js-sdk/src/crypto-api"; +import { CryptoApi, DecryptionFailureCode, UserVerificationStatus } from "matrix-js-sdk/src/crypto-api"; +import { sleep } from "matrix-js-sdk/src/utils"; -import { DecryptionFailureTracker } from "../src/DecryptionFailureTracker"; +import { DecryptionFailureTracker, ErrorProperties } from "../src/DecryptionFailureTracker"; +import { stubClient } from "./test-utils"; -async function createFailedDecryptionEvent(code?: DecryptionFailureCode) { +async function createFailedDecryptionEvent(opts: { sender?: string; code?: DecryptionFailureCode } = {}) { return await mkDecryptionFailureMatrixEvent({ roomId: "!room:id", - sender: "@alice:example.com", - code: code ?? DecryptionFailureCode.UNKNOWN_ERROR, + sender: opts.sender ?? "@alice:example.com", + code: opts.code ?? DecryptionFailureCode.UNKNOWN_ERROR, msg: ":(", }); } +// wrap tracker.eventDecrypted so that we don't need to have so many `ts-ignore`s +function eventDecrypted(tracker: DecryptionFailureTracker, e: MatrixEvent, nowTs: number): void { + // @ts-ignore access to private member + return tracker.eventDecrypted(e, nowTs); +} + describe("DecryptionFailureTracker", function () { it("tracks a failed decryption for a visible event", async function () { const failedDecryptionEvent = await createFailedDecryptionEvent(); @@ -35,12 +45,12 @@ describe("DecryptionFailureTracker", function () { let count = 0; // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (total: number) => (count += total), + () => count++, () => "UnknownError", ); tracker.addVisibleEvent(failedDecryptionEvent); - tracker.eventDecrypted(failedDecryptionEvent); + eventDecrypted(tracker, failedDecryptionEvent, Date.now()); // Pretend "now" is Infinity tracker.checkFailures(Infinity); @@ -53,23 +63,23 @@ describe("DecryptionFailureTracker", function () { }); it("tracks a failed decryption with expected raw error for a visible event", async function () { - const failedDecryptionEvent = await createFailedDecryptionEvent( - DecryptionFailureCode.OLM_UNKNOWN_MESSAGE_INDEX, - ); + const failedDecryptionEvent = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.OLM_UNKNOWN_MESSAGE_INDEX, + }); let count = 0; let reportedRawCode = ""; // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (total: number, _errCode: string, rawCode: string) => { - count += total; + (_errCode: string, rawCode: string) => { + count++; reportedRawCode = rawCode; }, () => "UnknownError", ); tracker.addVisibleEvent(failedDecryptionEvent); - tracker.eventDecrypted(failedDecryptionEvent); + eventDecrypted(tracker, failedDecryptionEvent, Date.now()); // Pretend "now" is Infinity tracker.checkFailures(Infinity); @@ -90,11 +100,11 @@ describe("DecryptionFailureTracker", function () { let count = 0; // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (total: number) => (count += total), + () => count++, () => "UnknownError", ); - tracker.eventDecrypted(failedDecryptionEvent); + eventDecrypted(tracker, failedDecryptionEvent, Date.now()); tracker.addVisibleEvent(failedDecryptionEvent); // Pretend "now" is Infinity @@ -107,33 +117,52 @@ describe("DecryptionFailureTracker", function () { expect(count).not.toBe(0); }); - it("does not track a failed decryption for an event that never becomes visible", async function () { - const failedDecryptionEvent = await createFailedDecryptionEvent(); - - let count = 0; + it("tracks visible vs. not visible events", async () => { + const propertiesByErrorCode: Record = {}; // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (total: number) => (count += total), - () => "UnknownError", + (errorCode: string, rawError: string, properties: ErrorProperties) => { + propertiesByErrorCode[errorCode] = properties; + }, + (error: string) => error, ); - tracker.eventDecrypted(failedDecryptionEvent); + // use three different errors so that we can distinguish the reports + const error1 = DecryptionFailureCode.MEGOLM_UNKNOWN_INBOUND_SESSION_ID; + const error2 = DecryptionFailureCode.MEGOLM_BAD_ROOM; + const error3 = DecryptionFailureCode.MEGOLM_MISSING_FIELDS; + + // event that will be marked as visible before it's marked as undecryptable + const markedVisibleFirst = await createFailedDecryptionEvent({ code: error1 }); + // event that will be marked as undecryptable before it's marked as visible + const markedUndecryptableFirst = await createFailedDecryptionEvent({ code: error2 }); + // event that is never marked as visible + const neverVisible = await createFailedDecryptionEvent({ code: error3 }); + + tracker.addVisibleEvent(markedVisibleFirst); + + const now = Date.now(); + eventDecrypted(tracker, markedVisibleFirst, now); + eventDecrypted(tracker, markedUndecryptableFirst, now); + eventDecrypted(tracker, neverVisible, now); + + tracker.addVisibleEvent(markedUndecryptableFirst); // Pretend "now" is Infinity tracker.checkFailures(Infinity); - // Immediately track the newest failures tracker.trackFailures(); - // should not track a failure for an event that never became visible - expect(count).toBe(0); + expect(propertiesByErrorCode[error1].wasVisibleToUser).toBe(true); + expect(propertiesByErrorCode[error2].wasVisibleToUser).toBe(true); + expect(propertiesByErrorCode[error3].wasVisibleToUser).toBe(false); }); it("does not track a failed decryption where the event is subsequently successfully decrypted", async () => { const decryptedEvent = await createFailedDecryptionEvent(); // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (_total: number) => { + () => { // should not track an event that has since been decrypted correctly expect(true).toBe(false); }, @@ -141,14 +170,14 @@ describe("DecryptionFailureTracker", function () { ); tracker.addVisibleEvent(decryptedEvent); - tracker.eventDecrypted(decryptedEvent); + eventDecrypted(tracker, decryptedEvent, Date.now()); // Indicate successful decryption. await decryptExistingEvent(decryptedEvent, { plainType: "m.room.message", plainContent: { body: "success" }, }); - tracker.eventDecrypted(decryptedEvent, null); + eventDecrypted(tracker, decryptedEvent, Date.now()); // Pretend "now" is Infinity tracker.checkFailures(Infinity); @@ -164,21 +193,21 @@ describe("DecryptionFailureTracker", function () { const decryptedEvent = await createFailedDecryptionEvent(); // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (_total: number) => { + () => { // should not track an event that has since been decrypted correctly expect(true).toBe(false); }, () => "UnknownError", ); - tracker.eventDecrypted(decryptedEvent); + eventDecrypted(tracker, decryptedEvent, Date.now()); // Indicate successful decryption. await decryptExistingEvent(decryptedEvent, { plainType: "m.room.message", plainContent: { body: "success" }, }); - tracker.eventDecrypted(decryptedEvent); + eventDecrypted(tracker, decryptedEvent, Date.now()); tracker.addVisibleEvent(decryptedEvent); @@ -197,22 +226,23 @@ describe("DecryptionFailureTracker", function () { let count = 0; // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (total: number) => (count += total), + () => count++, () => "UnknownError", ); tracker.addVisibleEvent(decryptedEvent); // 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); + const now = Date.now(); + eventDecrypted(tracker, decryptedEvent, now); + eventDecrypted(tracker, decryptedEvent, now); + eventDecrypted(tracker, decryptedEvent, now); + eventDecrypted(tracker, decryptedEvent, now); + eventDecrypted(tracker, decryptedEvent, now); + eventDecrypted(tracker, decryptedEvent2, now); + eventDecrypted(tracker, decryptedEvent2, now); tracker.addVisibleEvent(decryptedEvent2); - tracker.eventDecrypted(decryptedEvent2); + eventDecrypted(tracker, decryptedEvent2, now); // Pretend "now" is Infinity tracker.checkFailures(Infinity); @@ -233,14 +263,14 @@ describe("DecryptionFailureTracker", function () { let count = 0; // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (total: number) => (count += total), + () => count++, () => "UnknownError", ); tracker.addVisibleEvent(decryptedEvent); // Indicate decryption - tracker.eventDecrypted(decryptedEvent); + eventDecrypted(tracker, decryptedEvent, Date.now()); // Pretend "now" is Infinity tracker.checkFailures(Infinity); @@ -248,7 +278,7 @@ describe("DecryptionFailureTracker", function () { tracker.trackFailures(); // Indicate a second decryption, after having tracked the failure - tracker.eventDecrypted(decryptedEvent); + eventDecrypted(tracker, decryptedEvent, Date.now()); tracker.trackFailures(); @@ -265,14 +295,14 @@ describe("DecryptionFailureTracker", function () { let count = 0; // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (total: number) => (count += total), + () => count++, () => "UnknownError", ); tracker.addVisibleEvent(decryptedEvent); // Indicate decryption - tracker.eventDecrypted(decryptedEvent); + eventDecrypted(tracker, decryptedEvent, Date.now()); // Pretend "now" is Infinity // NB: This saves to localStorage specific to DFT @@ -291,7 +321,7 @@ describe("DecryptionFailureTracker", function () { //secondTracker.loadTrackedEvents(); - secondTracker.eventDecrypted(decryptedEvent); + eventDecrypted(secondTracker, decryptedEvent, Date.now()); secondTracker.checkFailures(Infinity); secondTracker.trackFailures(); @@ -304,28 +334,31 @@ describe("DecryptionFailureTracker", function () { // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (total: number, errorCode: string) => (counts[errorCode] = (counts[errorCode] || 0) + total), + (errorCode: string) => (counts[errorCode] = (counts[errorCode] || 0) + 1), (error: DecryptionFailureCode) => error === DecryptionFailureCode.UNKNOWN_ERROR ? "UnknownError" : "OlmKeysNotSentError", ); - const decryptedEvent1 = await createFailedDecryptionEvent(DecryptionFailureCode.UNKNOWN_ERROR); - const decryptedEvent2 = await createFailedDecryptionEvent( - DecryptionFailureCode.MEGOLM_UNKNOWN_INBOUND_SESSION_ID, - ); - const decryptedEvent3 = await createFailedDecryptionEvent( - DecryptionFailureCode.MEGOLM_UNKNOWN_INBOUND_SESSION_ID, - ); + const decryptedEvent1 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.UNKNOWN_ERROR, + }); + const decryptedEvent2 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.MEGOLM_UNKNOWN_INBOUND_SESSION_ID, + }); + const decryptedEvent3 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.MEGOLM_UNKNOWN_INBOUND_SESSION_ID, + }); tracker.addVisibleEvent(decryptedEvent1); tracker.addVisibleEvent(decryptedEvent2); tracker.addVisibleEvent(decryptedEvent3); - // One failure of ERROR_CODE_1, and effectively two for ERROR_CODE_2 - tracker.eventDecrypted(decryptedEvent1); - tracker.eventDecrypted(decryptedEvent2); - tracker.eventDecrypted(decryptedEvent2); - tracker.eventDecrypted(decryptedEvent3); + // One failure of UNKNOWN_ERROR, and effectively two for MEGOLM_UNKNOWN_INBOUND_SESSION_ID + const now = Date.now(); + eventDecrypted(tracker, decryptedEvent1, now); + eventDecrypted(tracker, decryptedEvent2, now); + eventDecrypted(tracker, decryptedEvent2, now); + eventDecrypted(tracker, decryptedEvent3, now); // Pretend "now" is Infinity tracker.checkFailures(Infinity); @@ -341,23 +374,28 @@ describe("DecryptionFailureTracker", function () { // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (total: number, errorCode: string) => (counts[errorCode] = (counts[errorCode] || 0) + total), + (errorCode: string) => (counts[errorCode] = (counts[errorCode] || 0) + 1), (_errorCode: string) => "OlmUnspecifiedError", ); - const decryptedEvent1 = await createFailedDecryptionEvent( - DecryptionFailureCode.MEGOLM_UNKNOWN_INBOUND_SESSION_ID, - ); - const decryptedEvent2 = await createFailedDecryptionEvent(DecryptionFailureCode.OLM_UNKNOWN_MESSAGE_INDEX); - const decryptedEvent3 = await createFailedDecryptionEvent(DecryptionFailureCode.UNKNOWN_ERROR); + const decryptedEvent1 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.MEGOLM_UNKNOWN_INBOUND_SESSION_ID, + }); + const decryptedEvent2 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.OLM_UNKNOWN_MESSAGE_INDEX, + }); + const decryptedEvent3 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.UNKNOWN_ERROR, + }); tracker.addVisibleEvent(decryptedEvent1); tracker.addVisibleEvent(decryptedEvent2); tracker.addVisibleEvent(decryptedEvent3); - tracker.eventDecrypted(decryptedEvent1); - tracker.eventDecrypted(decryptedEvent2); - tracker.eventDecrypted(decryptedEvent3); + const now = Date.now(); + eventDecrypted(tracker, decryptedEvent1, now); + eventDecrypted(tracker, decryptedEvent2, now); + eventDecrypted(tracker, decryptedEvent3, now); // Pretend "now" is Infinity tracker.checkFailures(Infinity); @@ -372,13 +410,15 @@ describe("DecryptionFailureTracker", function () { // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (total: number, errorCode: string) => (counts[errorCode] = (counts[errorCode] || 0) + total), + (errorCode: string) => (counts[errorCode] = (counts[errorCode] || 0) + 1), (errorCode: string) => Array.from(errorCode).reverse().join(""), ); - const decryptedEvent = await createFailedDecryptionEvent(DecryptionFailureCode.OLM_UNKNOWN_MESSAGE_INDEX); + const decryptedEvent = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.OLM_UNKNOWN_MESSAGE_INDEX, + }); tracker.addVisibleEvent(decryptedEvent); - tracker.eventDecrypted(decryptedEvent); + eventDecrypted(tracker, decryptedEvent, Date.now()); // Pretend "now" is Infinity tracker.checkFailures(Infinity); @@ -394,40 +434,56 @@ describe("DecryptionFailureTracker", function () { // @ts-ignore access to private constructor const tracker = new DecryptionFailureTracker( - (total: number, errorCode: string) => { + (errorCode: string) => { errorCodes.push(errorCode); }, // @ts-ignore access to private member DecryptionFailureTracker.instance.errorCodeMapFn, ); - const event1 = await createFailedDecryptionEvent(DecryptionFailureCode.MEGOLM_UNKNOWN_INBOUND_SESSION_ID); + const now = Date.now(); + + const event1 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.MEGOLM_UNKNOWN_INBOUND_SESSION_ID, + }); tracker.addVisibleEvent(event1); - tracker.eventDecrypted(event1); + eventDecrypted(tracker, event1, now); - const event2 = await createFailedDecryptionEvent(DecryptionFailureCode.OLM_UNKNOWN_MESSAGE_INDEX); + const event2 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.OLM_UNKNOWN_MESSAGE_INDEX, + }); tracker.addVisibleEvent(event2); - tracker.eventDecrypted(event2); + eventDecrypted(tracker, event2, now); - const event3 = await createFailedDecryptionEvent(DecryptionFailureCode.HISTORICAL_MESSAGE_NO_KEY_BACKUP); + const event3 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.HISTORICAL_MESSAGE_NO_KEY_BACKUP, + }); tracker.addVisibleEvent(event3); - tracker.eventDecrypted(event3); + eventDecrypted(tracker, event3, now); - const event4 = await createFailedDecryptionEvent(DecryptionFailureCode.HISTORICAL_MESSAGE_BACKUP_UNCONFIGURED); + const event4 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.HISTORICAL_MESSAGE_BACKUP_UNCONFIGURED, + }); tracker.addVisibleEvent(event4); - tracker.eventDecrypted(event4); + eventDecrypted(tracker, event4, now); - const event5 = await createFailedDecryptionEvent(DecryptionFailureCode.HISTORICAL_MESSAGE_WORKING_BACKUP); + const event5 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.HISTORICAL_MESSAGE_WORKING_BACKUP, + }); tracker.addVisibleEvent(event5); - tracker.eventDecrypted(event5); + eventDecrypted(tracker, event5, now); - const event6 = await createFailedDecryptionEvent(DecryptionFailureCode.HISTORICAL_MESSAGE_USER_NOT_JOINED); + const event6 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.HISTORICAL_MESSAGE_USER_NOT_JOINED, + }); tracker.addVisibleEvent(event6); - tracker.eventDecrypted(event6); + eventDecrypted(tracker, event6, now); - const event7 = await createFailedDecryptionEvent(DecryptionFailureCode.UNKNOWN_ERROR); + const event7 = await createFailedDecryptionEvent({ + code: DecryptionFailureCode.UNKNOWN_ERROR, + }); tracker.addVisibleEvent(event7); - tracker.eventDecrypted(event7); + eventDecrypted(tracker, event7, now); // Pretend "now" is Infinity tracker.checkFailures(Infinity); @@ -444,4 +500,217 @@ describe("DecryptionFailureTracker", function () { "UnknownError", ]); }); + + it("tracks late decryptions vs. undecryptable", async () => { + const propertiesByErrorCode: Record = {}; + // @ts-ignore access to private constructor + const tracker = new DecryptionFailureTracker( + (errorCode: string, rawError: string, properties: ErrorProperties) => { + propertiesByErrorCode[errorCode] = properties; + }, + (error: string) => error, + ); + + // use three different errors so that we can distinguish the reports + const error1 = DecryptionFailureCode.MEGOLM_UNKNOWN_INBOUND_SESSION_ID; + const error2 = DecryptionFailureCode.MEGOLM_BAD_ROOM; + const error3 = DecryptionFailureCode.MEGOLM_MISSING_FIELDS; + + // event that will be slow to decrypt + const lateDecryption = await createFailedDecryptionEvent({ code: error1 }); + // event that will be so slow to decrypt, it gets counted as undecryptable + const veryLateDecryption = await createFailedDecryptionEvent({ code: error2 }); + // event that never gets decrypted + const neverDecrypted = await createFailedDecryptionEvent({ code: error3 }); + + tracker.addVisibleEvent(lateDecryption); + tracker.addVisibleEvent(veryLateDecryption); + tracker.addVisibleEvent(neverDecrypted); + + const now = Date.now(); + eventDecrypted(tracker, lateDecryption, now); + eventDecrypted(tracker, veryLateDecryption, now); + eventDecrypted(tracker, neverDecrypted, now); + + await decryptExistingEvent(lateDecryption, { + plainType: "m.room.message", + plainContent: { body: "success" }, + }); + await decryptExistingEvent(veryLateDecryption, { + plainType: "m.room.message", + plainContent: { body: "success" }, + }); + eventDecrypted(tracker, lateDecryption, now + 40000); + eventDecrypted(tracker, veryLateDecryption, now + 100000); + + // 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); + }); + + it("listens for client events", async () => { + // Test that the decryption failure tracker registers the right event + // handlers on start, and unregisters them when the client logs out. + const client = mocked(stubClient()); + const mockCrypto = { + getVersion: jest.fn().mockReturnValue("Rust SDK 0.7.0 (61b175b), Vodozemac 0.5.1"), + getUserVerificationStatus: jest.fn().mockResolvedValue(new UserVerificationStatus(false, false, false)), + } as unknown as Mocked; + client.getCrypto.mockReturnValue(mockCrypto); + + let errorCount: number = 0; + // @ts-ignore access to private constructor + const tracker = new DecryptionFailureTracker( + (errorCode: string, rawError: string, properties: ErrorProperties) => { + errorCount++; + }, + (error: string) => error, + ); + + // Calling .start will start some intervals. This test shouldn't run + // long enough for the timers to fire, but we'll use fake timers just + // to be safe. + jest.useFakeTimers(); + 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); + + client.emit(HttpApiEvent.SessionLoggedOut, {} as any); + + // After the client has logged out, we shouldn't be listening to events + // any more, so even if the client emits an event regarding a failed + // decryption, we won't track it. + const anotherFailedDecryption = await createFailedDecryptionEvent(); + client.emit(MatrixEventEvent.Decrypted, anotherFailedDecryption); + + // Pretend "now" is Infinity + tracker.checkFailures(Infinity); + tracker.trackFailures(); + + expect(errorCount).toEqual(1); + + jest.useRealTimers(); + }); + + it("tracks client information", async () => { + const client = mocked(stubClient()); + const mockCrypto = { + getVersion: jest.fn().mockReturnValue("Rust SDK 0.7.0 (61b175b), Vodozemac 0.5.1"), + getUserVerificationStatus: jest.fn().mockResolvedValue(new UserVerificationStatus(false, false, false)), + } as unknown as Mocked; + client.getCrypto.mockReturnValue(mockCrypto); + + const propertiesByErrorCode: Record = {}; + // @ts-ignore access to private constructor + const tracker = new DecryptionFailureTracker( + (errorCode: string, rawError: string, properties: ErrorProperties) => { + propertiesByErrorCode[errorCode] = properties; + }, + (error: string) => error, + ); + + // @ts-ignore access to private method + await tracker.calculateClientProperties(client); + // @ts-ignore access to private method + await tracker.registerHandlers(client); + + // use three different errors so that we can distinguish the reports + const error1 = DecryptionFailureCode.MEGOLM_UNKNOWN_INBOUND_SESSION_ID; + const error2 = DecryptionFailureCode.MEGOLM_BAD_ROOM; + const error3 = DecryptionFailureCode.MEGOLM_MISSING_FIELDS; + + // event from a federated user (@alice:example.com) + const federatedDecryption = await createFailedDecryptionEvent({ + code: error1, + }); + // event from a local user + const localDecryption = await createFailedDecryptionEvent({ + sender: "@bob:matrix.org", + code: error2, + }); + + tracker.addVisibleEvent(federatedDecryption); + tracker.addVisibleEvent(localDecryption); + + const now = Date.now(); + eventDecrypted(tracker, federatedDecryption, now); + + mockCrypto.getUserVerificationStatus.mockResolvedValue(new UserVerificationStatus(true, true, false)); + client.emit(CryptoEvent.KeysChanged, {}); + await sleep(100); + eventDecrypted(tracker, localDecryption, now); + + // Pretend "now" is Infinity + tracker.checkFailures(Infinity); + + tracker.trackFailures(); + + expect(propertiesByErrorCode[error1].isMatrixDotOrg).toBe(true); + expect(propertiesByErrorCode[error1].cryptoSDK).toEqual("Rust"); + + expect(propertiesByErrorCode[error1].isFederated).toBe(true); + expect(propertiesByErrorCode[error1].userTrustsOwnIdentity).toEqual(false); + expect(propertiesByErrorCode[error2].isFederated).toBe(false); + expect(propertiesByErrorCode[error2].userTrustsOwnIdentity).toEqual(true); + + // change client params, and make sure the reports the right values + client.getDomain.mockReturnValue("example.com"); + mockCrypto.getVersion.mockReturnValue("Olm 0.0.0"); + // @ts-ignore access to private method + await tracker.calculateClientProperties(client); + + const anotherFailure = await createFailedDecryptionEvent({ + code: error3, + }); + tracker.addVisibleEvent(anotherFailure); + eventDecrypted(tracker, anotherFailure, now); + tracker.checkFailures(Infinity); + tracker.trackFailures(); + expect(propertiesByErrorCode[error3].isMatrixDotOrg).toBe(false); + expect(propertiesByErrorCode[error3].cryptoSDK).toEqual("Legacy"); + }); + + it("keeps the original timestamp after repeated decryption failures", async () => { + const failedDecryptionEvent = await createFailedDecryptionEvent(); + + let failure: ErrorProperties | undefined; + // @ts-ignore access to private constructor + const tracker = new DecryptionFailureTracker( + (errorCode: string, rawError: string, properties: ErrorProperties) => { + failure = properties; + }, + () => "UnknownError", + ); + + tracker.addVisibleEvent(failedDecryptionEvent); + + const now = Date.now(); + eventDecrypted(tracker, failedDecryptionEvent, now); + eventDecrypted(tracker, failedDecryptionEvent, now + 20000); + await decryptExistingEvent(failedDecryptionEvent, { + plainType: "m.room.message", + plainContent: { body: "success" }, + }); + eventDecrypted(tracker, failedDecryptionEvent, now + 50000); + + // 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 + expect(failure?.timeToDecryptMillis).toEqual(50000); + }); }); diff --git a/test/components/structures/MatrixChat-test.tsx b/test/components/structures/MatrixChat-test.tsx index 00a44c44bd..8ce80eed03 100644 --- a/test/components/structures/MatrixChat-test.tsx +++ b/test/components/structures/MatrixChat-test.tsx @@ -955,6 +955,7 @@ describe("", () => { describe("post login setup", () => { beforeEach(() => { const mockCrypto = { + getVersion: jest.fn().mockReturnValue("Version 0"), getVerificationRequestsToDeviceInProgress: jest.fn().mockReturnValue([]), getUserDeviceInfo: jest.fn().mockResolvedValue(new Map()), getUserVerificationStatus: jest diff --git a/test/test-utils/client.ts b/test/test-utils/client.ts index 03dc475d32..be3f3425c2 100644 --- a/test/test-utils/client.ts +++ b/test/test-utils/client.ts @@ -98,6 +98,7 @@ export const unmockClientPeg = () => { */ export const mockClientMethodsUser = (userId = "@alice:domain") => ({ getUserId: jest.fn().mockReturnValue(userId), + getDomain: jest.fn().mockReturnValue(userId.split(":")[1]), getSafeUserId: jest.fn().mockReturnValue(userId), getUser: jest.fn().mockReturnValue(new User(userId)), isGuest: jest.fn().mockReturnValue(false),