diff --git a/src/crypto/algorithms/megolm.js b/src/crypto/algorithms/megolm.js index 0fa3d046d..66694bedf 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 {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}`, + ); }; /** diff --git a/src/crypto/olmlib.js b/src/crypto/olmlib.js index f55a9122e..f21bd5db4 100644 --- a/src/crypto/olmlib.js +++ b/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 + - ") for device " + userId + ":" + deviceId; - logger.warn(msg); + log.warn( + `No one-time keys (alg=${oneTimeKeyAlgorithm}) ` + + `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; } diff --git a/src/logger.ts b/src/logger.ts index fc5ceeb4d..ad455b19f 100644 --- a/src/logger.ts +++ b/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; +}