element-hq / element-hq/synapse
To-device message delivery delayed by queue of device_lists replication updates
- Dominant language
- Python
- Stars
- 4.6k
- Forks
- 600
- Avg merge
- 5d 22h
- Merged PRs (30d)
- 51
Description
15:06:58: to-device message is sent:
```
2025-05-07 15:06:58,641 - synapse.9533_debug - 953 - DEBUG - PUT-93c19fd45f36bce8-CDG---- - Stored to-device messages with stream_id 1485097545: ['@ormaz:matrix.org/7gwqBC1yOE (msgid None)']
2025-05-07 15:06:58,662 - synapse.access.http.28101 - 508 - INFO - PUT-93c19fd45f36bce8-CDG - 2a01:cb08:9152:7c00:5823:3f25:1727:39be - 28101 - {@ormaz:matrix.org} Processed request: 0.024sec/0.012sec (0.004sec>
```
On a receiving synchrotron
```
2025-05-07 15:07:15,733 - synapse.notifier - 811 - INFO - GET-93c1a03aef0ad30d-CDG- - Waiting for current token to reach StreamToken(room: RoomStreamToken(stream: 5876311209, topological: None, instances: {}), presence: 757284974, typing: 12996801, receipt: MultiWriterStreamToken(stream: 3616167719, instances: {}), account_data: 4046266428, push_rules: 265575574, to_device: 1485097259, device_list: 11124064479, groups: 0, un_partial_stated_rooms: 473177); currently at StreamToken(room: RoomStreamToken(stream: 5876314855, topological: None, instances: {}), presence: 757284974, typing: 13003394, receipt: MultiWriterStreamToken(stream: 3616171444, instances: {}), account_data: 4046271831, push_rules: 265575585, to_device: 1485097614, device_list: 11124063701, groups: 0, un_partial_stated_rooms: 473177)
2025-05-07 15:07:26,519 - synapse.handlers.sync - 527 - WARNING - GET-93c1a03aef0ad30d-CDG- - Timed out waiting for worker to catch up. Returning empty response
2025-05-07 15:07:27,384 - synapse.access.http.21150 - 508 - INFO - GET-93c1a03aef0ad30d-CDG - 2a01:cb08:9152:7c00:4811:4624:82b9:23eb - 21150 - {@ormaz:matrix.org} Processed request: 11.553sec/0.369sec (0.005sec, 0.000sec) (0.197sec/0.016sec/2) 298B 200 "GET /_matrix/client/v3/sync?filter=8&timeout=30000&org.matrix.msc4222.use_state_after=true&set_presence=online&since=s5876311209_757284974_12996801_3616167719_4046266428_265575574_1485097259_11124064479_0_473177 HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64; rv:138.0) Gecko/20100101 Firefox/138.0" [0 dbevts]
```
The message is eventually delivered at 15:09:04, over two minutes after it was sent:
```
2025-05-07 15:08:46,257 - synapse.notifier - 811 - INFO - GET-93c1a273a8cfd30d-CDG- - Waiting for current token to reach StreamToken(room: RoomStreamToken(stream: 5876311209, topological: None, instances: {}), presence: 757284974, typing: 12996801, receipt: MultiWriterStreamToken(stream: 3616167719, instances: {}), account_data: 4046266428, push_rules: 265575574, to_device: 1485097259, device_list: 11124064479, groups: 0, un_partial_stated_rooms: 473177); currently at StreamToken(room: RoomStreamToken(stream: 5876319515, topological: None, instances: {}), presence: 757284974, typing: 13011213, receipt: MultiWriterStreamToken(stream: 3616176183, instances: {receipts-3: 3616176185}), account_data: 4046278614, push_rules: 265575589, to_device: 1485098117, device_list: 11124064401, groups: 0, un_partial_stated_rooms: 473178)
2025-05-07 15:09:03,764 - synapse.9533_debug - 2228 - DEBUG - GET-93c1a273a8cfd30d-CDG---- - Returning to-device messages with stream_ids (1485097259, 1485098139]; now: 1485098139; msgids: [None, None, None, '01JTNMJV3DFXK56NT2QE14CED7', None]
2025-05-07 15:09:04,035 - synapse.access.http.21150 - 508 - INFO - GET-93c1a273a8cfd30d-CDG - 2a01:cb08:9152:7c00:4811:4624:82b9:23eb - 21150 - {@ormaz:matrix.org} Processed request: 17.653sec/0.270sec (0.030sec, 0.006sec) (0.645sec/0.330sec/19) 7100B 200 "GET /_matrix/client/v3/sync?filter=8&timeout=30000&org.matrix.msc4222.use_state_after=true&set_presence=online&since=s5876311209_757284974_12996801_3616167719_4046266428_265575574_1485097259_11124064479_0_473177 HTTP/1.1" "Mozilla/5.0 (X11; Linux x86_64; rv:138.0) Gecko/20100101 Firefox/138.0" [7 dbevts]
```
According to the logging, it is waiting for the device_list stream to catch up. It looks like the device was served a sync response up to device_list 11124064479 by the initial synchrotron, but this synchrotron is lagging a long way behind.
Two questions, then:
1. Why is this synchrotron's idea of the device_list stream so far behind that of other workers?
2. Even if the device_list stream is a long way behind, can't we deliver the to-device messages?
Contributor guide
Research direction
Start with the synchrotron handling of the /sync request and the device_list stream, using the supplied logs to trace why this worker lags behind. Determine whether to-device delivery can proceed independently of device_list replication, and document the expected behavior and a way to verify both causes are addressed.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- python
- Domain
- backend, distributed-systems
- Issue type
- Bug
- Difficulty
- 5/5
- Estimated time
- Over a week
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100