Merge pull request #273 from vector-im/bwindels/keybackuplogging

Add logging to key backup operations

Author: bwindels

src/logging/LogItem.js

@@ -140,7 +140,8 @@ export class LogItem {
             // (e)rror
             item.e = {
                 stack: this.error.stack,
-                name: this.error.name
+                name: this.error.name,
+                message: this.error.message.split("\n")[0]
             };
         }
         if (forced) {

src/logging/NullLogger.js

@@ -15,16 +15,30 @@ limitations under the License.
 */
 import {LogLevel} from "./LogFilter.js";
 
-// TODO: add missing methods
+function noop () {}
+
+
 export class NullLogger {
     constructor() {
-        this._item = new NullLogItem();
+        this.item = new NullLogItem();
     }
 
     log() {}
 
     run(_, callback) {
-        return callback(this._item);    
+        return callback(this.item);    
+    }
+
+    wrapOrRun(item, _, callback) {
+        if (item) {
+            item.wrap(null, callback);
+        } else {
+            this.run(null, callback);
+        }
+    }
+
+    runDetached(_, callback) {
+        new Promise(r => r(callback(this.item))).then(noop, noop);
     }
 
     async export() {
@@ -42,12 +56,29 @@ class NullLogItem {
     }
     log() {}
     set() {}
-    anonymize() {}
+
+    runDetached(_, callback) {
+        new Promise(r => r(callback(this))).then(noop, noop);
+    }
+
+    wrapDetached(_, callback) {
+        return this.refDetached(null, callback);
+    }
+
+    run(callback) {
+        return callback(this);
+    }
+
+    refDetached() {}
 
     get level() {
         return LogLevel;
     }
 
+    get duration() {
+        return 0;
+    }
+
     catch(err) {
         return err;
     }
@@ -58,3 +89,5 @@ class NullLogItem {
 
     finish() {}
 }
+
+export const Instance = new NullLogger(); 

src/logging/utils.js

@@ -0,0 +1,16 @@
+// these are helper functions if you can't assume you always have a log item (e.g. some code paths call with one set, others don't)
+// if you know you always have a log item, better to use the methods on the log item than these utility functions.
+
+import {Instance as NullLoggerInstance} from "./NullLogger.js";
+
+export function wrapOrRunNullLogger(logItem, labelOrValues, callback, logLevel = null, filterCreator = null) {
+    if (logItem) {
+        return logItem.wrap(logItem, labelOrValues, callback, logLevel, filterCreator);
+    } else {
+        return NullLoggerInstance.run(null, callback);
+    }
+}
+
+export function ensureLogItem(logItem) {
+    return logItem || NullLoggerInstance.item;
+}

src/matrix/SessionContainer.js

@@ -146,6 +146,7 @@ export class SessionContainer {
     }
 
     async _loadSessionInfo(sessionInfo, isNewLogin, log) {
+        log.set("appVersion", this._platform.version);
         const clock = this._platform.clock;
         this._sessionStartedByReconnector = false;
         this._status.set(LoadStatus.Loading);

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,47 +134,50 @@ 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";
         });
         if (!missingSessionEvents.length) {
             return;
         }
-        const eventsBySession = groupEventsBySession(events);
+        // store missing event ids if received from sync
+        const missingEventsBySession = groupEventsBySession(missingSessionEvents);
         if (source === DecryptionSource.Sync) {
-            await Promise.all(Array.from(eventsBySession.values()).map(async group => {
+            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);
             }));
         }
+        
+        if (!this._sessionBackup) {
+            return;
+        }
 
-        // TODO: do proper logging here
-        // run detached
-        Promise.resolve().then(async () => {
+        log.wrapDetached("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) {
                     return;
                 }
                 // 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 +194,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 +219,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 +234,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 +492,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);
     }
 }

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,

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<string>} 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, 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);
             }
-        });
+        }, ensureLogItem(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, null, log);
                 await decryptRequest.complete();
             }
             // once txn is committed, update in-memory state & emit events
@@ -588,7 +589,9 @@ 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._platform.logger.run("enableSessionBackup", log => {
+                return this._roomEncryption.restoreMissingSessionsFromBackup(this._timeline.remoteEntries, log);
+            });
         }
     }
 
@@ -675,7 +678,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 +748,10 @@ export class Room extends EventEmitter {
 }
 
 class DecryptionRequest {
-    constructor(decryptFn) {
+    constructor(decryptFn, log) {
         this._cancelled = false;
         this.preparation = null;
-        this._promise = decryptFn(this);
+        this._promise = log.wrap("decryptEntries", log => decryptFn(this, log));
     }
 
     complete() {