From fcc06b275431f03c23b38107d697b1254006ea4e Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Mon, 15 Mar 2021 12:56:40 +0100 Subject: [PATCH] WIP to add logging to decryption and fetching key backups --- src/matrix/e2ee/RoomEncryption.js | 57 ++++++++++--------- src/matrix/e2ee/megolm/SessionBackup.js | 4 +- src/matrix/room/Room.js | 25 ++++---- src/matrix/room/timeline/Timeline.js | 4 +- .../timeline/persistence/TimelineReader.js | 24 ++++---- 5 files changed, 59 insertions(+), 55 deletions(-) diff --git a/src/matrix/e2ee/RoomEncryption.js b/src/matrix/e2ee/RoomEncryption.js index 1f6365a4..7af65553 100644 --- a/src/matrix/e2ee/RoomEncryption.js +++ b/src/matrix/e2ee/RoomEncryption.js @@ -56,7 +56,7 @@ export class RoomEncryption { this._sessionBackup = sessionBackup; } - async restoreMissingSessionsFromBackup(entries) { + async restoreMissingSessionsFromBackup(entries, log) { const events = entries.filter(e => e.isEncrypted && !e.isDecrypted && e.event).map(e => e.event); const eventsBySession = groupEventsBySession(events); const groups = Array.from(eventsBySession.values()); @@ -69,7 +69,7 @@ export class RoomEncryption { // start with last sessions which should be for the last items in the timeline for (var i = missingSessions.length - 1; i >= 0; i--) { const session = missingSessions[i]; - await this._requestMissingSessionFromBackup(session.senderKey, session.sessionId); + await log.wrap("session", log => this._requestMissingSessionFromBackup(session.senderKey, session.sessionId, log)); } } } @@ -98,9 +98,6 @@ export class RoomEncryption { return shouldFlush; } - // this happens before entries exists, as they are created by the syncwriter - // but we want to be able to map it back to something in the timeline easily - // when retrying decryption. async prepareDecryptAll(events, newKeys, source, txn) { const errors = new Map(); const validEvents = []; @@ -137,7 +134,7 @@ export class RoomEncryption { return new DecryptionPreparation(preparation, errors, source, this, events); } - async _processDecryptionResults(events, results, errors, source, txn) { + async _processDecryptionResults(events, results, errors, source, txn, log) { const missingSessionEvents = events.filter(event => { const error = errors.get(event.event_id); return error?.code === "MEGOLM_NO_SESSION"; @@ -145,20 +142,22 @@ export class RoomEncryption { if (!missingSessionEvents.length) { return; } - const eventsBySession = groupEventsBySession(events); + const missingEventsBySession = groupEventsBySession(missingSessionEvents); if (source === DecryptionSource.Sync) { - await Promise.all(Array.from(eventsBySession.values()).map(async group => { + // store missing event ids if received from sync + await Promise.all(Array.from(missingEventsBySession.values()).map(async group => { const eventIds = group.events.map(e => e.event_id); return this._megolmDecryption.addMissingKeyEventIds( this._room.id, group.senderKey, group.sessionId, eventIds, txn); })); } - // TODO: do proper logging here - // run detached - Promise.resolve().then(async () => { + log.refDetached("check key backup", async log => { // if the message came from sync, wait 10s to see if the room key arrives late, // and only after that proceed to request from backup + log.set("source", source); + log.set("events", missingSessionEvents.length); + log.set("sessions", missingEventsBySession.size); if (source === DecryptionSource.Sync) { await this._clock.createTimeout(10000).elapsed(); if (this._disposed) { @@ -166,18 +165,15 @@ export class RoomEncryption { } // now check which sessions have been received already const txn = await this._storage.readTxn([this._storage.storeNames.inboundGroupSessions]); - await Promise.all(Array.from(eventsBySession).map(async ([key, group]) => { + await Promise.all(Array.from(missingEventsBySession).map(async ([key, group]) => { if (await this._megolmDecryption.hasSession(this._room.id, group.senderKey, group.sessionId, txn)) { - eventsBySession.delete(key); + missingEventsBySession.delete(key); } })); } - await Promise.all(Array.from(eventsBySession.values()).map(group => { - return this._requestMissingSessionFromBackup(group.senderKey, group.sessionId); + await Promise.all(Array.from(missingEventsBySession.values()).map(group => { + return log.wrap("session", log => this._requestMissingSessionFromBackup(group.senderKey, group.sessionId, log)); })); - }).catch(err => { - console.log("failed to fetch missing session from key backup"); - console.error(err); }); } @@ -194,18 +190,21 @@ export class RoomEncryption { } } - async _requestMissingSessionFromBackup(senderKey, sessionId) { + async _requestMissingSessionFromBackup(senderKey, sessionId, log) { // show prompt to enable secret storage if (!this._sessionBackup) { + log.set("enabled", false); this._notifyMissingMegolmSession(); return; } - + log.set("id", sessionId); + log.set("senderKey", senderKey); try { - const session = await this._sessionBackup.getSession(this._room.id, sessionId); + const session = await this._sessionBackup.getSession(this._room.id, sessionId, log); if (session?.algorithm === MEGOLM_ALGORITHM) { if (session["sender_key"] !== senderKey) { - console.warn("Got session key back from backup with different sender key, ignoring", {session, senderKey}); + log.set("wrong_sender_key", session["sender_key"]); + log.logLevel = log.level.Warn; return; } let roomKey = this._megolmDecryption.roomKeyFromBackup(this._room.id, sessionId, session); @@ -216,6 +215,7 @@ export class RoomEncryption { const txn = await this._storage.readWriteTxn([this._storage.storeNames.inboundGroupSessions]); try { keyIsBestOne = await this._megolmDecryption.writeRoomKey(roomKey, txn); + log.set("isBetter", keyIsBestOne); if (keyIsBestOne) { retryEventIds = roomKey.eventIds; } @@ -230,15 +230,18 @@ export class RoomEncryption { roomKey.dispose(); } if (keyIsBestOne) { - await this._room.notifyRoomKey(roomKey, retryEventIds || []); + await log.wrap("retryDecryption", log => this._room.notifyRoomKey(roomKey, retryEventIds || [], log)); } } } else if (session?.algorithm) { - console.info(`Backed-up session of unknown algorithm: ${session.algorithm}`); + log.set("unknown algorithm", session.algorithm); } } catch (err) { if (!(err.name === "HomeServerError" && err.errcode === "M_NOT_FOUND")) { - console.error(`Could not get session ${sessionId} from backup`, err); + log.set("not_found", true); + } else { + log.error = err; + log.logLevel = log.level.Error; } } } @@ -485,10 +488,10 @@ class DecryptionChanges { this._events = events; } - async write(txn) { + async write(txn, log) { const {results, errors} = await this._megolmDecryptionChanges.write(txn); mergeMap(this._extraErrors, errors); - await this._roomEncryption._processDecryptionResults(this._events, results, errors, this._source, txn); + await this._roomEncryption._processDecryptionResults(this._events, results, errors, this._source, txn, log); return new BatchDecryptionResult(results, errors, this._roomEncryption); } } diff --git a/src/matrix/e2ee/megolm/SessionBackup.js b/src/matrix/e2ee/megolm/SessionBackup.js index e4c3788c..daba9961 100644 --- a/src/matrix/e2ee/megolm/SessionBackup.js +++ b/src/matrix/e2ee/megolm/SessionBackup.js @@ -21,8 +21,8 @@ export class SessionBackup { this._hsApi = hsApi; } - async getSession(roomId, sessionId) { - const sessionResponse = await this._hsApi.roomKeyForRoomAndSession(this._backupInfo.version, roomId, sessionId).response(); + async getSession(roomId, sessionId, log) { + const sessionResponse = await this._hsApi.roomKeyForRoomAndSession(this._backupInfo.version, roomId, sessionId, {log}).response(); const sessionInfo = this._decryption.decrypt( sessionResponse.session_data.ephemeral, sessionResponse.session_data.mac, diff --git a/src/matrix/room/Room.js b/src/matrix/room/Room.js index d3d04c93..a88250f0 100644 --- a/src/matrix/room/Room.js +++ b/src/matrix/room/Room.js @@ -29,6 +29,7 @@ import {EventEntry} from "./timeline/entries/EventEntry.js"; import {ObservedEventMap} from "./ObservedEventMap.js"; import {AttachmentUpload} from "./AttachmentUpload.js"; import {DecryptionSource} from "../e2ee/common.js"; +import {ensureLogItem} from "../../logging/utils.js"; const EVENT_ENCRYPTED_TYPE = "m.room.encrypted"; @@ -81,7 +82,7 @@ export class Room extends EventEmitter { * @param {Array} eventIds any event ids that should be retried. There might be more in the timeline though for this key. * @return {Promise} */ - async notifyRoomKey(roomKey, eventIds) { + async notifyRoomKey(roomKey, eventIds, log) { if (!this._roomEncryption) { return; } @@ -95,7 +96,7 @@ export class Room extends EventEmitter { retryEntries = retryEntries.concat(retryTimelineEntries); } if (retryEntries.length) { - const decryptRequest = this._decryptEntries(DecryptionSource.Retry, retryEntries, txn); + const decryptRequest = this._decryptEntries(DecryptionSource.Retry, retryEntries, txn, log); // this will close txn while awaiting decryption await decryptRequest.complete(); @@ -125,8 +126,8 @@ export class Room extends EventEmitter { * Used for decrypting when loading/filling the timeline, and retrying decryption, * not during sync, where it is split up during the multiple phases. */ - _decryptEntries(source, entries, inboundSessionTxn = null) { - const request = new DecryptionRequest(async r => { + _decryptEntries(source, entries, inboundSessionTxn = null, log = null) { + const request = new DecryptionRequest(async (r, log) => { if (!inboundSessionTxn) { inboundSessionTxn = await this._storage.readTxn([this._storage.storeNames.inboundGroupSessions]); } @@ -148,7 +149,7 @@ export class Room extends EventEmitter { const writeTxn = await this._storage.readWriteTxn(stores); let decryption; try { - decryption = await changes.write(writeTxn); + decryption = await changes.write(writeTxn, log); if (isTimelineOpen) { await decryption.verifySenders(writeTxn); } @@ -162,7 +163,7 @@ export class Room extends EventEmitter { if (this._observedEvents) { this._observedEvents.updateEvents(entries); } - }); + }, this._platform.logger, log); return request; } @@ -248,7 +249,7 @@ export class Room extends EventEmitter { await log.wrap("syncWriter", log => this._syncWriter.writeSync(roomResponse, txn, log), log.level.Detail); let allEntries = newEntries; if (decryptChanges) { - const decryption = await decryptChanges.write(txn); + const decryption = await log.wrap("decryptChanges", log => decryptChanges.write(txn, log)); log.set("decryptionResults", decryption.results.size); log.set("decryptionErrors", decryption.errors.size); if (this._isTimelineOpen) { @@ -510,7 +511,7 @@ export class Room extends EventEmitter { } await txn.complete(); if (this._roomEncryption) { - const decryptRequest = this._decryptEntries(DecryptionSource.Timeline, gapResult.entries); + const decryptRequest = this._decryptEntries(DecryptionSource.Timeline, gapResult.entries, log); await decryptRequest.complete(); } // once txn is committed, update in-memory state & emit events @@ -588,7 +589,7 @@ export class Room extends EventEmitter { this._roomEncryption?.enableSessionBackup(sessionBackup); // TODO: do we really want to do this every time you open the app? if (this._timeline) { - this._roomEncryption.restoreMissingSessionsFromBackup(this._timeline.remoteEntries); + this._roomEncryption.restoreMissingSessionsFromBackup(this._timeline.remoteEntries, ensureLogItem()); } } @@ -675,7 +676,7 @@ export class Room extends EventEmitter { if (this._roomEncryption) { this._timeline.enableEncryption(this._decryptEntries.bind(this, DecryptionSource.Timeline)); } - await this._timeline.load(this._user); + await this._timeline.load(this._user, log); return this._timeline; }); } @@ -745,10 +746,10 @@ export class Room extends EventEmitter { } class DecryptionRequest { - constructor(decryptFn) { + constructor(decryptFn, logger, log) { this._cancelled = false; this.preparation = null; - this._promise = decryptFn(this); + this._promise = logger.wrapOrRun(log, "decryptEntries", log => decryptFn(this, log)); } complete() { diff --git a/src/matrix/room/timeline/Timeline.js b/src/matrix/room/timeline/Timeline.js index 9abd5b88..2cccdf83 100644 --- a/src/matrix/room/timeline/Timeline.js +++ b/src/matrix/room/timeline/Timeline.js @@ -45,7 +45,7 @@ export class Timeline { } /** @package */ - async load(user) { + async load(user, log) { const txn = await this._storage.readTxn(this._timelineReader.readTxnStores.concat(this._storage.storeNames.roomMembers)); const memberData = await txn.roomMembers.get(this._roomId, user.id); this._ownMember = new RoomMember(memberData); @@ -54,7 +54,7 @@ export class Timeline { // if they are populated already, the sender profile would be empty // 30 seems to be a good amount to fill the entire screen - const readerRequest = this._disposables.track(this._timelineReader.readFromEnd(30, txn)); + const readerRequest = this._disposables.track(this._timelineReader.readFromEnd(30, txn, log)); try { const entries = await readerRequest.complete(); this._remoteEntries.setManySorted(entries); diff --git a/src/matrix/room/timeline/persistence/TimelineReader.js b/src/matrix/room/timeline/persistence/TimelineReader.js index dc759cc5..27b88ea9 100644 --- a/src/matrix/room/timeline/persistence/TimelineReader.js +++ b/src/matrix/room/timeline/persistence/TimelineReader.js @@ -20,9 +20,9 @@ import {EventEntry} from "../entries/EventEntry.js"; import {FragmentBoundaryEntry} from "../entries/FragmentBoundaryEntry.js"; class ReaderRequest { - constructor(fn) { + constructor(fn, log) { this.decryptRequest = null; - this._promise = fn(this); + this._promise = fn(this, log); } complete() { @@ -106,15 +106,15 @@ export class TimelineReader { return stores; } - readFrom(eventKey, direction, amount) { - return new ReaderRequest(async r => { + readFrom(eventKey, direction, amount, log) { + return new ReaderRequest(async (r, log) => { const txn = await this._storage.readTxn(this.readTxnStores); - return await this._readFrom(eventKey, direction, amount, r, txn); - }); + return await this._readFrom(eventKey, direction, amount, r, txn, log); + }, log); } - readFromEnd(amount, existingTxn = null) { - return new ReaderRequest(async r => { + readFromEnd(amount, existingTxn = null, log) { + return new ReaderRequest(async (r, log) => { const txn = existingTxn || await this._storage.readTxn(this.readTxnStores); const liveFragment = await txn.timelineFragments.liveFragment(this._roomId); let entries; @@ -125,17 +125,17 @@ export class TimelineReader { this._fragmentIdComparer.add(liveFragment); const liveFragmentEntry = FragmentBoundaryEntry.end(liveFragment, this._fragmentIdComparer); const eventKey = liveFragmentEntry.asEventKey(); - entries = await this._readFrom(eventKey, Direction.Backward, amount, r, txn); + entries = await this._readFrom(eventKey, Direction.Backward, amount, r, txn, log); entries.unshift(liveFragmentEntry); } return entries; - }); + }, log); } - async _readFrom(eventKey, direction, amount, r, txn) { + async _readFrom(eventKey, direction, amount, r, txn, log) { const entries = await readRawTimelineEntriesWithTxn(this._roomId, eventKey, direction, amount, this._fragmentIdComparer, txn); if (this._decryptEntries) { - r.decryptRequest = this._decryptEntries(entries, txn); + r.decryptRequest = this._decryptEntries(entries, txn, log); try { await r.decryptRequest.complete(); } finally {