From 52c32f37c3bd0f0423e7c885a42c2c029a682c7a Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Sat, 13 Jul 2024 13:36:45 +0100 Subject: [PATCH] Add logging to encryption setup (#12765) * Add logging to `getSecretStorageKey` * Replace call to deprecated MatrixClient.hasSecretStorageKey * Add/improve logging in `accessSecretStorage` * Add/improve logging in SetupEncryptionStore.usePassPhrase --- src/SecurityManager.ts | 46 ++++++++++++++++++++++-------- src/stores/SetupEncryptionStore.ts | 36 ++++++++++++----------- test/SecurityManager-test.ts | 4 +-- 3 files changed, 56 insertions(+), 30 deletions(-) diff --git a/src/SecurityManager.ts b/src/SecurityManager.ts index c5958a6f48..c1c4e7a72b 100644 --- a/src/SecurityManager.ts +++ b/src/SecurityManager.ts @@ -111,14 +111,17 @@ async function getSecretStorageKey({ } [keyId, keyInfo] = keyInfoEntries[0]; } + logger.debug(`getSecretStorageKey: request for 4S keys [${Object.keys(keyInfos)}]: looking for key ${keyId}`); // Check the in-memory cache if (secretStorageBeingAccessed && secretStorageKeys[keyId]) { + logger.debug(`getSecretStorageKey: returning key ${keyId} from cache`); return [keyId, secretStorageKeys[keyId]]; } if (dehydrationCache.key) { if (await MatrixClientPeg.safeGet().checkSecretStorageKey(dehydrationCache.key, keyInfo)) { + logger.debug("getSecretStorageKey: returning key from dehydration cache"); cacheSecretStorageKey(keyId, keyInfo, dehydrationCache.key); return [keyId, dehydrationCache.key]; } @@ -126,11 +129,12 @@ async function getSecretStorageKey({ const keyFromCustomisations = ModuleRunner.instance.extensions.cryptoSetup.getSecretStorageKey(); if (keyFromCustomisations) { - logger.log("CryptoSetupExtension: Using key from extension (secret storage)"); + logger.log("getSecretStorageKey: Using secret storage key from CryptoSetupExtension"); cacheSecretStorageKey(keyId, keyInfo, keyFromCustomisations); return [keyId, keyFromCustomisations]; } + logger.debug("getSecretStorageKey: prompting user for key"); const inputToKey = makeInputToKey(keyInfo); const { finished } = Modal.createDialog( AccessSecretStorageDialog, @@ -158,6 +162,7 @@ async function getSecretStorageKey({ if (!keyParams) { throw new AccessCancelledError(); } + logger.debug("getSecretStorageKey: got key from user"); const key = await inputToKey(keyParams); // Save to cache to avoid future prompts in the current session @@ -282,11 +287,13 @@ export const crossSigningCallbacks: ICryptoCallbacks = { * @param func - The operation to be wrapped. */ export async function withSecretStorageKeyCache(func: () => Promise): Promise { + logger.debug("SecurityManager: enabling 4S key cache"); secretStorageBeingAccessed = true; try { return await func(); } finally { // Clear secret storage key cache now that work is complete + logger.debug("SecurityManager: disabling 4S key cache"); secretStorageBeingAccessed = false; secretStorageKeys = {}; secretStorageKeyInfo = {}; @@ -322,7 +329,21 @@ export async function accessSecretStorage(func = async (): Promise => {}, async function doAccessSecretStorage(func: () => Promise, forceReset: boolean): Promise { try { const cli = MatrixClientPeg.safeGet(); - if (!(await cli.hasSecretStorageKey()) || forceReset) { + const crypto = cli.getCrypto(); + if (!crypto) { + throw new Error("End-to-end encryption is disabled - unable to access secret storage."); + } + + let createNew = false; + if (forceReset) { + logger.debug("accessSecretStorage: resetting 4S"); + createNew = true; + } else if (!(await cli.secretStorage.hasKey())) { + logger.debug("accessSecretStorage: no 4S key configured, creating a new one"); + createNew = true; + } + + if (createNew) { // This dialog calls bootstrap itself after guiding the user through // passphrase creation. const { finished } = Modal.createDialogAsync( @@ -350,13 +371,10 @@ async function doAccessSecretStorage(func: () => Promise, forceReset: bool throw new Error("Secret storage creation canceled"); } } else { - const crypto = cli.getCrypto(); - if (!crypto) { - throw new Error("End-to-end encryption is disabled - unable to access secret storage."); - } - + logger.debug("accessSecretStorage: bootstrapCrossSigning"); await crypto.bootstrapCrossSigning({ authUploadDeviceSigningKeys: async (makeRequest): Promise => { + logger.debug("accessSecretStorage: performing UIA to upload cross-signing keys"); const { finished } = Modal.createDialog(InteractiveAuthDialog, { title: _t("encryption|bootstrap_title"), matrixClient: cli, @@ -366,8 +384,10 @@ async function doAccessSecretStorage(func: () => Promise, forceReset: bool if (!confirmed) { throw new Error("Cross-signing key upload auth canceled"); } + logger.debug("accessSecretStorage: Cross-signing key upload successful"); }, }); + logger.debug("accessSecretStorage: bootstrapSecretStorage"); await crypto.bootstrapSecretStorage({}); const keyId = Object.keys(secretStorageKeys)[0]; @@ -376,21 +396,23 @@ async function doAccessSecretStorage(func: () => Promise, forceReset: bool if (secretStorageKeyInfo[keyId] && secretStorageKeyInfo[keyId].passphrase) { dehydrationKeyInfo = { passphrase: secretStorageKeyInfo[keyId].passphrase }; } - logger.log("Setting dehydration key"); + logger.log("accessSecretStorage: Setting dehydration key"); await cli.setDehydrationKey(secretStorageKeys[keyId], dehydrationKeyInfo, "Backup device"); } else if (!keyId) { - logger.warn("Not setting dehydration key: no SSSS key found"); + logger.warn("accessSecretStorage: Not setting dehydration key: no SSSS key found"); } else { - logger.log("Not setting dehydration key: feature disabled"); + logger.log("accessSecretStorage: Not setting dehydration key: feature disabled"); } } + logger.debug("accessSecretStorage: 4S now ready"); // `return await` needed here to ensure `finally` block runs after the // inner operation completes. - return await func(); + await func(); + logger.debug("accessSecretStorage: operation complete"); } catch (e) { ModuleRunner.instance.extensions.cryptoSetup.catchAccessSecretStorageError(e as Error); - logger.error(e); + logger.error("accessSecretStorage: error during operation", e); // Re-throw so that higher level logic can abort as needed throw e; } diff --git a/src/stores/SetupEncryptionStore.ts b/src/stores/SetupEncryptionStore.ts index dce523875e..62a3412d81 100644 --- a/src/stores/SetupEncryptionStore.ts +++ b/src/stores/SetupEncryptionStore.ts @@ -135,6 +135,7 @@ export class SetupEncryptionStore extends EventEmitter { } public async usePassPhrase(): Promise { + logger.debug("SetupEncryptionStore.usePassphrase"); this.phase = Phase.Busy; this.emit("update"); try { @@ -142,21 +143,21 @@ export class SetupEncryptionStore extends EventEmitter { const backupInfo = await cli.getKeyBackupVersion(); this.backupInfo = backupInfo; this.emit("update"); - // The control flow is fairly twisted here... - // For the purposes of completing security, we only wait on getting - // as far as the trust check and then show a green shield. - // We also begin the key backup restore as well, which we're - // awaiting inside `accessSecretStorage` only so that it keeps your - // passphase cached for that work. This dialog itself will only wait - // on the first trust check, and the key backup restore will happen - // in the background. + await new Promise((resolve: (value?: unknown) => void, reject: (reason?: any) => void) => { accessSecretStorage(async (): Promise => { - // The remaining tasks (device dehydration and restoring - // key backup) may take some time due to processing many - // to-device messages in the case of device dehydration, or - // having many keys to restore in the case of key backups, - // so we allow the dialog to advance before this. + // `accessSecretStorage` will call `boostrapCrossSigning` and `bootstrapSecretStorage`, so that + // should be enough to ensure that our device is correctly cross-signed. + // + // The remaining tasks (device dehydration and restoring key backup) may take some time due to + // processing many to-device messages in the case of device dehydration, or having many keys to + // restore in the case of key backups, so we allow the dialog to advance before this. + // + // However, we need to keep the 4S key cached, so we stay inside `accessSecretStorage`. + logger.debug( + "SetupEncryptionStore.usePassphrase: cross-signing and secret storage set up; checking " + + "dehydration and backup in the background", + ); resolve(); await initialiseDehydration(); @@ -168,14 +169,17 @@ export class SetupEncryptionStore extends EventEmitter { }); if (await cli.getCrypto()?.getCrossSigningKeyId()) { + logger.debug("SetupEncryptionStore.usePassphrase: done"); this.phase = Phase.Done; this.emit("update"); } } catch (e) { - if (!(e instanceof AccessCancelledError)) { - logger.log(e); + if (e instanceof AccessCancelledError) { + logger.debug("SetupEncryptionStore.usePassphrase: user cancelled access to secret storage"); + } else { + logger.log("SetupEncryptionStore.usePassphrase: error", e); } - // this will throw if the user hits cancel, so ignore + this.phase = Phase.Intro; this.emit("update"); } diff --git a/test/SecurityManager-test.ts b/test/SecurityManager-test.ts index 15d1eb1dec..13d5f2f63f 100644 --- a/test/SecurityManager-test.ts +++ b/test/SecurityManager-test.ts @@ -31,7 +31,7 @@ describe("SecurityManager", () => { bootstrapSecretStorage: () => {}, } as unknown as CryptoApi; const client = stubClient(); - mocked(client.hasSecretStorageKey).mockResolvedValue(true); + client.secretStorage.hasKey = jest.fn().mockResolvedValue(true); mocked(client.getCrypto).mockReturnValue(crypto); // When I run accessSecretStorage @@ -48,7 +48,7 @@ describe("SecurityManager", () => { it("throws if crypto is unavailable", async () => { // Given a client with no crypto const client = stubClient(); - mocked(client.hasSecretStorageKey).mockResolvedValue(true); + client.secretStorage.hasKey = jest.fn().mockResolvedValue(true); mocked(client.getCrypto).mockReturnValue(undefined); // When I run accessSecretStorage