Skip to content

Commit

Permalink
Element-R: reduce log spam when checking server key backup (#3826)
Browse files Browse the repository at this point in the history 
* 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".

* Improve integ tests for backup query after UTD

* Yield in the backup decryption loop

* Fix another broken test
  • Loading branch information
@richvdh
richvdh authored Oct 26, 2023
1 parent f8f22a3 commit 07a9eb3
Show file tree
Hide file tree
Showing 5 changed files with 245 additions and 97 deletions.
13 changes: 11 additions & 2 deletions spec/integ/crypto/crypto.spec.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,14 @@ import { MockResponse, MockResponseFunction } from "fetch-mock";
import Olm from "@matrix-org/olm";

import * as testUtils from "../../test-utils/test-utils";
import { CRYPTO_BACKENDS, getSyncResponse, InitCrypto, mkEventCustom, syncPromise } from "../../test-utils/test-utils";
import {
advanceTimersUntil,
CRYPTO_BACKENDS,
getSyncResponse,
InitCrypto,
mkEventCustom,
syncPromise,
} from "../../test-utils/test-utils";
import * as testData from "../../test-utils/test-data";
import {
BOB_SIGNED_CROSS_SIGNING_KEYS_DATA,
Expand Down Expand Up @@ -2767,7 +2774,9 @@ describe.each(Object.entries(CRYPTO_BACKENDS))("crypto (%s)", (backend: string,
fetchMock.get("express:/_matrix/client/v3/room_keys/keys", keyBackupData);

// should be able to restore from 4S
const importResult = await aliceClient.restoreKeyBackupWithSecretStorage(check!.backupInfo!);
const importResult = await advanceTimersUntil(
aliceClient.restoreKeyBackupWithSecretStorage(check!.backupInfo!),
);
expect(importResult.imported).toStrictEqual(1);
});

Expand Down
207 changes: 144 additions & 63 deletions spec/integ/crypto/megolm-backup.spec.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,10 +23,17 @@ import { SyncResponder } from "../../test-utils/SyncResponder";
import { E2EKeyReceiver } from "../../test-utils/E2EKeyReceiver";
import { E2EKeyResponder } from "../../test-utils/E2EKeyResponder";
import { mockInitialApiRequests } from "../../test-utils/mockEndpoints";
import { awaitDecryption, CRYPTO_BACKENDS, InitCrypto, syncPromise } from "../../test-utils/test-utils";
import {
advanceTimersUntil,
awaitDecryption,
CRYPTO_BACKENDS,
InitCrypto,
syncPromise,
} from "../../test-utils/test-utils";
import * as testData from "../../test-utils/test-data";
import { KeyBackupInfo } from "../../../src/crypto-api/keybackup";
import { IKeyBackup } from "../../../src/crypto/backup";
import { flushPromises } from "../../test-utils/flushPromises";

const ROOM_ID = testData.TEST_ROOM_ID;

Expand Down Expand Up @@ -110,9 +117,9 @@ describe.each(Object.entries(CRYPTO_BACKENDS))("megolm-keys backup (%s)", (backe
/** an object which intercepts `/keys/query` requests on the test homeserver */
let e2eKeyResponder: E2EKeyResponder;

jest.useFakeTimers();

beforeEach(async () => {
jest.useFakeTimers();

// anything that we don't have a specific matcher for silently returns a 404
fetchMock.catch(404);
fetchMock.config.warnOnFallback = false;
Expand All @@ -134,6 +141,7 @@ describe.each(Object.entries(CRYPTO_BACKENDS))("megolm-keys backup (%s)", (backe
await jest.runAllTimersAsync();

fetchMock.mockReset();
jest.restoreAllMocks();
});

async function initTestClient(opts: Partial<ICreateClientOpts> = {}): Promise<MatrixClient> {
Expand All @@ -149,64 +157,131 @@ describe.each(Object.entries(CRYPTO_BACKENDS))("megolm-keys backup (%s)", (backe
return client;
}

it("Alice checks key backups when receiving a message she can't decrypt", async function () {
const syncResponse = {
describe("Key backup check on UTD message", () => {
// sync response which contains an encrypted event
const SYNC_RESPONSE = {
next_batch: 1,
rooms: {
join: {
[ROOM_ID]: {
timeline: {
events: [testData.ENCRYPTED_EVENT],
},
},
},
},
rooms: { join: { [ROOM_ID]: { timeline: { events: [testData.ENCRYPTED_EVENT] } } } },
};

fetchMock.get("express:/_matrix/client/v3/room_keys/keys/:room_id/:session_id", (url, request) => {
// check that the version is correct
const version = new URLSearchParams(new URL(url).search).get("version");
if (version == "1") {
return testData.CURVE25519_KEY_BACKUP_DATA;
} else {
return {
status: 403,
body: {
current_version: "1",
errcode: "M_WRONG_ROOM_KEYS_VERSION",
error: "Wrong backup version.",
},
};
const EXPECTED_URL =
[
"https://alice-server.com/_matrix/client/v3/room_keys/keys",
encodeURIComponent(testData.TEST_ROOM_ID),
encodeURIComponent(testData.MEGOLM_SESSION_DATA.session_id),
].join("/") + "?version=1";

/** Flush promises enough times to get the crypto stacks to make the backup request */
async function flushBackupRequest() {
// we have to run flushPromises lots of times. It seems like each time the rust code touches indexeddb,
// it needs another round of flushPromises to progress, or something.
for (let i = 0; i < 10; i++) {
await flushPromises();
}
}

beforeEach(async () => {
fetchMock.get("path:/_matrix/client/v3/room_keys/version", testData.SIGNED_BACKUP_DATA);

// ignore requests to send room key requests
fetchMock.put("express:/_matrix/client/v3/sendToDevice/m.room_key_request/:request_id", {});

aliceClient = await initTestClient();
const aliceCrypto = aliceClient.getCrypto()!;
await aliceCrypto.storeSessionBackupPrivateKey(
Buffer.from(testData.BACKUP_DECRYPTION_KEY_BASE64, "base64"),
testData.SIGNED_BACKUP_DATA.version!,
);

// start after saving the private key
await aliceClient.startClient();

// tell Alice to trust the dummy device that signed the backup, and re-check the backup.
// XXX: should we automatically re-check after a device becomes verified?
await waitForDeviceList();
await aliceClient.getCrypto()!.setDeviceVerified(testData.TEST_USER_ID, testData.TEST_DEVICE_ID);
await aliceClient.getCrypto()!.checkKeyBackupAndEnable();
});

fetchMock.get("path:/_matrix/client/v3/room_keys/version", testData.SIGNED_BACKUP_DATA);
it("Alice checks key backups when receiving a message she can't decrypt", async () => {
fetchMock.get("express:/_matrix/client/v3/room_keys/keys/:room_id/:session_id", (url, request) => {
// check that the version is correct
const version = new URLSearchParams(new URL(url).search).get("version");
if (version == "1") {
return testData.CURVE25519_KEY_BACKUP_DATA;
} else {
return {
status: 403,
body: {
current_version: "1",
errcode: "M_WRONG_ROOM_KEYS_VERSION",
error: "Wrong backup version.",
},
};
}
});

aliceClient = await initTestClient();
const aliceCrypto = aliceClient.getCrypto()!;
await aliceCrypto.storeSessionBackupPrivateKey(
Buffer.from(testData.BACKUP_DECRYPTION_KEY_BASE64, "base64"),
testData.SIGNED_BACKUP_DATA.version!,
);
// Send Alice a message that she won't be able to decrypt, and check that she fetches the key from the backup.
syncResponder.sendOrQueueSyncResponse(SYNC_RESPONSE);
await syncPromise(aliceClient);

// start after saving the private key
await aliceClient.startClient();
const room = aliceClient.getRoom(ROOM_ID)!;
const event = room.getLiveTimeline().getEvents()[0];
await advanceTimersUntil(awaitDecryption(event, { waitOnDecryptionFailure: true }));

// tell Alice to trust the dummy device that signed the backup, and re-check the backup.
// XXX: should we automatically re-check after a device becomes verified?
await waitForDeviceList();
await aliceCrypto.setDeviceVerified(testData.TEST_USER_ID, testData.TEST_DEVICE_ID);
await aliceClient.getCrypto()!.checkKeyBackupAndEnable();
expect(event.getContent()).toEqual(testData.CLEAR_EVENT.content);
});

it("handles error on backup query gracefully", async () => {
jest.spyOn(console, "error").mockImplementation(() => {});

fetchMock.get(
"express:/_matrix/client/v3/room_keys/keys/:room_id/:session_id",
{ status: 404, body: { errcode: "M_NOT_FOUND" } },
{ name: "getKey" },
);

// Now, send Alice a message that she won't be able to decrypt, and check that she fetches the key from the backup.
syncResponder.sendOrQueueSyncResponse(syncResponse);
await syncPromise(aliceClient);
// Send Alice a message that she won't be able to decrypt
syncResponder.sendOrQueueSyncResponse(SYNC_RESPONSE);
await flushBackupRequest();

const calls = fetchMock.calls("getKey");
expect(calls.length).toEqual(1);
expect(calls[0][0]).toEqual(EXPECTED_URL);

await flushBackupRequest();

// we should not have logged an error.
// eslint-disable-next-line no-console
expect(console.error).not.toHaveBeenCalled();
});

it("Only queries once", async () => {
fetchMock.get(
"express:/_matrix/client/v3/room_keys/keys/:room_id/:session_id",
{ status: 404, body: { errcode: "M_NOT_FOUND" } },
{ name: "getKey" },
);

const room = aliceClient.getRoom(ROOM_ID)!;
const event = room.getLiveTimeline().getEvents()[0];
await awaitDecryption(event, { waitOnDecryptionFailure: true });
// Send Alice a message that she won't be able to decrypt
syncResponder.sendOrQueueSyncResponse(SYNC_RESPONSE);
await flushBackupRequest();
const calls = fetchMock.calls("getKey");
expect(calls.length).toEqual(1);
expect(calls[0][0]).toEqual(EXPECTED_URL);

expect(event.getContent()).toEqual(testData.CLEAR_EVENT.content);
fetchMock.resetHistory();

// another message
const event2 = { ...testData.ENCRYPTED_EVENT, event_id: "$event2" };
const syncResponse2 = {
next_batch: 1,
rooms: { join: { [ROOM_ID]: { timeline: { events: [event2] } } } },
};
syncResponder.sendOrQueueSyncResponse(syncResponse2);
await flushBackupRequest();
expect(fetchMock.calls("getKey").length).toEqual(0);
});
});

describe("recover from backup", () => {
Expand Down Expand Up @@ -240,22 +315,26 @@ describe.each(Object.entries(CRYPTO_BACKENDS))("megolm-keys backup (%s)", (backe
onKeyCached = resolve;
});

const result = await aliceClient.restoreKeyBackupWithRecoveryKey(
testData.BACKUP_DECRYPTION_KEY_BASE58,
undefined,
undefined,
check!.backupInfo!,
{
cacheCompleteCallback: () => onKeyCached(),
},
const result = await advanceTimersUntil(
aliceClient.restoreKeyBackupWithRecoveryKey(
testData.BACKUP_DECRYPTION_KEY_BASE58,
undefined,
undefined,
check!.backupInfo!,
{
cacheCompleteCallback: () => onKeyCached(),
},
),
);

expect(result.imported).toStrictEqual(1);

await awaitKeyCached;

// The key should be now cached
const afterCache = await aliceClient.restoreKeyBackupWithCache(undefined, undefined, check!.backupInfo!);
const afterCache = await advanceTimersUntil(
aliceClient.restoreKeyBackupWithCache(undefined, undefined, check!.backupInfo!),
);

expect(afterCache.imported).toStrictEqual(1);
});
Expand All @@ -278,11 +357,13 @@ describe.each(Object.entries(CRYPTO_BACKENDS))("megolm-keys backup (%s)", (backe

const check = await aliceCrypto.checkKeyBackupAndEnable();

const result = await aliceClient.restoreKeyBackupWithRecoveryKey(
testData.BACKUP_DECRYPTION_KEY_BASE58,
ROOM_ID,
testData.MEGOLM_SESSION_DATA.session_id,
check!.backupInfo!,
const result = await advanceTimersUntil(
aliceClient.restoreKeyBackupWithRecoveryKey(
testData.BACKUP_DECRYPTION_KEY_BASE58,
ROOM_ID,
testData.MEGOLM_SESSION_DATA.session_id,
check!.backupInfo!,
),
);

expect(result.imported).toStrictEqual(1);
Expand Down
24 changes: 22 additions & 2 deletions spec/test-utils/test-utils.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -537,8 +537,6 @@ export async function awaitDecryption(
});
}

export const emitPromise = (e: EventEmitter, k: string): Promise<any> => new Promise((r) => e.once(k, r));

export const mkPusher = (extra: Partial<IPusher> = {}): IPusher => ({
app_display_name: "app",
app_id: "123",
Expand All @@ -561,3 +559,25 @@ CRYPTO_BACKENDS["rust-sdk"] = (client: MatrixClient) => client.initRustCrypto();
if (global.Olm) {
CRYPTO_BACKENDS["libolm"] = (client: MatrixClient) => client.initCrypto();
}

export const emitPromise = (e: EventEmitter, k: string): Promise<any> => new Promise((r) => e.once(k, r));

/**
* Advance the fake timers in a loop until the given promise resolves or rejects.
*
* Returns the result of the promise.
*
* This can be useful when there are multiple steps in the code which require an iteration of the event loop.
*/
export async function advanceTimersUntil<T>(promise: Promise<T>): Promise<T> {
let resolved = false;
promise.finally(() => {
resolved = true;
});

while (!resolved) {
await jest.advanceTimersByTimeAsync(1);
}

return await promise;
}
7 changes: 5 additions & 2 deletions src/rust-crypto/backup.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,7 @@ import { logger } from "../logger";
import { ClientPrefix, IHttpOpts, MatrixError, MatrixHttpApi, Method } from "../http-api";
import { CryptoEvent, IMegolmSessionData } from "../crypto";
import { TypedEventEmitter } from "../models/typed-event-emitter";
import { encodeUri } from "../utils";
import { encodeUri, immediate } from "../utils";
import { OutgoingRequestProcessor } from "./OutgoingRequestProcessor";
import { sleep } from "../utils";
import { BackupDecryptor } from "../common-crypto/CryptoBackend";
Expand Down Expand Up @@ -460,14 +460,17 @@ 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,
),
);
decrypted.session_id = sessionId;
keys.push(decrypted);

// there might be lots of sessions, so don't hog the event loop
await immediate();
} catch (e) {
logger.log("Failed to decrypt megolm session from backup", e, sessionData);
}
Expand Down
Loading

0 comments on commit 07a9eb3

Please sign in to comment.