diff --git a/spec/unit/http-api/fetch.spec.ts b/spec/unit/http-api/fetch.spec.ts index 434d507dafc..47eeb3af7c3 100644 --- a/spec/unit/http-api/fetch.spec.ts +++ b/spec/unit/http-api/fetch.spec.ts @@ -14,14 +14,14 @@ See the License for the specific language governing permissions and limitations under the License. */ -import { mocked } from "jest-mock"; +import { Mocked } from "jest-mock"; import { FetchHttpApi } from "../../../src/http-api/fetch"; import { TypedEventEmitter } from "../../../src/models/typed-event-emitter"; import { ClientPrefix, HttpApiEvent, HttpApiEventHandlerMap, IdentityPrefix, IHttpOpts, Method } from "../../../src"; import { emitPromise } from "../../test-utils/test-utils"; import { defer, QueryDict } from "../../../src/utils"; -import { logger } from "../../../src/logger"; +import { Logger } from "../../../src/logger"; describe("FetchHttpApi", () => { const baseUrl = "http://baseUrl"; @@ -300,22 +300,29 @@ describe("FetchHttpApi", () => { jest.useFakeTimers(); const deferred = defer(); const fetchFn = jest.fn().mockReturnValue(deferred.promise); - jest.spyOn(logger, "debug").mockImplementation(() => {}); - const api = new FetchHttpApi(new TypedEventEmitter(), { baseUrl, prefix, fetchFn }); + const mockLogger = { + debug: jest.fn(), + } as unknown as Mocked; + const api = new FetchHttpApi(new TypedEventEmitter(), { + baseUrl, + prefix, + fetchFn, + logger: mockLogger, + }); const prom = api.requestOtherUrl(Method.Get, "https://server:8448/some/path?query=param#fragment"); jest.advanceTimersByTime(1234); deferred.resolve({ ok: true, status: 200, text: () => Promise.resolve("RESPONSE") } as Response); await prom; - expect(logger.debug).not.toHaveBeenCalledWith("fragment"); - expect(logger.debug).not.toHaveBeenCalledWith("query"); - expect(logger.debug).not.toHaveBeenCalledWith("param"); - expect(logger.debug).toHaveBeenCalledTimes(2); - expect(mocked(logger.debug).mock.calls[0]).toMatchInlineSnapshot(` + expect(mockLogger.debug).not.toHaveBeenCalledWith("fragment"); + expect(mockLogger.debug).not.toHaveBeenCalledWith("query"); + expect(mockLogger.debug).not.toHaveBeenCalledWith("param"); + expect(mockLogger.debug).toHaveBeenCalledTimes(2); + expect(mockLogger.debug.mock.calls[0]).toMatchInlineSnapshot(` [ "FetchHttpApi: --> GET https://server:8448/some/path?query=xxx", ] `); - expect(mocked(logger.debug).mock.calls[1]).toMatchInlineSnapshot(` + expect(mockLogger.debug.mock.calls[1]).toMatchInlineSnapshot(` [ "FetchHttpApi: <-- GET https://server:8448/some/path?query=xxx [1234ms 200]", ] diff --git a/spec/unit/rust-crypto/rust-crypto.spec.ts b/spec/unit/rust-crypto/rust-crypto.spec.ts index d0b6383b044..fb196fd29d4 100644 --- a/spec/unit/rust-crypto/rust-crypto.spec.ts +++ b/spec/unit/rust-crypto/rust-crypto.spec.ts @@ -48,6 +48,7 @@ import { } from "../../../src/crypto-api"; import * as testData from "../../test-utils/test-data"; import { defer } from "../../../src/utils"; +import { logger } from "../../../src/logger"; const TEST_USER = "@alice:example.com"; const TEST_DEVICE_ID = "TEST_DEVICE"; @@ -71,6 +72,7 @@ describe("initRustCrypto", () => { jest.spyOn(OlmMachine, "initialize").mockResolvedValue(testOlmMachine); await initRustCrypto( + logger, {} as MatrixClient["http"], TEST_USER, TEST_DEVICE_ID, @@ -93,6 +95,7 @@ describe("initRustCrypto", () => { jest.spyOn(OlmMachine, "initialize").mockResolvedValue(testOlmMachine); await initRustCrypto( + logger, {} as MatrixClient["http"], TEST_USER, TEST_DEVICE_ID, @@ -315,6 +318,7 @@ describe("RustCrypto", () => { } as unknown as Mocked; rustCrypto = new RustCrypto( + logger, olmMachine, {} as MatrixHttpApi, TEST_USER, @@ -444,6 +448,7 @@ describe("RustCrypto", () => { getRoomEventEncryptionInfo: jest.fn(), } as unknown as Mocked; rustCrypto = new RustCrypto( + logger, olmMachine, {} as MatrixClient["http"], TEST_USER, @@ -618,6 +623,7 @@ describe("RustCrypto", () => { getDevice: jest.fn(), } as unknown as Mocked; rustCrypto = new RustCrypto( + logger, olmMachine, {} as MatrixClient["http"], TEST_USER, @@ -836,6 +842,7 @@ describe("RustCrypto", () => { getIdentity: jest.fn(), } as unknown as Mocked; rustCrypto = new RustCrypto( + logger, olmMachine, {} as MatrixClient["http"], TEST_USER, @@ -882,6 +889,7 @@ describe("RustCrypto", () => { } as unknown as Mocked; const rustCrypto = new RustCrypto( + logger, olmMachine, mockHttpApi, testData.TEST_USER_ID, @@ -914,5 +922,5 @@ async function makeTestRustCrypto( secretStorage: ServerSideSecretStorage = {} as ServerSideSecretStorage, cryptoCallbacks: CryptoCallbacks = {} as CryptoCallbacks, ): Promise { - return await initRustCrypto(http, userId, deviceId, secretStorage, cryptoCallbacks, null, undefined); + return await initRustCrypto(logger, http, userId, deviceId, secretStorage, cryptoCallbacks, null, undefined); } diff --git a/src/client.ts b/src/client.ts index 47c21127648..15d93343de1 100644 --- a/src/client.ts +++ b/src/client.ts @@ -52,7 +52,7 @@ import { IExportedDevice as IExportedOlmDevice } from "./crypto/OlmDevice"; import { IOlmDevice } from "./crypto/algorithms/megolm"; import { TypedReEmitter } from "./ReEmitter"; import { IRoomEncryption, RoomList } from "./crypto/RoomList"; -import { logger } from "./logger"; +import { logger, Logger } from "./logger"; import { SERVICE_TYPES } from "./service-types"; import { Body, @@ -415,6 +415,12 @@ export interface ICreateClientOpts { * so that livekit media can be used in the application layert (js-sdk contains no livekit code). */ useLivekitForGroupCalls?: boolean; + + /** + * A logger to associate with this MatrixClient. + * Defaults to the built-in global logger. + */ + logger?: Logger; } export interface IMatrixClientCreateOpts extends ICreateClientOpts { @@ -1207,6 +1213,8 @@ const SSO_ACTION_PARAM = new UnstableValue("action", "org.matrix.msc3824.action" export class MatrixClient extends TypedEventEmitter { public static readonly RESTORE_BACKUP_ERROR_BAD_KEY = "RESTORE_BACKUP_ERROR_BAD_KEY"; + private readonly logger: Logger; + public reEmitter = new TypedReEmitter(this); public olmVersion: [number, number, number] | null = null; // populated after initCrypto public usingExternalCrypto = false; @@ -1312,6 +1320,10 @@ export class MatrixClient extends TypedEventEmitter logger.info("Sync startup aborted with an error:", e)); + this.syncApi.sync().catch((e) => this.logger.info("Sync startup aborted with an error:", e)); if (this.clientOpts.clientWellKnownPollPeriod !== undefined) { this.clientWellKnownIntervalID = setInterval(() => { @@ -1604,7 +1620,7 @@ export class MatrixClient extends TypedEventEmitter { // copy the key so that it doesn't get clobbered account.unpickle(new Uint8Array(k), deviceData.account); }); account.unpickle(key, deviceData.account); - logger.log("unpickled device"); + this.logger.debug("unpickled device"); const rehydrateResult = await this.http.authedRequest<{ success: boolean }>( Method.Post, @@ -1687,7 +1703,7 @@ export class MatrixClient extends TypedEventEmitter { if (!this.crypto) { - logger.warn("not dehydrating device if crypto is not enabled"); + this.logger.warn("not dehydrating device if crypto is not enabled"); return; } return this.crypto.dehydrationManager.setKeyAndQueueDehydration(key, keyInfo, deviceDisplayName); @@ -1766,7 +1782,7 @@ export class MatrixClient extends TypedEventEmitter { if (!this.crypto) { - logger.warn("not dehydrating device if crypto is not enabled"); + this.logger.warn("not dehydrating device if crypto is not enabled"); return; } await this.crypto.dehydrationManager.setKey(key, keyInfo, deviceDisplayName); @@ -1775,7 +1791,7 @@ export class MatrixClient extends TypedEventEmitter { if (!this.crypto) { - logger.warn("not exporting device if crypto is not enabled"); + this.logger.warn("not exporting device if crypto is not enabled"); return; } return { @@ -1818,10 +1834,10 @@ export class MatrixClient extends TypedEventEmitter { - logger.info(`Removing IndexedDB instance ${dbname}`); + this.logger.info(`Removing IndexedDB instance ${dbname}`); const req = indexedDB.deleteDatabase(dbname); req.onsuccess = (_): void => { - logger.info(`Removed IndexedDB instance ${dbname}`); + this.logger.info(`Removed IndexedDB instance ${dbname}`); resolve(0); }; req.onerror = (e): void => { @@ -1830,11 +1846,11 @@ export class MatrixClient extends TypedEventEmitter { - logger.info(`cannot yet remove IndexedDB instance ${dbname}`); + this.logger.info(`cannot yet remove IndexedDB instance ${dbname}`); }; }); await prom; @@ -2141,7 +2157,7 @@ export class MatrixClient extends TypedEventEmitter(Method.Get, "/capabilities") .catch((e: Error): Response => { // We swallow errors because we need a default object anyhow - logger.error(e); + this.logger.error(e); return {}; }) .then((r = {}) => { @@ -2168,7 +2184,7 @@ export class MatrixClient extends TypedEventEmitter { // TODO: throwing away this error is a really bad idea. - logger.error("Error uploading device keys", e); + this.logger.error("Error uploading device keys", e); }); } @@ -2281,7 +2297,7 @@ export class MatrixClient extends TypedEventEmitter { if (this.cryptoBackend) { - logger.warn("Attempt to re-initialise e2e encryption on MatrixClient"); + this.logger.warn("Attempt to re-initialise e2e encryption on MatrixClient"); return; } @@ -2304,6 +2320,7 @@ export class MatrixClient extends TypedEventEmitter { - logger.warn("MatrixClient.uploadKeys is deprecated"); + this.logger.warn("MatrixClient.uploadKeys is deprecated"); } /** @@ -3462,7 +3479,7 @@ export class MatrixClient extends TypedEventEmitter { - logger.warn("Error caching session backup key:", e); + this.logger.warn("Error caching session backup key:", e); }) .then(cacheCompleteCallback); @@ -3934,7 +3951,7 @@ export class MatrixClient extends TypedEventEmitter { - logger.error("Error sending event", err.stack || err); + this.logger.error("Error sending event", err.stack || err); try { // set the error on the event before we update the status: // updating the status emits the event, so the state should be @@ -4658,7 +4675,7 @@ export class MatrixClient extends TypedEventEmittere).stack || err); + this.logger.error("Exception in error handler!", (e).stack || err); } if (err instanceof MatrixError) { err.event = event; @@ -4771,7 +4788,7 @@ export class MatrixClient extends TypedEventEmitter(Method.Put, path, undefined, event.getWireContent()) .then((res) => { - logger.log(`Event sent to ${event.getRoomId()} with event id ${res.event_id}`); + this.logger.debug(`Event sent to ${event.getRoomId()} with event id ${res.event_id}`); return res; }); } @@ -5871,7 +5888,7 @@ export class MatrixClient extends TypedEventEmitter { - logger.log("Marking success of sync left room request"); + this.logger.debug("Marking success of sync left room request"); this.syncedLeftRooms = true; // flip the bit on success }) .finally(() => { @@ -7213,14 +7230,14 @@ export class MatrixClient extends TypedEventEmitter TURN_CHECK_INTERVAL) { - logger.debug("TURN creds are valid for another " + remainingTime + " ms: not fetching new ones."); + this.logger.debug("TURN creds are valid for another " + remainingTime + " ms: not fetching new ones."); credentialsGood = true; } else { - logger.debug("Fetching new TURN credentials"); + this.logger.debug("Fetching new TURN credentials"); try { const res = await this.turnServer(); if (res.uris) { - logger.log("Got TURN URIs: " + res.uris + " refresh in " + res.ttl + " secs"); + this.logger.debug("Got TURN URIs: " + res.uris + " refresh in " + res.ttl + " secs"); // map the response to a format that can be fed to RTCPeerConnection const servers: ITurnServer = { urls: res.uris, @@ -7234,10 +7251,10 @@ export class MatrixClient extends TypedEventEmittererr).httpStatus === 403) { // We got a 403, so there's no point in looping forever. - logger.info("TURN access unavailable for this account: stopping credentials checks"); + this.logger.info("TURN access unavailable for this account: stopping credentials checks"); if (this.checkTurnServersIntervalID !== null) global.clearInterval(this.checkTurnServersIntervalID); this.checkTurnServersIntervalID = undefined; this.emit(ClientEvent.TurnServersError, err, true); // fatal @@ -7976,7 +7993,10 @@ export class MatrixClient extends TypedEventEmitter 0); } catch (err) { - logger.error("Key backup request failed when logging out. Some keys may be missing from backup", err); + this.logger.error( + "Key backup request failed when logging out. Some keys may be missing from backup", + err, + ); } } @@ -8137,7 +8157,7 @@ export class MatrixClient extends TypedEventEmitter extends Response { json(): Promise; @@ -225,7 +224,7 @@ export class FetchHttpApi { opts: Pick = {}, ): Promise> { const urlForLogs = this.sanitizeUrlForLogs(url); - logger.debug(`FetchHttpApi: --> ${method} ${urlForLogs}`); + this.opts.logger?.debug(`FetchHttpApi: --> ${method} ${urlForLogs}`); const headers = Object.assign({}, opts.headers || {}); const json = opts.json ?? true; @@ -279,9 +278,11 @@ export class FetchHttpApi { priority: opts.priority, }); - logger.debug(`FetchHttpApi: <-- ${method} ${urlForLogs} [${Date.now() - start}ms ${res.status}]`); + this.opts.logger?.debug( + `FetchHttpApi: <-- ${method} ${urlForLogs} [${Date.now() - start}ms ${res.status}]`, + ); } catch (e) { - logger.debug(`FetchHttpApi: <-- ${method} ${urlForLogs} [${Date.now() - start}ms ${e}]`); + this.opts.logger?.debug(`FetchHttpApi: <-- ${method} ${urlForLogs} [${Date.now() - start}ms ${e}]`); if ((e).name === "AbortError") { throw e; } diff --git a/src/http-api/interface.ts b/src/http-api/interface.ts index 57e8a18e851..7f23d3b091d 100644 --- a/src/http-api/interface.ts +++ b/src/http-api/interface.ts @@ -15,6 +15,7 @@ limitations under the License. */ import { MatrixError } from "./errors"; +import { Logger } from "../logger"; export type Body = Record | BodyInit; @@ -31,6 +32,9 @@ export interface IHttpOpts { onlyData?: boolean; localTimeoutMs?: number; + + /** Optional logger instance. If provided, requests and responses will be logged. */ + logger?: Logger; } export interface IRequestOpts extends Pick { diff --git a/src/rust-crypto/index.ts b/src/rust-crypto/index.ts index 3288f66e58b..b6fe82d0fb6 100644 --- a/src/rust-crypto/index.ts +++ b/src/rust-crypto/index.ts @@ -17,14 +17,15 @@ limitations under the License. import * as RustSdkCryptoJs from "@matrix-org/matrix-sdk-crypto-wasm"; import { RustCrypto } from "./rust-crypto"; -import { logger } from "../logger"; import { IHttpOpts, MatrixHttpApi } from "../http-api"; import { ServerSideSecretStorage } from "../secret-storage"; import { ICryptoCallbacks } from "../crypto"; +import { Logger } from "../logger"; /** * Create a new `RustCrypto` implementation * + * @param logger - A `Logger` instance that will be used for debug output. * @param http - Low-level HTTP interface: used to make outgoing requests required by the rust SDK. * We expect it to set the access token, etc. * @param userId - The local user's User ID. @@ -40,6 +41,7 @@ import { ICryptoCallbacks } from "../crypto"; * @internal */ export async function initRustCrypto( + logger: Logger, http: MatrixHttpApi, userId: string, deviceId: string, @@ -65,7 +67,7 @@ export async function initRustCrypto( storePrefix ?? undefined, (storePrefix && storePassphrase) ?? undefined, ); - const rustCrypto = new RustCrypto(olmMachine, http, userId, deviceId, secretStorage, cryptoCallbacks); + const rustCrypto = new RustCrypto(logger, olmMachine, http, userId, deviceId, secretStorage, cryptoCallbacks); await olmMachine.registerRoomKeyUpdatedCallback((sessions: RustSdkCryptoJs.RoomKeyInfo[]) => rustCrypto.onRoomKeysUpdated(sessions), ); diff --git a/src/rust-crypto/rust-crypto.ts b/src/rust-crypto/rust-crypto.ts index 22f6f70be03..73db10cc960 100644 --- a/src/rust-crypto/rust-crypto.ts +++ b/src/rust-crypto/rust-crypto.ts @@ -24,7 +24,7 @@ import { IContent, MatrixEvent, MatrixEventEvent } from "../models/event"; import { Room } from "../models/room"; import { RoomMember } from "../models/room-member"; import { BackupDecryptor, CryptoBackend, OnSyncCompletedData } from "../common-crypto/CryptoBackend"; -import { logger } from "../logger"; +import { Logger } from "../logger"; import { ClientPrefix, IHttpOpts, MatrixHttpApi, Method } from "../http-api"; import { RoomEncryptor } from "./RoomEncryptor"; import { OutgoingRequest, OutgoingRequestProcessor } from "./OutgoingRequestProcessor"; @@ -118,6 +118,8 @@ export class RustCrypto extends TypedEventEmitter(this); public constructor( + private readonly logger: Logger, + /** The `OlmMachine` from the underlying rust crypto sdk. */ private readonly olmMachine: RustSdkCryptoJs.OlmMachine, @@ -143,7 +145,7 @@ export class RustCrypto extends TypedEventEmitter `${e.getId()}`), ); @@ -1326,7 +1330,7 @@ export class RustCrypto extends TypedEventEmitter { - logger.info(`Still unable to decrypt event ${ev.getId()} after receiving key`); + this.logger.info(`Still unable to decrypt event ${ev.getId()} after receiving key`); }); } } @@ -1402,7 +1406,9 @@ export class RustCrypto extends TypedEventEmitter { - logger.error("Error processing outgoing-message requests from rust crypto-sdk", e); + this.logger.error("Error processing outgoing-message requests from rust crypto-sdk", e); }); } @@ -1483,7 +1489,7 @@ export class RustCrypto extends TypedEventEmitter new MapWithDefault>(() => new Set()), ); - public constructor(private readonly olmMachine: RustSdkCryptoJs.OlmMachine, private readonly crypto: RustCrypto) {} + public constructor( + private readonly logger: Logger, + private readonly olmMachine: RustSdkCryptoJs.OlmMachine, + private readonly crypto: RustCrypto, + ) {} public async attemptEventDecryption(event: MatrixEvent): Promise { - logger.info( + this.logger.info( `Attempting decryption of event ${event.getId()} in ${event.getRoomId()} from ${event.getSender()}`, ); @@ -1602,7 +1612,7 @@ class EventDecryptor { new RustSdkCryptoJs.RoomId(event.getRoomId()!), ); - return rustEncryptionInfoToJsEncryptionInfo(encryptionInfo); + return rustEncryptionInfoToJsEncryptionInfo(this.logger, encryptionInfo); } /** @@ -1674,6 +1684,7 @@ function stringifyEvent(event: MatrixEvent): string { } function rustEncryptionInfoToJsEncryptionInfo( + logger: Logger, encryptionInfo: RustSdkCryptoJs.EncryptionInfo | undefined, ): EventEncryptionInfo | null { if (encryptionInfo === undefined) {