/federation/v1/user/keys/claim times out sometimes

[uhoreg]

/federation/v1/user/keys/claim seems to randomly time out, which may be a cause of UISIs. Also possibly related to element-hq/element-web#11836

e.g. I see some occurrences of things such as

POST-203- {POST-O-258} [matrix.org] Request failed: POST matrix://matrix.org/_matrix/federation/v1/user/keys/claim: ResponseNeverReceived:[CancelledError()]

in my logs

[Half-Shot]

Also seeing similar issues, is matrix.org just too slow to respond to key requests?

will@reckless:/var/log/matrix-synapse$ grep "POST-1569884" homeserver.log.4
2020-01-13 16:25:37,327 - synapse.access.http.8008 - 233 - INFO - POST-1569884- - - 8008 - Received request: POST /_matrix/client/r0/keys/claim
2020-01-13 16:25:37,328 - synapse.http.matrixfederationclient - 408 - INFO - POST-1569884- {POST-O-3707487} [sw1v.org] Sending request: POST matrix://sw1v.org/_matrix/federation/v1/user/keys/claim; timeout 10.000000s
2020-01-13 16:25:37,328 - synapse.http.federation.matrix_federation_agent - 242 - INFO - POST-1569884- Connecting to faith.sw1v.org:8448
2020-01-13 16:25:37,330 - synapse.http.matrixfederationclient - 408 - INFO - POST-1569884- {POST-O-3707488} [matrix.org] Sending request: POST matrix://matrix.org/_matrix/federation/v1/user/keys/claim; timeout 10.000000s
2020-01-13 16:25:37,331 - synapse.http.matrixfederationclient - 408 - INFO - POST-1569884- {POST-O-3707489} [vector.modular.im] Sending request: POST matrix://vector.modular.im/_matrix/federation/v1/user/keys/claim; timeout 10.000000s
2020-01-13 16:25:37,332 - synapse.http.matrixfederationclient - 408 - INFO - POST-1569884- {POST-O-3707490} [t2l.io] Sending request: POST matrix://t2l.io/_matrix/federation/v1/user/keys/claim; timeout 10.000000s
2020-01-13 16:25:37,348 - synapse.http.matrixfederationclient - 440 - INFO - POST-1569884- {POST-O-3707489} [vector.modular.im] Got response headers: 200 OK
2020-01-13 16:25:37,348 - synapse.http.matrixfederationclient - 164 - INFO - POST-1569884- {POST-O-3707489} [vector.modular.im] Completed: 200 OK
2020-01-13 16:25:37,382 - synapse.http.matrixfederationclient - 440 - INFO - POST-1569884- {POST-O-3707490} [t2l.io] Got response headers: 200 OK
2020-01-13 16:25:37,382 - synapse.http.matrixfederationclient - 164 - INFO - POST-1569884- {POST-O-3707490} [t2l.io] Completed: 200 OK
2020-01-13 16:25:37,392 - synapse.http.matrixfederationclient - 440 - INFO - POST-1569884- {POST-O-3707487} [sw1v.org] Got response headers: 200 OK
2020-01-13 16:25:37,393 - synapse.http.matrixfederationclient - 164 - INFO - POST-1569884- {POST-O-3707487} [sw1v.org] Completed: 200 OK
2020-01-13 16:25:47,341 - synapse.http.matrixfederationclient - 432 - INFO - POST-1569884- Failed to send request: [<twisted.python.failure.Failure twisted.internet.defer.CancelledError: >]
2020-01-13 16:25:47,341 - synapse.http.matrixfederationclient - 487 - WARNING - POST-1569884- {POST-O-3707488} [matrix.org] Request failed: POST matrix://matrix.org/_matrix/federation/v1/user/keys/claim: ResponseNeverReceived:[CancelledError()]
2020-01-13 16:25:47,341 - synapse.util.retryutils - 218 - INFO - POST-1569884- Connection to matrix.org was unsuccessful (<class 'synapse.api.errors.RequestSendFailed'>(Failed to send request: ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.defer.CancelledError: >])); backoff now 600000
2020-01-13 16:25:47,342 - synapse.handlers.e2e_keys - 425 - INFO - POST-1569884- Claimed one-time-keys: 
2020-01-13 16:25:47,366 - synapse.access.http.8008 - 302 - INFO - POST-1569884- - - 8008 - {@Half-Shot:half-shot.uk} Processed request: 10.015sec/0.024sec (0.006sec, 0.000sec) (0.001sec/0.019sec/2) 202B 200 "POST /_matrix/client/r0/keys/claim HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Riot/1.5.6 Chrome/78.0.3904.126 Electron/7.1.3 Safari/537.36" [0 dbevts]

[richvdh]

unfortunately, this is just matrix.org's master server being overloaded.

2020-01-13 16:25:47,410 - synapse.access.http.8080 - 233 - INFO - POST-34401316 - 164.132.203.213 - 8080 - Received request: POST /_matrix/federation/v1/user/keys/claim
2020-01-13 16:25:52,750 - synapse.access.http.8080 - 302 - INFO - POST-34401316 - 164.132.203.213 - 8080 - {half-shot.uk} Processed request: 0.027sec/5.311sec (0.003sec, 0.000sec) (0.005sec/0.011sec/1) 21B 200 "POST /_matrix/federation/v1/user/keys/claim HTTP/1.1" "Synapse/1.7.0rc1" [0 dbevts]

A workaround would be to bump up the timeout... ultimately though the solution is more work on synapse workers.

[uhoreg]

Bumping the timeout wouldn't be great, as it means that encryption gets delayed even more (as per element-hq/element-web#11836 ) Though maybe we could start by trying with a short timeout, encrypting to the devices that we can, and then re-trying with a longer timeout for the devices that we couldn't get.

[richvdh]

It looks like synapse does up to two (2) db transactions for each requested device (db.claim_e2e_one_time_key, followed by db._get_fallback_key if there are no OTKs). If there are lots of devices in the room, this can easily stack up into many seconds. It seems like there is potential to improve this.

cf: #16554