Element-R: reduce log spam when checking server key backup

Fixes a lot of spam in the logs about "uncaught in promise: No room_keys found".
matrix-org · Oct 23, 2023 · 217fef9 · 217fef9
1 parent 2f3f0b3
commit 217fef9
Show file tree

Hide file tree

Showing 2 changed files with 64 additions and 29 deletions.
diff --git a/src/rust-crypto/backup.ts b/src/rust-crypto/backup.ts
@@ -460,7 +460,7 @@ export class RustBackupDecryptor implements BackupDecryptor {
         for (const [sessionId, sessionData] of Object.entries(ciphertexts)) {
             try {
                 const decrypted = JSON.parse(
-                    await this.decryptionKey.decryptV1(
+                    this.decryptionKey.decryptV1(
                         sessionData.session_data.ephemeral,
                         sessionData.session_data.mac,
                         sessionData.session_data.ciphertext,

diff --git a/src/rust-crypto/rust-crypto.ts b/src/rust-crypto/rust-crypto.ts
@@ -161,43 +161,72 @@ export class RustCrypto extends TypedEventEmitter<RustCryptoEvents, RustCryptoEv
     }
 
     /**
-     * Attempts to retrieve a session from a key backup, if enough time
+     * Starts an attempt to retrieve a session from a key backup, if enough time
      * has elapsed since the last check for this session id.
+     *
+     * If a backup is found, it is decrypted and imported.
+     *
+     * @param targetRoomId - ID of the room that the session is used in.
+     * @param targetSessionId - ID of the session for which to check backup.
      */
-    public async queryKeyBackupRateLimited(targetRoomId: string, targetSessionId: string): Promise<void> {
-        const backupKeys: RustSdkCryptoJs.BackupKeys = await this.olmMachine.getBackupKeys();
-        if (!backupKeys.decryptionKey) return;
-        const version = backupKeys.backupVersion;
-
+    public startQueryKeyBackupRateLimited(targetRoomId: string, targetSessionId: string): void {
         const now = new Date().getTime();
-        if (
-            !this.sessionLastCheckAttemptedTime[targetSessionId!] ||
-            now - this.sessionLastCheckAttemptedTime[targetSessionId!] > KEY_BACKUP_CHECK_RATE_LIMIT
-        ) {
+        const lastCheck = this.sessionLastCheckAttemptedTime[targetSessionId];
+        if (!lastCheck || now - lastCheck > KEY_BACKUP_CHECK_RATE_LIMIT) {
             this.sessionLastCheckAttemptedTime[targetSessionId!] = now;
-
-            const path = encodeUri("/room_keys/keys/$roomId/$sessionId", {
-                $roomId: targetRoomId,
-                $sessionId: targetSessionId,
+            this.queryKeyBackup(targetRoomId, targetSessionId).catch((e) => {
+                this.logger.error(`Unhandled error while checking key backup for session ${targetSessionId}`, e);
             });
+        } else {
+            const lastCheckStr = new Date(lastCheck).toISOString();
+            this.logger.debug(
+                `Not checking key backup for session ${targetSessionId} (last checked at ${lastCheckStr})`,
+            );
+        }
+    }
+
+    /**
+     * Helper for {@link RustCrypto#startQueryKeyBackupRateLimited}.
+     *
+     * Requests the backup and imports it. Doesn't do any rate-limiting.
+     *
+     * @param targetRoomId - ID of the room that the session is used in.
+     * @param targetSessionId - ID of the session for which to check backup.
+     */
+    private async queryKeyBackup(targetRoomId: string, targetSessionId: string): Promise<void> {
+        const backupKeys: RustSdkCryptoJs.BackupKeys = await this.olmMachine.getBackupKeys();
+        if (!backupKeys.decryptionKey) {
+            this.logger.debug(`Not checking key backup for session ${targetSessionId} (no decryption key)`);
+            return;
+        }
+
+        this.logger.debug(`Checking key backup for session ${targetSessionId}`);
+
+        const version = backupKeys.backupVersion;
+        const path = encodeUri("/room_keys/keys/$roomId/$sessionId", {
+            $roomId: targetRoomId,
+            $sessionId: targetSessionId,
+        });
 
-            const res = await this.http.authedRequest<KeyBackupSession>(Method.Get, path, { version }, undefined, {
+        let res: KeyBackupSession;
+        try {
+            res = await this.http.authedRequest<KeyBackupSession>(Method.Get, path, { version }, undefined, {
                 prefix: ClientPrefix.V3,
             });
+        } catch (e) {
+            this.logger.info(`No luck requesting key backup for session ${targetSessionId}: ${e}`);
+            return;
+        }
 
-            if (this.stopped) return;
+        if (this.stopped) return;
 
-            const backupDecryptor = new RustBackupDecryptor(backupKeys.decryptionKey);
-            if (res) {
-                const sessionsToImport: Record<string, KeyBackupSession> = {};
-                sessionsToImport[targetSessionId] = res;
-                const keys = await backupDecryptor.decryptSessions(sessionsToImport);
-                for (const k of keys) {
-                    k.room_id = targetRoomId!;
-                }
-                await this.importRoomKeys(keys);
-            }
+        const backupDecryptor = new RustBackupDecryptor(backupKeys.decryptionKey);
+        const sessionsToImport: Record<string, KeyBackupSession> = { [targetSessionId]: res };
+        const keys = await backupDecryptor.decryptSessions(sessionsToImport);
+        for (const k of keys) {
+            k.room_id = targetRoomId;
         }
+        await this.importRoomKeys(keys);
     }
 
     /**
@@ -1619,7 +1648,10 @@ class EventDecryptor {
                                 session: content.sender_key + "|" + content.session_id,
                             },
                         );
-                        this.crypto.queryKeyBackupRateLimited(event.getRoomId()!, event.getWireContent().session_id!);
+                        this.crypto.startQueryKeyBackupRateLimited(
+                            event.getRoomId()!,
+                            event.getWireContent().session_id!,
+                        );
                         break;
                     }
                     case RustSdkCryptoJs.DecryptionErrorCode.UnknownMessageIndex: {
@@ -1630,7 +1662,10 @@ class EventDecryptor {
                                 session: content.sender_key + "|" + content.session_id,
                             },
                         );
-                        this.crypto.queryKeyBackupRateLimited(event.getRoomId()!, event.getWireContent().session_id!);
+                        this.crypto.startQueryKeyBackupRateLimited(
+                            event.getRoomId()!,
+                            event.getWireContent().session_id!,
+                        );
                         break;
                     }
                     // We don't map MismatchedIdentityKeys for now, as there is no equivalent in legacy.