TestRoomKeyIsCycledAfterEnoughTime flake due to no local/remote echo

[kegsay]

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

[kegsay]

It's not the sending task. It's the fact that we don't see the remote echo for this event. We don't even see the local echo for this event actually...

[kegsay]

The local echo handler worked for the previous message sent by Alice:

2024-07-09T07:40:13.530040Z  INFO TestRoomKeyIsCycledAfterEnoughTime/{rust_hs1}|{rust_hs1}: [@user-49-alice:hs1](rust) SendMessage !KWuNNCWLHHGZwtRoVU:hs1 => Before we start | rust.go:0
...
2024-07-09T07:40:13.531892Z  INFO matrix_sdk_ui::timeline::builder: spawned the local echo handler! | crates/matrix-sdk-ui/src/timeline/builder.rs:286 | spans: local_echo_handler{room_id="!KWuNNCWLHHGZwtRoVU:hs1"}
...
2024-07-09T07:40:13.533799Z DEBUG matrix_sdk_ui::timeline::event_handler: Handling local event | crates/matrix-sdk-ui/src/timeline/event_handler.rs:301 | spans: local_echo_handler{room_id="!KWuNNCWLHHGZwtRoVU:hs1"} > handle_local_event > handle_local_event > handle_event{txn_id="85ace0bf7c2d454f9095200a9528ccc0"}
2024-07-09T07:40:13.533775Z DEBUG matrix_sdk_crypto::olm::account: The fallback key either expired or we didn't have one: generated a new fallback key. removed_fallback_key=None | crates/matrix-sdk-crypto/src/olm/account.rs:598 | spans: next_sync_with_lock > sync_once > handle_response > preprocess_to_device_events > receive_sync_changes
2024-07-09T07:40:13.533912Z DEBUG log: processing CharacterTokens(NotSplit, Tendril<UTF8>(shared: \"Before we start\")) in insertion mode InBody     | spans: local_echo_handler{room_id="!KWuNNCWLHHGZwtRoVU:hs1"} > handle_local_event > handle_local_event > handle_event{txn_id="85ace0bf7c2d454f9095200a9528ccc0"}
2024-07-09T07:40:13.533969Z DEBUG log: processing EOF in state Data     | spans: local_echo_handler{room_id="!KWuNNCWLHHGZwtRoVU:hs1"} > handle_local_event > handle_local_event > handle_event{txn_id="85ace0bf7c2d454f9095200a9528ccc0"}
2024-07-09T07:40:13.534005Z DEBUG log: processing EOFToken in insertion mode InBody     | spans: local_echo_handler{room_id="!KWuNNCWLHHGZwtRoVU:hs1"} > handle_local_event > handle_local_event > handle_event{txn_id="85ace0bf7c2d454f9095200a9528ccc0"}
2024-07-09T07:40:13.534056Z TRACE matrix_sdk_ui::timeline::event_handler: Adding new local timeline item | crates/matrix-sdk-ui/src/timeline/event_handler.rs:937 | spans: local_echo_handler{room_id="!KWuNNCWLHHGZwtRoVU:hs1"} > handle_local_event > handle_local_event > handle_event{txn_id="85ace0bf7c2d454f9095200a9528ccc0"}

There's literally 0 log lines for "local" for the event that wasn't in the timeline.