Activate share_pos on the room-list sliding sync instance

MatMaul commented 1 month ago

Fixes #3936.

Signed-off-by: Mathieu Velten mathieu.velten@beta.gouv.fr

codecov[bot] commented 1 month ago

Codecov Report

All modified and coverable lines are covered by tests :white_check_mark:

Project coverage is 84.87%. Comparing base (90d6a37) to head (67f18d5). Report is 3 commits behind head on main.

Additional details and impacted files

```diff @@ Coverage Diff @@ ## main #4035 +/- ## ========================================== - Coverage 84.88% 84.87% -0.01% ========================================== Files 272 272 Lines 29166 29166 ========================================== - Hits 24757 24756 -1 - Misses 4409 4410 +1 ```

:umbrella: View full report in Codecov by Sentry.
:loudspeaker: Have feedback on the report? Share it here.

MatMaul commented 1 month ago

Ahhh crypto dragons has been triggered :/ . Time to set up complement-crypto :)

MatMaul commented 1 month ago

Hum TestRoomKeyIsNotCycledOnClientRestart works locally, and it worked after triggering the CI again.

MatMaul commented 1 month ago

The failed test was a timeout so I think it's a false alarm.

MatMaul commented 1 month ago

It failed again, it may not be a flake especially since it's restart related ?

kegsay commented 1 month ago

The log files show:

2024-09-30T09:49:06.508671Z  INFO TestRoomKeyIsNotCycledOnClientRestart/rust: [@user-44-alice:hs1](rust) MustStartSyncing starting to sync | rust.go:0
2024-09-30T09:49:06.508759Z DEBUG log: sync_service    
2024-09-30T09:49:06.508799Z DEBUG log: finish    
2024-09-30T09:49:06.509119Z DEBUG matrix_sdk::sliding_sync::cache: loading list from DB all_rooms finished in 0ms | crates/matrix-sdk/src/sliding_sync/cache.rs:142
2024-09-30T09:49:06.509142Z DEBUG matrix_sdk::sliding_sync::builder: restoring (loading+processing) list all_rooms finished in 0ms | crates/matrix-sdk/src/sliding_sync/builder.rs:86
2024-09-30T09:49:06.509974Z DEBUG matrix_sdk::sliding_sync::cache: loading sliding sync sliding_sync_store::room-list::@user-44-alice:hs1 state from DB finished in 0ms | crates/matrix-sdk/src/sliding_sync/cache.rs:198
2024-09-30T09:49:06.510712Z DEBUG matrix_sdk::sliding_sync::cache: loading sliding sync sliding_sync_store::encryption::@user-44-alice:hs1 state from DB finished in 0ms | crates/matrix-sdk/src/sliding_sync/cache.rs:198
2024-09-30T09:49:06.510797Z DEBUG log: room_list_service    
2024-09-30T09:49:06.510821Z DEBUG log: all_rooms    
2024-09-30T09:49:06.510906Z DEBUG log: loading_state    
2024-09-30T09:49:06.510975Z DEBUG log: entries    
2024-09-30T09:49:06.510997Z DEBUG log: start    
2024-09-30T09:49:06.511117Z DEBUG matrix_sdk::sliding_sync: Starting sync stream | crates/matrix-sdk/src/sliding_sync/mod.rs:742 | spans: sync_stream{conn_id="room-list" with_e2ee=false}
2024-09-30T09:49:06.511134Z DEBUG matrix_sdk::sliding_sync: Starting sync stream | crates/matrix-sdk/src/sliding_sync/mod.rs:742 | spans: sync_stream{conn_id="encryption" with_e2ee=true}
2024-09-30T09:49:06.511142Z DEBUG log: id    
2024-09-30T09:49:06.511159Z DEBUG matrix_sdk_ui::room_list_service: Run a sync iteration | crates/matrix-sdk-ui/src/room_list_service/mod.rs:211
2024-09-30T09:49:06.511179Z DEBUG matrix_sdk::sliding_sync: Sync stream is running | crates/matrix-sdk/src/sliding_sync/mod.rs:748
2024-09-30T09:49:06.511195Z DEBUG matrix_sdk::sliding_sync: Sync stream is running | crates/matrix-sdk/src/sliding_sync/mod.rs:748 | spans: next_sync_with_lock
2024-09-30T09:49:06.512025Z DEBUG matrix_sdk::sliding_sync::cache: loading sliding sync sliding_sync_store::encryption::@user-44-alice:hs1 state from DB finished in 0ms | crates/matrix-sdk/src/sliding_sync/cache.rs:198 | spans: next_sync_with_lock > sync_once
2024-09-30T09:49:06.512079Z  INFO matrix_sdk::sliding_sync: Marking all tracked users as dirty | crates/matrix-sdk/src/sliding_sync/mod.rs:512 | spans: next_sync_with_lock > sync_once
2024-09-30T09:49:06.512496Z DEBUG matrix_sdk::sliding_sync::cache: loading sliding sync sliding_sync_store::room-list::@user-44-alice:hs1 state from DB finished in 1ms | crates/matrix-sdk/src/sliding_sync/cache.rs:198 | spans: sync_once
2024-09-30T09:49:06.512586Z DEBUG matrix_sdk::sliding_sync: Sending request | crates/matrix-sdk/src/sliding_sync/mod.rs:578 | spans: sync_once{pos="49/s259_3_0_1_17_1_30_242_0_1"}
2024-09-30T09:49:06.512908Z DEBUG matrix_sdk::http_client::native: Sending request num_attempt=1 | crates/matrix-sdk/src/http_client/native.rs:55 | spans: sync_once{pos="49/s259_3_0_1_17_1_30_242_0_1"} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 60s } request_id="REQ-3" method=POST uri="http://127.0.0.1:32795/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="476 B"}
2024-09-30T09:49:06.514751Z DEBUG matrix_sdk::sliding_sync: Sending request | crates/matrix-sdk/src/sliding_sync/mod.rs:578 | spans: next_sync_with_lock > sync_once
2024-09-30T09:49:06.514968Z DEBUG matrix_sdk::http_client::native: Sending request num_attempt=1 | crates/matrix-sdk/src/http_client/native.rs:55 | spans: next_sync_with_lock > sync_once > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 60s } request_id="REQ-4" method=POST uri="http://127.0.0.1:32795/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="149 B"}
2024-09-30T09:49:06.515221Z DEBUG matrix_sdk_crypto::session_manager::sessions: Collected user/device pairs that are missing an Olm session missing_session_devices_by_user={} timed_out_devices_by_user={} | crates/matrix-sdk-crypto/src/session_manager/sessions.rs:292 | spans: get_missing_sessions
2024-09-30T09:49:06.520260Z DEBUG matrix_sdk::http_client: Got response | crates/matrix-sdk/src/http_client/mod.rs:224 | spans: next_sync_with_lock > sync_once > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 60s } request_id="REQ-4" method=POST uri="http://127.0.0.1:32795/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="149 B" status=200 response_size="228 B"}
2024-09-30T09:49:06.522438Z DEBUG matrix_sdk_crypto::identities::manager: Created a /keys/query request request_id="5ef0f846b210407bbed86f20b04f8382" users=["@user-44-alice:hs1", "@user-45-bob:hs1"] | crates/matrix-sdk-crypto/src/identities/manager.rs:869
2024-09-30T09:49:06.522916Z DEBUG matrix_sdk::http_client::native: Sending request num_attempt=1 | crates/matrix-sdk/src/http_client/native.rs:55 | spans: keys_query{request_id="5ef0f846b210407bbed86f20b04f8382" device_keys={"@user-44-alice:hs1": [], "@user-45-bob:hs1": []}} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 30s } request_id="REQ-5" method=POST uri="http://127.0.0.1:32795/_matrix/client/v3/keys/query" request_size="63 B"}
2024-09-30T09:49:06.528319Z DEBUG matrix_sdk::http_client: Got response | crates/matrix-sdk/src/http_client/mod.rs:224 | spans: keys_query{request_id="5ef0f846b210407bbed86f20b04f8382" device_keys={"@user-44-alice:hs1": [], "@user-45-bob:hs1": []}} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 30s } request_id="REQ-5" method=POST uri="http://127.0.0.1:32795/_matrix/client/v3/keys/query" request_size="63 B" status=200 response_size="3.3 kiB"}
2024-09-30T09:49:06.528396Z DEBUG matrix_sdk_crypto::identities::manager: Handling a `/keys/query` response request_id="5ef0f846b210407bbed86f20b04f8382" users={"@user-44-alice:hs1", "@user-45-bob:hs1"} failures={} | crates/matrix-sdk-crypto/src/identities/manager.rs:129 | spans: keys_query{request_id="5ef0f846b210407bbed86f20b04f8382" device_keys={"@user-44-alice:hs1": [], "@user-45-bob:hs1": []}}
2024-09-30T09:49:06.580464Z DEBUG matrix_sdk_crypto::identities::manager: Finished handling of the `/keys/query` response request_id="5ef0f846b210407bbed86f20b04f8382" new_devices={} changed_devices={} deleted_devices={} new_identities={} changed_identities={} | crates/matrix-sdk-crypto/src/identities/manager.rs:1203 | spans: keys_query{request_id="5ef0f846b210407bbed86f20b04f8382" device_keys={"@user-44-alice:hs1": [], "@user-45-bob:hs1": []}}
2024-09-30T09:49:06.580767Z DEBUG matrix_sdk::http_client::native: Sending request num_attempt=1 | crates/matrix-sdk/src/http_client/native.rs:55 | spans: keys_query{request_id="5ef0f846b210407bbed86f20b04f8382" device_keys={"@user-44-alice:hs1": [], "@user-45-bob:hs1": []}} > update_state_after_keys_query{self=Recovery { client: Client } response=Response { failures: {}, device_keys: {"@user-44-alice:hs1": {"SRCESEGNRC": Raw::<ruma_common::encryption::DeviceKeys> { json: RawValue({"algorithms":["m.olm.v1.curve25519-aes-sha2","m.megolm.v1.aes-sha2"],"device_id":"SRCESEGNRC","keys":{"curve25519:SRCESEGNRC":"qBdONGb4LtwfOT6Qy6e9cBQ/VJYYH5AVsqnMHFAx+xc","ed25519:SRCESEGNRC":"V7NN1W9G4GugPBJzm6HyLJzpGQro46Qh9PUcNI5B5WU"},"signatures":{"@user-44-alice:hs1":{"ed25519:SRCESEGNRC":"XhQuyzKREDjyif1ekgaZb7wGFYHc3rl4OUcaXN/awOrE3pykf1feKyy26T7Xa994emVUOBNQP7mUYdKyLEJKBA","ed25519:zviQGNfIVzd04siQJEUX8MdZs/gArsYmWphFRKTSoNE":"ZPeoyax/YhezVXjOrjuT8YClQ8eTe6AcJuFd51EEPWrSSGcgJkrSwIiuVuy3T1qbk8r7taEixJ+8jUcKVgVzDw"}},"user_id":"@user-44-alice:hs1","unsigned":{}}) }}, "@user-45-bob:hs1": {"QNQCFLLDVU": Raw::<ruma_common::encryption::DeviceKeys> { json: RawValue({"algorithms":["m.olm.v1.curve25519-aes-sha2","m.megolm.v1.aes-sha2"],"device_id":"QNQCFLLDVU","keys":{"curve25519:QNQCFLLDVU":"sp1FfJsjkjHEYDj2nzTl8+HlKLm3Q/wtCHOtij/GbSY","ed25519:QNQCFLLDVU":"xoDfcsaWIW9HheLR1fh47mUO7ATgxHh5tCRSp4Zn63M"},"signatures":{"@user-45-bob:hs1":{"ed25519:QNQCFLLDVU":"OkADe7LsxiqLFh53I/ofsM9+jGlc2Zj4dn3oisfklpIK/w1HPEF7gN4fGZ+1cfPKKezqgtI4dRgcPenDtkILBQ","ed25519:q5WNGl9r/lvF23P2KhBnHW09jvQDTgL3JDfTt4DPbeM":"Tv2wdI4HOgg+/G72I1p8c07bWJWP7K0CjelFD4wckdmMoLIllDtOQA1y0se8PlI3MTYVeiTPCbX25O9T3ci8CQ"}},"user_id":"@user-45-bob:hs1","unsigned":{}}) }}}, master_keys: {"@user-44-alice:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-44-alice:hs1","usage":["master"],"keys":{"ed25519:BvPijCW8m3Lcxw6EJU/Xng++v4jGXJhtrCk/N2yMhvM":"BvPijCW8m3Lcxw6EJU/Xng++v4jGXJhtrCk/N2yMhvM"},"signatures":{"@user-44-alice:hs1":{"ed25519:BvPijCW8m3Lcxw6EJU/Xng++v4jGXJhtrCk/N2yMhvM":"PWxPFG3Cv16zlX1squiwttMjeMIXua4roXtQsOzFrMC9GclKmL6bJsaNv+xFDLysA52TEUFJyscXxKZQjdzXBg","ed25519:SRCESEGNRC":"ZVDiYK0nU4YrqLE9xuv4M6fOXtSIsxqRsgFH3gw2UA90fd0BT25CBbDeNecqGDjxVBBF8lcm5Z5LOq+YJcuCBw"}}}) }, "@user-45-bob:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-45-bob:hs1","usage":["master"],"keys":{"ed25519:nLEpNwhyKgAjCDxd3e250al/NspBkZzknPR6Xm0bQ0o":"nLEpNwhyKgAjCDxd3e250al/NspBkZzknPR6Xm0bQ0o"},"signatures":{"@user-45-bob:hs1":{"ed25519:QNQCFLLDVU":"5B71JDRFCOzvRfUGH+iNl7Cv2EWWPuIxUaNVZmwLxIG0ysl6jqxvbRhWet025ku566ZW3o7QDyUUrERQD1uWCw","ed25519:nLEpNwhyKgAjCDxd3e250al/NspBkZzknPR6Xm0bQ0o":"e0BmEae70cKJVolpJOZfEbdFBAKUF2enznrE25sDoA+tyXwiyKaLwPxRohsTIgg+WNp5ls5tXXkZXY3W0ihVCQ"}}}) }}, self_signing_keys: {"@user-44-alice:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-44-alice:hs1","usage":["self_signing"],"keys":{"ed25519:zviQGNfIVzd04siQJEUX8MdZs/gArsYmWphFRKTSoNE":"zviQGNfIVzd04siQJEUX8MdZs/gArsYmWphFRKTSoNE"},"signatures":{"@user-44-alice:hs1":{"ed25519:BvPijCW8m3Lcxw6EJU/Xng++v4jGXJhtrCk/N2yMhvM":"kYjOxxzSQcH+yyCVegQaiTJCxx1A9CYRq2rlZN0Ykmeu3Qo1MeGua1Bo3RoxsCiQsO3sNxXY/Ln0vPSjkqU/DQ"}}}) }, "@user-45-bob:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-45-bob:hs1","usage":["self_signing"],"keys":{"ed25519:q5WNGl9r/lvF23P2KhBnHW09jvQDTgL3JDfTt4DPbeM":"q5WNGl9r/lvF23P2KhBnHW09jvQDTgL3JDfTt4DPbeM"},"signatures":{"@user-45-bob:hs1":{"ed25519:nLEpNwhyKgAjCDxd3e250al/NspBkZzknPR6Xm0bQ0o":"kzOw3DBZgCWtatz6cxhEtd1YbRNtLl1CsrPz2caTZ3bsnfxdZj+vFFcTRKcsL8nDHcnYEFpJ6qMQs4Jns4heBg"}}}) }}, user_signing_keys: {"@user-44-alice:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-44-alice:hs1","usage":["user_signing"],"keys":{"ed25519:estmkFICGia14T4vXsaCGv5hQ5uh+A1h3RmuTbWgj8I":"estmkFICGia14T4vXsaCGv5hQ5uh+A1h3RmuTbWgj8I"},"signatures":{"@user-44-alice:hs1":{"ed25519:BvPijCW8m3Lcxw6EJU/Xng++v4jGXJhtrCk/N2yMhvM":"CooRzxqR2ROdEaKtfY38ozxaAahbTWo9c7odntA2K6TVfrltTW0Rz1da6WhcW3W7wuShv+WH3Xzq9GUPQw2eAw"}}}) }} }} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 30s } request_id="REQ-6" method=GET uri="http://127.0.0.1:32795/_matrix/client/v3/user/@user-44-alice:hs1/account_data/m.secret_storage.default_key"}
2024-09-30T09:49:06.585951Z DEBUG matrix_sdk::http_client: Error while sending request: Api(Server(ClientApi(Error { status_code: 404, body: Standard { kind: NotFound, message: "Account data not found" } }))) | crates/matrix-sdk/src/http_client/mod.rs:228 | spans: keys_query{request_id="5ef0f846b210407bbed86f20b04f8382" device_keys={"@user-44-alice:hs1": [], "@user-45-bob:hs1": []}} > update_state_after_keys_query{self=Recovery { client: Client } response=Response { failures: {}, device_keys: {"@user-44-alice:hs1": {"SRCESEGNRC": Raw::<ruma_common::encryption::DeviceKeys> { json: RawValue({"algorithms":["m.olm.v1.curve25519-aes-sha2","m.megolm.v1.aes-sha2"],"device_id":"SRCESEGNRC","keys":{"curve25519:SRCESEGNRC":"qBdONGb4LtwfOT6Qy6e9cBQ/VJYYH5AVsqnMHFAx+xc","ed25519:SRCESEGNRC":"V7NN1W9G4GugPBJzm6HyLJzpGQro46Qh9PUcNI5B5WU"},"signatures":{"@user-44-alice:hs1":{"ed25519:SRCESEGNRC":"XhQuyzKREDjyif1ekgaZb7wGFYHc3rl4OUcaXN/awOrE3pykf1feKyy26T7Xa994emVUOBNQP7mUYdKyLEJKBA","ed25519:zviQGNfIVzd04siQJEUX8MdZs/gArsYmWphFRKTSoNE":"ZPeoyax/YhezVXjOrjuT8YClQ8eTe6AcJuFd51EEPWrSSGcgJkrSwIiuVuy3T1qbk8r7taEixJ+8jUcKVgVzDw"}},"user_id":"@user-44-alice:hs1","unsigned":{}}) }}, "@user-45-bob:hs1": {"QNQCFLLDVU": Raw::<ruma_common::encryption::DeviceKeys> { json: RawValue({"algorithms":["m.olm.v1.curve25519-aes-sha2","m.megolm.v1.aes-sha2"],"device_id":"QNQCFLLDVU","keys":{"curve25519:QNQCFLLDVU":"sp1FfJsjkjHEYDj2nzTl8+HlKLm3Q/wtCHOtij/GbSY","ed25519:QNQCFLLDVU":"xoDfcsaWIW9HheLR1fh47mUO7ATgxHh5tCRSp4Zn63M"},"signatures":{"@user-45-bob:hs1":{"ed25519:QNQCFLLDVU":"OkADe7LsxiqLFh53I/ofsM9+jGlc2Zj4dn3oisfklpIK/w1HPEF7gN4fGZ+1cfPKKezqgtI4dRgcPenDtkILBQ","ed25519:q5WNGl9r/lvF23P2KhBnHW09jvQDTgL3JDfTt4DPbeM":"Tv2wdI4HOgg+/G72I1p8c07bWJWP7K0CjelFD4wckdmMoLIllDtOQA1y0se8PlI3MTYVeiTPCbX25O9T3ci8CQ"}},"user_id":"@user-45-bob:hs1","unsigned":{}}) }}}, master_keys: {"@user-44-alice:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-44-alice:hs1","usage":["master"],"keys":{"ed25519:BvPijCW8m3Lcxw6EJU/Xng++v4jGXJhtrCk/N2yMhvM":"BvPijCW8m3Lcxw6EJU/Xng++v4jGXJhtrCk/N2yMhvM"},"signatures":{"@user-44-alice:hs1":{"ed25519:BvPijCW8m3Lcxw6EJU/Xng++v4jGXJhtrCk/N2yMhvM":"PWxPFG3Cv16zlX1squiwttMjeMIXua4roXtQsOzFrMC9GclKmL6bJsaNv+xFDLysA52TEUFJyscXxKZQjdzXBg","ed25519:SRCESEGNRC":"ZVDiYK0nU4YrqLE9xuv4M6fOXtSIsxqRsgFH3gw2UA90fd0BT25CBbDeNecqGDjxVBBF8lcm5Z5LOq+YJcuCBw"}}}) }, "@user-45-bob:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-45-bob:hs1","usage":["master"],"keys":{"ed25519:nLEpNwhyKgAjCDxd3e250al/NspBkZzknPR6Xm0bQ0o":"nLEpNwhyKgAjCDxd3e250al/NspBkZzknPR6Xm0bQ0o"},"signatures":{"@user-45-bob:hs1":{"ed25519:QNQCFLLDVU":"5B71JDRFCOzvRfUGH+iNl7Cv2EWWPuIxUaNVZmwLxIG0ysl6jqxvbRhWet025ku566ZW3o7QDyUUrERQD1uWCw","ed25519:nLEpNwhyKgAjCDxd3e250al/NspBkZzknPR6Xm0bQ0o":"e0BmEae70cKJVolpJOZfEbdFBAKUF2enznrE25sDoA+tyXwiyKaLwPxRohsTIgg+WNp5ls5tXXkZXY3W0ihVCQ"}}}) }}, self_signing_keys: {"@user-44-alice:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-44-alice:hs1","usage":["self_signing"],"keys":{"ed25519:zviQGNfIVzd04siQJEUX8MdZs/gArsYmWphFRKTSoNE":"zviQGNfIVzd04siQJEUX8MdZs/gArsYmWphFRKTSoNE"},"signatures":{"@user-44-alice:hs1":{"ed25519:BvPijCW8m3Lcxw6EJU/Xng++v4jGXJhtrCk/N2yMhvM":"kYjOxxzSQcH+yyCVegQaiTJCxx1A9CYRq2rlZN0Ykmeu3Qo1MeGua1Bo3RoxsCiQsO3sNxXY/Ln0vPSjkqU/DQ"}}}) }, "@user-45-bob:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-45-bob:hs1","usage":["self_signing"],"keys":{"ed25519:q5WNGl9r/lvF23P2KhBnHW09jvQDTgL3JDfTt4DPbeM":"q5WNGl9r/lvF23P2KhBnHW09jvQDTgL3JDfTt4DPbeM"},"signatures":{"@user-45-bob:hs1":{"ed25519:nLEpNwhyKgAjCDxd3e250al/NspBkZzknPR6Xm0bQ0o":"kzOw3DBZgCWtatz6cxhEtd1YbRNtLl1CsrPz2caTZ3bsnfxdZj+vFFcTRKcsL8nDHcnYEFpJ6qMQs4Jns4heBg"}}}) }}, user_signing_keys: {"@user-44-alice:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-44-alice:hs1","usage":["user_signing"],"keys":{"ed25519:estmkFICGia14T4vXsaCGv5hQ5uh+A1h3RmuTbWgj8I":"estmkFICGia14T4vXsaCGv5hQ5uh+A1h3RmuTbWgj8I"},"signatures":{"@user-44-alice:hs1":{"ed25519:BvPijCW8m3Lcxw6EJU/Xng++v4jGXJhtrCk/N2yMhvM":"CooRzxqR2ROdEaKtfY38ozxaAahbTWo9c7odntA2K6TVfrltTW0Rz1da6WhcW3W7wuShv+WH3Xzq9GUPQw2eAw"}}}) }} }} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 30s } request_id="REQ-6" method=GET uri="http://127.0.0.1:32795/_matrix/client/v3/user/@user-44-alice:hs1/account_data/m.secret_storage.default_key" status=404 response_size="58 B"}
2024-09-30T09:49:06.598952Z DEBUG matrix_sdk::sliding_sync: Received response | crates/matrix-sdk/src/sliding_sync/mod.rs:648 | spans: next_sync_with_lock > sync_once
2024-09-30T09:49:06.599016Z DEBUG matrix_sdk::sliding_sync: Start handling response | crates/matrix-sdk/src/sliding_sync/mod.rs:664 | spans: next_sync_with_lock > sync_once
2024-09-30T09:49:06.599072Z TRACE matrix_sdk_base::sliding_sync: Processing sliding sync e2ee events to_device_events=0 device_one_time_keys_count=1 device_unused_fallback_key_types=1 | crates/matrix-sdk-base/src/sliding_sync/mod.rs:75 | spans: next_sync_with_lock > sync_once > handle_response
2024-09-30T09:49:06.607046Z TRACE matrix_sdk_base::sliding_sync: ready to submit changes to store | crates/matrix-sdk-base/src/sliding_sync/mod.rs:109 | spans: next_sync_with_lock > sync_once > handle_response
2024-09-30T09:49:06.607278Z TRACE matrix_sdk_base::sliding_sync: applied changes | crates/matrix-sdk-base/src/sliding_sync/mod.rs:112 | spans: next_sync_with_lock > sync_once > handle_response
2024-09-30T09:49:06.607360Z DEBUG matrix_sdk::sync: Ran event handlers in 23.544µs | crates/matrix-sdk/src/sync.rs:228 | spans: next_sync_with_lock > sync_once > handle_response > call_sync_response_handlers
2024-09-30T09:49:06.607396Z  WARN matrix_sdk_crypto::backups: Trying to backup room keys but no backup key was found | crates/matrix-sdk-crypto/src/backups/mod.rs:520
2024-09-30T09:49:06.607394Z DEBUG matrix_sdk::sync: Ran notification handlers in 9.287µs | crates/matrix-sdk/src/sync.rs:253 | spans: next_sync_with_lock > sync_once > handle_response > call_sync_response_handlers
2024-09-30T09:49:06.607440Z DEBUG matrix_sdk::sliding_sync: Sliding Sync response has been handled by the client sync_response=SyncResponse { rooms: Rooms { leave: {}, join: {}, invite: {} }, account_data: [], to_device: [], notifications: {}, .. } | crates/matrix-sdk/src/sliding_sync/mod.rs:323 | spans: next_sync_with_lock > sync_once > handle_response
2024-09-30T09:49:06.607474Z DEBUG matrix_sdk::sliding_sync: Update lists lists={} | crates/matrix-sdk/src/sliding_sync/mod.rs:388 | spans: next_sync_with_lock > sync_once > handle_response
2024-09-30T09:49:06.609303Z DEBUG matrix_sdk::sliding_sync: Done handling response | crates/matrix-sdk/src/sliding_sync/mod.rs:679 | spans: next_sync_with_lock > sync_once
2024-09-30T09:49:06.609415Z DEBUG matrix_sdk::sliding_sync: Sync stream is running | crates/matrix-sdk/src/sliding_sync/mod.rs:748 | spans: next_sync_with_lock
2024-09-30T09:49:06.610086Z DEBUG matrix_sdk::sliding_sync::cache: loading sliding sync sliding_sync_store::encryption::@user-44-alice:hs1 state from DB finished in 0ms | crates/matrix-sdk/src/sliding_sync/cache.rs:198 | spans: next_sync_with_lock > sync_once
2024-09-30T09:49:06.610157Z DEBUG matrix_sdk::sliding_sync: Sending request | crates/matrix-sdk/src/sliding_sync/mod.rs:578 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"}
2024-09-30T09:49:06.610340Z DEBUG matrix_sdk::http_client::native: Sending request num_attempt=1 | crates/matrix-sdk/src/http_client/native.rs:55 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 60s } request_id="REQ-7" method=POST uri="http://127.0.0.1:32795/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="149 B"}
2024-09-30T09:49:06.610561Z DEBUG matrix_sdk_crypto::session_manager::sessions: Collected user/device pairs that are missing an Olm session missing_session_devices_by_user={} timed_out_devices_by_user={} | crates/matrix-sdk-crypto/src/session_manager/sessions.rs:292 | spans: get_missing_sessions
2024-09-30T09:49:06.616337Z DEBUG matrix_sdk::http_client: Got response | crates/matrix-sdk/src/http_client/mod.rs:224 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 60s } request_id="REQ-7" method=POST uri="http://127.0.0.1:32795/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="149 B" status=200 response_size="268 B"}
2024-09-30T09:49:06.616404Z DEBUG matrix_sdk::sliding_sync: Received response | crates/matrix-sdk/src/sliding_sync/mod.rs:648 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"}
2024-09-30T09:49:06.616465Z DEBUG matrix_sdk::sliding_sync: Start handling response | crates/matrix-sdk/src/sliding_sync/mod.rs:664 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"}
2024-09-30T09:49:06.616524Z TRACE matrix_sdk_base::sliding_sync: Processing sliding sync e2ee events to_device_events=0 device_one_time_keys_count=1 device_unused_fallback_key_types=1 | crates/matrix-sdk-base/src/sliding_sync/mod.rs:75 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"} > handle_response
2024-09-30T09:49:06.623773Z TRACE matrix_sdk_base::sliding_sync: ready to submit changes to store | crates/matrix-sdk-base/src/sliding_sync/mod.rs:109 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"} > handle_response
2024-09-30T09:49:06.623992Z TRACE matrix_sdk_base::sliding_sync: applied changes | crates/matrix-sdk-base/src/sliding_sync/mod.rs:112 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"} > handle_response
2024-09-30T09:49:06.624063Z DEBUG matrix_sdk::sync: Ran event handlers in 18.534µs | crates/matrix-sdk/src/sync.rs:228 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"} > handle_response > call_sync_response_handlers
2024-09-30T09:49:06.624093Z DEBUG matrix_sdk::sync: Ran notification handlers in 7.043µs | crates/matrix-sdk/src/sync.rs:253 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"} > handle_response > call_sync_response_handlers
2024-09-30T09:49:06.624097Z  WARN matrix_sdk_crypto::backups: Trying to backup room keys but no backup key was found | crates/matrix-sdk-crypto/src/backups/mod.rs:520
2024-09-30T09:49:06.624135Z DEBUG matrix_sdk::sliding_sync: Sliding Sync response has been handled by the client sync_response=SyncResponse { rooms: Rooms { leave: {}, join: {}, invite: {} }, account_data: [], to_device: [], notifications: {}, .. } | crates/matrix-sdk/src/sliding_sync/mod.rs:323 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"} > handle_response
2024-09-30T09:49:06.624166Z DEBUG matrix_sdk::sliding_sync: Update lists lists={} | crates/matrix-sdk/src/sliding_sync/mod.rs:388 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"} > handle_response
2024-09-30T09:49:06.626139Z DEBUG matrix_sdk::sliding_sync: Done handling response | crates/matrix-sdk/src/sliding_sync/mod.rs:679 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_31_242_0_1"}
2024-09-30T09:49:06.626241Z DEBUG matrix_sdk::sliding_sync: Sync stream is running | crates/matrix-sdk/src/sliding_sync/mod.rs:748 | spans: next_sync_with_lock
2024-09-30T09:49:06.626969Z DEBUG matrix_sdk::sliding_sync::cache: loading sliding sync sliding_sync_store::encryption::@user-44-alice:hs1 state from DB finished in 0ms | crates/matrix-sdk/src/sliding_sync/cache.rs:198 | spans: next_sync_with_lock > sync_once
2024-09-30T09:49:06.627032Z DEBUG matrix_sdk::sliding_sync: Sending request | crates/matrix-sdk/src/sliding_sync/mod.rs:578 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_30_242_0_1"}
2024-09-30T09:49:06.627187Z DEBUG matrix_sdk::http_client::native: Sending request num_attempt=1 | crates/matrix-sdk/src/http_client/native.rs:55 | spans: next_sync_with_lock > sync_once{pos="0/s259_3_0_1_17_1_30_242_0_1"} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 60s } request_id="REQ-8" method=POST uri="http://127.0.0.1:32795/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="149 B"}
2024-09-30T09:49:06.627412Z DEBUG matrix_sdk_crypto::session_manager::sessions: Collected user/device pairs that are missing an Olm session missing_session_devices_by_user={} timed_out_devices_by_user={} | crates/matrix-sdk-crypto/src/session_manager/sessions.rs:292 | spans: get_missing_sessions
2024-09-30T09:49:11.511842Z DEBUG log: log_event    
2024-09-30T09:49:11.511936Z  INFO TestRoomKeyIsNotCycledOnClientRestart/rust: [@user-44-alice:hs1](rust) Close | rust.go:0

..which imply that StartSyncing is not returning, likely because the /sync request hasn't returned? It looks like the first /sync does return but the 2nd one blocks. This is expected server behaviour, I would expect the FFI layer to unblock after the first /sync response, but this isn't happening? Specifically, it's waiting for the RoomListLoadingStateLoaded state to fire which is attached by syncService.RoomListService().AllRooms().LoadingState(listener).

kegsay commented 1 month ago

A successful local run shows:

2024-10-01T09:06:32.107085Z  INFO TestRoomKeyIsNotCycledOnClientRestart/rust: [@user-1-alice:hs1](rust) MustStartSyncing starting to sync | rust.go:0
2024-10-01T09:06:32.107120Z DEBUG log: sync_service    
2024-10-01T09:06:32.107143Z DEBUG log: finish    
2024-10-01T09:06:32.107828Z DEBUG matrix_sdk::sliding_sync::cache: loading list from DB all_rooms finished in 0ms | crates/matrix-sdk/src/sliding_sync/cache.rs:142
2024-10-01T09:06:32.107854Z DEBUG matrix_sdk::sliding_sync::builder: restoring (loading+processing) list all_rooms finished in 0ms | crates/matrix-sdk/src/sliding_sync/builder.rs:86
2024-10-01T09:06:32.108188Z DEBUG matrix_sdk::sliding_sync::cache: loading sliding sync sliding_sync_store::room-list::@user-1-alice:hs1 state from DB finished in 0ms | crates/matrix-sdk/src/sliding_sync/cache.rs:198
2024-10-01T09:06:32.108436Z DEBUG matrix_sdk::sliding_sync::cache: loading sliding sync sliding_sync_store::encryption::@user-1-alice:hs1 state from DB finished in 0ms | crates/matrix-sdk/src/sliding_sync/cache.rs:198
2024-10-01T09:06:32.108467Z DEBUG log: room_list_service    
2024-10-01T09:06:32.108484Z DEBUG log: all_rooms    
2024-10-01T09:06:32.108531Z DEBUG log: loading_state    
2024-10-01T09:06:32.108564Z DEBUG log: entries    
2024-10-01T09:06:32.108584Z DEBUG log: start    
2024-10-01T09:06:32.108639Z DEBUG matrix_sdk::sliding_sync: Starting sync stream | crates/matrix-sdk/src/sliding_sync/mod.rs:742 | spans: sync_stream{conn_id="room-list" with_e2ee=false}
2024-10-01T09:06:32.108643Z DEBUG matrix_sdk::sliding_sync: Starting sync stream | crates/matrix-sdk/src/sliding_sync/mod.rs:742 | spans: sync_stream{conn_id="encryption" with_e2ee=true}
2024-10-01T09:06:32.108657Z DEBUG matrix_sdk_ui::room_list_service: Run a sync iteration | crates/matrix-sdk-ui/src/room_list_service/mod.rs:211
2024-10-01T09:06:32.108666Z DEBUG matrix_sdk::sliding_sync: Sync stream is running | crates/matrix-sdk/src/sliding_sync/mod.rs:748
2024-10-01T09:06:32.108669Z DEBUG matrix_sdk::sliding_sync: Sync stream is running | crates/matrix-sdk/src/sliding_sync/mod.rs:748 | spans: next_sync_with_lock
2024-10-01T09:06:32.108664Z DEBUG log: id    
2024-10-01T09:06:32.108973Z DEBUG matrix_sdk::sliding_sync::cache: loading sliding sync sliding_sync_store::encryption::@user-1-alice:hs1 state from DB finished in 0ms | crates/matrix-sdk/src/sliding_sync/cache.rs:198 | spans: next_sync_with_lock > sync_once
2024-10-01T09:06:32.108988Z  INFO matrix_sdk::sliding_sync: Marking all tracked users as dirty | crates/matrix-sdk/src/sliding_sync/mod.rs:512 | spans: next_sync_with_lock > sync_once
2024-10-01T09:06:32.109326Z DEBUG matrix_sdk::sliding_sync::cache: loading sliding sync sliding_sync_store::room-list::@user-1-alice:hs1 state from DB finished in 0ms | crates/matrix-sdk/src/sliding_sync/cache.rs:198 | spans: sync_once
2024-10-01T09:06:32.109359Z DEBUG matrix_sdk::sliding_sync: Sending request | crates/matrix-sdk/src/sliding_sync/mod.rs:578 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"}
2024-10-01T09:06:32.109445Z DEBUG matrix_sdk::sliding_sync: Sending request | crates/matrix-sdk/src/sliding_sync/mod.rs:578 | spans: next_sync_with_lock > sync_once
2024-10-01T09:06:32.109493Z DEBUG matrix_sdk::http_client::native: Sending request num_attempt=1 | crates/matrix-sdk/src/http_client/native.rs:55 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 60s } request_id="REQ-3" method=POST uri="http://127.0.0.1:64875/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="476 B"}
2024-10-01T09:06:32.109513Z DEBUG matrix_sdk::http_client::native: Sending request num_attempt=1 | crates/matrix-sdk/src/http_client/native.rs:55 | spans: next_sync_with_lock > sync_once > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 60s } request_id="REQ-4" method=POST uri="http://127.0.0.1:64875/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="148 B"}
2024-10-01T09:06:32.109627Z DEBUG matrix_sdk_crypto::session_manager::sessions: Collected user/device pairs that are missing an Olm session missing_session_devices_by_user={} timed_out_devices_by_user={} | crates/matrix-sdk-crypto/src/session_manager/sessions.rs:292 | spans: get_missing_sessions
2024-10-01T09:06:32.114455Z DEBUG matrix_sdk_crypto::identities::manager: Created a /keys/query request request_id="411ccfd19a044e4c8a37698d29bcdac3" users=["@user-1-alice:hs1", "@user-2-bob:hs1"] | crates/matrix-sdk-crypto/src/identities/manager.rs:869
2024-10-01T09:06:32.114760Z DEBUG matrix_sdk::http_client::native: Sending request num_attempt=1 | crates/matrix-sdk/src/http_client/native.rs:55 | spans: keys_query{request_id="411ccfd19a044e4c8a37698d29bcdac3" device_keys={"@user-1-alice:hs1": [], "@user-2-bob:hs1": []}} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 30s } request_id="REQ-5" method=POST uri="http://127.0.0.1:64875/_matrix/client/v3/keys/query" request_size="61 B"}
2024-10-01T09:06:32.114874Z DEBUG log: starting new connection: http://127.0.0.1:64875/     | spans: keys_query{request_id="411ccfd19a044e4c8a37698d29bcdac3" device_keys={"@user-1-alice:hs1": [], "@user-2-bob:hs1": []}} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 30s } request_id="REQ-5" method=POST uri="http://127.0.0.1:64875/_matrix/client/v3/keys/query" request_size="61 B"}
2024-10-01T09:06:32.122200Z DEBUG matrix_sdk::http_client: Got response | crates/matrix-sdk/src/http_client/mod.rs:224 | spans: next_sync_with_lock > sync_once > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 60s } request_id="REQ-4" method=POST uri="http://127.0.0.1:64875/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="148 B" status=200 response_size="223 B"}
2024-10-01T09:06:32.128727Z DEBUG matrix_sdk::http_client: Got response | crates/matrix-sdk/src/http_client/mod.rs:224 | spans: keys_query{request_id="411ccfd19a044e4c8a37698d29bcdac3" device_keys={"@user-1-alice:hs1": [], "@user-2-bob:hs1": []}} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 30s } request_id="REQ-5" method=POST uri="http://127.0.0.1:64875/_matrix/client/v3/keys/query" request_size="61 B" status=200 response_size="3.3 kiB"}
2024-10-01T09:06:32.128808Z DEBUG matrix_sdk_crypto::identities::manager: Handling a `/keys/query` response request_id="411ccfd19a044e4c8a37698d29bcdac3" users={"@user-1-alice:hs1", "@user-2-bob:hs1"} failures={} | crates/matrix-sdk-crypto/src/identities/manager.rs:129 | spans: keys_query{request_id="411ccfd19a044e4c8a37698d29bcdac3" device_keys={"@user-1-alice:hs1": [], "@user-2-bob:hs1": []}}
2024-10-01T09:06:32.129306Z DEBUG matrix_sdk::http_client: Got response | crates/matrix-sdk/src/http_client/mod.rs:224 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 60s } request_id="REQ-3" method=POST uri="http://127.0.0.1:64875/_matrix/client/unstable/org.matrix.simplified_msc3575/sync" request_size="476 B" status=200 response_size="1.3 kiB"}
2024-10-01T09:06:32.129376Z DEBUG matrix_sdk::sliding_sync: Received response | crates/matrix-sdk/src/sliding_sync/mod.rs:648 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"}
2024-10-01T09:06:32.129419Z DEBUG matrix_sdk::sliding_sync: Start handling response | crates/matrix-sdk/src/sliding_sync/mod.rs:664 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"}
2024-10-01T09:06:32.129463Z TRACE matrix_sdk_base::sliding_sync: Processing sliding sync room events rooms=1 lists=1 extensions=false | crates/matrix-sdk-base/src/sliding_sync/mod.rs:146 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response > process_sliding_sync
2024-10-01T09:06:32.132588Z DEBUG matrix_sdk_base::read_receipts: Starting. read_receipts=RoomReadReceipts { num_unread: 0, num_notifications: 0, num_mentions: 0, latest_active: None, pending: RingBuffer { inner: [] } } | crates/matrix-sdk-base/src/read_receipts.rs:461 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response > process_sliding_sync > compute_unread_counts{room_id=!UVxAtJiTYqykKINRsR:hs1}
2024-10-01T09:06:32.132668Z TRACE matrix_sdk_base::read_receipts: found an implicit receipt candidate event_id=$ZpvMbwoQJkSBFtdWgx6ye5sb7WQ2TMtM4jgA-5HhiGk | crates/matrix-sdk-base/src/read_receipts.rs:416 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response > process_sliding_sync > compute_unread_counts{room_id=!UVxAtJiTYqykKINRsR:hs1} > try_match_implicit
2024-10-01T09:06:32.132692Z DEBUG matrix_sdk_base::read_receipts: saving for the first time | crates/matrix-sdk-base/src/read_receipts.rs:344 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response > process_sliding_sync > compute_unread_counts{room_id=!UVxAtJiTYqykKINRsR:hs1} > try_match_implicit > try_select_later{event_id="$ZpvMbwoQJkSBFtdWgx6ye5sb7WQ2TMtM4jgA-5HhiGk" event_pos=1 prev_pos=None prev_receipt=None}
2024-10-01T09:06:32.132717Z TRACE matrix_sdk_base::read_receipts: Saving a new active read receipt event_id=$ZpvMbwoQJkSBFtdWgx6ye5sb7WQ2TMtM4jgA-5HhiGk | crates/matrix-sdk-base/src/read_receipts.rs:501 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response > process_sliding_sync > compute_unread_counts{room_id=!UVxAtJiTYqykKINRsR:hs1}
2024-10-01T09:06:32.132740Z TRACE matrix_sdk_base::read_receipts: Found the event the receipt was referring to! Starting to count. | crates/matrix-sdk-base/src/read_receipts.rs:252 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response > process_sliding_sync > compute_unread_counts{room_id=!UVxAtJiTYqykKINRsR:hs1} > find_and_process_events
2024-10-01T09:06:32.132752Z DEBUG matrix_sdk_base::read_receipts: after finding a better receipt read_receipts=RoomReadReceipts { num_unread: 0, num_notifications: 0, num_mentions: 0, latest_active: Some(LatestReadReceipt { event_id: "$ZpvMbwoQJkSBFtdWgx6ye5sb7WQ2TMtM4jgA-5HhiGk" }), pending: RingBuffer { inner: [] } } | crates/matrix-sdk-base/src/read_receipts.rs:508 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response > process_sliding_sync > compute_unread_counts{room_id=!UVxAtJiTYqykKINRsR:hs1}
2024-10-01T09:06:32.132811Z DEBUG matrix_sdk_crypto::identities::manager: Finished handling of the `/keys/query` response request_id="411ccfd19a044e4c8a37698d29bcdac3" new_devices={} changed_devices={} deleted_devices={} new_identities={} changed_identities={} | crates/matrix-sdk-crypto/src/identities/manager.rs:1203 | spans: keys_query{request_id="411ccfd19a044e4c8a37698d29bcdac3" device_keys={"@user-1-alice:hs1": [], "@user-2-bob:hs1": []}}
2024-10-01T09:06:32.132853Z TRACE matrix_sdk_base::sliding_sync: ready to submit changes to store | crates/matrix-sdk-base/src/sliding_sync/mod.rs:339 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response > process_sliding_sync
2024-10-01T09:06:32.132971Z DEBUG matrix_sdk::http_client::native: Sending request num_attempt=1 | crates/matrix-sdk/src/http_client/native.rs:55 | spans: keys_query{request_id="411ccfd19a044e4c8a37698d29bcdac3" device_keys={"@user-1-alice:hs1": [], "@user-2-bob:hs1": []}} > update_state_after_keys_query{self=Recovery { client: Client } response=Response { failures: {}, device_keys: {"@user-1-alice:hs1": {"DXAJSVMTBK": Raw::<ruma_common::encryption::DeviceKeys> { json: RawValue({"algorithms":["m.olm.v1.curve25519-aes-sha2","m.megolm.v1.aes-sha2"],"device_id":"DXAJSVMTBK","keys":{"curve25519:DXAJSVMTBK":"gJ9gM2iS373AV6P7EpLyDfmaFNUG2T5eNFsz1EvR2Gw","ed25519:DXAJSVMTBK":"nhVYaKyK1UGQpB//7H2jOf3yZ8T/AQXS0mgDQ1UkkwY"},"signatures":{"@user-1-alice:hs1":{"ed25519:DXAJSVMTBK":"vRcsiYcA+V+eXfYzSKK2pCAWETzMJDmKPrrOmLNgS1Ge+7DitQ2z4zCa0cjVnKrlCZo4PYwegZao3vmfseVeAQ","ed25519:V52nJrShkQOyOlEUZUg9kYdH3ykL5obUisUGX3LA2WA":"wCfYhpyQZuAt1d7keT/z7IuYZEY9OxTZWSsIMBGjZtzIYm1cC2BH7fqM/zeP0ENy0J2LGXArUMxyO+pHh6g3Ag"}},"user_id":"@user-1-alice:hs1","unsigned":{}}) }}, "@user-2-bob:hs1": {"HSFBWTHASM": Raw::<ruma_common::encryption::DeviceKeys> { json: RawValue({"algorithms":["m.olm.v1.curve25519-aes-sha2","m.megolm.v1.aes-sha2"],"device_id":"HSFBWTHASM","keys":{"curve25519:HSFBWTHASM":"PXrBB3H5DwkX+jg8VHkclzRj7Ql2jRAAbMABB9V7X28","ed25519:HSFBWTHASM":"w/iS/chY1fVLRUhNFy5YOAODh7Nt2Id3Nnk3ia5vmaY"},"signatures":{"@user-2-bob:hs1":{"ed25519:HSFBWTHASM":"uXJQn0r13A2ruTh0RhHl74hCTK9KnFtaBxQB0w0xt6gKy9D3tVnEdldO7ksbw9G5qkQpQHHAz1SuIs+iIqvDCw","ed25519:S643I3dgLPOw+elj2zcq5X9ACB9yHnuVO+GrzPmb3zI":"PGQmXihPG/f9JjL2QJGYP4OSrysWRZHFtlq6osdDI1t5LBA/ikPLYO0+IuD+QnSyGKuU5+AisSYnR+xVt2JOAA"}},"user_id":"@user-2-bob:hs1","unsigned":{}}) }}}, master_keys: {"@user-1-alice:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-1-alice:hs1","usage":["master"],"keys":{"ed25519:lH4mbSzaBSxje8D0B0VzvHoP7vjtdA/HdIL4rm65Q1o":"lH4mbSzaBSxje8D0B0VzvHoP7vjtdA/HdIL4rm65Q1o"},"signatures":{"@user-1-alice:hs1":{"ed25519:DXAJSVMTBK":"3+0AvZIaz76i9Z+XQeoK1mRhCqo6EswgbqaycJh1RvZATzITBVIHzahXkJNQJrvpSYBKoy6lml+oeftWV3mkBg","ed25519:lH4mbSzaBSxje8D0B0VzvHoP7vjtdA/HdIL4rm65Q1o":"6nPMtBS29cLMHcCM0rx4pQE4kYRNl6HfYNnXeO9FoFQ8Edm+IftZb4JQwv9fboWZaCio9her6G0b43qQIgdLBA"}}}) }, "@user-2-bob:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-2-bob:hs1","usage":["master"],"keys":{"ed25519:ENOuvQRyOUWEfQhuCb/PcrBOuHMVj0cnoGJ6r847Z6Y":"ENOuvQRyOUWEfQhuCb/PcrBOuHMVj0cnoGJ6r847Z6Y"},"signatures":{"@user-2-bob:hs1":{"ed25519:ENOuvQRyOUWEfQhuCb/PcrBOuHMVj0cnoGJ6r847Z6Y":"D8rt3qyZL4XRAPXkpG5pKVfcjqbfA1pI+4jej98WG5p6CeFbParFw4ssZa+ojRSj94MAYcZ9H/mEr/9RShdoCg","ed25519:HSFBWTHASM":"mpeRxWtZlHIqKeWzm0pjbR0FCcN5Es6YSj0G5a943QjopBYio7zsSIxIRE+qs9WfY7gDyKpKBpQnhj6Q91bXDA"}}}) }}, self_signing_keys: {"@user-1-alice:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-1-alice:hs1","usage":["self_signing"],"keys":{"ed25519:V52nJrShkQOyOlEUZUg9kYdH3ykL5obUisUGX3LA2WA":"V52nJrShkQOyOlEUZUg9kYdH3ykL5obUisUGX3LA2WA"},"signatures":{"@user-1-alice:hs1":{"ed25519:lH4mbSzaBSxje8D0B0VzvHoP7vjtdA/HdIL4rm65Q1o":"xPR8Cb36hR2o3gMaodIuSFJ5oB46MjDvDVT56hVLhe/OmPCEK+ayUf7Zki2J+YfNQHhgR9i7hy1leyrpbJSYBg"}}}) }, "@user-2-bob:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-2-bob:hs1","usage":["self_signing"],"keys":{"ed25519:S643I3dgLPOw+elj2zcq5X9ACB9yHnuVO+GrzPmb3zI":"S643I3dgLPOw+elj2zcq5X9ACB9yHnuVO+GrzPmb3zI"},"signatures":{"@user-2-bob:hs1":{"ed25519:ENOuvQRyOUWEfQhuCb/PcrBOuHMVj0cnoGJ6r847Z6Y":"u9/g01tz2FQO0TKMsWZ3QNtCa2XN2taz/6msT/sMNZLbwyfmpH5oRBtBFZkOV6vCzQWcr+9U89pwpRVsVSkcAA"}}}) }}, user_signing_keys: {"@user-1-alice:hs1": Raw::<ruma_common::encryption::CrossSigningKey> { json: RawValue({"user_id":"@user-1-alice:hs1","usage":["user_signing"],"keys":{"ed25519:7b5aowAsI0/g6lTfJZSAbw2+jlJjbxOU3hWXleAYoYQ":"7b5aowAsI0/g6lTfJZSAbw2+jlJjbxOU3hWXleAYoYQ"},"signatures":{"@user-1-alice:hs1":{"ed25519:lH4mbSzaBSxje8D0B0VzvHoP7vjtdA/HdIL4rm65Q1o":"pNjJdS0QPijHuxmUZZcHE+H5hNcgQrssbs9xeWDf10k0ICLuinjTdyeZgWmj/8y83OkHSfC1/mMiOyJvcfmWBw"}}}) }} }} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6, V1_7, V1_8, V1_9, V1_10, V1_11] config=RequestConfig { timeout: 30s } request_id="REQ-6" method=GET uri="http://127.0.0.1:64875/_matrix/client/v3/user/@user-1-alice:hs1/account_data/m.secret_storage.default_key"}
2024-10-01T09:06:32.133383Z TRACE matrix_sdk_base::sliding_sync: applied changes | crates/matrix-sdk-base/src/sliding_sync/mod.rs:342 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response > process_sliding_sync
2024-10-01T09:06:32.134159Z DEBUG matrix_sdk::sync: Ran event handlers in 122.625µs | crates/matrix-sdk/src/sync.rs:228 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response > call_sync_response_handlers
2024-10-01T09:06:32.134180Z DEBUG matrix_sdk::sync: Ran notification handlers in 4.917µs | crates/matrix-sdk/src/sync.rs:253 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response > call_sync_response_handlers
2024-10-01T09:06:32.134193Z DEBUG matrix_sdk::sliding_sync: Sliding Sync response has been handled by the client sync_response=SyncResponse { rooms: Rooms { leave: {}, join: {"!UVxAtJiTYqykKINRsR:hs1": JoinedRoom { unread_notifications: UnreadNotificationsCount { highlight_count: 0, notification_count: 0 }, timeline: Timeline { limited: false, prev_batch: Some("s11_1_0_1_1_1_1_11_0_1"), events: [SyncTimelineEvent { event: RawEvent { event_id: "$ZpvMbwoQJkSBFtdWgx6ye5sb7WQ2TMtM4jgA-5HhiGk", event_type: "m.room.message", .. }, encryption_info: EncryptionInfo { sender: "@user-1-alice:hs1", sender_device: Some("DXAJSVMTBK"), algorithm_info: MegolmV1AesSha2 { curve25519_key: "gJ9gM2iS373AV6P7EpLyDfmaFNUG2T5eNFsz1EvR2Gw", sender_claimed_keys: {"ed25519": "nhVYaKyK1UGQpB//7H2jOf3yZ8T/AQXS0mgDQ1UkkwY"} }, verification_state: Verified } }] }, state: [], account_data: [], ephemeral: [], ambiguity_changes: {} }}, invite: {} }, account_data: [], to_device: [], notifications: {}, .. } | crates/matrix-sdk/src/sliding_sync/mod.rs:323 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response
2024-10-01T09:06:32.134248Z DEBUG matrix_sdk::sliding_sync: Update lists lists={"all_rooms": List { count: 1 }} | crates/matrix-sdk/src/sliding_sync/mod.rs:388 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"} > handle_response
2024-10-01T09:06:32.135080Z DEBUG matrix_sdk::sliding_sync: Done handling response | crates/matrix-sdk/src/sliding_sync/mod.rs:679 | spans: sync_once{pos="2/s11_1_0_1_1_1_1_11_0_1"}
2024-10-01T09:06:32.135134Z DEBUG matrix_sdk_ui::room_list_service: New state state=SettingUp | crates/matrix-sdk-ui/src/room_list_service/mod.rs:220
2024-10-01T09:06:32.135153Z DEBUG matrix_sdk_ui::room_list_service: Run a sync iteration | crates/matrix-sdk-ui/src/room_list_service/mod.rs:211
2024-10-01T09:06:32.135211Z DEBUG matrix_sdk::sliding_sync: Sync stream is running | crates/matrix-sdk/src/sliding_sync/mod.rs:748
2024-10-01T09:06:32.135222Z DEBUG matrix_sdk::sliding_sync: Sync stream has received an internal message internal_message=Ok(SyncLoopSkipOverCurrentIteration) | crates/matrix-sdk/src/sliding_sync/mod.rs:756
2024-10-01T09:06:32.135230Z DEBUG matrix_sdk::sliding_sync: Sync stream is running | crates/matrix-sdk/src/sliding_sync/mod.rs:748
2024-10-01T09:06:32.135409Z DEBUG log: cancel    
2024-10-01T09:06:32.135423Z DEBUG matrix_sdk_ffi::task_handle: Cancelling the task handle | bindings/matrix-sdk-ffi/src/task_handle.rs:24
2024-10-01T09:06:32.135464Z DEBUG log: log_event    
2024-10-01T09:06:32.135477Z  INFO TestRoomKeyIsNotCycledOnClientRestart/rust: [@user-1-alice:hs1](rust) MustStartSyncing now syncing | rust.go:0

kegsay commented 1 month ago

Right, found the cause. When it starts up, 2 sliding sync connections are made:

Starting sync stream | crates/matrix-sdk/src/sliding_sync/mod.rs:742 | spans: sync_stream{conn_id="room-list" with_e2ee=false}
Starting sync stream | crates/matrix-sdk/src/sliding_sync/mod.rs:742 | spans: sync_stream{conn_id="encryption" with_e2ee=true}

This causes 2x HTTP requests to /sync. On passing tests, both finish quickly. On failing tests, one does not return at all for the duration of the test. Looking at the MITM dump for the failed run and it's clear that the one that doesn't return is room-list, which is sent as POST http://hs1:8008/_matrix/client/unstable/org.matrix.simplified_msc3575/sync?pos=0%2Fs259_3_0_1_17_1_31_245_0_1&timeout=30000:

{
    "conn_id": "room-list",
    "extensions": {
        "account_data": {
            "enabled": true
        },
        "receipts": {
            "enabled": true,
            "rooms": [
                "*"
            ]
        },
        "typing": {
            "enabled": true
        }
    },
    "lists": {
        "all_rooms": {
            "filters": {
                "not_room_types": [
                    "m.space"
                ]
            },
            "include_heroes": true,
            "ranges": [
                [
                    0,
                    0
                ]
            ],
            "required_state": [
                [
                    "m.room.encryption",
                    ""
                ],
                [
                    "m.room.member",
                    "$LAZY"
                ],
                [
                    "m.room.member",
                    "$ME"
                ],
                [
                    "m.room.name",
                    ""
                ],
                [
                    "m.room.canonical_alias",
                    ""
                ],
                [
                    "m.room.power_levels",
                    ""
                ]
            ],
            "timeline_limit": 1
        }
    },
    "txn_id": "86a22ed3a03948dc985c7c32be1b5327"
}

I suspect the sync code assumes that room-list requests return immediately on startup (which has been true up until now). By sharing the pos, it's possible for this request to block until there is new data, up to timeout seconds.

So this is a real bug unfortunately. The reason why it is flakey is likely due to the slow speed of GHA boxes. I suspect the test itself runs much more slowly, giving enough time for the new data to come down before the restart, meaning when it starts up again there is no new data to fetch, hence it blocks waiting for more data.

The end-user impact of this will presumably be a spinner showing for 30s (as it's also waiting on the same listener the tests are) upon restart. You likely didn't see this because your account is way more active, meaning there is a high chance something will come down before the timeout, but in a test scenario this is not the case.

MatMaul commented 1 month ago

@kegsay thanks a lot for the detailed investigation :pray:

The fix should be easy-ish with all those infos, I'll have a look tomorrow.

kegsay commented 1 month ago

The fix fwiw is to just use ?timeout=0 on the first sync (before the room list state is loaded). This matches sync V2 behaviour in other clients.

MatMaul commented 1 month ago

The fix fwiw is to just use ?timeout=0 on the first sync (before the room list state is loaded). This matches sync V2 behaviour in other clients.

I don't think it will be useful: syncv2 spec is saying that no timeout specified is the same as timeout=0. Synapse code seems to agree, for both syncv2 and SSS.

MatMaul commented 1 month ago

Nevermind, timeout of the first req is 60s in your logs.

MatMaul commented 1 month ago

The fix fwiw is to just use ?timeout=0 on the first sync (before the room list state is loaded). This matches sync V2 behaviour in other clients.

It seems we don't really need to use this trick here, cf https://github.com/matrix-org/matrix-rust-sdk/pull/4035/commits/492166a3d6377a363dc86ec50d9718fa29ee8ad6.

MatMaul commented 1 month ago

Right I think this is ready.

@kegsay what you found should now be tested.

Hywan commented 2 weeks ago

We are very close to see a merge here. As soon as you address the last comments, we are good.

Hywan commented 1 week ago

@MatMaul I've written https://github.com/matrix-org/matrix-rust-sdk/pull/4208 which should remove the handling of with_encryption in your patch. Since you've some necessary rebasing anyway, I thought it would be helpful.

matrix-org / matrix-rust-sdk

Activate share_pos on the room-list sliding sync instance #4035

Codecov Report