element-hq / element-hq/synapse

Device list update which takes >60s will prevent federation from working

Open
#5,445 0 comments 0 reactions 0 assignees View on GitHub
A-Device-List-Tracking A-Federation A-Performance A-Workers O-Uncommon S-Major T-Defect
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

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.