No backoff for failed ServerKeyFetcher request

[Ultimator14]

Description

My server tries to fetch a key from a remote server for federation. The connection if refused by the other server but synapse retries every few seconds (~6 retries per minute).

The logged message repeats every few seconds. i tried blocking the domain via firewall or dns entry but this only changes the message a bit (e.g. instead of connection refused I get dns lookup failed). I noticed the issue because the domain rsolabs.com is one of the top domains listed in my pihole. I suspect there is some sort of backoff required to stop this.

docker logs synapse 2>&1 | rg rsolabs

2023-09-22 19:16:24,510 - synapse.http.federation.matrix_federation_agent - 365 - INFO - ServerKeyFetcher-88 - Failed to connect to rsolabs.com:8448: Connection was refused by other side: 111: Connection refused.
2023-09-22 19:16:24,513 - synapse.http.matrixfederationclient - 761 - INFO - ServerKeyFetcher-88 - {GET-O-471} [rsolabs.com] Request failed: GET matrix-federation://rsolabs.com/_matrix/key/v2/server: ConnectionRefusedError('Connection refused')
2023-09-22 19:16:24,514 - synapse.crypto.keyring - 865 - WARNING - ServerKeyFetcher-88 - Error looking up keys from rsolabs.com: Failed to send request: ConnectionRefusedError: Connection was refused by other side: 111: Connection refused.
2023-09-22 19:16:24,515 - synapse.federation.transport.server._base - 312 - WARNING - PUT-398 - authenticate_request failed: 401: Failed to find any key to satisfy: _FetchKeyRequest(server_name='rsolabs.com', minimum_valid_until_ts=1695410179925, key_ids=['ed25519:a_HYCJ'])
2023-09-22 19:16:24,516 - synapse.http.server - 124 - INFO - PUT-398 - <XForwardedForRequest at 0x7f9b31bc50 method='PUT' uri='/_matrix/federation/v1/send/1693714544974' clientproto='HTTP/1.1' site='8008'> SynapseError: 401 - Failed to find any key to satisfy: _FetchKeyRequest(server_name='rsolabs.com', minimum_valid_until_ts=1695410179925, key_ids=['ed25519:a_HYCJ'])
2023-09-22 19:16:24,852 - synapse.crypto.keyring - 687 - INFO - PerspectivesKeyFetcher-88 - Requesting keys [_FetchKeyRequest(server_name='rsolabs.com', minimum_valid_until_ts=1695410184844, key_ids=['ed25519:a_HYCJ'])] from notary server matrix.org
2023-09-22 19:16:24,856 - synapse.crypto.keyring - 687 - INFO - PerspectivesKeyFetcher-88 - Requesting keys [_FetchKeyRequest(server_name='rsolabs.com', minimum_valid_until_ts=1695410184844, key_ids=['ed25519:a_HYCJ'])] from notary server privacytools.io

I also tried synapse v1.93.0rc1 but the issue still occurs there.

Steps to reproduce

I have no idea how to reproduce

Homeserver

matrix.pygos.space

Synapse Version

1.92.3

Installation Method

Docker (matrixdotorg/synapse)

Database

postgresql-15.4, single server, no port, no restore

Workers

Multiple workers

Platform

Hardware: Raspberry Pi 4b
OS: Gentoo Linux
Virtualization: Docker

Configuration

Nothing special. I'm using the server only for myself. It runs on defaults mostly.

Relevant log output

2023-09-22 19:19:06,258 - synapse.http.federation.matrix_federation_agent - 365 - INFO - ServerKeyFetcher-101 - Failed to connect to rsolabs.com:8448: Connection was refused by other side: 111: Connection refused.
2023-09-22 19:19:06,260 - synapse.http.matrixfederationclient - 761 - INFO - ServerKeyFetcher-101 - {GET-O-530} [rsolabs.com] Request failed: GET matrix-federation://rsolabs.com/_matrix/key/v2/server: ConnectionRefusedError('Connection refused')
2023-09-22 19:19:06,260 - synapse.crypto.keyring - 865 - WARNING - ServerKeyFetcher-101 - Error looking up keys from rsolabs.com: Failed to send request: ConnectionRefusedError: Connection was refused by other side: 111: Connection refused.
2023-09-22 19:19:06,262 - synapse.federation.transport.server._base - 312 - WARNING - PUT-447 - authenticate_request failed: 401: Failed to find any key to satisfy: _FetchKeyRequest(server_name='rsolabs.com', minimum_valid_until_ts=1695410339270, key_ids=['ed25519:a_HYCJ'])
2023-09-22 19:19:06,263 - synapse.http.server - 124 - INFO - PUT-447 - <XForwardedForRequest at 0x7f98dd4390 method='PUT' uri='/_matrix/federation/v1/send/1693714545799' clientproto='HTTP/1.1' site='8008'> SynapseError: 401 - Failed to find any key to satisfy: _FetchKeyRequest(server_name='rsolabs.com', minimum_valid_until_ts=1695410339270, key_ids=['ed25519:a_HYCJ'])
2023-09-22 19:19:06,267 - synapse.access.http.8008 - 465 - INFO - PUT-447 - 206.189.177.240 - 8008 - {None} Processed request: 6.994sec/0.002sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 183B 401 "PUT /_matrix/federation/v1/send/1693714545799 HTTP/1.1" "Synapse/1.90.0" [0 dbevts]
2023-09-22 19:19:06,501 - synapse.crypto.keyring - 687 - INFO - PerspectivesKeyFetcher-101 - Requesting keys [_FetchKeyRequest(server_name='rsolabs.com', minimum_valid_until_ts=1695410346494, key_ids=['ed25519:a_HYCJ'])] from notary server matrix.org
2023-09-22 19:19:06,504 - synapse.crypto.keyring - 687 - INFO - PerspectivesKeyFetcher-101 - Requesting keys [_FetchKeyRequest(server_name='rsolabs.com', minimum_valid_until_ts=1695410346494, key_ids=['ed25519:a_HYCJ'])] from notary server privacytools.io
2023-09-22 19:19:06,505 - synapse.crypto.keyring - 642 - WARNING - PerspectivesKeyFetcher-101 - Key lookup failed from 'privacytools.io': Not retrying server privacytools.io because we tried it recently retry_last_ts=1655747948773 and we won't check for another retry_interval=122320858679ms.
2023-09-22 19:19:13,990 - synapse.http.matrixfederationclient - 348 - INFO - PerspectivesKeyFetcher-101 - {POST-O-531} [matrix.org] Completed request: 200 OK in 7.49 secs, got 442 bytes - POST matrix-federation://matrix.org/_matrix/key/v2/query
2023-09-22 19:19:14,381 - synapse.http.federation.matrix_federation_agent - 365 - INFO - ServerKeyFetcher-102 - Failed to connect to rsolabs.com:8448: Connection was refused by other side: 111: Connection refused.
2023-09-22 19:19:14,383 - synapse.http.matrixfederationclient - 761 - INFO - ServerKeyFetcher-102 - {GET-O-533} [rsolabs.com] Request failed: GET matrix-federation://rsolabs.com/_matrix/key/v2/server: ConnectionRefusedError('Connection refused')
2023-09-22 19:19:14,384 - synapse.crypto.keyring - 865 - WARNING - ServerKeyFetcher-102 - Error looking up keys from rsolabs.com: Failed to send request: ConnectionRefusedError: Connection was refused by other side: 111: Connection refused.
2023-09-22 19:19:14,385 - synapse.federation.transport.server._base - 312 - WARNING - PUT-448 - authenticate_request failed: 401: Failed to find any key to satisfy: _FetchKeyRequest(server_name='rsolabs.com', minimum_valid_until_ts=1695410346494, key_ids=['ed25519:a_HYCJ'])
2023-09-22 19:19:14,386 - synapse.http.server - 124 - INFO - PUT-448 - <XForwardedForRequest at 0x7f9d1a5e50 method='PUT' uri='/_matrix/federation/v1/send/1693714545834' clientproto='HTTP/1.1' site='8008'> SynapseError: 401 - Failed to find any key to satisfy: _FetchKeyRequest(server_name='rsolabs.com', minimum_valid_until_ts=1695410346494, key_ids=['ed25519:a_HYCJ'])
2023-09-22 19:19:14,391 - synapse.access.http.8008 - 465 - INFO - PUT-448 - 206.189.177.240 - 8008 - {None} Processed request: 7.893sec/0.004sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 183B 401 "PUT /_matrix/federation/v1/send/1693714545834 HTTP/1.1" "Synapse/1.90.0" [0 dbevts]
2023-09-22 19:19:14,611 - synapse.crypto.keyring - 687 - INFO - PerspectivesKeyFetcher-102 - Requesting keys [_FetchKeyRequest(server_name='rsolabs.com', minimum_valid_until_ts=1695410354600, key_ids=['ed25519:a_HYCJ'])] from notary server matrix.org
2023-09-22 19:19:14,614 - synapse.crypto.keyring - 687 - INFO - PerspectivesKeyFetcher-102 - Requesting keys [_FetchKeyRequest(server_name='rsolabs.com', minimum_valid_until_ts=1695410354600, key_ids=['ed25519:a_HYCJ'])] from notary server privacytools.io
2023-09-22 19:19:14,615 - synapse.crypto.keyring - 642 - WARNING - PerspectivesKeyFetcher-102 - Key lookup failed from 'privacytools.io': Not retrying server privacytools.io because we tried it recently retry_last_ts=1655747948773 and we won't check for another retry_interval=122320858679ms.
2023-09-22 19:19:16,332 - synapse.http.matrixfederationclient - 348 - INFO - PerspectivesKeyFetcher-102 - {POST-O-534} [matrix.org] Completed request: 200 OK in 1.72 secs, got 442 bytes - POST matrix-federation://matrix.org/_matrix/key/v2/query
2023-09-22 19:19:16,523 - synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 1
2023-09-22 19:19:16,733 - synapse.http.federation.matrix_federation_agent - 365 - INFO - ServerKeyFetcher-103 - Failed to connect to rsolabs.com:8448: Connection was refused by other side: 111: Connection refused.

Anything else that would be useful to know?

No response

[clokep]

Something around this was fixed in the upcoming version (#16252), it could be worth seeing if this still an issue once you're on v1.93.0.

[Ultimator14]

I think i fixed the issue for now. The reason was another server that queried my server multiple times a second.

2023-09-23 07:50:23,911 - synapse.access.http.8008 - 420 - DEBUG - PUT-906 - 206.189.177.240 - 8008 - Received request: PUT /_matrix/federation/v1/send/1693714971263

Since I did not have rate limiting enabled, this caused my server to answer every time. I still do not understand why it tried to fetch keys from the domain rsolabs.com because the requesting IP does not resolve to this domain. But after all this was just a reaction to another (probably misconfigured) server so it's probably not an issue with synapse.
I blocked the requesting server now in my firewall and that works.
Thanks anyway.