Tests: gate logging behind DEBUG env var (#4903)

* Add `DebugLogger` type for logging matrix-js-sdk to `debug` * unit tests for DebugLogger * Use `DebugLogger` in some tests * Use `DebugLogger` in rust-crypto.spec * test-utils: silence some logging
2026-01-03 23:22:30 +03:00 · 2025-07-10 07:15:00 +01:00
parent 090b8079db
commit be15a709c6
9 changed files with 157 additions and 25 deletions
--- 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);
--- 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");
--- 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();
--- 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<void> {

    const p = new Promise<void>((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);
            });
        }
--- 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);
+    });
+});
--- 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<any>,
                TEST_USER,
@@ -898,6 +904,7 @@ describe("RustCrypto", () => {
                makeOutgoingRequest: jest.fn(),
            } as unknown as Mocked<OutgoingRequestProcessor>;

+            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<RustSdkCryptoJs.OlmMachine>;
            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<RustSdkCryptoJs.OlmMachine>;
            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<RustSdkCryptoJs.OlmMachine>;
            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<RustSdkCryptoJs.OlmMachine>;
            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<RustSdkCryptoJs.OlmMachine>;

            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<RustCrypto> {
    return await initRustCrypto({
-        logger,
+        logger: new DebugLogger(debug("matrix-js-sdk:test:rust-crypto.spec")),
        http,
        userId,
        deviceId,
--- 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;
 }
--- 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);
+    }
+}
--- 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();