From 198c9a2507dae8f7d82fe6d039fb9cb02cd88a76 Mon Sep 17 00:00:00 2001 From: "J. Ryan Stinnett" Date: Fri, 26 Feb 2021 17:27:06 +0000 Subject: [PATCH 1/3] Add logging to in progress Olm sessions It seems like this might be where https://github.com/vector-im/element-web/issues/16194 is deadlocking. --- src/crypto/OlmDevice.js | 12 ++++++++---- src/crypto/olmlib.js | 10 ++++++++-- 2 files changed, 16 insertions(+), 6 deletions(-) diff --git a/src/crypto/OlmDevice.js b/src/crypto/OlmDevice.js index 625586320..eed0a0833 100644 --- a/src/crypto/OlmDevice.js +++ b/src/crypto/OlmDevice.js @@ -621,8 +621,10 @@ OlmDevice.prototype.createInboundSession = async function( * @return {Promise} 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; diff --git a/src/crypto/olmlib.js b/src/crypto/olmlib.js index f21bd5db4..b11af14d7 100644 --- a/src/crypto/olmlib.js +++ b/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]); } From e217bf9e373eedefe700e758a3f96deb2bc0a6ea Mon Sep 17 00:00:00 2001 From: "J. Ryan Stinnett" Date: Fri, 26 Feb 2021 17:47:52 +0000 Subject: [PATCH 2/3] Enable prefixed loggers to chain --- src/crypto/OlmDevice.js | 24 ++++++++++++------------ src/crypto/algorithms/megolm.js | 4 ++-- src/logger.ts | 16 +++++++++++++--- 3 files changed, 27 insertions(+), 17 deletions(-) diff --git a/src/crypto/OlmDevice.js b/src/crypto/OlmDevice.js index eed0a0833..cd04f785f 100644 --- a/src/crypto/OlmDevice.js +++ b/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,7 +621,7 @@ OlmDevice.prototype.createInboundSession = async function( * @return {Promise} a list of known session ids for the device */ OlmDevice.prototype.getSessionIdsForDevice = async function(theirDeviceIdentityKey) { - const log = getPrefixedLogger("[getSessionIdsForDevice]"); + const log = logger.withPrefix("[getSessionIdsForDevice]"); if (this._sessionsInProgress[theirDeviceIdentityKey]) { log.debug(`Waiting for Olm session for ${theirDeviceIdentityKey} to be created`); @@ -705,7 +705,7 @@ OlmDevice.prototype.getSessionIdForDevice = async function( * @return {Array.<{sessionId: string, hasReceivedMessage: Boolean}>} */ OlmDevice.prototype.getSessionInfoForDevice = async function(deviceIdentityKey, nowait) { - const log = getPrefixedLogger("[getSessionInfoForDevice]"); + const log = logger.withPrefix("[getSessionInfoForDevice]"); if (this._sessionsInProgress[deviceIdentityKey] && !nowait) { log.debug(`Waiting for Olm session for ${deviceIdentityKey} to be created`); @@ -769,7 +769,7 @@ OlmDevice.prototype.encryptMessage = async function( this._saveSession(theirDeviceIdentityKey, sessionInfo, txn); }); }, - getPrefixedLogger("[encryptMessage]"), + logger.withPrefix("[encryptMessage]"), ); return res; }; @@ -803,7 +803,7 @@ OlmDevice.prototype.decryptMessage = async function( this._saveSession(theirDeviceIdentityKey, sessionInfo, txn); }); }, - getPrefixedLogger("[decryptMessage]"), + logger.withPrefix("[decryptMessage]"), ); return payloadString; }; @@ -835,7 +835,7 @@ OlmDevice.prototype.matchesSession = async function( matches = sessionInfo.session.matches_inbound(ciphertext); }); }, - getPrefixedLogger("[matchesSession]"), + logger.withPrefix("[matchesSession]"), ); return matches; }; @@ -1106,7 +1106,7 @@ OlmDevice.prototype.addInboundGroupSession = async function( }, ); }, - getPrefixedLogger("[addInboundGroupSession]"), + logger.withPrefix("[addInboundGroupSession]"), ); }; @@ -1277,7 +1277,7 @@ OlmDevice.prototype.decryptGroupMessage = async function( }, ); }, - getPrefixedLogger("[decryptGroupMessage]"), + logger.withPrefix("[decryptGroupMessage]"), ); if (error) { @@ -1323,7 +1323,7 @@ OlmDevice.prototype.hasInboundSessionKeys = async function(roomId, senderKey, se }, ); }, - getPrefixedLogger("[hasInboundSessionKeys]"), + logger.withPrefix("[hasInboundSessionKeys]"), ); return result; @@ -1383,7 +1383,7 @@ OlmDevice.prototype.getInboundGroupSessionKey = async function( }, ); }, - getPrefixedLogger("[getInboundGroupSessionKey]"), + logger.withPrefix("[getInboundGroupSessionKey]"), ); return result; diff --git a/src/crypto/algorithms/megolm.js b/src/crypto/algorithms/megolm.js index 66694bedf..7ea048d2b 100644 --- a/src/crypto/algorithms/megolm.js +++ b/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}`); diff --git a/src/logger.ts b/src/logger.ts index 8357c70c0..4a6b96158 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -59,17 +59,27 @@ log.methodFactory = function(methodName, logLevel, loggerName) { * Drop-in replacement for console 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) { + return getPrefixedLogger(this.prefix + 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); } From 8152fa44e099a10ce354250b096b926b789924e8 Mon Sep 17 00:00:00 2001 From: "J. Ryan Stinnett" Date: Fri, 26 Feb 2021 17:53:39 +0000 Subject: [PATCH 3/3] Add more logging scopes to session IDs This uses prefix chaining to correlate several scopes together. --- src/crypto/OlmDevice.js | 12 ++++++++---- src/crypto/olmlib.js | 4 ++-- src/crypto/store/indexeddb-crypto-store.js | 2 +- src/logger.ts | 5 +++-- 4 files changed, 14 insertions(+), 9 deletions(-) diff --git a/src/crypto/OlmDevice.js b/src/crypto/OlmDevice.js index cd04f785f..0989d19f3 100644 --- a/src/crypto/OlmDevice.js +++ b/src/crypto/OlmDevice.js @@ -656,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} 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) { @@ -702,10 +703,13 @@ 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) { - const log = logger.withPrefix("[getSessionInfoForDevice]"); +OlmDevice.prototype.getSessionInfoForDevice = async function( + deviceIdentityKey, nowait, log = logger, +) { + log = log.withPrefix("[getSessionInfoForDevice]"); if (this._sessionsInProgress[deviceIdentityKey] && !nowait) { log.debug(`Waiting for Olm session for ${deviceIdentityKey} to be created`); diff --git a/src/crypto/olmlib.js b/src/crypto/olmlib.js index b11af14d7..c4e3278cf 100644 --- a/src/crypto/olmlib.js +++ b/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 @@ -257,7 +257,7 @@ 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]) { diff --git a/src/crypto/store/indexeddb-crypto-store.js b/src/crypto/store/indexeddb-crypto-store.js index 217c5e621..50f3c2678 100644 --- a/src/crypto/store/indexeddb-crypto-store.js +++ b/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 diff --git a/src/logger.ts b/src/logger.ts index 4a6b96158..e5fced726 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -68,8 +68,9 @@ interface PrefixedLogger extends Logger { } function extendLogger(logger: PrefixedLogger) { - logger.withPrefix = function(prefix: string) { - return getPrefixedLogger(this.prefix + prefix); + logger.withPrefix = function(prefix: string): PrefixedLogger { + const existingPrefix = this.prefix || ""; + return getPrefixedLogger(existingPrefix + prefix); }; }