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

@@ -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<T>(func: () => Promise<T>): Promise<T> {
+    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<void> => {},
 async function doAccessSecretStorage(func: () => Promise<void>, forceReset: boolean): Promise<void> {
     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<void>, forceReset: bool
                 throw new Error("Secret storage creation canceled");
             }
         } else {
-            const crypto = cli.getCrypto();
+            logger.debug("accessSecretStorage: bootstrapCrossSigning");
-            if (!crypto) {
-                throw new Error("End-to-end encryption is disabled - unable to access secret storage.");
-            }
-
             await crypto.bootstrapCrossSigning({
                 authUploadDeviceSigningKeys: async (makeRequest): Promise<void> => {
+                    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<void>, 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<void>, 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;
     }

src/stores/SetupEncryptionStore.ts

@@ -135,6 +135,7 @@ export class SetupEncryptionStore extends EventEmitter {
     }
 
     public async usePassPhrase(): Promise<void> {
+        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<void> => {
-                    // The remaining tasks (device dehydration and restoring
+                    // `accessSecretStorage` will call `boostrapCrossSigning` and `bootstrapSecretStorage`, so that
-                    // key backup) may take some time due to processing many
+                    // should be enough to ensure that our device is correctly cross-signed.
-                    // to-device messages in the case of device dehydration, or
+                    //
-                    // having many keys to restore in the case of key backups,
+                    // The remaining tasks (device dehydration and restoring key backup) may take some time due to
-                    // so we allow the dialog to advance before this.
+                    // 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)) {
+            if (e instanceof AccessCancelledError) {
-                logger.log(e);
+                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");
         }

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