This repository was archived by the owner on Apr 26, 2024. It is now read-only.
This repository was archived by the owner on Apr 26, 2024. It is now read-only.
Why do we query for signature keys even if the local HS has the key in its DB? #6242
Description
I just got stuck debugging weirdness just now where a user couldn't join rooms via matrix.org because matrix.org wasn't able to get a copy of their server's signature key (due to a stale cached .well-known lookup). However, the server_signature_keys table had a valid copy of the key already present (which it was using to successfully service other federation reqs from the server), so I don't understand why it was trying to re-fetch it.
matrix=> select * from matrix.server_signature_keys where server_name='mimar.rs';
server_name | key_id | from_server | ts_added_ms | verify_key | ts_valid_until_ms
-------------+----------------+-------------+---------------+--------------------------------------------------------------------+-------------------
mimar.rs | ed25519:a_hTQY | mimar.rs | 1571827449816 | \x9f4cce96e2ecc1de7fb8e8f1d5adb8144d658846fd29216592ceabcb5cec73e5 | 1571912024358
Here's a request which failed due to failing to fetch a new key at the time:
2019-10-23 10:58:33,340 - synapse.access.http.8101 - 233 - INFO - GET-661900 - 193.53.106.131 - 8101 - Received request: GET /_matrix/federation/v1/make_join/%21mjbDjyNsRXndKLkHIe%3Amatrix.org/%40marko.cupac%3Amimar.rs?ver=1&ver=2&ver=3&ver=4&ver=5
2019-10-23 10:58:33,349 - synapse.http.matrixfederationclient - 408 - INFO - GET-661900 - {GET-O-214} [mimar.rs] Sending request: GET matrix://mimar.rs/_matrix/key/v2/server/ed25519%3Aa_hTQY; timeout 10.000000s
2019-10-23 10:58:33,350 - synapse.http.federation.matrix_federation_agent - 242 - INFO - GET-661900 - Connecting to im1.mimar.rs:8443
2019-10-23 10:58:43,352 - synapse.http.federation.matrix_federation_agent - 253 - INFO - GET-661900 - Failed to connect to im1.mimar.rs:8443: HostnameAddress(hostname=b'im1.mimar.rs', port=8443)
2019-10-23 10:58:43,353 - synapse.http.matrixfederationclient - 432 - INFO - GET-661900 - Failed to send request: HostnameAddress(hostname=b'im1.mimar.rs', port=8443)
2019-10-23 10:58:43,353 - synapse.http.matrixfederationclient - 487 - WARNING - GET-661900 - {GET-O-214} [mimar.rs] Request failed: GET matrix://mimar.rs/_matrix/key/v2/server/ed25519%3Aa_hTQY: ConnectingCancelledError(HostnameAddress(hostname=b'im1.mimar.rs', port=8443))
2019-10-23 10:58:43,353 - synapse.crypto.keyring - 766 - WARNING - GET-661900 - Error looking up keys {'ed25519:a_hTQY': 1571828313341} from mimar.rs: Failed to send request: ConnectingCancelledError: HostnameAddress(hostname=b'im1.mimar.rs', port=8443)
2019-10-23 10:58:43,354 - synapse.federation.transport.server - 293 - WARNING - GET-661900 - authenticate_request failed: 401: No key for mimar.rs with ids in ['ed25519:a_hTQY'] (min_validity 1571828313341)
2019-10-23 10:58:43,354 - synapse.http.server - 80 - INFO - GET-661900 - <XForwardedForRequest at 0x7fc66b6c0828 method='GET' uri='/_matrix/federation/v1/make_join/%21mjbDjyNsRXndKLkHIe%3Amatrix.org/%40marko.cupac%3Amimar.rs?ver=1&ver=2&ver=3&ver=4&ver=5' clientproto='HTTP/1.1' site=8101> SynapseError: 401 - No key for mimar.rs with ids in ['ed25519:a_hTQY'] (min_validity 1571828313341)
2019-10-23 10:58:43,354 - synapse.access.http.8101 - 302 - INFO - GET-661900 - 193.53.106.131 - 8101 - {None} Processed request: 10.014sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.007sec/1) 118B 401 "GET /_matrix/federation/v1/make_join/%21mjbDjyNsRXndKLkHIe%3Amatrix.org/%40marko.cupac%3Amimar.rs?ver=1&ver=2&ver=3&ver=4&ver=5 HTTP/1.1" "Synapse/1.4.0" [0 dbevts]