Add debug logs to encryption prep, take 3

This continues adding more logs to work out the root cause of
https://github.com/vector-im/element-web/issues/16194.

Somehow, we're getting stuck while sharing keys with new sessions.

src/crypto/algorithms/megolm.js

@@ -22,7 +22,7 @@ limitations under the License.
  * @module crypto/algorithms/megolm
  */
 
-import {logger} from '../../logger';
+import {getPrefixedLogger, logger} from '../../logger';
 import * as utils from "../../utils";
 import {polyfillSuper} from "../../utils";
 import * as olmlib from "../olmlib";
@@ -271,7 +271,7 @@ MegolmEncryption.prototype._ensureOutboundSession = async function(
                 logger.debug(`Shared keys with existing Olm sessions in ${this._roomId}`);
             })(),
             (async () => {
-                logger.debug(`Sharing keys with new Olm sessions in ${this._roomId}`);
+                logger.debug(`Sharing keys (start phase 1) with new Olm sessions in ${this._roomId}`);
                 const errorDevices = [];
 
                 // meanwhile, establish olm sessions for devices that we don't
@@ -285,6 +285,7 @@ MegolmEncryption.prototype._ensureOutboundSession = async function(
                     session, key, payload, devicesWithoutSession, errorDevices,
                     singleOlmCreationPhase ? 10000 : 2000, failedServers,
                 );
+                logger.debug(`Shared keys (end phase 1) with new Olm sessions in ${this._roomId}`);
 
                 if (!singleOlmCreationPhase && (Date.now() - start < 10000)) {
                     // perform the second phase of olm session creation if requested,
@@ -313,21 +314,24 @@ MegolmEncryption.prototype._ensureOutboundSession = async function(
                             }
                         }
 
+                        logger.debug(`Sharing keys (start phase 2) with new Olm sessions in ${this._roomId}`);
                         await this._shareKeyWithDevices(
                             session, key, payload, retryDevices, failedDevices, 30000,
                         );
+                        logger.debug(`Shared keys (end phase 2) with new Olm sessions in ${this._roomId}`);
 
                         await this._notifyFailedOlmDevices(session, key, failedDevices);
                     })();
                 } else {
                     await this._notifyFailedOlmDevices(session, key, errorDevices);
                 }
-                logger.debug(`Shared keys with new Olm sessions in ${this._roomId}`);
+                logger.debug(`Shared keys (all phases done) with new Olm sessions in ${this._roomId}`);
             })(),
             (async () => {
                 logger.debug(`Notifying blocked devices in ${this._roomId}`);
                 // also, notify blocked devices that they're blocked
                 const blockedMap = {};
+                let blockedCount = 0;
                 for (const [userId, userBlockedDevices] of Object.entries(blocked)) {
                     for (const [deviceId, device] of Object.entries(userBlockedDevices)) {
                         if (
@@ -335,13 +339,14 @@ MegolmEncryption.prototype._ensureOutboundSession = async function(
                             session.blockedDevicesNotified[userId][deviceId] === undefined
                         ) {
                             blockedMap[userId] = blockedMap[userId] || {};
-                            blockedMap[userId][deviceId] = {device};
+                            blockedMap[userId][deviceId] = { device };
+                            blockedCount++;
                         }
                     }
                 }
 
                 await this._notifyBlockedDevices(session, blockedMap);
-                logger.debug(`Notified blocked devices in ${this._roomId}`);
+                logger.debug(`Notified ${blockedCount} blocked devices in ${this._roomId}`);
             })(),
         ]);
     };
@@ -728,13 +733,18 @@ MegolmEncryption.prototype.reshareKeyWithDevice = async function(
 MegolmEncryption.prototype._shareKeyWithDevices = async function(
     session, key, payload, devicesByUser, errorDevices, otkTimeout, failedServers,
 ) {
+    logger.debug(`Ensuring Olm sessions for devices in ${this._roomId}`);
     const devicemap = await olmlib.ensureOlmSessionsForDevices(
         this._olmDevice, this._baseApis, devicesByUser, otkTimeout, failedServers,
+        getPrefixedLogger(`[${this._roomId}]`),
     );
+    logger.debug(`Ensured Olm sessions for devices in ${this._roomId}`);
 
     this._getDevicesWithoutSessions(devicemap, devicesByUser, errorDevices);
 
+    logger.debug(`Sharing keys with Olm sessions in ${this._roomId}`);
     await this._shareKeyWithOlmSessions(session, key, payload, devicemap);
+    logger.debug(`Shared keys with Olm sessions in ${this._roomId}`);
 };
 
 MegolmEncryption.prototype._shareKeyWithOlmSessions = async function(
@@ -772,6 +782,11 @@ MegolmEncryption.prototype._shareKeyWithOlmSessions = async function(
 MegolmEncryption.prototype._notifyFailedOlmDevices = async function(
     session, key, failedDevices,
 ) {
+    logger.debug(
+        `Notifying ${failedDevices.length} devices we failed to ` +
+        `create Olm sessions in ${this._roomId}`,
+    );
+
     // mark the devices that failed as "handled" because we don't want to try
     // to claim a one-time-key for dead devices on every message.
     for (const {userId, deviceInfo} of failedDevices) {
@@ -786,6 +801,10 @@ MegolmEncryption.prototype._notifyFailedOlmDevices = async function(
           await this._olmDevice.filterOutNotifiedErrorDevices(
               failedDevices,
           );
+    logger.debug(
+        `Filtered down to ${filteredFailedDevices.length} error devices ` +
+        `in ${this._roomId}`,
+    );
     const blockedMap = {};
     for (const {userId, deviceInfo} of filteredFailedDevices) {
         blockedMap[userId] = blockedMap[userId] || {};
@@ -803,6 +822,10 @@ MegolmEncryption.prototype._notifyFailedOlmDevices = async function(
 
     // send the notifications
     await this._notifyBlockedDevices(session, blockedMap);
+    logger.debug(
+        `Notified ${filteredFailedDevices.length} devices we failed to ` +
+        `create Olm sessions in ${this._roomId}`,
+    );
 };
 
 /**

src/crypto/olmlib.js

@@ -183,18 +183,24 @@ export async function getExistingOlmSessions(
  * @param {Array} [failedServers] An array to fill with remote servers that
  *     failed to respond to one-time-key requests.
  *
+ * @param {Object} [log] A possibly customised log
+ *
  * @return {Promise} resolves once the sessions are complete, to
  *    an Object mapping from userId to deviceId to
  *    {@link module:crypto~OlmSessionResult}
  */
 export async function ensureOlmSessionsForDevices(
-    olmDevice, baseApis, devicesByUser, force, otkTimeout, failedServers,
+    olmDevice, baseApis, devicesByUser, force, otkTimeout, failedServers, log,
 ) {
     if (typeof force === "number") {
+        log = failedServers;
         failedServers = otkTimeout;
         otkTimeout = force;
         force = false;
     }
+    if (!log) {
+        log = logger;
+    }
 
     const devicesWithoutSession = [
         // [userId, deviceId], ...
@@ -216,7 +222,7 @@ export async function ensureOlmSessionsForDevices(
                 // new chain when this side has an active sender chain.
                 // If you see this message being logged in the wild, we should find
                 // the thing that is trying to send Olm messages to itself and fix it.
-                logger.info("Attempted to start session with ourself! Ignoring");
+                log.info("Attempted to start session with ourself! Ignoring");
                 // We must fill in the section in the return value though, as callers
                 // expect it to be there.
                 result[userId][deviceId] = {
@@ -258,9 +264,9 @@ export async function ensureOlmSessionsForDevices(
             }
             if (sessionId === null || force) {
                 if (force) {
-                    logger.info("Forcing new Olm session for " + userId + ":" + deviceId);
+                    log.info(`Forcing new Olm session for ${userId}:${deviceId}`);
                 } else {
-                    logger.info("Making new Olm session for " + userId + ":" + deviceId);
+                    log.info(`Making new Olm session for ${userId}:${deviceId}`);
                 }
                 devicesWithoutSession.push([userId, deviceId]);
             }
@@ -284,19 +290,19 @@ export async function ensureOlmSessionsForDevices(
     // 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}`);
+        log.error(`Homeserver never replied while claiming ${taskDetail}`);
     }, otkTimeout);
     try {
-        logger.debug(`Claiming ${taskDetail}`);
+        log.debug(`Claiming ${taskDetail}`);
         res = await baseApis.claimOneTimeKeys(
             devicesWithoutSession, oneTimeKeyAlgorithm, otkTimeout,
         );
-        logger.debug(`Claimed ${taskDetail}`);
+        log.debug(`Claimed ${taskDetail}`);
     } catch (e) {
         for (const resolver of Object.values(resolveSession)) {
             resolver.resolve();
         }
-        logger.log(`Failed to claim ${taskDetail}`, e, devicesWithoutSession);
+        log.log(`Failed to claim ${taskDetail}`, e, devicesWithoutSession);
         throw e;
     } finally {
         clearTimeout(otkTimeoutLogger);
@@ -336,9 +342,10 @@ export async function ensureOlmSessionsForDevices(
             }
 
             if (!oneTimeKey) {
-                const msg = "No one-time keys (alg=" + oneTimeKeyAlgorithm +
+                log.warn(
-                      ") for device " + userId + ":" + deviceId;
+                    `No one-time keys (alg=${oneTimeKeyAlgorithm}) ` +
-                logger.warn(msg);
+                    `for device ${userId}:${deviceId}`,
+                );
                 if (resolveSession[key]) {
                     resolveSession[key].resolve();
                 }
@@ -364,9 +371,9 @@ export async function ensureOlmSessionsForDevices(
     }
 
     taskDetail = `Olm sessions for ${promises.length} devices`;
-    logger.debug(`Starting ${taskDetail}`);
+    log.debug(`Starting ${taskDetail}`);
     await Promise.all(promises);
-    logger.debug(`Started ${taskDetail}`);
+    log.debug(`Started ${taskDetail}`);
     return result;
 }
 

src/logger.ts

@@ -1,6 +1,6 @@
 /*
 Copyright 2018 André Jaenisch
-Copyright 2019 The Matrix.org Foundation C.I.C.
+Copyright 2019, 2021 The Matrix.org Foundation C.I.C.
 
 Licensed under the Apache License, Version 2.0 (the "License");
 you may not use this file except in compliance with the License.
@@ -19,7 +19,7 @@ limitations under the License.
  * @module logger
  */
 
-import log from "loglevel";
+import log, { Logger } from "loglevel";
 
 // This is to demonstrate, that you can use any namespace you want.
 // Namespaces allow you to turn on/off the logging for specific parts of the
@@ -36,6 +36,11 @@ const DEFAULT_NAMESPACE = "matrix";
 // when logging so we always get the current value of console methods.
 log.methodFactory = function(methodName, logLevel, loggerName) {
     return function(...args) {
+        /* eslint-disable babel/no-invalid-this */
+        if (this.prefix) {
+            args.unshift(this.prefix);
+        }
+        /* eslint-enable babel/no-invalid-this */
         const supportedByConsole = methodName === "error" ||
             methodName === "warn" ||
             methodName === "trace" ||
@@ -57,3 +62,13 @@ log.methodFactory = function(methodName, logLevel, loggerName) {
 export const logger = log.getLogger(DEFAULT_NAMESPACE);
 logger.setLevel(log.levels.DEBUG);
 
+interface PrefixedLogger extends Logger {
+    prefix?: any;
+}
+
+export function getPrefixedLogger(prefix): PrefixedLogger {
+    const prefixLogger: PrefixedLogger = log.getLogger(`${DEFAULT_NAMESPACE}-${prefix}`);
+    prefixLogger.prefix = prefix;
+    prefixLogger.setLevel(log.levels.DEBUG);
+    return prefixLogger;
+}