element-hq / element-hq/synapse
toDevice messages sent to appservice users while the appservice is offline are dropped
- Dominant language
- Python
- Stars
- 4.6k
- Forks
- 600
- Avg merge
- 5d 22h
- Merged PRs (30d)
- 51
Description
This issue has been migrated from [#14710](https://github.com/matrix-org/synapse/issues/14710).
---
### Description
With encrypted appservices enabled (all of it), appservices are meant to receive their to-device messages when they come back online. However, it appears Synapse is eating them instead.
The primary failure mode for appservices is being unable to decrypt messages sent to it while it was offline (and while keys are needed).
### Steps to reproduce
This is a bit challenging as it requires a fairly unique environment.
1. Have an encrypted appservice or way to inspect transactions
2. Turn off that appservice or otherwise take it offline.
3. Refresh Element Web (this will cause it to generate a new room key on startup)
4. Send a message
5. Turn the appservice back on
6. Monitor transactions for to-device messages
### Homeserver
localhost
### Synapse Version
1.73.0
### Installation Method
Docker (matrixdotorg/synapse)
### Database
postgresql, in a docker container
### Workers
Single process
### Platform
Docker for Windows, under Docker Compose for deployment
### Configuration
In the appservice:
```
de.sorunome.msc2409.push_ephemeral: true
org.matrix.msc3202: true
```
In `homeserver.yaml`:
```
experimental_features:
msc2409_to_device_messages_enabled: true
msc3202_device_masquerading: true
msc3202_transaction_extensions: true
#msc2285_enabled: true
msc1767_enabled: true
```
### Relevant log output
```shell
<< ================================================================== >>
<< FROM THE APPSERVICE, SHOWING AN ENCRYPTED MESSAGE WITHOUT ROOM KEY >>
<< ================================================================== >>
Mon, 19 Dec 2022 20:23:40 GMT [INFO] [index] Starting appservice...
@@ txn body: {
"de.sorunome.msc2409.ephemeral": [],
"de.sorunome.msc2409.to_device": [],
"events": []
}
Mon, 19 Dec 2022 20:23:47 GMT [INFO] [Appservice] Processing transaction 1628
Mon, 19 Dec 2022 20:23:47 GMT [INFO] [Appservice] 127.0.0.1 - - [19/Dec/2022:20:23:47 +0000] "PUT /_matrix/app/v1/transactions/1628?access_token=%3Credacted%3E HTTP/1.1" 200 2 "-" "Synapse/1.73.0"
@@ txn body: {
"de.sorunome.msc2409.ephemeral": [],
"de.sorunome.msc2409.to_device": [],
"events": [
{
"age": 14656,
"content": {
"algorithm": "m.megolm.v1.aes-sha2",
"ciphertext": "AwgAEqABsxVFPCsorrorifmg8ss5CSqEZOJqqGlz/c7lFSpr98OcPuziQh3jgCidW8fOlnOcV3q66hYEK65kmGIv6P9UOs2Q6yLlARWIqQzakQ+GxDBHZDp+o+STPM3Mq7gIyDnv9GvYbeOv/0rcBZ4KlXNTqSjG/bhJdE/lHhNAZit/NhwVNMUgmSMMcRxESyOumVppy0+Pvbi8Spb6mZr7WD0vcSZrOJKniHNOejxOpcZfcLIrpC0ViYUa6PwG7OrPC7BC5LjLKQXD1/wpWSy9L
mR28S1Wpzxd2kNq5rv77fBDFsfePx3WCYwgAg",
"device_id": "YOQFQRGBNR",
"sender_key": "g3do21sL26UntdxUsZjGHY20MghS1TzpCCXnNGPQ/Ww",
"session_id": "p9D4w2A+6ILVmAnNYBAD0w8gQpyNS+hJ+QQwl7+O8cM"
},
"event_id": "$CIdkAd1BWJezbYolsltKLEw8s7KCbkZUqyT17rEg66Q",
"origin_server_ts": 1671481413308,
"room_id": "!HvtWphayPOfPUjxONx:localhost",
"sender": "@travis:localhost",
"type": "m.room.encrypted",
"unsigned": {
"age": 14656
},
"user_id": "@travis:localhost"
}
]
}
Mon, 19 Dec 2022 20:23:47 GMT [INFO] [Appservice] Processing transaction 1629
Mon, 19 Dec 2022 20:23:47 GMT [INFO] [Appservice] Processing event of type m.room.encrypted
Mon, 19 Dec 2022 20:23:47 GMT [WARN] [Appservice] Bot client was not able to decrypt !HvtWphayPOfPUjxONx:localhost $CIdkAd1BWJezbYolsltKLEw8s7KCbkZUqyT17rEg66Q - trying other intents
Mon, 19 Dec 2022 20:23:47 GMT [DEBUG] [MatrixHttpClient] (REQ-6) GET http://localhost:8338/_matrix/client/v3/rooms/!HvtWphayPOfPUjxONx%3Alocalhost/joined_members
Mon, 19 Dec 2022 20:23:47 GMT [DEBUG] [MatrixHttpClient] (REQ-6) qs = {"user_id":"@crypto_main_bot_user:localhost","org.matrix.msc3202.device_id":"EQEMWWXBOT"}
Mon, 19 Dec 2022 20:23:47 GMT [DEBUG] [MatrixHttpClient] (REQ-6 RESP-H200) {
joined: {
'@crypto_main_bot_user:localhost': { avatar_url: null, display_name: 'crypto_main_bot_user' },
'@travis:localhost': {
avatar_url: 'mxc://localhost/QHWkCEbTILlymWtZbhcIIKkK',
display_name: 'TravisR'
}
}
}
Mon, 19 Dec 2022 20:23:47 GMT [ERROR] [Appservice] Decryption error on !HvtWphayPOfPUjxONx:localhost $CIdkAd1BWJezbYolsltKLEw8s7KCbkZUqyT17rEg66Q [Error: decryption failed because the room key is missing] {
code: 'GenericFailure'
}
Mon, 19 Dec 2022 20:23:47 GMT [ERROR] [index] Failed to decrypt !HvtWphayPOfPUjxONx:localhost $CIdkAd1BWJezbYolsltKLEw8s7KCbkZUqyT17rEg66Q because [Error: decryption failed because the room key is missing] {
code: 'GenericFailure'
}
```
### Anything else that would be useful to know?
It appears as though Synapse is sending two transactions when the appservice comes back online: is the first one (empty in the log output) meant to contain the missing EDUs?
Contributor guide
Research direction
No source file or test is named. Start at the appservice transaction endpoint `/_matrix/app/v1/transactions` and trace handling of `de.sorunome.msc2409.to_device` while reproducing the offline/online sequence; done means the encrypted to-device message is present in a transaction after the appservice reconnects, rather than being dropped.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- docker, postgresql, python
- Domain
- api, backend
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 38/100