matrix-org / matrix-org/complement-crypto
TestRoomKeyIsCycledAfterEnoughTime flake due to no local/remote echo
Nobody has claimed this yet.
- Dominant language
- Go
- Stars
- 18
- Forks
- 12
- Avg merge
- 2d 12h
- Merged PRs (30d)
- 6
Description
Run https://github.com/matrix-org/matrix-rust-sdk/actions/runs/9852865102/job/27202217506
It looks like the sending_task never returns, despite it sending the message.
Relevant logs:
```
2024-07-09T07:40:13.676048Z INFO TestRoomKeyIsCycledAfterEnoughTime/{rust_hs1}|{rust_hs1}: [@user-49-alice:hs1](rust) SendMessage !KWuNNCWLHHGZwtRoVU:hs1 => Before the time expires | rust.go:0
...
2024-07-09T07:40:13.676539Z TRACE matrix_sdk::send_queue: received an event to send! txn_id=1e5843d0d07644df946b0ad9c55abebb | crates/matrix-sdk/src/send_queue.rs:436 | spans: sending_task{room_id=!KWuNNCWLHHGZwtRoVU:hs1}
...
2024-07-09T07:40:13.676655Z TRACE matrix_sdk::room::futures: Sending encrypted event because the room is encrypted. room_id="!KWuNNCWLHHGZwtRoVU:hs1" | crates/matrix-sdk/src/room/futures.rs:194 | spans: sending_task{room_id=!KWuNNCWLHHGZwtRoVU:hs1} > send_raw{room_id="!KWuNNCWLHHGZwtRoVU:hs1" transaction_id="1e5843d0d07644df946b0ad9c55abebb" is_room_encrypted=true}
...
2024-07-09T07:40:13.677198Z 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:301 | spans: sending_task{room_id=!KWuNNCWLHHGZwtRoVU:hs1} > send_raw{room_id="!KWuNNCWLHHGZwtRoVU:hs1" transaction_id="1e5843d0d07644df946b0ad9c55abebb" is_room_encrypted=true} > preshare_room_key{room_id="!KWuNNCWLHHGZwtRoVU:hs1" } > get_missing_sessions
...
2024-07-09T07:40:13.678445Z DEBUG matrix_sdk::http_client::native: Sending request num_attempt=1 | crates/matrix-sdk/src/http_client/native.rs:55 | spans: sending_task{room_id=!KWuNNCWLHHGZwtRoVU:hs1} > send_raw{room_id="!KWuNNCWLHHGZwtRoVU:hs1" transaction_id="1e5843d0d07644df946b0ad9c55abebb" is_room_encrypted=true} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6] config=RequestConfig { timeout: 30s, retry_limit: 3 } request_id="REQ-21" method=PUT uri="http://127.0.0.1:32781/_matrix/client/v3/rooms/!KWuNNCWLHHGZwtRoVU:hs1/send/m.room.encrypted/1e5843d0d07644df946b0ad9c55abebb" request_size="577 B"}
...
2024-07-09T07:40:13.699839Z DEBUG matrix_sdk::http_client: Got response | crates/matrix-sdk/src/http_client/mod.rs:228 | spans: sending_task{room_id=!KWuNNCWLHHGZwtRoVU:hs1} > send_raw{room_id="!KWuNNCWLHHGZwtRoVU:hs1" transaction_id="1e5843d0d07644df946b0ad9c55abebb" is_room_encrypted=true} > send{server_versions=[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5, V1_6] config=RequestConfig { timeout: 30s, retry_limit: 3 } request_id="REQ-21" method=PUT uri="http://127.0.0.1:32781/_matrix/client/v3/rooms/!KWuNNCWLHHGZwtRoVU:hs1/send/m.room.encrypted/1e5843d0d07644df946b0ad9c55abebb" request_size="577 B" status=200 response_size="59 B"}
...
2024-07-09T07:40:13.699942Z INFO matrix_sdk::room::futures: Sent event in room | crates/matrix-sdk/src/room/futures.rs:236 | spans: sending_task{room_id=!KWuNNCWLHHGZwtRoVU:hs1} > send_raw{room_id="!KWuNNCWLHHGZwtRoVU:hs1" transaction_id="1e5843d0d07644df946b0ad9c55abebb" is_room_encrypted=true event_id="$WjfmfvepH3dxgepiHbRJQ_WfTMrFAVcEuslWDB_9lrs"}
2024-07-09T07:40:13.699991Z TRACE matrix_sdk::send_queue: successfully sent txn_id=1e5843d0d07644df946b0ad9c55abebb event_id=$WjfmfvepH3dxgepiHbRJQ_WfTMrFAVcEuslWDB_9lrs | crates/matrix-sdk/src/send_queue.rs:454 | spans: sending_task{room_id=!KWuNNCWLHHGZwtRoVU:hs1}
2024-07-09T07:40:13.700070Z TRACE matrix_sdk::send_queue: queue is empty, sleeping | crates/matrix-sdk/src/send_queue.rs:424 | spans: sending_task{room_id=!KWuNNCWLHHGZwtRoVU:hs1}
```
Despite this:
```
room_keys_test.go:214: [@user-50-bob:hs1](rust) WaitUntilEventInRoom !KWuNNCWLHHGZwtRoVU:hs1
room_keys_test.go:215: [@user-49-alice:hs1](rust) SendMessage !KWuNNCWLHHGZwtRoVU:hs1 => Before the time expires
rust.go:692: [@user-50-bob:hs1]AddTimelineListener[!KWuNNCWLHHGZwtRoVU:hs1] TimelineDiff len=2
rust.go:788: [@user-50-bob:hs1]TimelineDiff change: &{ID:$nOnJ6G2db0lEjeJVee7VWJN7goLxIFNZq49sDBySYbM Text:Before we start Sender:@user-49-alice:hs1 Target: Membership: FailedToDecrypt:false}
rust.go:788: [@user-50-bob:hs1]TimelineDiff change: &{ID:$WjfmfvepH3dxgepiHbRJQ_WfTMrFAVcEuslWDB_9lrs Text:Before the time expires Sender:@user-49-alice:hs1 Target: Membership: FailedToDecrypt:false}
room_keys_test.go:215: SendMessage(rust) @user-49-alice:hs1: timed out after 11s
```
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start with room_keys_test.go around lines 214-215 and the SendMessage/WaitUntilEventInRoom flow, then compare it with the matrix-rust-sdk send_queue and room futures logs shown here. Run the referenced Complement crypto test or CI job to reproduce the timeout. Done means the test reliably observes completion after the event is sent and no longer flakes.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go, rust
- Domain
- cryptography, testing
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 35/100