Some notifications don't decrypt

[kongo09]

Steps to reproduce

1. Rolling down the notification drawer of Android
2. Looking at EX notifications

Outcome

What did you expect?

See a line of text with the notification

What happened instead?

Some notifications only contain the line "message"

Your phone model

Pixel 5

Operating system version

Android 13

Application version and app store

0.1.6-nightly

Homeserver

element.io

Will you send logs?

No

Are you willing to provide a PR?

No

[jmartinesp]

This should be better after #1199. Could you use the nightly and let us know if the problem is fixed?

[manuroe]

@julioromano for info, I moved this issue to S-Major because notifications are very important for the trust a user can have in an app. If a messaging app cannot deliver notifications, it is pointless.
I do not think we wrote that somewhere but I wanted to let you know why this move happened.

[manuroe]

One way to reproduce the problem:

• Alice and Bob in room. Bob is using EAX
• bob kills EAX
• Alice rotates their megolm keys by typing '/discardsession' in this room
• Alice sends a message
• Bob should see the notification decrypted on their android device

[bmarty]

(Bob does not need to kill EXA, putting the app into background is sufficient).

Here are the log showing the issue:

Logs

2023-09-01 16:52:10.429 18652-18652 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: onPause RootFlowNode | LifecycleExt.kt:26
2023-09-01 16:52:10.429 18652-18652 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: onPause LoggedInAppScopeFlowNode | LifecycleExt.kt:26
2023-09-01 16:52:10.430 18652-18652 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: onPause LoggedInFlowNode | LifecycleExt.kt:26
2023-09-01 16:52:10.433 18652-18652 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: onPause LoggedInNode | LifecycleExt.kt:26
2023-09-01 16:52:10.444 18652-18652 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: onPause RoomListNode | LifecycleExt.kt:26
2023-09-01 16:52:10.459 18652-18652 org.matrix.rust.sdk     io.element.android.x.debug           W  elementx: onPause | MainActivity.kt:115
2023-09-01 16:52:10.522 18652-18686 EGL_emulation           io.element.android.x.debug           D  app_time_stats: avg=5148.01ms min=2.48ms max=138697.58ms count=27
2023-09-01 16:52:10.932 18652-18652 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: Save matrix session keys = [@benoit0816:matrix.org] | MatrixClientsHolder.kt:84
2023-09-01 16:52:10.933 18652-18652 org.matrix.rust.sdk     io.element.android.x.debug           I  elementx: Stop sync | RustSyncService.kt:45
2023-09-01 16:52:10.939 18652-18697 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::sliding_sync: Sync stream has received an internal message �[3minternal_message�[0m�[2m=�[0mOk(SyncLoopStop) | crates/matrix-sdk/src/sliding_sync/mod.rs:690 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"room-list" �[3mwith_e2ee�[0m�[2m=�[0mtrue}
2023-09-01 16:52:10.939 18652-18697 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::sliding_sync: Sync stream has exited. | crates/matrix-sdk/src/sliding_sync/mod.rs:734
2023-09-01 16:52:10.941 18652-18652 org.matrix.rust.sdk     io.element.android.x.debug           I  elementx: Sync state=Idle | RustSyncService.kt:55
2023-09-01 16:52:10.941 18652-18652 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: RoomList state=Terminated | RustRoomListService.kt:113
2023-09-01 16:52:29.848 18652-18848 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: New Firebase message | VectorFirebaseMessagingService.kt:52
2023-09-01 16:52:29.849 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: ## handling pushData | DefaultPushHandler.kt:69
2023-09-01 16:52:29.855 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: ## handleInternal() | DefaultPushHandler.kt:99
2023-09-01 16:52:29.856 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           I  matrix_sdk_ui::notification_client: fetching notification event with a sliding sync | crates/matrix-sdk-ui/src/notification_client.rs:326
2023-09-01 16:52:29.858 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           V  matrix_sdk::sliding_sync::cache: Successfully read the `SlidingSync` from the cache | crates/matrix-sdk/src/sliding_sync/cache.rs:194
2023-09-01 16:52:29.858 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::sliding_sync::cache: loading sliding sync sliding_sync_store::notifications::@benoit0816:matrix.org state from DB finished in 1ms | crates/matrix-sdk/src/sliding_sync/cache.rs:172
2023-09-01 16:52:29.858 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::sliding_sync: Starting sync stream | crates/matrix-sdk/src/sliding_sync/mod.rs:672 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse}
2023-09-01 16:52:29.858 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::sliding_sync: Sync stream is running | crates/matrix-sdk/src/sliding_sync/mod.rs:680 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse}
2023-09-01 16:52:29.862 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::sliding_sync: Sending request | crates/matrix-sdk/src/sliding_sync/mod.rs:545 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once
2023-09-01 16:52:29.873 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::http_client: Sending request | crates/matrix-sdk/src/http_client/mod.rs:198 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > send{�[3mhomeserver�[0m�[2m=�[0m"https://slidingsync.lab.matrix.org/" �[3mserver_versions�[0m�[2m=�[0m[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5] �[3mconfig�[0m�[2m=�[0mRequestConfig { timeout: 4s } �[3mrequest_id�[0m�[2m=�[0m"REQ-54" �[3mrequest_size�[0m�[2m=�[0m"749 B" �[3mrequest_body�[0m�[2m=�[0mb"{\"conn_id\":\"notifications\",\"txn_id\":\"a239235df7c14277a65640356fbfb409\",\"lists\":{\"invites\":{\"ranges\":[[0,16]],\"sort\":[\"by_recency\",\"by_name\"],\"required_state\":[[\"m.room.avatar\",\"\"],[\"m.room.encryption\",\"\"],[\"m.room.member\",\"$LAZY\"],[\"m.room.member\",\"$ME\"],[\"m.room.canonical_alias\",\"\"],[\"m.room.name\",\"\"],[\"m.room.power_levels\",\"\"]],\"timeline_limit\":8,\"filters\":{\"is_invite\":true,\"is_tombstoned\":false,\"not_room_types\":[\"m.space\"]}}},\"room_subscriptions\":{\"!XNchDzMJuRSsMtYRkr:matrix.org\":{\"required_state\":[[\"m.room.avatar\",\"\"],[\"m.room.encryption\",\"\"],[\"m.room.member\",\"$LAZY\"],[\"m.room.member\",\"$ME\"],[\"m.room.canonical_alias\",\"\"],[\"m.room.name\",\"\"],[\"m.room.power_levels\",\"\"]],\"timeline_limit\":16}},\"extensions\":{\"account_data\":{\"enabled\":true}}}" �[3mpath�[0m�[2m=�[0m"/_matrix/client/unstable/org.matrix.msc3575/sync?timeout=1000"}
2023-09-01 16:52:29.944 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::http_client: Got response | crates/matrix-sdk/src/http_client/mod.rs:204 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > send{�[3mhomeserver�[0m�[2m=�[0m"https://slidingsync.lab.matrix.org/" �[3mserver_versions�[0m�[2m=�[0m[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5] �[3mconfig�[0m�[2m=�[0mRequestConfig { timeout: 4s } �[3mrequest_id�[0m�[2m=�[0m"REQ-54" �[3mrequest_size�[0m�[2m=�[0m"749 B" �[3mrequest_body�[0m�[2m=�[0mb"{\"conn_id\":\"notifications\",\"txn_id\":\"a239235df7c14277a65640356fbfb409\",\"lists\":{\"invites\":{\"ranges\":[[0,16]],\"sort\":[\"by_recency\",\"by_name\"],\"required_state\":[[\"m.room.avatar\",\"\"],[\"m.room.encryption\",\"\"],[\"m.room.member\",\"$LAZY\"],[\"m.room.member\",\"$ME\"],[\"m.room.canonical_alias\",\"\"],[\"m.room.name\",\"\"],[\"m.room.power_levels\",\"\"]],\"timeline_limit\":8,\"filters\":{\"is_invite\":true,\"is_tombstoned\":false,\"not_room_types\":[\"m.space\"]}}},\"room_subscriptions\":{\"!XNchDzMJuRSsMtYRkr:matrix.org\":{\"required_state\":[[\"m.room.avatar\",\"\"],[\"m.room.encryption\",\"\"],[\"m.room.member\",\"$LAZY\"],[\"m.room.member\",\"$ME\"],[\"m.room.canonical_alias\",\"\"],[\"m.room.name\",\"\"],[\"m.room.power_levels\",\"\"]],\"timeline_limit\":16}},\"extensions\":{\"account_data\":{\"enabled\":true}}}" �[3mpath�[0m�[2m=�[0m"/_matrix/client/unstable/org.matrix.msc3575/sync?timeout=1000" �[3mstatus�[0m�[2m=�[0m200 �[3mresponse_size�[0m�[2m=�[0m"20.9 kiB"}
2023-09-01 16:52:29.944 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::sliding_sync: Received response | crates/matrix-sdk/src/sliding_sync/mod.rs:611 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once
2023-09-01 16:52:29.944 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::sliding_sync: Start handling response | crates/matrix-sdk/src/sliding_sync/mod.rs:627 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once
2023-09-01 16:52:29.944 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::sliding_sync: Update position markers` �[3mpos�[0m�[2m=�[0m"1" �[3mdelta_token�[0m�[2m=�[0mNone | crates/matrix-sdk/src/sliding_sync/mod.rs:285 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response
2023-09-01 16:52:29.945 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           V  matrix_sdk::sliding_sync: starting �[3mroom_id�[0m�[2m=�[0m"!XNchDzMJuRSsMtYRkr:matrix.org" | crates/matrix-sdk/src/sliding_sync/mod.rs:933 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > compute_limited
2023-09-01 16:52:29.945 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           V  matrix_sdk::sliding_sync: room isn't known locally => not limited | crates/matrix-sdk/src/sliding_sync/mod.rs:987 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > compute_limited
2023-09-01 16:52:29.945 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           V  matrix_sdk::sliding_sync: starting �[3mroom_id�[0m�[2m=�[0m"!cdWMMPQeQyjrYFmIAt:matrix.org" | crates/matrix-sdk/src/sliding_sync/mod.rs:933 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > compute_limited
2023-09-01 16:52:29.945 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           V  matrix_sdk::sliding_sync: room isn't known locally => not limited | crates/matrix-sdk/src/sliding_sync/mod.rs:987 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > compute_limited
2023-09-01 16:52:29.945 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           V  matrix_sdk::sliding_sync: starting �[3mroom_id�[0m�[2m=�[0m"!hGzmmUAyaJYjMiDVUR:matrix.org" | crates/matrix-sdk/src/sliding_sync/mod.rs:933 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > compute_limited
2023-09-01 16:52:29.945 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           V  matrix_sdk::sliding_sync: room isn't known locally => not limited | crates/matrix-sdk/src/sliding_sync/mod.rs:987 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > compute_limited
2023-09-01 16:52:29.945 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           V  matrix_sdk_base::sliding_sync: Processing sliding sync room events �[3mrooms�[0m�[2m=�[0m3 �[3mlists�[0m�[2m=�[0m1 �[3mextensions�[0m�[2m=�[0mtrue | crates/matrix-sdk-base/src/sliding_sync.rs:125 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > process_sliding_sync
2023-09-01 16:52:29.946 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           W  matrix_sdk_base::client: Failed to deserialize a global account data event: required colon is missing at line 1 column 355 �[3mevent_type�[0m�[2m=�[0m"m.direct" | crates/matrix-sdk-base/src/client.rs:538 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > process_sliding_sync > handle_account_data
2023-09-01 16:52:29.971 18652-18697 org.matrix.rust.sdk     io.element.android.x.debug           W  matrix_sdk_crypto::machine: Failed to decrypt a room event: Can't find the room key to decrypt the event, withheld code: None | crates/matrix-sdk-crypto/src/machine.rs:1434 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > process_sliding_sync > handle_timeline{�[3mroom_id�[0m�[2m=�[0m"!XNchDzMJuRSsMtYRkr:matrix.org"} > decrypt_room_event{�[3mroom_id�[0m�[2m=�[0m"!XNchDzMJuRSsMtYRkr:matrix.org" �[3msender�[0m�[2m=�[0m"@benoit.marty:matrix.org" �[3mevent_id�[0m�[2m=�[0m"$169357995016740tRrnj:matrix.org" �[3malgorithm�[0m�[2m=�[0m"m.megolm.v1.aes-sha2" �[3msender_key�[0m�[2m=�[0m"curve25519:eMBHGCpDlTlosCIb0g/BZf/WzXjIlQQO+NuWgjTOh3I" �[3msession_id�[0m�[2m=�[0m"FsSwGFXVqP0t8a54sT5rBer4I6CTVDTH+Rb4WO0AZtQ"}
2023-09-01 16:52:29.973 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           W  matrix_sdk_base::client: Failed to deserialize a global account data event: required colon is missing at line 1 column 355 �[3mevent_type�[0m�[2m=�[0m"m.direct" | crates/matrix-sdk-base/src/client.rs:538 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > process_sliding_sync > handle_account_data
2023-09-01 16:52:29.973 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           V  matrix_sdk_base::sliding_sync: ready to submit changes to store | crates/matrix-sdk-base/src/sliding_sync.rs:215 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > process_sliding_sync
2023-09-01 16:52:29.974 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           V  matrix_sdk_base::sliding_sync: applied changes | crates/matrix-sdk-base/src/sliding_sync.rs:218 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > process_sliding_sync
2023-09-01 16:52:29.975 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           W  matrix_sdk_ui::notification_client: could not get event id | crates/matrix-sdk-ui/src/notification_client.rs:239 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > handle_sync_response > call_event_handlers{�[3mevent_kind�[0m�[2m=�[0mStrippedState �[3mevent_type�[0m�[2m=�[0m"m.room.member" �[3mroom_id�[0m�[2m=�[0m"!cdWMMPQeQyjrYFmIAt:matrix.org"}
2023-09-01 16:52:29.975 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           W  matrix_sdk_ui::notification_client: could not get event id | crates/matrix-sdk-ui/src/notification_client.rs:239 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response > handle_sync_response > call_event_handlers{�[3mevent_kind�[0m�[2m=�[0mStrippedState �[3mevent_type�[0m�[2m=�[0m"m.room.member" �[3mroom_id�[0m�[2m=�[0m"!hGzmmUAyaJYjMiDVUR:matrix.org"}
2023-09-01 16:52:29.975 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::sliding_sync: Sliding Sync response has been handled by the client �[3msync_response�[0m�[2m=�[0mSyncResponse { rooms: Rooms { leave: {}, join: {"!XNchDzMJuRSsMtYRkr:matrix.org": JoinedRoom { unread_notifications: UnreadNotificationsCount { highlight_count: 0, notification_count: 13 }, timeline: Timeline { limited: false, prev_batch: Some("t1012-3749576595_757284974_14356886_2049432409_2072013127_4155483_853984210_7181929774_0_103987"), events: [SyncTimelineEvent { event: RawEvent { event_id: "$167749518171892AXXFH:matrix.org", event_type: "m.room.member", .. } }, SyncTimelineEvent { event: RawEvent { event_id: "$169357941616673RdyWf:matrix.org", event_type: "m.room.message", .. }, encryption_info: EncryptionInfo { sender: "@benoit.marty:matrix.org", sender_device: Some("KEKRFBLWLR"), algorithm_info: MegolmV1AesSha2 { curve25519_key: "eMBHGCpDlTlosCIb0g/BZf/WzXjIlQQO+NuWgjTOh3I", sender_claimed_keys: {"ed25519": "Pgyz8RHB+PClySPXtgIFROZK/1+ZL3vp6QiftewWuFQ"} }, verification_state: Unverified(UnverifiedIdentity) }, push_actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))] }, SyncTimelineEvent { event: RawEvent { event_id: "$169357943316677scvwB:matrix.org", event_type: "m.room.message", .. }, encryption_info: EncryptionInfo { sender: "@benoit.marty:matrix.org", sender_device: Some("KEKRFBLWLR"), algorithm_info: MegolmV1AesSha2 { curve25519_key: "eMBHGCpDlTlosCIb0g/BZf/WzXjIlQQO+NuWgjTOh3I", sender_claimed_keys: {"ed25519": "Pgyz8RHB+PClySPXtgIFROZK/1+ZL3vp6QiftewWuFQ"} }, verification_state: Unverified(UnverifiedIdentity) }, push_actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))] }, SyncTimelineEvent { event: RawEvent { event_id: "$169357944616681uVkKG:matrix.org", event_type: "m.room.message", .. }, encryption_info: EncryptionInfo { sender: "@benoit.marty:matrix.org", sender_device: Some("KEKRFBLWLR"), algorithm_info: MegolmV1AesSha2 { curve25519_key: "eMBHGCpDlTlosCIb0g/BZf/WzXjIlQQO+NuWgjTOh3I", sender_claimed_keys: {"ed25519": "Pgyz8RHB+PClySPXtgIFROZK/1+ZL3vp6QiftewWuFQ"} }, verification_state: Unverified(UnverifiedIdentity) }, push_actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))] }, SyncTimelineEvent { event: RawEvent { event_id: "$169357945316683SOiCI:matrix.org", event_type: "m.room.message", .. }, encryption_info: EncryptionInfo { sender: "@benoit.marty:matrix.org", sender_device: Some("KEKRFBLWLR"), algorithm_info: MegolmV1AesSha2 { curve25519_key: "eMBHGCpDlTlosCIb0g/BZf/WzXjIlQQO+NuWgjTOh3I", sender_claimed_keys: {"ed25519": "Pgyz8RHB+PClySPXtgIFROZK/1+ZL3vp6QiftewWuFQ"} }, verification_state: Unverified(UnverifiedIdentity) }, push_actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))] }, SyncTimelineEvent { event: RawEvent { event_id: "$169357946416684MnbJT:matrix.org", event_type: "m.room.message", .. }, encryption_info: EncryptionInfo { sender: "@benoit.marty:matrix.org", sender_device: Some("KEKRFBLWLR"), algorithm_info: MegolmV1AesSha2 { curve25519_key: "eMBHGCpDlTlosCIb0g/BZf/WzXjIlQQO+NuWgjTOh3I", sender_claimed_keys: {"ed25519": "Pgyz8RHB+PClySPXtgIFROZK/1+ZL3vp6QiftewWuFQ"} }, verification_state: Unverified(UnverifiedIdentity) }, push_actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))] }, SyncTimelineEvent { event: RawEvent { event_id: "$169357947516685rDflu:matrix.org", event_type: "m.room.message", .. }, encryption_info: EncryptionInfo { sender: "@benoit.marty:matrix.org", sender_device: Some("KEKRFBLWLR"), algorithm_info: MegolmV1AesSha2 { curve25519_key: "eMBHGCpDlTlosCIb0g/BZf/WzXjIlQQO+NuWgjTOh3I", sender_claimed_keys: {"ed25519": "Pgyz8RHB+PClySPXtgIFROZK/1+ZL3vp6QiftewWuFQ"} }, verification_state: Unverified(UnverifiedIdentity) }, push_actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))] }, SyncTimelineEvent { event: RawEvent { event_id: "$169357948516689XhgXl:matrix.org", event_type: "m.room.message", .. }, encryption_info: EncryptionInfo { sender: "@benoit.
2023-09-01 16:52:29.975 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           D  marty:matrix.org", sender_device: Some("KEKRFBLWLR"), algorithm_info: MegolmV1AesSha2 { curve25519_key: "eMBHGCpDlTlosCIb0g/BZf/WzXjIlQQO+NuWgjTOh3I", sender_claimed_keys: {"ed25519": "Pgyz8RHB+PClySPXtgIFROZK/1+ZL3vp6QiftewWuFQ"} }, verification_state: Unverified(UnverifiedIdentity) }, push_actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))] }, SyncTimelineEvent { event: RawEvent { event_id: "$169357958716702jNTmM:matrix.org", event_type: "m.room.message", .. }, encryption_info: EncryptionInfo { sender: "@benoit.marty:matrix.org", sender_device: Some("KEKRFBLWLR"), algorithm_info: MegolmV1AesSha2 { curve25519_key: "eMBHGCpDlTlosCIb0g/BZf/WzXjIlQQO+NuWgjTOh3I", sender_claimed_keys: {"ed25519": "Pgyz8RHB+PClySPXtgIFROZK/1+ZL3vp6QiftewWuFQ"} }, verification_state: Unverified(UnverifiedIdentity) }, push_actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))] }, SyncTimelineEvent { event: RawEvent { event_id: "$169357959816704mMrum:matrix.org", event_type: "m.room.message", .. }, encryption_info: EncryptionInfo { sender: "@benoit.marty:matrix.org", sender_device: Some("KEKRFBLWLR"), algorithm_info: MegolmV1AesSha2 { curve25519_key: "eMBHGCpDlTlosCIb0g/BZf/WzXjIlQQO+NuWgjTOh3I", sender_claimed_keys: {"ed25519": "Pgyz8RHB+PClySPXtgIFROZK/1+ZL3vp6QiftewWuFQ"} }, verification_state: Unverified(UnverifiedIdentity) }, push_actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))] }, SyncTimelineEvent { event: RawEvent { event_id: "$169357961416707tDgPJ:matrix.org", event_type: "m.room.message", .. }, encryption_info: EncryptionInfo { sender: "@benoit.marty:matrix.org", sender_device: Some("KEKRFBLWLR"), algorithm_info: MegolmV1AesSha2 { curve25519_key: "eMBHGCpDlTlosCIb0g/BZf/WzXjIlQQO+NuWgjTOh3I", sender_claimed_keys: {"ed25519": "Pgyz8RHB+PClySPXtgIFROZK/1+ZL3vp6QiftewWuFQ"} }, verification_state: Unverified(UnverifiedIdentity) }, push_actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))] }, SyncTimelineEvent { event: RawEvent { event_id: "$169357995016740tRrnj:matrix.org", event_type: "m.room.encrypted", .. }, push_actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))] }] }, state: [RawEvent { event_id: "$156899639462023YySgt:matrix.org", event_type: "m.room.member", .. }, RawEvent { event_id: "$153900955893XHOKr:matrix.org", event_type: "m.room.power_levels", .. }, RawEvent { event_id: "$156025282826140GNSJx:matrix.org", event_type: "m.room.name", .. }, RawEvent { event_id: "$15447906372693464vHXqU:matrix.org", event_type: "m.room.avatar", .. }, RawEvent { event_id: "$1542297278344431SEgcW:matrix.org", event_type: "m.room.encryption", .. }, RawEvent { event_id: "$167749518171892AXXFH:matrix.org", event_type: "m.room.member", .. }, RawEvent { event_id: "$167749518171892AXXFH:matrix.org", event_type: "m.room.member", .. }], account_data: [RawEvent { event_type: "m.fully_read", .. }, RawEvent { event_type: "org.matrix.room.preview_urls", .. }], ephemeral: [] }}, invite: {"!cdWMMPQeQyjrYFmIAt:matrix.org": InvitedRoom { invite_state: [RawEvent { event_id: Missing, event_type: "m.room.create", .. }, RawEvent { event_id: Missing, event_type: "m.room.encryption", .. }, RawEvent { event_id: Missing, event_type: "m.room.join_rules", .. }, RawEvent { event_id: Missing, event_type: "m.room.member", .. }, RawEvent { event_id: "$-OBNsT589PGCH7tqulca4nmQkdyAqn2aPy5zBARQLwo", event_type: "m.room.member", .. }] }, "!hGzmmUAyaJYjMiDVUR:matrix.org": InvitedRoom { invite_state: [RawEvent { event_id: Missing, event_type: "m.room.create", .. }, RawEvent { event_id: Missing, event_type: "m.room.join_rules", .. }, RawEvent { event_id: Missing, event_type: "m.room.member", .. }, RawEvent { event_id: Missing, event_type: "m.room.name", .. }, RawEvent { event_id: "$Dz6ZRWM2jZfD_Cdz9oqCJkqIdLwgf0P_DlZF58DcXvM", event_type: "m.room.member", .. }] }} }, account_data: [RawEvent { event_type: "m.cross_signing.master", .. }, RawEvent { event_type: "m.widgets", .. }, RawEv
2023-09-01 16:52:29.975 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           D  ent { event_type: "m.megolm_backup.v1", .. }, RawEvent { event_type: "m.ignored_user_list", .. }, RawEvent { event_type: "m.secret_storage.key.e1c5462b-c46f-4154-9a3e-b640c2a44946", .. }, RawEvent { event_type: "im.vector.setting.allowed_widgets", .. }, RawEvent { event_type: "m.cross_signing.self_signing", .. }, RawEvent { event_type: "m.accepted_terms", .. }, RawEvent { event_type: "m.push_rules", .. }, RawEvent { event_type: "im.vector.analytics", .. }, RawEvent { event_type: "im.vector.riot.breadcrumb_rooms", .. }, RawEvent { event_type: "m.identity_server", .. }, RawEvent { event_type: "m.cross_signing.user_signing", .. }, RawEvent { event_type: "m.secret_storage.default_key", .. }, RawEvent { event_type: "im.vector.setting.integration_provisioning", .. }, RawEvent { event_type: "org.matrix.preview_urls", .. }, RawEvent { event_type: "im.vector.setting.breadcrumbs", .. }, RawEvent { event_type: "im.vector.web.settings", .. }, RawEvent { event_type: "m.direct", .. }], to_device: [], ambiguity_changes: AmbiguityChanges { changes: {} }, notifications: {"!XNchDzMJuRSsMtYRkr:matrix.org": [Notification { actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))], event: RawEvent { event_id: "$169357941616673RdyWf:matrix.org", event_type: "m.room.message", .. }, profile_tag: None, read: false, room_id: "!XNchDzMJuRSsMtYRkr:matrix.org", ts: MilliSecondsSinceUnixEpoch(1693579949953) }, Notification { actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))], event: RawEvent { event_id: "$169357943316677scvwB:matrix.org", event_type: "m.room.message", .. }, profile_tag: None, read: false, room_id: "!XNchDzMJuRSsMtYRkr:matrix.org", ts: MilliSecondsSinceUnixEpoch(1693579949955) }, Notification { actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))], event: RawEvent { event_id: "$169357944616681uVkKG:matrix.org", event_type: "m.room.message", .. }, profile_tag: None, read: false, room_id: "!XNchDzMJuRSsMtYRkr:matrix.org", ts: MilliSecondsSinceUnixEpoch(1693579949957) }, Notification { actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))], event: RawEvent { event_id: "$169357945316683SOiCI:matrix.org", event_type: "m.room.message", .. }, profile_tag: None, read: false, room_id: "!XNchDzMJuRSsMtYRkr:matrix.org", ts: MilliSecondsSinceUnixEpoch(1693579949959) }, Notification { actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))], event: RawEvent { event_id: "$169357946416684MnbJT:matrix.org", event_type: "m.room.message", .. }, profile_tag: None, read: false, room_id: "!XNchDzMJuRSsMtYRkr:matrix.org", ts: MilliSecondsSinceUnixEpoch(1693579949961) }, Notification { actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))], event: RawEvent { event_id: "$169357947516685rDflu:matrix.org", event_type: "m.room.message", .. }, profile_tag: None, read: false, room_id: "!XNchDzMJuRSsMtYRkr:matrix.org", ts: MilliSecondsSinceUnixEpoch(1693579949963) }, Notification { actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))], event: RawEvent { event_id: "$169357948516689XhgXl:matrix.org", event_type: "m.room.message", .. }, profile_tag: None, read: false, room_id: "!XNchDzMJuRSsMtYRkr:matrix.org", ts: MilliSecondsSinceUnixEpoch(1693579949965) }, Notification { actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))], event: RawEvent { event_id: "$169357958716702jNTmM:matrix.org", event_type: "m.room.message", .. }, profile_tag: None, read: false, room_id: "!XNchDzMJuRSsMtYRkr:matrix.org", ts: MilliSecondsSinceUnixEpoch(1693579949967) }, Notification { actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))], event: RawEvent { event_id: "$169357959816704mMrum:matrix.org", event_type: "m.room.message", .. }, profile_tag: None, read: false, room_id: "!XNchDzMJuRSsMtYRkr:matrix.org", ts: MilliSecondsSinceUnixEpoch(1693579949968) }, Notification { actions: [Notify, SetTweak(Sound("default")), SetTwea
2023-09-01 16:52:29.976 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           D  k(Highlight(false))], event: RawEvent { event_id: "$169357961416707tDgPJ:matrix.org", event_type: "m.room.message", .. }, profile_tag: None, read: false, room_id: "!XNchDzMJuRSsMtYRkr:matrix.org", ts: MilliSecondsSinceUnixEpoch(1693579949970) }, Notification { actions: [Notify, SetTweak(Sound("default")), SetTweak(Highlight(false))], event: RawEvent { event_id: "$169357995016740tRrnj:matrix.org", event_type: "m.room.encrypted", .. }, profile_tag: None, read: false, room_id: "!XNchDzMJuRSsMtYRkr:matrix.org", ts: MilliSecondsSinceUnixEpoch(1693579949971) }]}, .. } | crates/matrix-sdk/src/sliding_sync/mod.rs:337 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response
2023-09-01 16:52:29.976 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::sliding_sync: Update lists �[3mlists�[0m�[2m=�[0m{"invites": SyncList { ops: [SyncOp { op: Sync, range: Some((0, 1)), index: None, room_ids: ["!cdWMMPQeQyjrYFmIAt:matrix.org", "!hGzmmUAyaJYjMiDVUR:matrix.org"], room_id: None }], count: 2 }} | crates/matrix-sdk/src/sliding_sync/mod.rs:393 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once > handle_response
2023-09-01 16:52:29.977 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           V  matrix_sdk::sliding_sync::cache: Saving a `SlidingSync` to the state store �[3mstorage_key�[0m�[2m=�[0m"sliding_sync_store::notifications::@benoit0816:matrix.org" | crates/matrix-sdk/src/sliding_sync/cache.rs:73 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once
2023-09-01 16:52:29.977 18652-18695 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::sliding_sync: Done handling response | crates/matrix-sdk/src/sliding_sync/mod.rs:653 | spans: sync_stream{�[3mconn_id�[0m�[2m=�[0m"notifications" �[3mwith_e2ee�[0m�[2m=�[0mfalse} > sync_once
2023-09-01 16:52:29.981 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: onNotifiableEventReceived(): is push: true | DefaultNotificationDrawerManager.kt:117
2023-09-01 16:52:29.983 18652-18652 org.matrix.rust.sdk     io.element.android.x.debug           V  elementx: refreshNotificationDrawer(), delay: 0 ms | DefaultNotificationDrawerManager.kt:225
2023-09-01 16:52:29.984 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           V  elementx: refreshNotificationDrawerBg() | DefaultNotificationDrawerManager.kt:238
2023-09-01 16:52:29.986 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::http_client: Sending request | crates/matrix-sdk/src/http_client/mod.rs:198 | spans: send{�[3mhomeserver�[0m�[2m=�[0m"https://matrix-client.matrix.org/" �[3mserver_versions�[0m�[2m=�[0m[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5] �[3mconfig�[0m�[2m=�[0mRequestConfig { timeout: 30s, force_auth: true } �[3mrequest_id�[0m�[2m=�[0m"REQ-55" �[3mrequest_size�[0m�[2m=�[0m"0 B" �[3mpath�[0m�[2m=�[0m"/_matrix/client/v3/profile/@benoit0816:matrix.org/displayname"}
2023-09-01 16:52:30.070 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::http_client: Got response | crates/matrix-sdk/src/http_client/mod.rs:204 | spans: send{�[3mhomeserver�[0m�[2m=�[0m"https://matrix-client.matrix.org/" �[3mserver_versions�[0m�[2m=�[0m[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5] �[3mconfig�[0m�[2m=�[0mRequestConfig { timeout: 30s, force_auth: true } �[3mrequest_id�[0m�[2m=�[0m"REQ-55" �[3mrequest_size�[0m�[2m=�[0m"0 B" �[3mpath�[0m�[2m=�[0m"/_matrix/client/v3/profile/@benoit0816:matrix.org/displayname" �[3mstatus�[0m�[2m=�[0m200 �[3mresponse_size�[0m�[2m=�[0m"28 B"}
2023-09-01 16:52:30.071 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::http_client: Sending request | crates/matrix-sdk/src/http_client/mod.rs:198 | spans: send{�[3mhomeserver�[0m�[2m=�[0m"https://matrix-client.matrix.org/" �[3mserver_versions�[0m�[2m=�[0m[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5] �[3mconfig�[0m�[2m=�[0mRequestConfig { timeout: 30s, force_auth: true } �[3mrequest_id�[0m�[2m=�[0m"REQ-56" �[3mrequest_size�[0m�[2m=�[0m"0 B" �[3mpath�[0m�[2m=�[0m"/_matrix/client/v3/profile/@benoit0816:matrix.org/avatar_url"}
2023-09-01 16:52:30.106 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  matrix_sdk::http_client: Got response | crates/matrix-sdk/src/http_client/mod.rs:204 | spans: send{�[3mhomeserver�[0m�[2m=�[0m"https://matrix-client.matrix.org/" �[3mserver_versions�[0m�[2m=�[0m[V1_0, V1_1, V1_2, V1_3, V1_4, V1_5] �[3mconfig�[0m�[2m=�[0mRequestConfig { timeout: 30s, force_auth: true } �[3mrequest_id�[0m�[2m=�[0m"REQ-56" �[3mrequest_size�[0m�[2m=�[0m"0 B" �[3mpath�[0m�[2m=�[0m"/_matrix/client/v3/profile/@benoit0816:matrix.org/avatar_url" �[3mstatus�[0m�[2m=�[0m200 �[3mresponse_size�[0m�[2m=�[0m"58 B"}
2023-09-01 16:52:30.116 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: Removing summary notification | NotificationRenderer.kt:57
2023-09-01 16:52:30.118 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: Removing room messages notification !XNchDzMJuRSsMtYRkr:matrix.org | NotificationRenderer.kt:67
2023-09-01 16:52:30.119 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: Removing fallback notification $169357961416707tDgPJ:matrix.org | NotificationRenderer.kt:127
2023-09-01 16:52:30.121 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: Updating fallback notification $169357995016740tRrnj:matrix.org | NotificationRenderer.kt:134
2023-09-01 16:52:30.125 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           D  elementx: Serializing 1 NotifiableEvent(s) | NotificationEventPersistence.kt:72
2023-09-01 16:52:30.126 18652-18813 org.matrix.rust.sdk     io.element.android.x.debug           W  elementx: Warning, unable to delete file /data/user/0/io.element.android.x.debug/databases/notifications.bin | File.kt:34

Seems that the slinding sync response is handled after we attempt to retrieve the notification content. But all further sent messages cannot be decrypted as well. The application has to be resumed to be able to decrypt the event content.

May be related to matrix-org/matrix-rust-sdk#2491 ?

CC @bnjbvr

[bnjbvr]

Yep, it does sound like #2491. Assuming the app stops the sync service upon bg (and of course no sync is running when the app has been killed, explaining why both steps to repro will reproduce the issue), then there's no sync getting encryption events for the notification. The issue linked above may help with solving this.

[bnjbvr]

We had a short call, and the outcome was:

• if not using a cross-process setup (as on iOS), the app must start the sync service before attempting to getting the notification (and take care of stopping it if the main app isn't foregrounded)
• then in the SDK, we'd need to have a mechanism to avoid a possible race condition (to-device events received and processed after the notification has been fully fetched). In the meanwhile, until the proper solution has been implemented, the app can wait a few hundreds milliseconds for the to-device events to be processed.