Use client logger in more places (crypto code) (#4900)

* Use client logger for `RustBackupManager`

* use client logger in `CrossSigningIdentity`

* use client logger in `OutgoingRequestProcessor`

* RoomEncryptor: use correct logger for logDuration

use the logger for this specific event, rather than the more general one for the room

* Use client logger in `RoomEncryptor`

Author: richvdh

spec/unit/rust-crypto/CrossSigningIdentity.spec.ts

@@ -20,6 +20,7 @@ import * as RustSdkCryptoJs from "@matrix-org/matrix-sdk-crypto-wasm";
 import { CrossSigningIdentity } from "../../../src/rust-crypto/CrossSigningIdentity";
 import { type OutgoingRequestProcessor } from "../../../src/rust-crypto/OutgoingRequestProcessor";
 import { type ServerSideSecretStorage } from "../../../src/secret-storage";
+import { logger } from "../../../src/logger.ts";
 
 describe("CrossSigningIdentity", () => {
     describe("bootstrapCrossSigning", () => {
@@ -55,7 +56,7 @@ describe("CrossSigningIdentity", () => {
                 store: jest.fn(),
             } as unknown as Mocked<ServerSideSecretStorage>;
 
-            crossSigning = new CrossSigningIdentity(olmMachine, outgoingRequestProcessor, secretStorage);
+            crossSigning = new CrossSigningIdentity(logger, olmMachine, outgoingRequestProcessor, secretStorage);
         });
 
         it("should do nothing if keys are present on-device and in secret storage", async () => {

spec/unit/rust-crypto/KeyClaimManager.spec.ts

@@ -53,7 +53,7 @@ describe("KeyClaimManager", () => {
             markRequestAsSent: jest.fn(),
         } as unknown as Mocked<RustSdkCryptoJs.OlmMachine>;
 
-        const outgoingRequestProcessor = new OutgoingRequestProcessor(olmMachine, httpApi);
+        const outgoingRequestProcessor = new OutgoingRequestProcessor(logger, olmMachine, httpApi);
 
         keyClaimManager = new KeyClaimManager(olmMachine, outgoingRequestProcessor);
     });

spec/unit/rust-crypto/OutgoingRequestProcessor.spec.ts

@@ -40,6 +40,7 @@ import {
     type UIAuthCallback,
 } from "../../../src";
 import { OutgoingRequestProcessor } from "../../../src/rust-crypto/OutgoingRequestProcessor";
+import { logger } from "../../../src/logger.ts";
 
 describe("OutgoingRequestProcessor", () => {
     /** the OutgoingRequestProcessor implementation under test */
@@ -76,7 +77,7 @@ describe("OutgoingRequestProcessor", () => {
             markRequestAsSent: jest.fn(),
         } as unknown as Mocked<RustSdkCryptoJs.OlmMachine>;
 
-        processor = new OutgoingRequestProcessor(olmMachine, httpApi);
+        processor = new OutgoingRequestProcessor(logger, olmMachine, httpApi);
     });
 
     /* simple requests that map directly to the request body */
@@ -293,7 +294,7 @@ describe("OutgoingRequestProcessor", () => {
                     return await authRequestResultResolvers.promise;
                 },
             } as unknown as Mocked<MatrixHttpApi<IHttpOpts & { onlyData: true }>>;
-            processor = new OutgoingRequestProcessor(olmMachine, mockHttpApi);
+            processor = new OutgoingRequestProcessor(logger, olmMachine, mockHttpApi);
         });
 
         // build a request
@@ -325,7 +326,7 @@ describe("OutgoingRequestProcessor", () => {
                 onlyData: true,
             });
 
-            processor = new OutgoingRequestProcessor(olmMachine, httpApi);
+            processor = new OutgoingRequestProcessor(logger, olmMachine, httpApi);
         });
 
         afterEach(() => {

spec/unit/rust-crypto/RoomEncryptor.spec.ts

@@ -36,6 +36,7 @@ import {
     AllDevicesIsolationMode,
     OnlySignedDevicesIsolationMode,
 } from "../../../src/crypto-api";
+import { logger } from "../../../src/logger.ts";
 
 describe("RoomEncryptor", () => {
     describe("History Visibility", () => {
@@ -108,6 +109,7 @@ describe("RoomEncryptor", () => {
             } as unknown as Mocked<Room>;
 
             roomEncryptor = new RoomEncryptor(
+                logger,
                 mockOlmMachine,
                 mockKeyClaimManager,
                 mockOutgoingRequestManager,

spec/unit/rust-crypto/backup.spec.ts

@@ -8,6 +8,7 @@ import { type OutgoingRequestProcessor } from "../../../src/rust-crypto/Outgoing
 import * as testData from "../../test-utils/test-data";
 import * as TestData from "../../test-utils/test-data";
 import { RustBackupManager, type KeyBackup } from "../../../src/rust-crypto/backup";
+import { logger } from "../../../src/logger.ts";
 
 describe("Upload keys to backup", () => {
     /** The backup manager under test */
@@ -63,7 +64,7 @@ describe("Upload keys to backup", () => {
             makeOutgoingRequest: jest.fn(),
         } as unknown as Mocked<OutgoingRequestProcessor>;
 
-        rustBackupManager = new RustBackupManager(mockOlmMachine, httpAPi, outgoingRequestProcessor);
+        rustBackupManager = new RustBackupManager(logger, mockOlmMachine, httpAPi, outgoingRequestProcessor);
 
         fetchMock.get("path:/_matrix/client/v3/room_keys/version", testData.SIGNED_BACKUP_DATA);
     });

src/rust-crypto/CrossSigningIdentity.ts

@@ -22,7 +22,7 @@ import {
 
 import type * as RustSdkCryptoJs from "@matrix-org/matrix-sdk-crypto-wasm";
 import { type BootstrapCrossSigningOpts } from "../crypto-api/index.ts";
-import { logger } from "../logger.ts";
+import { type Logger } from "../logger.ts";
 import { type OutgoingRequestProcessor } from "./OutgoingRequestProcessor.ts";
 import { type UIAuthCallback } from "../interactive-auth.ts";
 import { type ServerSideSecretStorage } from "../secret-storage.ts";
@@ -33,6 +33,7 @@ import { type ServerSideSecretStorage } from "../secret-storage.ts";
  */
 export class CrossSigningIdentity {
     public constructor(
+        private readonly logger: Logger,
         private readonly olmMachine: OlmMachine,
         private readonly outgoingRequestProcessor: OutgoingRequestProcessor,
         private readonly secretStorage: ServerSideSecretStorage,
@@ -61,7 +62,7 @@ export class CrossSigningIdentity {
             olmDeviceStatus.hasMaster && olmDeviceStatus.hasUserSigning && olmDeviceStatus.hasSelfSigning;
 
         // Log all relevant state for easier parsing of debug logs.
-        logger.log("bootstrapCrossSigning: starting", {
+        this.logger.debug("bootstrapCrossSigning: starting", {
             setupNewCrossSigning: opts.setupNewCrossSigning,
             olmDeviceHasMaster: olmDeviceStatus.hasMaster,
             olmDeviceHasUserSigning: olmDeviceStatus.hasUserSigning,
@@ -71,23 +72,23 @@ export class CrossSigningIdentity {
 
         if (olmDeviceHasKeys) {
             if (!(await this.secretStorage.hasKey())) {
-                logger.warn(
+                this.logger.warn(
                     "bootstrapCrossSigning: Olm device has private keys, but secret storage is not yet set up; doing nothing for now.",
                 );
                 // the keys should get uploaded to 4S once that is set up.
             } else if (!privateKeysInSecretStorage) {
                 // the device has the keys but they are not in 4S, so update it
-                logger.log("bootstrapCrossSigning: Olm device has private keys: exporting to secret storage");
+                this.logger.debug("bootstrapCrossSigning: Olm device has private keys: exporting to secret storage");
                 await this.exportCrossSigningKeysToStorage();
             } else {
-                logger.log(
+                this.logger.debug(
                     "bootstrapCrossSigning: Olm device has private keys and they are saved in secret storage; doing nothing",
                 );
             }
         } /* (!olmDeviceHasKeys) */ else {
             if (privateKeysInSecretStorage) {
                 // they are in 4S, so import from there
-                logger.log(
+                this.logger.debug(
                     "bootstrapCrossSigning: Cross-signing private keys not found locally, but they are available " +
                         "in secret storage, reading storage and caching locally",
                 );
@@ -116,7 +117,7 @@ export class CrossSigningIdentity {
                     device.free();
                 }
             } else {
-                logger.log(
+                this.logger.debug(
                     "bootstrapCrossSigning: Cross-signing private keys not found locally or in secret storage, creating new keys",
                 );
                 await this.resetCrossSigning(opts.authUploadDeviceSigningKeys);
@@ -125,7 +126,7 @@ export class CrossSigningIdentity {
 
         // TODO: we might previously have bootstrapped cross-signing but not completed uploading the keys to the
         //   server -- in which case we should call OlmDevice.bootstrap_cross_signing. How do we know?
-        logger.log("bootstrapCrossSigning: complete");
+        this.logger.debug("bootstrapCrossSigning: complete");
     }
 
     /** Reset our cross-signing keys
@@ -142,19 +143,19 @@ export class CrossSigningIdentity {
 
         // If 4S is configured we need to update it.
         if (!(await this.secretStorage.hasKey())) {
-            logger.warn(
+            this.logger.warn(
                 "resetCrossSigning: Secret storage is not yet set up; not exporting keys to secret storage yet.",
             );
             // the keys should get uploaded to 4S once that is set up.
         } else {
             // Update 4S before uploading cross-signing keys, to stay consistent with legacy that asks
             // 4S passphrase before asking for account password.
             // Ultimately should be made atomic and resistant to forgotten password/passphrase.
-            logger.log("resetCrossSigning: exporting private keys to secret storage");
+            this.logger.debug("resetCrossSigning: exporting private keys to secret storage");
             await this.exportCrossSigningKeysToStorage();
         }
 
-        logger.log("resetCrossSigning: publishing public keys to server");
+        this.logger.debug("resetCrossSigning: publishing public keys to server");
         for (const req of [
             outgoingRequests.uploadKeysRequest,
             outgoingRequests.uploadSigningKeysRequest,
@@ -178,17 +179,17 @@ export class CrossSigningIdentity {
         if (exported?.masterKey) {
             await this.secretStorage.store("m.cross_signing.master", exported.masterKey);
         } else {
-            logger.error(`Cannot export MSK to secret storage, private key unknown`);
+            this.logger.error(`Cannot export MSK to secret storage, private key unknown`);
         }
         if (exported?.self_signing_key) {
             await this.secretStorage.store("m.cross_signing.self_signing", exported.self_signing_key);
         } else {
-            logger.error(`Cannot export SSK to secret storage, private key unknown`);
+            this.logger.error(`Cannot export SSK to secret storage, private key unknown`);
         }
         if (exported?.userSigningKey) {
             await this.secretStorage.store("m.cross_signing.user_signing", exported.userSigningKey);
         } else {
-            logger.error(`Cannot export USK to secret storage, private key unknown`);
+            this.logger.error(`Cannot export USK to secret storage, private key unknown`);
         }
     }
 }

src/rust-crypto/OutgoingRequestProcessor.ts

@@ -28,7 +28,7 @@ import {
     UploadSigningKeysRequest,
 } from "@matrix-org/matrix-sdk-crypto-wasm";
 
-import { logger } from "../logger.ts";
+import { type Logger } from "../logger.ts";
 import { calculateRetryBackoff, type IHttpOpts, type MatrixHttpApi, Method } from "../http-api/index.ts";
 import { logDuration, type QueryDict, sleep } from "../utils.ts";
 import { type AuthDict, type UIAuthCallback } from "../interactive-auth.ts";
@@ -49,6 +49,7 @@ import { UnstablePrefix as DehydrationUnstablePrefix } from "./DehydratedDeviceM
  */
 export class OutgoingRequestProcessor {
     public constructor(
+        private readonly logger: Logger,
         private readonly olmMachine: OlmMachine,
         private readonly http: MatrixHttpApi<IHttpOpts & { onlyData: true }>,
     ) {}
@@ -100,13 +101,13 @@ export class OutgoingRequestProcessor {
             // PutDehydratedDeviceRequest does not implement OutgoingRequest and does not need to be marked as sent.
             return;
         } else {
-            logger.warn("Unsupported outgoing message", Object.getPrototypeOf(msg));
+            this.logger.warn("Unsupported outgoing message", Object.getPrototypeOf(msg));
             resp = "";
         }
 
         if (msg.id) {
             try {
-                await logDuration(logger, `Mark Request as sent ${msg.type}`, async () => {
+                await logDuration(this.logger, `Mark Request as sent ${msg.type}`, async () => {
                     await this.olmMachine.markRequestAsSent(msg.id!, msg.type, resp);
                 });
             } catch (e) {
@@ -116,13 +117,13 @@ export class OutgoingRequestProcessor {
                     e instanceof Error &&
                     (e.message === "Attempt to use a moved value" || e.message === "null pointer passed to rust")
                 ) {
-                    logger.log(`Ignoring error '${e.message}': client is likely shutting down`);
+                    this.logger.debug(`Ignoring error '${e.message}': client is likely shutting down`);
                 } else {
                     throw e;
                 }
             }
         } else {
-            logger.trace(`Outgoing request type:${msg.type} does not have an ID`);
+            this.logger.trace(`Outgoing request type:${msg.type} does not have an ID`);
         }
     }
 
@@ -143,7 +144,7 @@ export class OutgoingRequestProcessor {
             }
         }
 
-        logger.info(
+        this.logger.info(
             `Sending batch of to-device messages. type=${request.event_type} txnid=${request.txn_id}`,
             messageList,
         );

src/rust-crypto/RoomEncryptor.ts

@@ -29,7 +29,7 @@ import {
 import { EventType } from "../@types/event.ts";
 import { type IContent, type MatrixEvent } from "../models/event.ts";
 import { type Room } from "../models/room.ts";
-import { type Logger, logger, LogSpan } from "../logger.ts";
+import { type Logger, LogSpan } from "../logger.ts";
 import { type KeyClaimManager } from "./KeyClaimManager.ts";
 import { type RoomMember } from "../models/room-member.ts";
 import { HistoryVisibility } from "../@types/partials.ts";
@@ -44,8 +44,6 @@ import { type DeviceIsolationMode, DeviceIsolationModeKind } from "../crypto-api
  * @internal
  */
 export class RoomEncryptor {
-    private readonly prefixedLogger: Logger;
-
     /** whether the room members have been loaded and tracked for the first time */
     private lazyLoadedMembersResolved = false;
 
@@ -57,21 +55,21 @@ export class RoomEncryptor {
     private currentEncryptionPromise: Promise<void> = Promise.resolve();
 
     /**
+     * @param prefixedLogger - A logger to use for log messages.
      * @param olmMachine - The rust-sdk's OlmMachine
      * @param keyClaimManager - Our KeyClaimManager, which manages the queue of one-time-key claim requests
      * @param outgoingRequestManager - The OutgoingRequestManager, which manages the queue of outgoing requests.
      * @param room - The room we want to encrypt for
      * @param encryptionSettings - body of the m.room.encryption event currently in force in this room
      */
     public constructor(
+        private readonly prefixedLogger: Logger,
         private readonly olmMachine: OlmMachine,
         private readonly keyClaimManager: KeyClaimManager,
         private readonly outgoingRequestManager: OutgoingRequestsManager,
         private readonly room: Room,
         private encryptionSettings: IContent,
     ) {
-        this.prefixedLogger = logger.getChild(`[${room.roomId} encryption]`);
-
         // start tracking devices for any users already known to be in this room.
         // Do not load members here, would defeat lazy loading.
         const members = room.getJoinedMembers();
@@ -212,7 +210,7 @@ export class RoomEncryptor {
         // This could end up being racy (if two calls to ensureEncryptionSession happen at the same time), but that's
         // not a particular problem, since `OlmMachine.updateTrackedUsers` just adds any users that weren't already tracked.
         if (!this.lazyLoadedMembersResolved) {
-            await logDuration(this.prefixedLogger, "loadMembersIfNeeded: updateTrackedUsers", async () => {
+            await logDuration(logger, "loadMembersIfNeeded: updateTrackedUsers", async () => {
                 await this.olmMachine.updateTrackedUsers(members.map((u) => new RustSdkCryptoJs.UserId(u.userId)));
             });
             logger.debug(`Updated tracked users`);
@@ -229,7 +227,7 @@ export class RoomEncryptor {
             // XXX future improvement process only KeysQueryRequests for the users that have never been queried.
             logger.debug(`Processing outgoing requests`);
 
-            await logDuration(this.prefixedLogger, "doProcessOutgoingRequests", async () => {
+            await logDuration(logger, "doProcessOutgoingRequests", async () => {
                 await this.outgoingRequestManager.doProcessOutgoingRequests();
             });
         } else {
@@ -250,7 +248,7 @@ export class RoomEncryptor {
 
         const userList = members.map((u) => new UserId(u.userId));
 
-        await logDuration(this.prefixedLogger, "ensureSessionsForUsers", async () => {
+        await logDuration(logger, "ensureSessionsForUsers", async () => {
             await this.keyClaimManager.ensureSessionsForUsers(logger, userList);
         });
 
@@ -289,7 +287,7 @@ export class RoomEncryptor {
                 break;
         }
 
-        await logDuration(this.prefixedLogger, "shareRoomKey", async () => {
+        await logDuration(logger, "shareRoomKey", async () => {
             const shareMessages: ToDeviceRequest[] = await this.olmMachine.shareRoomKey(
                 new RoomId(this.room.roomId),
                 // safe to pass without cloning, as it's not reused here (before or after)