Fallback keys are cycled too quickly

[kegsay]

In this complement crypto test, it verifies that the fallback key is:

• used when run out of OTKs,
• can be used multiple times,
• is cycled when it has been used.

However, this test is flakey on rust. It fails because:

one_time_keys_test.go:158: @user-71-alice:hs1 (rust): Wait[!ExcNKImfHGMdhZjUAo:hs1]: timed out

where the test is waiting for an encrypted event to A) arrive and B) be decrypted. It arrives but fails to decrypt: rust.go:565: TimelineDiff change: &{ID:$MN2eva8reWolCQjYDb7qSRkqchbxXEX2G1BXbk_sfWw Text: Sender:@user-72-bob:hs1 Target: Membership: FailedToDecrypt:true}

Upon looking at the logs, the following appears:

2024-02-14T11:49:31.818275Z  INFO TestFallbackKeyIsUsedIfOneTimeKeysRunOut/{rust_hs1}|{js_hs1}: NewRustClient[@user-71-alice:hs1][VYMVRXKFBO] creating... | rust.go:0
...
// guessing this is the in-memory version, as it's pre https://github.com/matrix-org/matrix-rust-sdk/pull/3115
2024-02-14T11:49:31.940494Z DEBUG matrix_sdk_crypto::olm::account: No unused fallback keys were found on the server, generated a new fallback key. 
removed_fallback_key=None | crates/matrix-sdk-crypto/src/olm/account.rs:550 | spans: sync_stream{conn_id="encryption" with_e2ee=true} > sync_once > handle_response > preprocess_to_device_events > receive_sync_changes
...
2024-02-14T11:49:32.024951Z DEBUG matrix_sdk_crypto::olm::account: No unused fallback keys were found on the server, generated a new fallback key. 
removed_fallback_key=None | crates/matrix-sdk-crypto/src/olm/account.rs:550 | spans: sync_stream{conn_id="encryption" with_e2ee=true} > sync_once{pos="1"} > handle_response > preprocess_to_device_events > receive_sync_changes
...
2024-02-14T11:49:35.139395Z DEBUG matrix_sdk_crypto::olm::account: No unused fallback keys were found on the server, generated a new fallback key. 
removed_fallback_key=Some("curve25519:v3twqTB34U4/qMnTKo2Ua//ElZfmjUFIWyYS0Rzq6jk") | crates/matrix-sdk-crypto/src/olm/account.rs:550 | spans: sync_stream{conn_id="encryption" with_e2ee=true} > sync_once{pos="4"} > handle_response > preprocess_to_device_events > receive_sync_changes
...
2024-02-14T11:49:35.749521Z DEBUG matrix_sdk_crypto::olm::account: No unused fallback keys were found on the server, generated a new fallback key. 
removed_fallback_key=Some("curve25519:fE1Xt28vF9OxQsH9EsavYve6p99LkInWuvaszCJRWk8") | crates/matrix-sdk-crypto/src/olm/account.rs:550 | spans: sync_stream{conn_id="encryption" with_e2ee=true} > sync_once{pos="5"} > handle_response > preprocess_to_device_events > receive_sync_changes
...
2024-02-14T11:49:35.833983Z  WARN matrix_sdk_crypto::olm::account: Failed to create a new Olm session from a pre-key message:
InboundCreation(MissingOneTimeKey("curve25519:fE1Xt28vF9OxQsH9EsavYve6p99LkInWuvaszCJRWk8")) | crates/matrix-sdk-crypto/src/olm/account.rs:1213 | 
spans: sync_stream{conn_id="encryption" with_e2ee=true} > sync_once{pos="6"} > handle_response > preprocess_to_device_events > receive_sync_changes > receive_to_device_event{sender="@user-72-bob:hs1" event_type="m.room.encrypted" message_id="e89c05a039f2422eb2e80f6071233ad6"} > 
decrypt_to_device_event{algorithm="m.olm.v1.curve25519-aes-sha2"} > decrypt_olm_v1{sender_key="curve25519:JoK7cGOmsGoE7Y7z2DsG9Qk1E4AsnYcXxI597eQVXQo"} > decrypt_and_parse_olm_message{sender="@user-72-bob:hs1" sender_key="curve25519:JoK7cGOmsGoE7Y7z2DsG9Qk1E4AsnYcXxI597eQVXQo" PreKey(PreKeyMessage { session_keys: SessionKeys { identity_key: "JoK7cGOmsGoE7Y7z2DsG9Qk1E4AsnYcXxI597eQVXQo", base_key: "j9XzU9TUAJ+SFW+eBMGM4E+MmCju+tFR3DpTp84hYxU", one_time_key: "fE1Xt28vF9OxQsH9EsavYve6p99LkInWuvaszCJRWk8" }, message: Message { version: 3, ratchet_key: "curve25519:4Wf1KZFWs2ZQrUA4OzlWnfmUeH7NpSp0+CPCJVWuMh8", chain_index: 0, .. } }) session_id="FWLz+AuOCY+w+oT0qSc5DRVLDlt+gO/WLGrBF2q8qMI"}
...
2024-02-14T11:49:40.606398Z  INFO TestFallbackKeyIsUsedIfOneTimeKeysRunOut/{rust_hs1}|{js_hs1}: [@user-71-alice:hs1](rust) Close | rust.go:0

In other words:

• the fallback key is cycled out at 11:49:35: removed_fallback_key=Some("curve25519:fE1Xt28vF9OxQsH9EsavYve6p99LkInWuvaszCJRWk8")
• the to-device event using that key arrives in the same second: Failed to create a new Olm session from a pre-key message: InboundCreation(MissingOneTimeKey("curve25519:fE1Xt28vF9OxQsH9EsavYve6p99LkInWuvaszCJRWk8")

As per the fallback key MSC:

For this reason, clients should not store the private part of the fallback key indefinitely. For example, client should only store at most two fallback keys: the current fallback key (that it has not yet received any messages for) and the previous fallback key, and should remove the previous fallback key once it is reasonably certain that it has received all the messages that use it (for example, one hour after receiving the first message that used it).

https://github.com/uhoreg/matrix-doc/blob/fallback_keys/proposals/2732-olm-fallback-keys.md#security-considerations

We should probably hold onto the fallback key for 1 hour before deleting it entirely.

[kegsay]

To elaborate, this code cycles the fallback key and generates a new one: https://github.com/matrix-org/vodozemac/blob/8d0e0f704adeaeacd1cfd66c59ca319e3f1fe016/src/olm/account/fallback_keys.rs#L75:L85

This is called from generate_fallback_key_helper which logs "No unused fallback keys were found on the server, generated a new fallback key.".

update_key_counts calls generate_fallback_key_helper if the response realises there is no fallback key.

Proposal: have a "historical" fallback keys field in the account pickle, which includes the timestamp when it got cycled out. Then check historical fallback keys for up to 1 hour after cycling.