From 223dfffdfbb63e04abcb6e886f9027b05bfa3bbe Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Mon, 9 Oct 2023 14:06:16 +0100 Subject: [PATCH] Define a new `Logger` interface (#3789) * rename loglevel import to loglevel * Define new `Logger` interface to replace `PrefixedLogger` * PrefixedLogger -> Logger in crypto store * PrefixedLogger -> Logger in `src/crypto` * PrefixedLogger -> Logger in rust-crypto --- spec/unit/crypto.spec.ts | 2 +- src/crypto/OlmDevice.ts | 30 +++---- src/crypto/algorithms/megolm.ts | 36 ++++---- src/crypto/olmlib.ts | 6 +- src/crypto/store/base.ts | 4 +- .../store/indexeddb-crypto-store-backend.ts | 4 +- src/crypto/store/indexeddb-crypto-store.ts | 9 +- src/logger.ts | 83 +++++++++++++++---- src/rust-crypto/RoomEncryptor.ts | 6 +- 9 files changed, 115 insertions(+), 65 deletions(-) diff --git a/spec/unit/crypto.spec.ts b/spec/unit/crypto.spec.ts index 748a20cbe..17c7bc4f8 100644 --- a/spec/unit/crypto.spec.ts +++ b/spec/unit/crypto.spec.ts @@ -1106,7 +1106,7 @@ describe("Crypto", function () { describe("Secret storage", function () { it("creates secret storage even if there is no keyInfo", async function () { - jest.spyOn(logger, "log").mockImplementation(() => {}); + jest.spyOn(logger, "debug").mockImplementation(() => {}); jest.setTimeout(10000); const client = new TestClient("@a:example.com", "dev").client; await client.initCrypto(); diff --git a/src/crypto/OlmDevice.ts b/src/crypto/OlmDevice.ts index e0f070db9..45706d91c 100644 --- a/src/crypto/OlmDevice.ts +++ b/src/crypto/OlmDevice.ts @@ -16,7 +16,7 @@ limitations under the License. import { Account, InboundGroupSession, OutboundGroupSession, Session, Utility } from "@matrix-org/olm"; -import { logger, PrefixedLogger } from "../logger"; +import { logger, Logger } from "../logger"; import { IndexedDBCryptoStore } from "./store/indexeddb-crypto-store"; import * as algorithms from "./algorithms"; import { CryptoStore, IProblem, ISessionInfo, IWithheld } from "./store/base"; @@ -531,7 +531,7 @@ export class OlmDevice { } }); }, - logger.withPrefix("[createOutboundSession]"), + logger.getChild("[createOutboundSession]"), ); return newSessionId!; } @@ -588,7 +588,7 @@ export class OlmDevice { } }); }, - logger.withPrefix("[createInboundSession]"), + logger.getChild("[createInboundSession]"), ); return result!; @@ -602,7 +602,7 @@ export class OlmDevice { * @returns a list of known session ids for the device */ public async getSessionIdsForDevice(theirDeviceIdentityKey: string): Promise { - const log = logger.withPrefix("[getSessionIdsForDevice]"); + const log = logger.getChild("[getSessionIdsForDevice]"); if (theirDeviceIdentityKey in this.sessionsInProgress) { log.debug(`Waiting for Olm session for ${theirDeviceIdentityKey} to be created`); @@ -642,7 +642,7 @@ export class OlmDevice { public async getSessionIdForDevice( theirDeviceIdentityKey: string, nowait = false, - log?: PrefixedLogger, + log?: Logger, ): Promise { const sessionInfos = await this.getSessionInfoForDevice(theirDeviceIdentityKey, nowait, log); @@ -686,9 +686,9 @@ export class OlmDevice { public async getSessionInfoForDevice( deviceIdentityKey: string, nowait = false, - log = logger, + log: Logger = logger, ): Promise<{ sessionId: string; lastReceivedMessageTs: number; hasReceivedMessage: boolean }[]> { - log = log.withPrefix("[getSessionInfoForDevice]"); + log = log.getChild("[getSessionInfoForDevice]"); if (deviceIdentityKey in this.sessionsInProgress && !nowait) { log.debug(`Waiting for Olm session for ${deviceIdentityKey} to be created`); @@ -764,7 +764,7 @@ export class OlmDevice { this.saveSession(theirDeviceIdentityKey, sessionInfo, txn); }); }, - logger.withPrefix("[encryptMessage]"), + logger.getChild("[encryptMessage]"), ); return res!; } @@ -806,7 +806,7 @@ export class OlmDevice { this.saveSession(theirDeviceIdentityKey, sessionInfo, txn); }); }, - logger.withPrefix("[decryptMessage]"), + logger.getChild("[decryptMessage]"), ); return payloadString!; } @@ -842,7 +842,7 @@ export class OlmDevice { matches = sessionInfo.session.matches_inbound(ciphertext); }); }, - logger.withPrefix("[matchesSession]"), + logger.getChild("[matchesSession]"), ); return matches!; } @@ -1142,7 +1142,7 @@ export class OlmDevice { }, ); }, - logger.withPrefix("[addInboundGroupSession]"), + logger.getChild("[addInboundGroupSession]"), ); } @@ -1282,7 +1282,7 @@ export class OlmDevice { }; }); }, - logger.withPrefix("[decryptGroupMessage]"), + logger.getChild("[decryptGroupMessage]"), ); if (error!) { @@ -1328,7 +1328,7 @@ export class OlmDevice { } }); }, - logger.withPrefix("[hasInboundSessionKeys]"), + logger.getChild("[hasInboundSessionKeys]"), ); return result!; @@ -1398,7 +1398,7 @@ export class OlmDevice { }; }); }, - logger.withPrefix("[getInboundGroupSessionKey]"), + logger.getChild("[getInboundGroupSessionKey]"), ); return result; @@ -1443,7 +1443,7 @@ export class OlmDevice { (txn) => { result = this.cryptoStore.getSharedHistoryInboundGroupSessions(roomId, txn); }, - logger.withPrefix("[getSharedHistoryInboundGroupSessionsForRoom]"), + logger.getChild("[getSharedHistoryInboundGroupSessionsForRoom]"), ); return result!; } diff --git a/src/crypto/algorithms/megolm.ts b/src/crypto/algorithms/megolm.ts index 061e169e3..54d9d7fa3 100644 --- a/src/crypto/algorithms/megolm.ts +++ b/src/crypto/algorithms/megolm.ts @@ -21,7 +21,7 @@ limitations under the License. import { v4 as uuidv4 } from "uuid"; import type { IEventDecryptionResult, IMegolmSessionData } from "../../@types/crypto"; -import { logger, PrefixedLogger } from "../../logger"; +import { logger, Logger } from "../../logger"; import * as olmlib from "../olmlib"; import { DecryptionAlgorithm, @@ -246,12 +246,12 @@ export class MegolmEncryption extends EncryptionAlgorithm { }; protected readonly roomId: string; - private readonly prefixedLogger: PrefixedLogger; + private readonly prefixedLogger: Logger; public constructor(params: IParams & Required>) { super(params); this.roomId = params.roomId; - this.prefixedLogger = logger.withPrefix(`[${this.roomId} encryption]`); + this.prefixedLogger = logger.getChild(`[${this.roomId} encryption]`); this.sessionRotationPeriodMsgs = params.config?.rotation_period_msgs ?? 100; this.sessionRotationPeriodMs = params.config?.rotation_period_ms ?? 7 * 24 * 3600 * 1000; @@ -333,7 +333,7 @@ export class MegolmEncryption extends EncryptionAlgorithm { // need to make a brand new session? if (session?.needsRotation(this.sessionRotationPeriodMsgs, this.sessionRotationPeriodMs)) { - this.prefixedLogger.log("Starting new megolm session because we need to rotate."); + this.prefixedLogger.debug("Starting new megolm session because we need to rotate."); session = null; } @@ -343,9 +343,9 @@ export class MegolmEncryption extends EncryptionAlgorithm { } if (!session) { - this.prefixedLogger.log("Starting new megolm session"); + this.prefixedLogger.debug("Starting new megolm session"); session = await this.prepareNewSession(sharedHistory); - this.prefixedLogger.log(`Started new megolm session ${session.sessionId}`); + this.prefixedLogger.debug(`Started new megolm session ${session.sessionId}`); this.outboundSessions[session.sessionId] = session; } @@ -968,12 +968,12 @@ export class MegolmEncryption extends EncryptionAlgorithm { for (let i = 0; i < userDeviceMaps.length; i++) { try { await this.sendBlockedNotificationsToDevices(session, userDeviceMaps[i], payload); - this.prefixedLogger.log( + this.prefixedLogger.debug( `Completed blacklist notification for ${session.sessionId} ` + `(slice ${i + 1}/${userDeviceMaps.length})`, ); } catch (e) { - this.prefixedLogger.log( + this.prefixedLogger.debug( `blacklist notification for ${session.sessionId} ` + `(slice ${i + 1}/${userDeviceMaps.length}) failed`, ); @@ -1054,7 +1054,7 @@ export class MegolmEncryption extends EncryptionAlgorithm { * @returns Promise which resolves to the new event body */ public async encryptMessage(room: Room, eventType: string, content: IContent): Promise { - this.prefixedLogger.log("Starting to encrypt event"); + this.prefixedLogger.debug("Starting to encrypt event"); if (this.encryptionPreparation != null) { // If we started sending keys, wait for it to be done. @@ -1291,12 +1291,12 @@ export class MegolmDecryption extends DecryptionAlgorithm { private olmlib = olmlib; protected readonly roomId: string; - private readonly prefixedLogger: PrefixedLogger; + private readonly prefixedLogger: Logger; public constructor(params: DecryptionClassParams>>) { super(params); this.roomId = params.roomId; - this.prefixedLogger = logger.withPrefix(`[${this.roomId} decryption]`); + this.prefixedLogger = logger.getChild(`[${this.roomId} decryption]`); } /** @@ -1740,7 +1740,7 @@ export class MegolmDecryption extends DecryptionAlgorithm { "readwrite", ["parked_shared_history"], (txn) => this.crypto.cryptoStore.addParkedSharedHistory(roomKey.roomId, parkedData, txn), - logger.withPrefix("[addParkedSharedHistory]"), + logger.getChild("[addParkedSharedHistory]"), ); } @@ -1955,7 +1955,7 @@ export class MegolmDecryption extends DecryptionAlgorithm { return null; } - this.prefixedLogger.log( + this.prefixedLogger.debug( "sharing keys for session " + body.sender_key + "|" + @@ -2051,7 +2051,7 @@ export class MegolmDecryption extends DecryptionAlgorithm { this.crypto.backupManager.backupGroupSession(session.sender_key, session.session_id).catch((e) => { // This throws if the upload failed, but this is fine // since it will have written it to the db and will retry. - this.prefixedLogger.log("Failed to back up megolm session", e); + this.prefixedLogger.debug("Failed to back up megolm session", e); }); } // have another go at decrypting events sent with this session. @@ -2135,7 +2135,7 @@ export class MegolmDecryption extends DecryptionAlgorithm { await olmlib.ensureOlmSessionsForDevices(this.olmDevice, this.baseApis, devicesByUser); const sharedHistorySessions = await this.olmDevice.getSharedHistoryInboundGroupSessions(this.roomId); - this.prefixedLogger.log( + this.prefixedLogger.debug( `Sharing history in with users ${Array.from(devicesByUser.keys())}`, sharedHistorySessions.map(([senderKey, sessionId]) => `${senderKey}|${sessionId}`), ); @@ -2178,20 +2178,20 @@ export class MegolmDecryption extends DecryptionAlgorithm { for (const [userId, deviceMessages] of contentMap) { for (const [deviceId, content] of deviceMessages) { if (!hasCiphertext(content)) { - this.prefixedLogger.log("No ciphertext for device " + userId + ":" + deviceId + ": pruning"); + this.prefixedLogger.debug("No ciphertext for device " + userId + ":" + deviceId + ": pruning"); deviceMessages.delete(deviceId); } } // No devices left for that user? Strip that too. if (deviceMessages.size === 0) { - this.prefixedLogger.log("Pruned all devices for user " + userId); + this.prefixedLogger.debug("Pruned all devices for user " + userId); contentMap.delete(userId); } } // Is there anything left? if (contentMap.size === 0) { - this.prefixedLogger.log("No users left to send to: aborting"); + this.prefixedLogger.debug("No users left to send to: aborting"); return; } diff --git a/src/crypto/olmlib.ts b/src/crypto/olmlib.ts index c37b7f0a4..68b5aa6f0 100644 --- a/src/crypto/olmlib.ts +++ b/src/crypto/olmlib.ts @@ -24,7 +24,7 @@ import type { PkSigning } from "@matrix-org/olm"; import type { IOneTimeKey } from "../@types/crypto"; import { OlmDevice } from "./OlmDevice"; import { DeviceInfo } from "./deviceinfo"; -import { logger } from "../logger"; +import { Logger, logger } from "../logger"; import { IClaimOTKsResult, MatrixClient } from "../client"; import { ISignatures } from "../@types/signed"; import { MatrixEvent } from "../models/event"; @@ -215,7 +215,7 @@ export async function ensureOlmSessionsForDevices( force = false, otkTimeout?: number, failedServers?: string[], - log = logger, + log: Logger = logger, ): Promise>> { const devicesWithoutSession: [string, string][] = [ // [userId, deviceId], ... @@ -319,7 +319,7 @@ export async function ensureOlmSessionsForDevices( for (const resolver of resolveSession.values()) { resolver(); } - log.log(`Failed to claim ${taskDetail}`, e, devicesWithoutSession); + log.debug(`Failed to claim ${taskDetail}`, e, devicesWithoutSession); throw e; } diff --git a/src/crypto/store/base.ts b/src/crypto/store/base.ts index 8657c9392..773e65ed5 100644 --- a/src/crypto/store/base.ts +++ b/src/crypto/store/base.ts @@ -22,7 +22,7 @@ import { TrackingStatus } from "../DeviceList"; import { IRoomEncryption } from "../RoomList"; import { IDevice } from "../deviceinfo"; import { ICrossSigningInfo } from "../CrossSigning"; -import { PrefixedLogger } from "../../logger"; +import { Logger } from "../../logger"; import { InboundGroupSessionData } from "../OlmDevice"; import { MatrixEvent } from "../../models/event"; import { DehydrationManager } from "../dehydration"; @@ -144,7 +144,7 @@ export interface CryptoStore { takeParkedSharedHistory(roomId: string, txn?: unknown): Promise; // Session key backups - doTxn(mode: Mode, stores: Iterable, func: (txn: unknown) => T, log?: PrefixedLogger): Promise; + doTxn(mode: Mode, stores: Iterable, func: (txn: unknown) => T, log?: Logger): Promise; } export type Mode = "readonly" | "readwrite"; diff --git a/src/crypto/store/indexeddb-crypto-store-backend.ts b/src/crypto/store/indexeddb-crypto-store-backend.ts index 228418091..c6773b168 100644 --- a/src/crypto/store/indexeddb-crypto-store-backend.ts +++ b/src/crypto/store/indexeddb-crypto-store-backend.ts @@ -14,7 +14,7 @@ See the License for the specific language governing permissions and limitations under the License. */ -import { logger, PrefixedLogger } from "../../logger"; +import { Logger, logger } from "../../logger"; import { deepCompare } from "../../utils"; import { CryptoStore, @@ -906,7 +906,7 @@ export class Backend implements CryptoStore { mode: Mode, stores: string | string[], func: (txn: IDBTransaction) => T, - log: PrefixedLogger = logger, + log: Logger = logger, ): Promise { let startTime: number; let description: string; diff --git a/src/crypto/store/indexeddb-crypto-store.ts b/src/crypto/store/indexeddb-crypto-store.ts index 320235fbf..85c59a198 100644 --- a/src/crypto/store/indexeddb-crypto-store.ts +++ b/src/crypto/store/indexeddb-crypto-store.ts @@ -14,7 +14,7 @@ See the License for the specific language governing permissions and limitations under the License. */ -import { logger, PrefixedLogger } from "../../logger"; +import { logger, Logger } from "../../logger"; import { LocalStorageCryptoStore } from "./localStorage-crypto-store"; import { MemoryCryptoStore } from "./memory-crypto-store"; import * as IndexedDBCryptoStoreBackend from "./indexeddb-crypto-store-backend"; @@ -697,12 +697,7 @@ export class IndexedDBCryptoStore implements CryptoStore { * reject with that exception. On synchronous backends, the * exception will propagate to the caller of the getFoo method. */ - public doTxn( - mode: Mode, - stores: Iterable, - func: (txn: IDBTransaction) => T, - log?: PrefixedLogger, - ): Promise { + public doTxn(mode: Mode, stores: Iterable, func: (txn: IDBTransaction) => T, log?: Logger): Promise { return this.backend!.doTxn(mode, stores, func as (txn: unknown) => T, log); } } diff --git a/src/logger.ts b/src/logger.ts index af0cba21e..ed6691939 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -15,7 +15,53 @@ See the License for the specific language governing permissions and limitations under the License. */ -import log, { Logger } from "loglevel"; +import loglevel from "loglevel"; + +/** Logger interface used within the js-sdk codebase */ +export interface Logger { + /** + * Output trace message to the logger, with stack trace. + * + * @param msg - Data to log. + */ + trace(...msg: any[]): void; + + /** + * Output debug message to the logger. + * + * @param msg - Data to log. + */ + debug(...msg: any[]): void; + + /** + * Output info message to the logger. + * + * @param msg - Data to log. + */ + info(...msg: any[]): void; + + /** + * Output warn message to the logger. + * + * @param msg - Data to log. + */ + warn(...msg: any[]): void; + + /** + * Output error message to the logger. + * + * @param msg - Data to log. + */ + error(...msg: any[]): void; + + /** + * Create a child logger. + * + * @param namespace - name to add to the current logger to generate the child. Some implementations of `Logger` + * use this as a prefix; others use a different mechanism. + */ + getChild(namespace: string): Logger; +} // 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 @@ -30,7 +76,7 @@ const DEFAULT_NAMESPACE = "matrix"; // to avoid the issue, we override the methodFactory of loglevel that binds to the // console methods at initialization time by a factory that looks up the console methods // when logging so we always get the current value of console methods. -log.methodFactory = function (methodName, logLevel, loggerName) { +loglevel.methodFactory = function (methodName, logLevel, loggerName) { return function (this: PrefixedLogger, ...args): void { /* eslint-disable @typescript-eslint/no-invalid-this */ if (this.prefix) { @@ -54,33 +100,42 @@ 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. + * Implementation of {@link Logger} based on `loglevel`. + * + * @deprecated this shouldn't be public; prefer {@link Logger}. */ -export const logger = log.getLogger(DEFAULT_NAMESPACE) as PrefixedLogger; -logger.setLevel(log.levels.DEBUG, false); - -export interface PrefixedLogger extends Logger { +export interface PrefixedLogger extends loglevel.Logger, Logger { + /** @deprecated prefer {@link Logger.getChild} */ withPrefix: (prefix: string) => PrefixedLogger; + + /** @deprecated internal property */ prefix: string; } -function extendLogger(logger: Logger): void { - (logger).withPrefix = function (prefix: string): PrefixedLogger { +/** Internal utility function to turn a `loglevel.Logger` into a `PrefixedLogger` */ +function extendLogger(logger: loglevel.Logger): void { + const prefixedLogger = logger; + prefixedLogger.getChild = prefixedLogger.withPrefix = function (prefix: string): PrefixedLogger { const existingPrefix = this.prefix || ""; return getPrefixedLogger(existingPrefix + prefix); }; } -extendLogger(logger); - function getPrefixedLogger(prefix: string): PrefixedLogger { - const prefixLogger = log.getLogger(`${DEFAULT_NAMESPACE}-${prefix}`) as PrefixedLogger; + const prefixLogger = loglevel.getLogger(`${DEFAULT_NAMESPACE}-${prefix}`) as PrefixedLogger; 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, false); + prefixLogger.setLevel(loglevel.levels.DEBUG, false); } return prefixLogger; } + +/** + * 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 = loglevel.getLogger(DEFAULT_NAMESPACE) as PrefixedLogger; +logger.setLevel(loglevel.levels.DEBUG, false); +extendLogger(logger); diff --git a/src/rust-crypto/RoomEncryptor.ts b/src/rust-crypto/RoomEncryptor.ts index 166f9bb93..5f1af2610 100644 --- a/src/rust-crypto/RoomEncryptor.ts +++ b/src/rust-crypto/RoomEncryptor.ts @@ -19,7 +19,7 @@ import { EncryptionSettings, OlmMachine, RoomId, UserId } from "@matrix-org/matr import { EventType } from "../@types/event"; import { IContent, MatrixEvent } from "../models/event"; import { Room } from "../models/room"; -import { logger, PrefixedLogger } from "../logger"; +import { Logger, logger } from "../logger"; import { KeyClaimManager } from "./KeyClaimManager"; import { RoomMember } from "../models/room-member"; import { OutgoingRequestProcessor } from "./OutgoingRequestProcessor"; @@ -30,7 +30,7 @@ import { OutgoingRequestProcessor } from "./OutgoingRequestProcessor"; * @internal */ export class RoomEncryptor { - private readonly prefixedLogger: PrefixedLogger; + private readonly prefixedLogger: Logger; /** * @param olmMachine - The rust-sdk's OlmMachine @@ -45,7 +45,7 @@ export class RoomEncryptor { private readonly room: Room, private encryptionSettings: IContent, ) { - this.prefixedLogger = logger.withPrefix(`[${room.roomId} encryption]`); + this.prefixedLogger = logger.getChild(`[${room.roomId} encryption]`); } /**