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

@@ -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();

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<string[]> {
-        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<string | null> {
         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!;
     }

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<Pick<IParams, "roomId">>) {
         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<IMegolmEncryptedContent> {
-        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<IParams & Required<Pick<IParams, "roomId">>>) {
         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;
             }
 

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<Map<string, Map<string, IOlmSessionResult>>> {
     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;
     }
 

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<ParkedSharedHistory[]>;
 
     // Session key backups
-    doTxn<T>(mode: Mode, stores: Iterable<string>, func: (txn: unknown) => T, log?: PrefixedLogger): Promise<T>;
+    doTxn<T>(mode: Mode, stores: Iterable<string>, func: (txn: unknown) => T, log?: Logger): Promise<T>;
 }
 
 export type Mode = "readonly" | "readwrite";

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<T> {
         let startTime: number;
         let description: string;

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<T>(
+    public doTxn<T>(mode: Mode, stores: Iterable<string>, func: (txn: IDBTransaction) => T, log?: Logger): Promise<T> {
-        mode: Mode,
-        stores: Iterable<string>,
-        func: (txn: IDBTransaction) => T,
-        log?: PrefixedLogger,
-    ): Promise<T> {
         return this.backend!.doTxn<T>(mode, stores, func as (txn: unknown) => T, log);
     }
 }

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}.
+ * Implementation of {@link Logger} based on `loglevel`.
- * Can be tailored down to specific use cases if needed.
+ *
+ * @deprecated this shouldn't be public; prefer {@link Logger}.
  */
-export const logger = log.getLogger(DEFAULT_NAMESPACE) as PrefixedLogger;
+export interface PrefixedLogger extends loglevel.Logger, Logger {
-logger.setLevel(log.levels.DEBUG, false);
+    /** @deprecated prefer {@link Logger.getChild} */
-
-export interface PrefixedLogger extends Logger {
     withPrefix: (prefix: string) => PrefixedLogger;
+
+    /** @deprecated internal property */
     prefix: string;
 }
 
-function extendLogger(logger: Logger): void {
+/** Internal utility function to turn a `loglevel.Logger` into a `PrefixedLogger` */
-    (<PrefixedLogger>logger).withPrefix = function (prefix: string): PrefixedLogger {
+function extendLogger(logger: loglevel.Logger): void {
+    const prefixedLogger = <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);

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]`);
     }
 
     /**