Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 5 commits into from
Oct 26, 2023
Merged

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

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
217fef9
Element-R: reduce log spam when checking server key backup
richvdh Oct 23, 2023
bd97c17
Improve integ tests for backup query after UTD
richvdh Oct 24, 2023
131c524
Yield in the backup decryption loop
richvdh Oct 25, 2023
51ae71e
Fix another broken test
richvdh Oct 25, 2023
2698c7d
Merge branch 'develop' into rav/element-r/silence_backup_spam
richvdh Oct 25, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
165 changes: 117 additions & 48 deletions spec/integ/crypto/megolm-backup.spec.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,7 @@ import { awaitDecryption, CRYPTO_BACKENDS, InitCrypto, syncPromise } from "../..
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 +111,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 +135,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 +151,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 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);
});

// 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);
it("handles error on backup query gracefully", async () => {
jest.spyOn(console, "error").mockImplementation(() => {});

const room = aliceClient.getRoom(ROOM_ID)!;
const event = room.getLiveTimeline().getEvents()[0];
await awaitDecryption(event, { waitOnDecryptionFailure: true });
fetchMock.get(
"express:/_matrix/client/v3/room_keys/keys/:room_id/:session_id",
{ status: 404, body: { errcode: "M_NOT_FOUND" } },
{ name: "getKey" },
);

expect(event.getContent()).toEqual(testData.CLEAR_EVENT.content);
// 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();
BillCarsonFr marked this conversation as resolved.
Show resolved Hide resolved
});

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" },
);

// 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);

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
2 changes: 1 addition & 1 deletion src/rust-crypto/backup.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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(
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this is slightly separate, but a cleanup while I was in the area.

decryptionKey.decryptV1 doesn't return a promise.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah I have seen it now that I use WebStorm. I am wondering if you shouldn't update the bindings to make it async?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added an await immediate() in 131c524 to make sure we don't block the event loop.

sessionData.session_data.ephemeral,
sessionData.session_data.mac,
sessionData.session_data.ciphertext,
Expand Down
91 changes: 63 additions & 28 deletions src/rust-crypto/rust-crypto.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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) => {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we might want to check if we have the private key before marking the check as attempted (sessionLastCheckAttemptedTime = now). Because if we attempt to get the key and you don't have the private key yet (verification not yet done) it will not retry until KEY_BACKUP_CHECK_RATE_LIMIT. So when you verify after login, you'll have to wait?
KEY_BACKUP_CHECK_RATE_LIMIT isn't that high currently, so maybe not too important though.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we might want to check if we have the private key before marking the check as attempted (sessionLastCheckAttemptedTime = now).

The problem with that is that it is racy: if two calls to startQueryKeyBackupRateLimited happen in quick succession (eg, because there are two messages in a sync response), then both will check sessionLastCheckAttemptedTime and find it ok, and go on to make a backup request. We need to make sure there is no await between the check and the update on sessionLastCheckAttemptedTime.

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);
}

/**
Expand Down Expand Up @@ -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: {
Expand All @@ -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.
Expand Down
Loading