diff --git a/spec/integ/crypto/cross-signing.spec.ts b/spec/integ/crypto/cross-signing.spec.ts index 80a9d2588..81887f85d 100644 --- a/spec/integ/crypto/cross-signing.spec.ts +++ b/spec/integ/crypto/cross-signing.spec.ts @@ -17,9 +17,10 @@ limitations under the License. import fetchMock from "fetch-mock-jest"; import "fake-indexeddb/auto"; import { IDBFactory } from "fake-indexeddb"; +import debug from "debug"; import { syncPromise } from "../../test-utils/test-utils"; -import { type AuthDict, createClient, type MatrixClient } from "../../../src"; +import { type AuthDict, createClient, DebugLogger, type MatrixClient } from "../../../src"; import { mockInitialApiRequests, mockSetupCrossSigningRequests } from "../../test-utils/mockEndpoints"; import encryptAESSecretStorageItem from "../../../src/utils/encryptAESSecretStorageItem.ts"; import { type CryptoCallbacks, CrossSigningKey } from "../../../src/crypto-api"; @@ -91,6 +92,7 @@ describe("cross-signing", () => { accessToken: "akjgkrgjs", deviceId: TEST_DEVICE_ID, cryptoCallbacks: createCryptoCallbacks(), + logger: new DebugLogger(debug(`matrix-js-sdk:cross-signing`)), }); syncResponder = new SyncResponder(homeserverUrl); diff --git a/spec/integ/crypto/device-dehydration.spec.ts b/spec/integ/crypto/device-dehydration.spec.ts index 68428db94..79e27f4f0 100644 --- a/spec/integ/crypto/device-dehydration.spec.ts +++ b/spec/integ/crypto/device-dehydration.spec.ts @@ -16,8 +16,9 @@ limitations under the License. import "fake-indexeddb/auto"; import fetchMock from "fetch-mock-jest"; +import debug from "debug"; -import { ClientEvent, createClient, type MatrixClient, MatrixEvent } from "../../../src"; +import { ClientEvent, createClient, DebugLogger, type MatrixClient, MatrixEvent } from "../../../src"; import { CryptoEvent } from "../../../src/crypto-api/index"; import { type RustCrypto } from "../../../src/rust-crypto/rust-crypto"; import { type AddSecretStorageKeyOpts } from "../../../src/secret-storage"; @@ -38,6 +39,7 @@ describe("Device dehydration", () => { return [[...Object.keys(keys.keys)][0], new Uint8Array(32)]; }, }, + logger: new DebugLogger(debug(`matrix-js-sdk:dehydration`)), }); await initializeSecretStorage(matrixClient, "@alice:localhost", "http://test.server"); diff --git a/spec/integ/crypto/verification.spec.ts b/spec/integ/crypto/verification.spec.ts index b48cdc9b6..9af06dcf2 100644 --- a/spec/integ/crypto/verification.spec.ts +++ b/spec/integ/crypto/verification.spec.ts @@ -17,6 +17,7 @@ limitations under the License. import "fake-indexeddb/auto"; import anotherjson from "another-json"; +import debug from "debug"; import fetchMock from "fetch-mock-jest"; import { IDBFactory } from "fake-indexeddb"; import { createHash } from "crypto"; @@ -25,6 +26,7 @@ import Olm from "@matrix-org/olm"; import type FetchMock from "fetch-mock"; import { createClient, + DebugLogger, DeviceVerification, type IContent, type ICreateClientOpts, @@ -1475,6 +1477,7 @@ describe("verification", () => { userId: TEST_USER_ID, accessToken: "akjgkrgjs", deviceId: "device_under_test", + logger: new DebugLogger(debug(`matrix-js-sdk:verification`)), ...opts, }); await client.initRustCrypto(); diff --git a/spec/test-utils/test-utils.ts b/spec/test-utils/test-utils.ts index d031cdcb8..07d63e577 100644 --- a/spec/test-utils/test-utils.ts +++ b/spec/test-utils/test-utils.ts @@ -1,6 +1,7 @@ +import mkdebug from "debug"; + // eslint-disable-next-line no-restricted-imports import type EventEmitter from "events"; -import { logger } from "../../src/logger"; import { type IContent, type IEvent, @@ -24,6 +25,8 @@ import { eventMapperFor } from "../../src/event-mapper"; import { TEST_ROOM_ID } from "./test-data"; import { KnownMembership, type Membership } from "../../src/@types/membership"; +const debug = mkdebug("test-utils"); + /** * Return a promise that is resolved when the client next emits a * SYNCING event. @@ -38,7 +41,7 @@ export function syncPromise(client: MatrixClient, count = 1): Promise { const p = new Promise((resolve) => { const cb = (state: SyncState) => { - logger.log(`${Date.now()} syncPromise(${count}): ${state}`); + debug(`syncPromise(${count}): ${state}`); if (state === SyncState.Syncing) { resolve(); } else { @@ -519,25 +522,25 @@ export async function awaitDecryption( // already if (event.getClearContent() !== null) { if (waitOnDecryptionFailure && event.isDecryptionFailure()) { - logger.log(`${Date.now()}: event ${event.getId()} got decryption error; waiting`); + debug(`event ${event.getId()} got decryption error; waiting`); } else { return event; } } else { - logger.log(`${Date.now()}: event ${event.getId()} is not yet decrypted; waiting`); + debug(`event ${event.getId()} is not yet decrypted; waiting`); } return new Promise((resolve) => { if (waitOnDecryptionFailure) { event.on(MatrixEventEvent.Decrypted, (ev, err) => { - logger.log(`${Date.now()}: MatrixEventEvent.Decrypted for event ${event.getId()}: ${err ?? "success"}`); + debug(`MatrixEventEvent.Decrypted for event ${event.getId()}: ${err ?? "success"}`); if (!err) { resolve(ev); } }); } else { event.once(MatrixEventEvent.Decrypted, (ev, err) => { - logger.log(`${Date.now()}: MatrixEventEvent.Decrypted for event ${event.getId()}: ${err ?? "success"}`); + debug(`MatrixEventEvent.Decrypted for event ${event.getId()}: ${err ?? "success"}`); resolve(ev); }); } diff --git a/spec/unit/logger.spec.ts b/spec/unit/logger.spec.ts index 263d7683a..501c93d88 100644 --- a/spec/unit/logger.spec.ts +++ b/spec/unit/logger.spec.ts @@ -18,7 +18,7 @@ limitations under the License. import loglevel from "loglevel"; -import { logger } from "../../src/logger.ts"; +import { DebugLogger, logger } from "../../src/logger.ts"; afterEach(() => { jest.restoreAllMocks(); @@ -49,3 +49,42 @@ describe("logger", () => { expect(console.debug).toHaveBeenCalledWith("[prefix1][prefix2]", "test2"); }); }); + +describe("DebugLogger", () => { + it("should handle empty log messages", () => { + const mockTarget = jest.fn(); + const logger = new DebugLogger(mockTarget as any); + logger.info(); + expect(mockTarget).toHaveBeenCalledTimes(1); + expect(mockTarget).toHaveBeenCalledWith("[INFO] "); + }); + + it("should handle logging an Error", () => { + const mockTarget = jest.fn(); + const logger = new DebugLogger(mockTarget as any); + + // If there is a stack and a message, we use the stack. + const error = new Error("I am an error"); + logger.error(error); + expect(mockTarget).toHaveBeenCalledTimes(1); + expect(mockTarget).toHaveBeenCalledWith(expect.stringMatching(/^\[ERROR\] Error: I am an error\n\s*at/)); + + mockTarget.mockClear(); + + // If there is only a message, we use that. + error.stack = undefined; + logger.error(error); + expect(mockTarget).toHaveBeenCalledTimes(1); + expect(mockTarget).toHaveBeenCalledWith("[ERROR] I am an error"); + }); + + it("should handle logging an object", () => { + const mockTarget = jest.fn(); + const logger = new DebugLogger(mockTarget as any); + + const obj = { a: 1 }; + logger.warn(obj); + expect(mockTarget).toHaveBeenCalledTimes(1); + expect(mockTarget).toHaveBeenCalledWith("[WARN] %O", obj); + }); +}); diff --git a/spec/unit/rust-crypto/rust-crypto.spec.ts b/spec/unit/rust-crypto/rust-crypto.spec.ts index a92021751..36387e6cf 100644 --- a/spec/unit/rust-crypto/rust-crypto.spec.ts +++ b/spec/unit/rust-crypto/rust-crypto.spec.ts @@ -14,6 +14,7 @@ See the License for the specific language governing permissions and limitations under the License. */ +import debug from "debug"; import * as RustSdkCryptoJs from "@matrix-org/matrix-sdk-crypto-wasm"; import { BaseMigrationData, @@ -31,6 +32,7 @@ import { RustCrypto } from "../../../src/rust-crypto/rust-crypto"; import { initRustCrypto } from "../../../src/rust-crypto"; import { type AccountDataEvents, + DebugLogger, type Device, DeviceVerification, type EmptyObject, @@ -68,7 +70,6 @@ import { import * as testData from "../../test-utils/test-data"; import { E2EKeyReceiver } from "../../test-utils/E2EKeyReceiver"; import { E2EKeyResponder } from "../../test-utils/E2EKeyResponder"; -import { logger } from "../../../src/logger"; import { OutgoingRequestsManager } from "../../../src/rust-crypto/OutgoingRequestsManager"; import { ClientEvent, type ClientEventHandlerMap } from "../../../src/client"; import { type Curve25519AuthData } from "../../../src/crypto-api/keybackup"; @@ -117,6 +118,7 @@ describe("initRustCrypto", () => { const testOlmMachine = makeTestOlmMachine(); jest.spyOn(OlmMachine, "initFromStore").mockResolvedValue(testOlmMachine); + const logger = new DebugLogger(debug("matrix-js-sdk:test:initRustCrypto")); await initRustCrypto({ logger, http: {} as MatrixClient["http"], @@ -140,6 +142,7 @@ describe("initRustCrypto", () => { jest.spyOn(OlmMachine, "initFromStore").mockResolvedValue(testOlmMachine); const storeKey = new Uint8Array(32); + const logger = new DebugLogger(debug("matrix-js-sdk:test:initRustCrypto")); await initRustCrypto({ logger, http: {} as MatrixClient["http"], @@ -162,6 +165,7 @@ describe("initRustCrypto", () => { const testOlmMachine = makeTestOlmMachine(); jest.spyOn(OlmMachine, "initFromStore").mockResolvedValue(testOlmMachine); + const logger = new DebugLogger(debug("matrix-js-sdk:test:initRustCrypto")); await initRustCrypto({ logger, http: {} as MatrixClient["http"], @@ -186,7 +190,7 @@ describe("initRustCrypto", () => { jest.spyOn(OlmMachine, "initFromStore").mockResolvedValue(testOlmMachine); await initRustCrypto({ - logger, + logger: new DebugLogger(debug("matrix-js-sdk:test:initRustCrypto")), http: {} as MatrixClient["http"], userId: TEST_USER, deviceId: TEST_DEVICE_ID, @@ -251,9 +255,10 @@ describe("initRustCrypto", () => { jest.spyOn(RustSdkCryptoJs.BackupDecryptionKey, "fromBase64").mockReturnValue(mockBackupDecryptionKey); function legacyMigrationProgressListener(progress: number, total: number): void { - logger.log(`migrated ${progress} of ${total}`); + // console.log(`migrated ${progress} of ${total}`); } + const logger = new DebugLogger(debug("matrix-js-sdk:test:initRustCrypto")); await initRustCrypto({ logger, http: makeMatrixHttpApi(), @@ -358,11 +363,11 @@ describe("initRustCrypto", () => { fetchMock.get("path:/_matrix/client/v3/room_keys/version", 404); function legacyMigrationProgressListener(progress: number, total: number): void { - logger.log(`migrated ${progress} of ${total}`); + // console.log(`migrated ${progress} of ${total}`); } await initRustCrypto({ - logger, + logger: new DebugLogger(debug("matrix-js-sdk:test:initRustCrypto")), http: makeMatrixHttpApi(), userId: TEST_USER, deviceId: TEST_DEVICE_ID, @@ -400,6 +405,7 @@ describe("initRustCrypto", () => { ); const PICKLE_KEY = "pickle1234"; + const logger = new DebugLogger(debug("matrix-js-sdk:test:initRustCrypto")); await initRustCrypto({ logger, http: makeMatrixHttpApi(), @@ -813,7 +819,7 @@ describe("RustCrypto", () => { } as unknown as OlmMachine; const rustCrypto = new RustCrypto( - logger, + new DebugLogger(debug("matrix-js-sdk:test:RustCrypto")), mockOlmMachine, fetchMock as unknown as MatrixHttpApi, TEST_USER, @@ -898,6 +904,7 @@ describe("RustCrypto", () => { makeOutgoingRequest: jest.fn(), } as unknown as Mocked; + const logger = new DebugLogger(debug("matrix-js-sdk:test:RustCrypto")); const outgoingRequestsManager = new OutgoingRequestsManager(logger, olmMachine, outgoingRequestProcessor); rustCrypto = new RustCrypto( @@ -957,7 +964,11 @@ describe("RustCrypto", () => { const outgoingRequestProcessor = {} as unknown as OutgoingRequestProcessor; rustCrypto["outgoingRequestProcessor"] = outgoingRequestProcessor; - const outgoingRequestsManager = new OutgoingRequestsManager(logger, olmMachine, outgoingRequestProcessor); + const outgoingRequestsManager = new OutgoingRequestsManager( + new DebugLogger(debug("matrix-js-sdk:test:RustCrypto")), + olmMachine, + outgoingRequestProcessor, + ); rustCrypto["outgoingRequestsManager"] = outgoingRequestsManager; // The second time we do a /keys/upload, the `device_keys` property @@ -1015,7 +1026,7 @@ describe("RustCrypto", () => { getRoomEventEncryptionInfo: jest.fn(), } as unknown as Mocked; rustCrypto = new RustCrypto( - logger, + new DebugLogger(debug("matrix-js-sdk:test:RustCrypto")), olmMachine, {} as MatrixClient["http"], TEST_USER, @@ -1228,7 +1239,7 @@ describe("RustCrypto", () => { getDevice: jest.fn(), } as unknown as Mocked; rustCrypto = new RustCrypto( - logger, + new DebugLogger(debug("matrix-js-sdk:test:RustCrypto")), olmMachine, {} as MatrixClient["http"], TEST_USER, @@ -1471,7 +1482,7 @@ describe("RustCrypto", () => { getIdentity: jest.fn(), } as unknown as Mocked; rustCrypto = new RustCrypto( - logger, + new DebugLogger(debug("matrix-js-sdk:test:RustCrypto")), olmMachine, {} as MatrixClient["http"], TEST_USER, @@ -1558,7 +1569,7 @@ describe("RustCrypto", () => { getIdentity: jest.fn(), } as unknown as Mocked; const rustCrypto = new RustCrypto( - logger, + new DebugLogger(debug("matrix-js-sdk:test:RustCrypto")), olmMachine, {} as MatrixClient["http"], TEST_USER, @@ -1630,7 +1641,7 @@ describe("RustCrypto", () => { } as unknown as Mocked; const rustCrypto = new RustCrypto( - logger, + new DebugLogger(debug("matrix-js-sdk:test:RustCrypto")), olmMachine, makeMatrixHttpApi(), testData.TEST_USER_ID, @@ -2371,7 +2382,7 @@ async function makeTestRustCrypto( cryptoCallbacks: CryptoCallbacks = {} as CryptoCallbacks, ): Promise { return await initRustCrypto({ - logger, + logger: new DebugLogger(debug("matrix-js-sdk:test:rust-crypto.spec")), http, userId, deviceId, diff --git a/src/client.ts b/src/client.ts index b4237decd..ea7f41b6e 100644 --- a/src/client.ts +++ b/src/client.ts @@ -439,13 +439,13 @@ export interface ICreateClientOpts { /** * If true, group calls will not establish media connectivity and only create the signaling events, - * so that livekit media can be used in the application layert (js-sdk contains no livekit code). + * so that livekit media can be used in the application layer (js-sdk contains no livekit code). */ useLivekitForGroupCalls?: boolean; /** * A logger to associate with this MatrixClient. - * Defaults to the built-in global logger. + * Defaults to the built-in global logger; see {@link DebugLogger} for an alternative. */ logger?: Logger; } diff --git a/src/logger.ts b/src/logger.ts index 8554ac400..641e0b7d3 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -1,6 +1,6 @@ /* Copyright 2018 André Jaenisch -Copyright 2019, 2021 The Matrix.org Foundation C.I.C. +Copyright 2019-2025 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. @@ -206,3 +206,74 @@ export class LogSpan implements BaseLogger { this.parent.error(this.name, ...msg); } } + +/** + * A simplification of the `Debugger` type exposed by the `debug` library. We reimplement the bits we need here + * to avoid a dependency on `debug`. + */ +interface Debugger { + (formatter: any, ...args: any[]): void; + extend: (namespace: string, delimiter?: string) => Debugger; +} + +/** + * A `Logger` instance, suitable for use in {@link ICreateClientOpts.logger}, which will write to the `debug` library. + * + * @example + * ```js + * import debug from "debug"; + * + * const client = createClient({ + * baseUrl: homeserverUrl, + * userId: userId, + * accessToken: "akjgkrgjs", + * deviceId: "xzcvb", + * logger: new DebugLogger(debug(`matrix-js-sdk:${userId}`)), + * }); + * ``` + */ +export class DebugLogger implements Logger { + public constructor(private debugInstance: Debugger) {} + + public trace(...msg: any[]): void { + this.debugWithPrefix("[TRACE]", ...msg); + } + + public debug(...msg: any[]): void { + this.debugWithPrefix("[DEBUG]", ...msg); + } + + public info(...msg: any[]): void { + this.debugWithPrefix("[INFO]", ...msg); + } + + public warn(...msg: any[]): void { + this.debugWithPrefix("[WARN]", ...msg); + } + + public error(...msg: any[]): void { + this.debugWithPrefix("[ERROR]", ...msg); + } + + public getChild(namespace: string): DebugLogger { + return new DebugLogger(this.debugInstance.extend(namespace)); + } + + private debugWithPrefix(prefix: string, ...msg: any[]): void { + let formatter: string; + + // Convert the first argument to a string, so that we can safely add a prefix. This is much the same logic that + // `debug()` uses. + if (msg.length === 0) { + formatter = ""; + } else if (msg[0] instanceof Error) { + const err = msg.shift(); + formatter = err.stack || err.message; + } else if (typeof msg[0] == "string") { + formatter = msg.shift(); + } else { + formatter = "%O"; + } + this.debugInstance(prefix + " " + formatter, ...msg); + } +} diff --git a/src/matrix.ts b/src/matrix.ts index 419442187..c2d663604 100644 --- a/src/matrix.ts +++ b/src/matrix.ts @@ -109,6 +109,7 @@ export { IdentityProviderBrand, SSOAction } from "./@types/auth.ts"; export type { ISSOFlow as SSOFlow, LoginFlow } from "./@types/auth.ts"; export type { IHierarchyRelation as HierarchyRelation, IHierarchyRoom as HierarchyRoom } from "./@types/spaces.ts"; export { LocationAssetType } from "./@types/location.ts"; +export { DebugLogger } from "./logger.ts"; let cryptoStoreFactory = (): CryptoStore => new MemoryCryptoStore();