Successful download from key backup, but 0 keys returned

[richvdh]

During analysis of a rageshake log after an unable-to-decrypt error, I see an attempt to download a copy of the session key from backup:

2024-02-03T20:51:01.676356Z DEBUG matrix_sdk::http_client: Sending request | crates/matrix-sdk/src/http_client/mod.rs:176 | spans: root > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9] config=RequestConfig { timeout: 30s } request_id="REQ-351" method=GET uri="https://matrix-client.matrix.org/_matrix/client/v3/room_keys/keys/!kCCQTCfnABLKGGvQjo:matrix.org/WhTC0Sfh+nvqIRERS%2F2uY1B6kbfMlBDQ4Tr0JBdKT4Y"}
2024-02-03T20:51:01.814849Z DEBUG matrix_sdk::http_client: Got response | crates/matrix-sdk/src/http_client/mod.rs:182 | spans: root > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9] config=RequestConfig { timeout: 30s } request_id="REQ-351" method=GET uri="https://matrix-client.matrix.org/_matrix/client/v3/room_keys/keys/!kCCQTCfnABLKGGvQjo:matrix.org/WhTC0Sfh+nvqIRERS%2F2uY1B6kbfMlBDQ4Tr0JBdKT4Y" status=200 response_size="795 B"}
2024-02-03T20:51:01.814966Z  INFO matrix_sdk_crypto::store: Successfully imported room keys total_count=0 imported_count=0 room_keys={} | crates/matrix-sdk-crypto/src/store/mod.rs:1555 | spans: root

What is strange here is that the request returns successfully, but total_count=0, implying that no keys were found. Walking through the rust-sdk code starting at matrix-sdk::encryption::backups::Backups::download_room_key, I cannot see any code path in which a successful request to /_matrix/client/v3/room_keys/keys/:room_id/:session_id results in total_count=0.

Unless I'm missing something obvious, I suggest adding more logging to understand what's going on.

[kegsay]

Is it possible the user just didn't upload keys? Or are you surprised that it's 200 OKing with 0 keys rather than 404ing?

[richvdh]

Is it possible the user just didn't upload keys? Or are you surprised that it's 200 OKing with 0 keys rather than 404ing?

Indeed. If the user hadn't uploaded keys for this session, it would be a 404.

[BillCarsonFr]

I have a case of this log caused by this error

2024-03-06T17:56:07.668032Z  WARN matrix_sdk::encryption::backups: Couldn't decrypt a room key we downloaded from backups, session ID: CoxdHe6LNVlcKzqHz3yWvxqUijLywBMw8dke27RJMOQ, error: Json(Error("invalid type: string \"EQCtWSJclhxEU9mGlF4erDHxIacpUQz70yjYVRPODTg\", expected an array of length 32", line: 1, column: 255)) | crates/matrix-sdk/src/encryption/backups/mod.rs:469


2024-03-06T17:56:07.669676Z  INFO matrix_sdk_crypto::store: Successfully imported room keys total_count=0 imported_count=0 room_keys={} | crates/matrix-sdk-crypto/src/store/mod.rs:1555

[BillCarsonFr]

A source of this bug has been found #3247

[richvdh]

I think we can probably ascribe the observed failures to #3247 which is now fixed, and the fact that no warning was logged was probably fixed in #3149. I think we can close this, though it's worth noting that the fix to #3247 still needs releasing on EAR and EiR (https://github.com/element-hq/crypto-internal/issues/192 and https://github.com/element-hq/crypto-internal/issues/193)