Hookshot sometimes randomly omit sending encryption keys to some devices

[Twi1ightSparkle]

I cannot see any patterns. It just randomly happens sometimes for some devices. Then later it just starts working again without me doing anything. I cannot reproduce as I have not found any way to trigger this. Restarting one or more of Hookshot, Synapse, or Redis doesn't seem to make any difference.

Not sure if any of the below info is all that helpful tbh, but I guess better have too much than too little info

Here is one of my e2e Hookshot feed rooms seen from multiple devices and accounts. All of my Hookshot rooms tend to start and stop UTD-ing at the same time.

User on the same homeserver as Hookshot, Element Desktop. The two "test" messages were sent from the two Desktop sessions (device 1)

User on the same homeserver as Hookshot, Element Desktop, same account, another session (device 2)

Element Rageshake from this device

2025-01-16T16:17:20.513Z W WARN matrix_sdk_crypto::machine: Failed to decrypt a room event: Can't find the room key to decrypt the event, withheld code: None
    at /home/runner/.cargo/git/checkouts/matrix-rust-sdk-1f4927f82a3d27bb/37c17cf/crates/matrix-sdk-crypto/src/machine/mod.rs:1839
    in matrix_sdk_crypto::machine::decrypt_room_event with room_id="!room_id:example.com" sender="@hookshot:example.com" event_id="$event_id" origin_server_ts="2025-01-16T16:17:20.246Z" algorithm="m.megolm.v1.aes-sha2" sender_key="curve25519:<sender_key>" session_id="<session_id>" message_index=0
2025-01-16T16:17:20.514Z W Error decrypting event (id=$event_id type=m.room.encrypted sender=@hookshot:example.com room=!room_id:example.com ts=2025-01-16T16:17:20.246Z): DecryptionError[msg: The sender's device has not sent us the keys for this message., sender_key: <sender_key>, session_id: <session_id>]
2025-01-16T16:17:20.515Z W MatrixRTCSessionManager Decryption failed for event $event_id: MEGOLM_UNKNOWN_INBOUND_SESSION_ID will retry once only
2025-01-16T16:17:21.517Z W MatrixRTCSessionManager Decryption failed for event $event_id: MEGOLM_UNKNOWN_INBOUND_SESSION_ID
2025-01-16T16:18:08.187Z D FetchHttpApi: <-- POST https://matrix.example.com/_matrix/client/v3/rooms/!room_id%3Aexample.com/receipt/m.read.private/%24event_id [568ms 200]

User on the same homeserver as Hookshot, Element Desktop, same account, Element X iOS (device 3)

User on another homeserver, Element Desktop (device 4)

User on another homeserver, same user, Element X Android (device 5)

---

Hookshot is not logging anything relevant in debug mode.

Here is Synapse debug logs when grepping for the event ID

2025-01-16 16:17:20,249 - synapse.handlers.message - 1321 - DEBUG - PUT-427 - Created event $<event_id>
2025-01-16 16:17:20,251 - synapse.event_auth - 373 - DEBUG - PUT-427 - Allowing! <FrozenEventV3 event_id=$<event_id>, type=m.room.encrypted, state_key=None, outlier=False>
2025-01-16 16:17:20,310 - synapse.storage.databases.main.events - 2404 - DEBUG - persist_events-0 - _update_outliers_txn: events=['$<event_id>'] have_persisted={}
2025-01-16 16:17:20,311 - synapse.storage.databases.main.events - 2413 - DEBUG - persist_events-0 - _update_outliers_txn: event=$<event_id> outlier=False outlier_persisted=None
2025-01-16 16:17:20,387 - synapse.federation.sender - 594 - INFO - process_event_queue_for_federation-0 - Unexpectedly did not have cached prev group for $<event_id>
2025-01-16 16:17:20,413 - synapse.federation.sender - 631 - DEBUG - process_event_queue_for_federation-0 - Sending <FrozenEventV3 event_id=$<event_id>, type=m.room.encrypted, state_key=None, outlier=False> to {federated-server.tld', 'example.com'}
2025-01-16 16:18:07,827 - synapse.access.http.8008 - 463 - DEBUG - POST-503 - 78.144.30.127 - 8008 - Received request: POST /_matrix/client/v3/rooms/!<room_id>%3Aexample.com/receipt/m.read.private/%24<event_id>
2025-01-16 16:18:07,975 - synapse.storage.databases.main.receipts - 1095 - DEBUG - POST-503 - Receipt m.read.private for event $<event_id> in !<room_id>:example.com (47662 ms old)
2025-01-16 16:18:08,079 - synapse.access.http.8008 - 508 - INFO - POST-503 - 78.144.30.127 - 8008 - {@twilight:example.com} Processed request: 0.219sec/0.033sec (0.009sec, 0.005sec) (0.031sec/0.052sec/6) 2B 200 "POST /_matrix/client/v3/rooms/!<room_id>%3Aexample.com/receipt/m.read.private/%24<event_id> HTTP/1.1" <user_agent> [0 dbevts]

Also, as I'm looking closer at this and editing screenshots, etc. I noticed that I get two different encryption errors on different devices:

Device 1, all messages form Hookshot are red shield. This is the most reliable device of all, I don't think I have ever gotten a UTD from Hookshot here.

Device 2, mix of red and grey shields. On of the worst devices for Hookshot UTDs

Device 4, also a mix:

[Half-Shot]

The decision to send device keys is basically down to the matrix-rust-sdk (and/or Synapse, which feeds it the information), so really this issue is about gathering the right amount of data for the crypto team.

[Twi1ightSparkle]

Is there a way to log anything about this in Hookshot? There's nothing about keys or devices in debug

[Half-Shot]

My feeling is that https://github.com/matrix-org/matrix-rust-sdk/blob/47fc073b708a72806ae21a9e8ee7c4726f245cdb/crates/matrix-sdk/README.md?plain=1#L74 doesn't work for Hookshot, but might be worth a try. I'll see if we can add logging via our binding layer.

[Twi1ightSparkle]

👍️ I'm also setting up a lab env trying to replicate this issue so I can more easily share logs etc without carefully redacting confidential information