From 2215087f96a150383f95703c9f505d6bf8be73c6 Mon Sep 17 00:00:00 2001
From: Matthew Hodgson <matthew@matrix.org>
Date: Tue, 26 Nov 2019 01:17:12 +0000
Subject: [PATCH 1/4] expand e2ee logging to better debug UISIs

---
 src/client.js                   |  6 +++---
 src/crypto/OlmDevice.js         | 12 +++++++-----
 src/crypto/algorithms/megolm.js | 23 ++++++++++++-----------
 src/crypto/index.js             |  2 ++
 src/crypto/olmlib.js            |  4 ++--
 5 files changed, 26 insertions(+), 21 deletions(-)

diff --git a/src/client.js b/src/client.js
index 6fc6a3223..820404c50 100644
--- a/src/client.js
+++ b/src/client.js
@@ -73,7 +73,7 @@ function keysFromRecoverySession(sessions, decryptionKey, roomId) {
             decrypted.room_id = roomId;
             keys.push(decrypted);
         } catch (e) {
-            logger.log("Failed to decrypt session from backup");
+            logger.log("Failed to decrypt megolm session from backup", e);
         }
     }
     return keys;
@@ -1626,7 +1626,7 @@ MatrixClient.prototype._restoreKeyBackup = function(
                 key.session_id = targetSessionId;
                 keys.push(key);
             } catch (e) {
-                logger.log("Failed to decrypt session from backup");
+                logger.log("Failed to decrypt megolm session from backup", e);
             }
         }
 
@@ -4705,7 +4705,7 @@ function setupCallEventHandler(client) {
         const content = event.getContent();
         let call = content.call_id ? client.callList[content.call_id] : undefined;
         let i;
-        //console.log("RECV %s content=%s", event.getType(), JSON.stringify(content));
+        //console.info("RECV %s content=%s", event.getType(), JSON.stringify(content));
 
         if (event.getType() === "m.call.invite") {
             if (event.getSender() === client.credentials.userId) {
diff --git a/src/crypto/OlmDevice.js b/src/crypto/OlmDevice.js
index 7060074a7..6bbdfda84 100644
--- a/src/crypto/OlmDevice.js
+++ b/src/crypto/OlmDevice.js
@@ -462,7 +462,7 @@ OlmDevice.prototype.createInboundSession = async function(
  */
 OlmDevice.prototype.getSessionIdsForDevice = async function(theirDeviceIdentityKey) {
     if (this._sessionsInProgress[theirDeviceIdentityKey]) {
-        logger.log("waiting for session to be created");
+        logger.log("waiting for olm session to be created");
         try {
             await this._sessionsInProgress[theirDeviceIdentityKey];
         } catch (e) {
@@ -543,7 +543,7 @@ OlmDevice.prototype.getSessionIdForDevice = async function(
  */
 OlmDevice.prototype.getSessionInfoForDevice = async function(deviceIdentityKey, nowait) {
     if (this._sessionsInProgress[deviceIdentityKey] && !nowait) {
-        logger.log("waiting for session to be created");
+        logger.log("waiting for olm session to be created");
         try {
             await this._sessionsInProgress[deviceIdentityKey];
         } catch (e) {
@@ -596,7 +596,7 @@ OlmDevice.prototype.encryptMessage = async function(
             this._getSession(theirDeviceIdentityKey, sessionId, txn, (sessionInfo) => {
                 const sessionDesc = sessionInfo.session.describe();
                 console.log(
-                    "Session ID " + sessionId + " to " +
+                    "encryptMessage: Olm Session ID " + sessionId + " to " +
                     theirDeviceIdentityKey + ": " + sessionDesc,
                 );
                 res = sessionInfo.session.encrypt(payloadString);
@@ -628,7 +628,7 @@ OlmDevice.prototype.decryptMessage = async function(
             this._getSession(theirDeviceIdentityKey, sessionId, txn, (sessionInfo) => {
                 const sessionDesc = sessionInfo.session.describe();
                 console.log(
-                    "Session ID " + sessionId + " to " +
+                    "decryptMessage: Olm Session ID " + sessionId + " from " +
                     theirDeviceIdentityKey + ": " + sessionDesc,
                 );
                 payloadString = sessionInfo.session.decrypt(messageType, ciphertext);
@@ -740,6 +740,8 @@ OlmDevice.prototype.createOutboundGroupSession = function() {
 OlmDevice.prototype.encryptGroupMessage = function(sessionId, payloadString) {
     const self = this;
 
+    console.log(`encrypting msg with megolm session ${sessionId}`);
+
     checkPayloadLength(payloadString);
 
     return this._getOutboundGroupSession(sessionId, function(session) {
@@ -886,7 +888,7 @@ OlmDevice.prototype.addInboundGroupSession = async function(
                                 <= session.first_known_index()) {
                                 // existing session has lower index (i.e. can
                                 // decrypt more), so keep it
-                                logger.log("Keeping existing session");
+                                logger.log(`Keeping existing megolm session ${sessionId}`);
                                 return;
                             }
                         }
diff --git a/src/crypto/algorithms/megolm.js b/src/crypto/algorithms/megolm.js
index 4262c2cee..f6fe7afc0 100644
--- a/src/crypto/algorithms/megolm.js
+++ b/src/crypto/algorithms/megolm.js
@@ -104,7 +104,7 @@ OutboundSessionInfo.prototype.sharedWithTooManyDevices = function(
         }
 
         if (!devicesInRoom.hasOwnProperty(userId)) {
-            logger.log("Starting new session because we shared with " + userId);
+            logger.log("Starting new megolm session because we shared with " + userId);
             return true;
         }
 
@@ -115,7 +115,7 @@ OutboundSessionInfo.prototype.sharedWithTooManyDevices = function(
 
             if (!devicesInRoom[userId].hasOwnProperty(deviceId)) {
                 logger.log(
-                    "Starting new session because we shared with " +
+                    "Starting new megolm session because we shared with " +
                         userId + ":" + deviceId,
                 );
                 return true;
@@ -200,6 +200,7 @@ MegolmEncryption.prototype._ensureOutboundSession = function(devicesInRoom) {
         if (!session) {
             logger.log(`Starting new megolm session for room ${self._roomId}`);
             session = await self._prepareNewSession();
+            logger.log(`Started new megolm session ${session.sessionId} for room ${self._roomId}`);
             self._outboundSessions[session.sessionId] = session;
         }
 
@@ -278,7 +279,7 @@ MegolmEncryption.prototype._prepareNewSession = async function() {
         ).catch((e) => {
             // This throws if the upload failed, but this is fine
             // since it will have written it to the db and will retry.
-            logger.log("Failed to back up group session", e);
+            logger.log("Failed to back up megolm session", e);
         });
     }
 
@@ -440,19 +441,19 @@ MegolmEncryption.prototype.reshareKeyWithDevice = async function(
 ) {
     const obSessionInfo = this._outboundSessions[sessionId];
     if (!obSessionInfo) {
-        logger.debug("Session ID " + sessionId + " not found: not re-sharing keys");
+        logger.debug("megolm session ID " + sessionId + " not found: not re-sharing keys");
         return;
     }
 
     // The chain index of the key we previously sent this device
     if (obSessionInfo.sharedWithDevices[userId] === undefined) {
-        logger.debug("Session ID " + sessionId + " never shared with user " + userId);
+        logger.debug("megolm session ID " + sessionId + " never shared with user " + userId);
         return;
     }
     const sentChainIndex = obSessionInfo.sharedWithDevices[userId][device.deviceId];
     if (sentChainIndex === undefined) {
         logger.debug(
-            "Session ID " + sessionId + " never shared with device " +
+            "megolm session ID " + sessionId + " never shared with device " +
             userId + ":" + device.deviceId,
         );
         return;
@@ -466,7 +467,7 @@ MegolmEncryption.prototype.reshareKeyWithDevice = async function(
 
     if (!key) {
         logger.warn(
-            "No outbound session key found for " + sessionId + ": not re-sharing keys",
+            "No inbound session key found for megolm " + sessionId + ": not re-sharing keys",
         );
         return;
     }
@@ -514,7 +515,7 @@ MegolmEncryption.prototype.reshareKeyWithDevice = async function(
         },
     });
     logger.debug(
-        `Re-shared key for session ${sessionId}  with ${userId}:${device.deviceId}`,
+        `Re-shared key for megolm session ${sessionId}  with ${userId}:${device.deviceId}`,
     );
 };
 
@@ -922,7 +923,7 @@ MegolmDecryption.prototype.onRoomKeyEvent = function(event) {
         keysClaimed = event.getKeysClaimed();
     }
 
-    logger.log(`Adding key for megolm session ${senderKey}|${sessionId}`);
+    logger.log(`Received and adding key for megolm session ${senderKey}|${sessionId}`);
     return this._olmDevice.addInboundGroupSession(
         content.room_id, senderKey, forwardingKeyChain, sessionId,
         content.session_key, keysClaimed,
@@ -955,7 +956,7 @@ MegolmDecryption.prototype.onRoomKeyEvent = function(event) {
             ).catch((e) => {
                 // This throws if the upload failed, but this is fine
                 // since it will have written it to the db and will retry.
-                logger.log("Failed to back up group session", e);
+                logger.log("Failed to back up megolm session", e);
             });
         }
     }).catch((e) => {
@@ -1088,7 +1089,7 @@ MegolmDecryption.prototype.importRoomKey = function(session) {
             ).catch((e) => {
                 // This throws if the upload failed, but this is fine
                 // since it will have written it to the db and will retry.
-                logger.log("Failed to back up group session", e);
+                logger.log("Failed to back up megolm session", e);
             });
         }
         // have another go at decrypting events sent with this session.
diff --git a/src/crypto/index.js b/src/crypto/index.js
index 20ec1a2dd..989117bf9 100644
--- a/src/crypto/index.js
+++ b/src/crypto/index.js
@@ -2296,6 +2296,8 @@ Crypto.prototype._getTrackedE2eRooms = function() {
 
 Crypto.prototype._onToDeviceEvent = function(event) {
     try {
+        console.log(`received to_device ${event.getType()} from: ${event.getSender()} id: ${event.getId()}`);
+
         if (event.getType() == "m.room_key"
             || event.getType() == "m.forwarded_room_key") {
             this._onRoomKeyEvent(event);
diff --git a/src/crypto/olmlib.js b/src/crypto/olmlib.js
index 93a492e26..4af8e035d 100644
--- a/src/crypto/olmlib.js
+++ b/src/crypto/olmlib.js
@@ -287,12 +287,12 @@ async function _verifyKeyAndStartSession(olmDevice, oneTimeKey, userId, deviceIn
         );
     } catch (e) {
         // possibly a bad key
-        logger.error("Error starting session with device " +
+        logger.error("Error starting olm session with device " +
                       userId + ":" + deviceId + ": " + e);
         return null;
     }
 
-    logger.log("Started new sessionid " + sid +
+    logger.log("Started new olm sessionid " + sid +
                 " for device " + userId + ":" + deviceId);
     return sid;
 }

From 191695da5a8c4d2ad3058b2c0b23c9e9fb91b97d Mon Sep 17 00:00:00 2001
From: Matthew Hodgson <matthew@matrix.org>
Date: Tue, 26 Nov 2019 01:41:59 +0000
Subject: [PATCH 2/4] lint

---
 src/crypto/OlmDevice.js         |  4 +++-
 src/crypto/algorithms/megolm.js | 14 +++++++-------
 src/crypto/index.js             |  3 ++-
 3 files changed, 12 insertions(+), 9 deletions(-)

diff --git a/src/crypto/OlmDevice.js b/src/crypto/OlmDevice.js
index 6bbdfda84..abe0bc90b 100644
--- a/src/crypto/OlmDevice.js
+++ b/src/crypto/OlmDevice.js
@@ -888,7 +888,9 @@ OlmDevice.prototype.addInboundGroupSession = async function(
                                 <= session.first_known_index()) {
                                 // existing session has lower index (i.e. can
                                 // decrypt more), so keep it
-                                logger.log(`Keeping existing megolm session ${sessionId}`);
+                                logger.log(
+                                    `Keeping existing megolm session ${sessionId}`,
+                                );
                                 return;
                             }
                         }
diff --git a/src/crypto/algorithms/megolm.js b/src/crypto/algorithms/megolm.js
index f6fe7afc0..c9124c401 100644
--- a/src/crypto/algorithms/megolm.js
+++ b/src/crypto/algorithms/megolm.js
@@ -200,7 +200,8 @@ MegolmEncryption.prototype._ensureOutboundSession = function(devicesInRoom) {
         if (!session) {
             logger.log(`Starting new megolm session for room ${self._roomId}`);
             session = await self._prepareNewSession();
-            logger.log(`Started new megolm session ${session.sessionId} for room ${self._roomId}`);
+            logger.log(`Started new megolm session ${session.sessionId} ` +
+                       `for room ${self._roomId}`);
             self._outboundSessions[session.sessionId] = session;
         }
 
@@ -441,13 +442,13 @@ MegolmEncryption.prototype.reshareKeyWithDevice = async function(
 ) {
     const obSessionInfo = this._outboundSessions[sessionId];
     if (!obSessionInfo) {
-        logger.debug("megolm session ID " + sessionId + " not found: not re-sharing keys");
+        logger.debug(`megolm session ${sessionId} not found: not re-sharing keys`);
         return;
     }
 
     // The chain index of the key we previously sent this device
     if (obSessionInfo.sharedWithDevices[userId] === undefined) {
-        logger.debug("megolm session ID " + sessionId + " never shared with user " + userId);
+        logger.debug(`megolm session ${sessionId} never shared with user ${userId}`);
         return;
     }
     const sentChainIndex = obSessionInfo.sharedWithDevices[userId][device.deviceId];
@@ -467,7 +468,7 @@ MegolmEncryption.prototype.reshareKeyWithDevice = async function(
 
     if (!key) {
         logger.warn(
-            "No inbound session key found for megolm " + sessionId + ": not re-sharing keys",
+            `No inbound session key found for megolm ${sessionId}: not re-sharing keys`,
         );
         return;
     }
@@ -514,9 +515,8 @@ MegolmEncryption.prototype.reshareKeyWithDevice = async function(
             [device.deviceId]: encryptedContent,
         },
     });
-    logger.debug(
-        `Re-shared key for megolm session ${sessionId}  with ${userId}:${device.deviceId}`,
-    );
+    logger.debug(`Re-shared key for megolm session ${sessionId} ` +
+                 `with ${userId}:${device.deviceId}`);
 };
 
 /**
diff --git a/src/crypto/index.js b/src/crypto/index.js
index 989117bf9..4f29d15af 100644
--- a/src/crypto/index.js
+++ b/src/crypto/index.js
@@ -2296,7 +2296,8 @@ Crypto.prototype._getTrackedE2eRooms = function() {
 
 Crypto.prototype._onToDeviceEvent = function(event) {
     try {
-        console.log(`received to_device ${event.getType()} from: ${event.getSender()} id: ${event.getId()}`);
+        console.log(`received to_device ${event.getType()} from: ` +
+                    `${event.getSender()} id: ${event.getId()}`);
 
         if (event.getType() == "m.room_key"
             || event.getType() == "m.forwarded_room_key") {

From 6e08835496cec5a4551ba8476ee181430d6de2d9 Mon Sep 17 00:00:00 2001
From: Matthew Hodgson <matthew@matrix.org>
Date: Tue, 26 Nov 2019 01:58:04 +0000
Subject: [PATCH 3/4] log keyshare ID

---
 src/crypto/algorithms/megolm.js            | 6 +++---
 src/crypto/store/indexeddb-crypto-store.js | 2 +-
 2 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/src/crypto/algorithms/megolm.js b/src/crypto/algorithms/megolm.js
index c9124c401..286c29804 100644
--- a/src/crypto/algorithms/megolm.js
+++ b/src/crypto/algorithms/megolm.js
@@ -551,10 +551,10 @@ MegolmEncryption.prototype._shareKeyWithDevices = async function(session, device
             await this._encryptAndSendKeysToDevices(
                 session, key.chain_index, userDeviceMaps[i], payload,
             );
-            logger.log(`Completed megolm keyshare in ${this._roomId} `
-                + `(slice ${i + 1}/${userDeviceMaps.length})`);
+            logger.log(`Completed megolm keyshare for ${session.sessionId} `
+                + `in ${this._roomId} (slice ${i + 1}/${userDeviceMaps.length})`);
         } catch (e) {
-            logger.log(`megolm keyshare in ${this._roomId} `
+            logger.log(`megolm keyshare for ${session.sessionId} in ${this._roomId} `
                 + `(slice ${i + 1}/${userDeviceMaps.length}) failed`);
 
             throw e;
diff --git a/src/crypto/store/indexeddb-crypto-store.js b/src/crypto/store/indexeddb-crypto-store.js
index b2c2fe4d0..e20edf18b 100644
--- a/src/crypto/store/indexeddb-crypto-store.js
+++ b/src/crypto/store/indexeddb-crypto-store.js
@@ -389,7 +389,7 @@ export default class IndexedDBCryptoStore {
         );
     }
 
-    // Inbound group saessions
+    // Inbound group sessions
 
     /**
      * Retrieve the end-to-end inbound group session for a given

From 3787b6f1c7ba293e9acb09545535bb5fffefb974 Mon Sep 17 00:00:00 2001
From: Matthew Hodgson <matthew@matrix.org>
Date: Tue, 26 Nov 2019 09:07:23 +0000
Subject: [PATCH 4/4] s/console/logger/ as per review

---
 src/crypto/OlmDevice.js | 6 +++---
 src/crypto/index.js     | 4 ++--
 2 files changed, 5 insertions(+), 5 deletions(-)

diff --git a/src/crypto/OlmDevice.js b/src/crypto/OlmDevice.js
index abe0bc90b..b86b4f858 100644
--- a/src/crypto/OlmDevice.js
+++ b/src/crypto/OlmDevice.js
@@ -595,7 +595,7 @@ OlmDevice.prototype.encryptMessage = async function(
         (txn) => {
             this._getSession(theirDeviceIdentityKey, sessionId, txn, (sessionInfo) => {
                 const sessionDesc = sessionInfo.session.describe();
-                console.log(
+                logger.log(
                     "encryptMessage: Olm Session ID " + sessionId + " to " +
                     theirDeviceIdentityKey + ": " + sessionDesc,
                 );
@@ -627,7 +627,7 @@ OlmDevice.prototype.decryptMessage = async function(
         (txn) => {
             this._getSession(theirDeviceIdentityKey, sessionId, txn, (sessionInfo) => {
                 const sessionDesc = sessionInfo.session.describe();
-                console.log(
+                logger.log(
                     "decryptMessage: Olm Session ID " + sessionId + " from " +
                     theirDeviceIdentityKey + ": " + sessionDesc,
                 );
@@ -740,7 +740,7 @@ OlmDevice.prototype.createOutboundGroupSession = function() {
 OlmDevice.prototype.encryptGroupMessage = function(sessionId, payloadString) {
     const self = this;
 
-    console.log(`encrypting msg with megolm session ${sessionId}`);
+    logger.log(`encrypting msg with megolm session ${sessionId}`);
 
     checkPayloadLength(payloadString);
 
diff --git a/src/crypto/index.js b/src/crypto/index.js
index 4f29d15af..f53d1fcce 100644
--- a/src/crypto/index.js
+++ b/src/crypto/index.js
@@ -1638,7 +1638,7 @@ Crypto.prototype.setRoomEncryption = async function(roomId, config, inhibitDevic
     // It would otherwise just throw later as an unknown algorithm would, but we may
     // as well catch this here
     if (!config.algorithm) {
-        console.log("Ignoring setRoomEncryption with no algorithm");
+        logger.log("Ignoring setRoomEncryption with no algorithm");
         return;
     }
 
@@ -2296,7 +2296,7 @@ Crypto.prototype._getTrackedE2eRooms = function() {
 
 Crypto.prototype._onToDeviceEvent = function(event) {
     try {
-        console.log(`received to_device ${event.getType()} from: ` +
+        logger.log(`received to_device ${event.getType()} from: ` +
                     `${event.getSender()} id: ${event.getId()}`);
 
         if (event.getType() == "m.room_key"