element-hq / element-hq/synapse
Device list update which takes >60s will prevent federation from working
- Dominant language
- Python
- Stars
- 4.6k
- Forks
- 600
- Avg merge
- 5d 22h
- Merged PRs (30d)
- 51
Description
This issue has been migrated from [#5445](https://github.com/matrix-org/synapse/issues/5445).
---
A device list update received from matrix.org is taking a reliable 72 seconds to persist on the main process. The replication timeout is 60s, so it times out every time, failing the transaction. The transaction is then retried by matrix.org a minute or so later, which then causes the device list update to go the main process, which then takes 72s, which then times out, and the transaction fails. Repeat forever.
Federation reader:
```
federation_reader_3 - 2019-06-13 04:53:24,315 - synapse.access.http.6100 - 233 - INFO - PUT-44155- 94.237.61.93 - 6100 - Received request: PUT /_matrix/federation/v1/send/1560336834949/
federation_reader_3 - 2019-06-13 04:53:24,316 - synapse.federation.transport.server - 147 - INFO - PUT-44155- Request from matrix.org
federation_reader_3 - 2019-06-13 04:53:24,320 - synapse.federation.transport.server - 371 - INFO - PUT-44155- Received txn 1560336834949 from matrix.org. (PDUs: 1, Accepted EDUs: 1, Ignored EDUs: 0)
federation_reader_3 - 2019-06-13 04:53:24,324 - synapse.handlers.federation - 152 - INFO - PUT-44155-$redacted:matrix.org- [!redacted:matrix.org $redacted:matrix.org] handling received PDU:
federation_reader_3 - 2019-06-13 04:53:24,328 - synapse.handlers.federation - 212 - INFO - PUT-44155-$redacted:matrix.org- [!redacted:matrix.org $redacted:matrix.org] Ignoring PDU from matrix.org as we're not in the room
federation_reader_3 - 2019-06-13 04:53:24,329 - synapse.http.client - 273 - INFO - PUT-44155- Sending request POST http://127.0.0.1:9091/_synapse/replication/fed_send_edu/m.device_list_update/RzKcjkPgVG
federation_reader_3 - 2019-06-13 04:54:24,151 - synapse.http.site - 203 - WARNING - PUT-44155- Error processing request : Connection was closed cleanly.
federation_reader_3 - 2019-06-13 04:54:24,333 - synapse.http.client - 308 - INFO - PUT-44155- Error sending request to POST http://127.0.0.1:9091/_synapse/replication/fed_send_edu/m.device_list_update/RzKcjkPgVG: ResponseNeverReceived []
federation_reader_3 - 2019-06-13 04:54:24,334 - synapse.federation.transport.server - 396 - ERROR - PUT-44155- on_incoming_transaction failed
federation_reader_3 - 2019-06-13 04:54:24,411 - synapse.http.server - 112 - ERROR - PUT-44155- Failed handle request via 'FederationSendServlet':
federation_reader_3 - 2019-06-13 04:54:24,415 - synapse.http.server - 415 - WARNING - PUT-44155- Not sending response to request , already disconnected.
federation_reader_3 - 2019-06-13 04:54:24,416 - synapse.access.http.6100 - 302 - INFO - PUT-44155- 94.237.61.93 - 6100 - {matrix.org} Processed request: 60.101sec/-0.265sec (0.084sec, 0.004sec) (0.001sec/0.004sec/2) 0B 200! "PUT /_matrix/federation/v1/send/1560336834949/ HTTP/1.0" "Synapse/1.0.0 (b=matrix-org-hotfixes,6dbd49877)" [1 dbevts]
```
Main process (correlated by the replication transaction ID then by request ID):
```
homeserver_1 - 2019-06-13 04:53:24,332 - synapse.access.http.9091 - 233 - INFO - POST-29713 - 127.0.0.1 - 9091 - Received request: POST /_synapse/replication/fed_send_edu/m.device_list_update/RzKcjkPgVG
homeserver_1 - 2019-06-13 04:53:24,333 - synapse.util.caches.response_cache - 151 - INFO - POST-29713 - [repl.fed_send_edu]: no cached result for [RzKcjkPgVG], calculating new one
homeserver_1 - 2019-06-13 04:53:24,333 - synapse.replication.http.federation - 164 - INFO - POST-29713 - Got 'm.device_list_update' edu from matrix.org
homeserver_1 - 2019-06-13 04:53:24,341 - synapse.http.matrixfederationclient - 401 - INFO - POST-29713 - {GET-O-215} [matrix.org] Sending request: GET matrix://matrix.org/_matrix/federation/v1/user/devices/%40redacted%3Amatrix.org; timeout 30.000000s
homeserver_1 - 2019-06-13 04:53:24,348 - synapse.http.federation.matrix_federation_agent - 373 - INFO - POST-29713 - Connecting to matrix.org.cdn.cloudflare.net:8443
homeserver_1 - 2019-06-13 04:53:24,472 - synapse.http.matrixfederationclient - 433 - INFO - POST-29713 - {GET-O-215} [matrix.org] Got response headers: 200 OK
homeserver_1 - 2019-06-13 04:53:24,503 - synapse.http.matrixfederationclient - 160 - INFO - POST-29713 - {GET-O-215} [matrix.org] Completed: 200 OK
homeserver_1 - 2019-06-13 04:54:24,419 - synapse.http.site - 203 - WARNING - POST-29713 - Error processing request : Connection to the other side was lost in a non-clean fashion.
homeserver_1 - 2019-06-13 04:54:37,235 - synapse.http.server - 415 - WARNING - POST-29713 - Not sending response to request , already disconnected.
homeserver_1 - 2019-06-13 04:54:37,236 - synapse.access.http.9091 - 302 - INFO - POST-29713 - 127.0.0.1 - 9091 - {None} Processed request: 72.904sec/-12.817sec (0.164sec, 0.064sec) (0.003sec/72.726sec/4) 0B 200! "POST /_synapse/replication/fed_send_edu/m.device_list_update/RzKcjkPgVG HTTP/1.1" "Synapse/1.0.0" [0 dbevts]
```
**Edit**: The user in question has 409 devices.
Contributor guide
Assessment
This issue has not been assessed yet.