Add logging to in progress Olm sessions

It seems like this might be where
element-hq/element-web#16194 is deadlocking.

Author: jryans

src/crypto/OlmDevice.js

@@ -621,8 +621,10 @@ OlmDevice.prototype.createInboundSession = async function(
  * @return {Promise<string[]>}  a list of known session ids for the device
  */
 OlmDevice.prototype.getSessionIdsForDevice = async function(theirDeviceIdentityKey) {
+    const log = getPrefixedLogger("[getSessionIdsForDevice]");
+
     if (this._sessionsInProgress[theirDeviceIdentityKey]) {
-        logger.log("waiting for olm session to be created");
+        log.debug(`Waiting for Olm session for ${theirDeviceIdentityKey} to be created`);
         try {
             await this._sessionsInProgress[theirDeviceIdentityKey];
         } catch (e) {
@@ -640,7 +642,7 @@ OlmDevice.prototype.getSessionIdsForDevice = async function(theirDeviceIdentityK
                 },
             );
         },
-        getPrefixedLogger("[getSessionIdsForDevice]"),
+        log,
     );
 
     return sessionIds;
@@ -703,8 +705,10 @@ OlmDevice.prototype.getSessionIdForDevice = async function(
  * @return {Array.<{sessionId: string, hasReceivedMessage: Boolean}>}
  */
 OlmDevice.prototype.getSessionInfoForDevice = async function(deviceIdentityKey, nowait) {
+    const log = getPrefixedLogger("[getSessionInfoForDevice]");
+
     if (this._sessionsInProgress[deviceIdentityKey] && !nowait) {
-        logger.log("waiting for olm session to be created");
+        log.debug(`Waiting for Olm session for ${deviceIdentityKey} to be created`);
         try {
             await this._sessionsInProgress[deviceIdentityKey];
         } catch (e) {
@@ -730,7 +734,7 @@ OlmDevice.prototype.getSessionInfoForDevice = async function(deviceIdentityKey,
                 }
             });
         },
-        getPrefixedLogger("[getSessionInfoForDevice]"),
+        log,
     );
 
     return info;

src/crypto/olmlib.js

@@ -232,18 +232,23 @@ export async function ensureOlmSessionsForDevices(
                 continue;
             }
 
+            const forWhom = `for ${key} (${userId}:${deviceId})`;
+            log.debug(`Ensuring Olm session ${forWhom}`);
             if (!olmDevice._sessionsInProgress[key]) {
                 // pre-emptively mark the session as in-progress to avoid race
                 // conditions.  If we find that we already have a session, then
                 // we'll resolve
+                log.debug(`Marking Olm session in progress ${forWhom}`);
                 olmDevice._sessionsInProgress[key] = new Promise(
                     (resolve, reject) => {
                         resolveSession[key] = {
                             resolve: (...args) => {
+                                log.debug(`Resolved Olm session in progress ${forWhom}`);
                                 delete olmDevice._sessionsInProgress[key];
                                 resolve(...args);
                             },
                             reject: (...args) => {
+                                log.debug(`Rejected Olm session in progress ${forWhom}`);
                                 delete olmDevice._sessionsInProgress[key];
                                 reject(...args);
                             },
@@ -254,6 +259,7 @@ export async function ensureOlmSessionsForDevices(
             const sessionId = await olmDevice.getSessionIdForDevice(
                 key, resolveSession[key],
             );
+            log.debug(`Got Olm session ${sessionId} ${forWhom}`);
             if (sessionId !== null && resolveSession[key]) {
                 // we found a session, but we had marked the session as
                 // in-progress, so unmark it and unblock anything that was
@@ -264,9 +270,9 @@ export async function ensureOlmSessionsForDevices(
             }
             if (sessionId === null || force) {
                 if (force) {
-                    log.info(`Forcing new Olm session for ${userId}:${deviceId}`);
+                    log.info(`Forcing new Olm session ${forWhom}`);
                 } else {
-                    log.info(`Making new Olm session for ${userId}:${deviceId}`);
+                    log.info(`Making new Olm session ${forWhom}`);
                 }
                 devicesWithoutSession.push([userId, deviceId]);
             }