From 4a0f848551d4ba6d6b6f0975a13e20b7714d244d Mon Sep 17 00:00:00 2001
From: "J. Ryan Stinnett" <jryans@gmail.com>
Date: Wed, 17 Feb 2021 13:45:26 +0000
Subject: [PATCH] Add more debug logs to encryption prep

This continues work from https://github.com/matrix-org/matrix-js-sdk/pull/1580
and adds more logging, including specialised logging for a potential cause of
https://github.com/vector-im/element-web/issues/16194.

So far, it seems clear that something's going wrong in the "sharing keys with
new Olm session" step.
---
 src/crypto/algorithms/megolm.js | 11 ++++++-----
 src/crypto/olmlib.js            | 18 +++++++++++++++++-
 2 files changed, 23 insertions(+), 6 deletions(-)

diff --git a/src/crypto/algorithms/megolm.js b/src/crypto/algorithms/megolm.js
index d2e4e86fb..0fa3d046d 100644
--- a/src/crypto/algorithms/megolm.js
+++ b/src/crypto/algorithms/megolm.js
@@ -743,16 +743,17 @@ MegolmEncryption.prototype._shareKeyWithOlmSessions = async function(
     const userDeviceMaps = this._splitDevices(devicemap);
 
     for (let i = 0; i < userDeviceMaps.length; i++) {
+        const taskDetail =
+            `megolm keys for ${session.sessionId} ` +
+            `in ${this._roomId} (slice ${i + 1}/${userDeviceMaps.length})`;
         try {
+            logger.debug(`Sharing ${taskDetail}`);
             await this._encryptAndSendKeysToDevices(
                 session, key.chain_index, userDeviceMaps[i], payload,
             );
-            logger.log(`Completed megolm keyshare for ${session.sessionId} `
-                + `in ${this._roomId} (slice ${i + 1}/${userDeviceMaps.length})`);
+            logger.debug(`Shared ${taskDetail}`);
         } catch (e) {
-            logger.log(`megolm keyshare for ${session.sessionId} in ${this._roomId} `
-                + `(slice ${i + 1}/${userDeviceMaps.length}) failed`);
-
+            logger.error(`Failed to share ${taskDetail}`);
             throw e;
         }
     }
diff --git a/src/crypto/olmlib.js b/src/crypto/olmlib.js
index dbdf07dba..f55a9122e 100644
--- a/src/crypto/olmlib.js
+++ b/src/crypto/olmlib.js
@@ -277,16 +277,29 @@ export async function ensureOlmSessionsForDevices(
 
     const oneTimeKeyAlgorithm = "signed_curve25519";
     let res;
+    let taskDetail = `one-time keys for ${devicesWithoutSession.length} devices`;
+    // If your homeserver takes a nap here and never replies, this process
+    // would hang indefinitely. While that's easily fixed by setting a
+    // timeout on this request, let's first log whether that's the root
+    // cause we're seeing in practice.
+    // See also https://github.com/vector-im/element-web/issues/16194
+    const otkTimeoutLogger = setTimeout(() => {
+        logger.error(`Homeserver never replied while claiming ${taskDetail}`);
+    }, otkTimeout);
     try {
+        logger.debug(`Claiming ${taskDetail}`);
         res = await baseApis.claimOneTimeKeys(
             devicesWithoutSession, oneTimeKeyAlgorithm, otkTimeout,
         );
+        logger.debug(`Claimed ${taskDetail}`);
     } catch (e) {
         for (const resolver of Object.values(resolveSession)) {
             resolver.resolve();
         }
-        logger.log("failed to claim one-time keys", e, devicesWithoutSession);
+        logger.log(`Failed to claim ${taskDetail}`, e, devicesWithoutSession);
         throw e;
+    } finally {
+        clearTimeout(otkTimeoutLogger);
     }
 
     if (failedServers && "failures" in res) {
@@ -350,7 +363,10 @@ export async function ensureOlmSessionsForDevices(
         }
     }
 
+    taskDetail = `Olm sessions for ${promises.length} devices`;
+    logger.debug(`Starting ${taskDetail}`);
     await Promise.all(promises);
+    logger.debug(`Started ${taskDetail}`);
     return result;
 }