Merge pull request #1621 from matrix-org/jryans/megolm-logs-2021-02-26

Add logging to in progress Olm sessions

src/crypto/OlmDevice.js

@@ -16,7 +16,7 @@ See the License for the specific language governing permissions and
 limitations under the License.
 */
 
-import {getPrefixedLogger, logger} from '../logger';
+import {logger} from '../logger';
 import {IndexedDBCryptoStore} from './store/indexeddb-crypto-store';
 import * as algorithms from './algorithms';
 
@@ -545,7 +545,7 @@ OlmDevice.prototype.createOutboundSession = async function(
                 }
             });
         },
-        getPrefixedLogger("[createOutboundSession]"),
+        logger.withPrefix("[createOutboundSession]"),
     );
     return newSessionId;
 };
@@ -606,7 +606,7 @@ OlmDevice.prototype.createInboundSession = async function(
                 }
             });
         },
-        getPrefixedLogger("[createInboundSession]"),
+        logger.withPrefix("[createInboundSession]"),
     );
 
     return result;
@@ -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 = logger.withPrefix("[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;
@@ -654,13 +656,14 @@ OlmDevice.prototype.getSessionIdsForDevice = async function(theirDeviceIdentityK
  * @param {boolean} nowait Don't wait for an in-progress session to complete.
  *     This should only be set to true of the calling function is the function
  *     that marked the session as being in-progress.
+ * @param {Logger} [log] A possibly customised log
  * @return {Promise<?string>}  session id, or null if no established session
  */
 OlmDevice.prototype.getSessionIdForDevice = async function(
-    theirDeviceIdentityKey, nowait,
+    theirDeviceIdentityKey, nowait, log,
 ) {
     const sessionInfos = await this.getSessionInfoForDevice(
-        theirDeviceIdentityKey, nowait,
+        theirDeviceIdentityKey, nowait, log,
     );
 
     if (sessionInfos.length === 0) {
@@ -700,11 +703,16 @@ OlmDevice.prototype.getSessionIdForDevice = async function(
  * @param {boolean} nowait Don't wait for an in-progress session to complete.
  *     This should only be set to true of the calling function is the function
  *     that marked the session as being in-progress.
+ * @param {Logger} [log] A possibly customised log
  * @return {Array.<{sessionId: string, hasReceivedMessage: Boolean}>}
  */
-OlmDevice.prototype.getSessionInfoForDevice = async function(deviceIdentityKey, nowait) {
+OlmDevice.prototype.getSessionInfoForDevice = async function(
+    deviceIdentityKey, nowait, log = logger,
+) {
+    log = log.withPrefix("[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 +738,7 @@ OlmDevice.prototype.getSessionInfoForDevice = async function(deviceIdentityKey,
                 }
             });
         },
-        getPrefixedLogger("[getSessionInfoForDevice]"),
+        log,
     );
 
     return info;
@@ -765,7 +773,7 @@ OlmDevice.prototype.encryptMessage = async function(
                 this._saveSession(theirDeviceIdentityKey, sessionInfo, txn);
             });
         },
-        getPrefixedLogger("[encryptMessage]"),
+        logger.withPrefix("[encryptMessage]"),
     );
     return res;
 };
@@ -799,7 +807,7 @@ OlmDevice.prototype.decryptMessage = async function(
                 this._saveSession(theirDeviceIdentityKey, sessionInfo, txn);
             });
         },
-        getPrefixedLogger("[decryptMessage]"),
+        logger.withPrefix("[decryptMessage]"),
     );
     return payloadString;
 };
@@ -831,7 +839,7 @@ OlmDevice.prototype.matchesSession = async function(
                 matches = sessionInfo.session.matches_inbound(ciphertext);
             });
         },
-        getPrefixedLogger("[matchesSession]"),
+        logger.withPrefix("[matchesSession]"),
     );
     return matches;
 };
@@ -1102,7 +1110,7 @@ OlmDevice.prototype.addInboundGroupSession = async function(
                 },
             );
         },
-        getPrefixedLogger("[addInboundGroupSession]"),
+        logger.withPrefix("[addInboundGroupSession]"),
     );
 };
 
@@ -1273,7 +1281,7 @@ OlmDevice.prototype.decryptGroupMessage = async function(
                 },
             );
         },
-        getPrefixedLogger("[decryptGroupMessage]"),
+        logger.withPrefix("[decryptGroupMessage]"),
     );
 
     if (error) {
@@ -1319,7 +1327,7 @@ OlmDevice.prototype.hasInboundSessionKeys = async function(roomId, senderKey, se
                 },
             );
         },
-        getPrefixedLogger("[hasInboundSessionKeys]"),
+        logger.withPrefix("[hasInboundSessionKeys]"),
     );
 
     return result;
@@ -1379,7 +1387,7 @@ OlmDevice.prototype.getInboundGroupSessionKey = async function(
                 },
             );
         },
-        getPrefixedLogger("[getInboundGroupSessionKey]"),
+        logger.withPrefix("[getInboundGroupSessionKey]"),
     );
 
     return result;

src/crypto/algorithms/megolm.js

@@ -22,7 +22,7 @@ limitations under the License.
  * @module crypto/algorithms/megolm
  */
 
-import {getPrefixedLogger, logger} from '../../logger';
+import {logger} from '../../logger';
 import * as utils from "../../utils";
 import {polyfillSuper} from "../../utils";
 import * as olmlib from "../olmlib";
@@ -736,7 +736,7 @@ MegolmEncryption.prototype._shareKeyWithDevices = async function(
     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.withPrefix(`[${this._roomId}]`),
     );
     logger.debug(`Ensured Olm sessions for devices in ${this._roomId}`);
 

src/crypto/olmlib.js

@@ -183,7 +183,7 @@ 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
+ * @param {Logger} [log] A possibly customised log
  *
  * @return {Promise} resolves once the sessions are complete, to
  *    an Object mapping from userId to deviceId to
@@ -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);
                             },
@@ -252,8 +257,9 @@ export async function ensureOlmSessionsForDevices(
                 );
             }
             const sessionId = await olmDevice.getSessionIdForDevice(
-                key, resolveSession[key],
+                key, resolveSession[key], log,
             );
+            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]);
             }

src/crypto/store/indexeddb-crypto-store.js

@@ -596,7 +596,7 @@ export class IndexedDBCryptoStore {
      * @param {function(*)} func Function called with the
      *     transaction object: an opaque object that should be passed
      *     to store functions.
-     * @param {object} [log] A possibly customised log
+     * @param {Logger} [log] A possibly customised log
      * @return {Promise} Promise that resolves with the result of the `func`
      *     when the transaction is complete. If the backend is
      *     async (ie. the indexeddb backend) any of the callback

src/logger.ts

@@ -59,17 +59,28 @@ log.methodFactory = function(methodName, logLevel, loggerName) {
  * Drop-in replacement for <code>console</code> using {@link https://www.npmjs.com/package/loglevel|loglevel}.
  * Can be tailored down to specific use cases if needed.
  */
-export const logger = log.getLogger(DEFAULT_NAMESPACE);
+export const logger: PrefixedLogger = log.getLogger(DEFAULT_NAMESPACE);
 logger.setLevel(log.levels.DEBUG);
 
 interface PrefixedLogger extends Logger {
-    prefix?: any;
+    withPrefix?: (prefix: string) => PrefixedLogger;
+    prefix?: string;
 }
 
-export function getPrefixedLogger(prefix): PrefixedLogger {
+function extendLogger(logger: PrefixedLogger) {
+    logger.withPrefix = function(prefix: string): PrefixedLogger {
+        const existingPrefix = this.prefix || "";
+        return getPrefixedLogger(existingPrefix + prefix);
+    };
+}
+
+extendLogger(logger);
+
+function getPrefixedLogger(prefix): PrefixedLogger {
     const prefixLogger: PrefixedLogger = log.getLogger(`${DEFAULT_NAMESPACE}-${prefix}`);
     if (prefixLogger.prefix !== prefix) {
         // Only do this setup work the first time through, as loggers are saved by name.
+        extendLogger(prefixLogger);
         prefixLogger.prefix = prefix;
         prefixLogger.setLevel(log.levels.DEBUG);
     }