Federation fails when using a DNS server on a link-local IPv6 address #5846

jans23 · 2019-08-13T14:22:22Z

Our Matrix instance nitro.chat has issues connecting to matrix.org rooms. In the logs we see these messages:

2019-08-12 16:51:28,877 - synapse.crypto.keyring - 652 - INFO - POST-104458- Requesting keys dict_items([('matrix.org', {'ed25519:auto':1565621488877})]) from notary server matrix.org
2019-08-12 16:51:28,879 - synapse.crypto.keyring - 604 - WARNING - POST-104458- Key lookup failed from 'matrix.org': Failed to connect to remote server
2019-08-12 16:51:28,880 - synapse.http.matrixfederationclient - 404 - INFO - POST-104458- {GET-O-3981} [matrix.org] Sending request: GET matrix://matrix.org/_matrix/key/v2/server/ed25519%3Aauto; timeout 10.000000s
2019-08-12 16:51:28,880 - synapse.http.federation.matrix_federation_agent - 335 - INFO - POST-104458- Fetching https://matrix.org/.well-known/matrix/server
2019-08-12 16:51:28,984 - synapse.http.federation.matrix_federation_agent - 351 - INFO - POST-104458- Error fetching https://matrix.org/.well-known/matrix/server: Non-200 response 404
2019-08-12 16:51:38,894 - synapse.http.matrixfederationclient - 485 - WARNING - POST-104458- {GET-O-3981} [matrix.org] Request failed: GET matrix://matrix.org/_matrix/key/v2/server/ed25519%3Aauto: TimeoutError(10.0, 'Deferred')
2019-08-12 16:51:38,894 - synapse.crypto.keyring - 783 - WARNING - POST-104458- Error looking up keys {'ed25519:auto': 1565621488877} from matrix.org: Failed to connect to remote server
2019-08-12 16:51:38,895 - synapse.federation.transport.server - 286 - WARNING - POST-104458- authenticate_request failed: 401: No key for matrix.org with ids in ['ed25519:auto'] (min_validity 1565621488877)
2019-08-12 16:51:38,895 - synapse.http.server - 79 - INFO - POST-104458- <XForwardedForRequest at 0x7f711034b278 method='POST' uri='/_matrix/federation/v1/get_groups_publicised' clientproto='HTTP/1.0' site=8008> SynapseError: 401 - No key for matrix.org with ids in ['ed25519:auto'] (min_validity 1565621488877)
2019-08-12 16:51:38,896 - synapse.access.http.8008 - 302 - INFO - POST-104458- 2a04:3541:1000:500:6866:a4ff:fe4c:58c1 - 8008 - {None} Processed request: 10.018sec/0.000sec (0.013sec, 0.001sec) (0.000sec/0.001sec/1) 118B 401 "POST /_matrix/federation/v1/get_groups_publicised HTTP/1.0" "Synapse/1.2.1 (b=matrix-org-hotfixes,873ff9522)" [0 dbevts] root@matrix-nitrochat:/etc/matrix-synapse# tail /var/log/matrix-synapse/homeserver.log -n 200

curl matrix.org/_matrix/key/v2/server/ed25519%3Aauto says:

{"old_verify_keys":{},"server_name":"matrix.org","signatures":{"matrix.org":{"ed25519:auto":"IV3Ql81UyFkZdPD9JbdxcqMeKoflQCiR1OgUvumu87tNFa9XC/gNdtcBn2xIYut73KZ1IFZZDvGdlwgdTUxvBw"}},"tls_fingerprints":[{"sha256":"Pq3kW4n2StFnOFtA0PTiXIk0HZF6jwLyR8tMlaRko6I"},{"sha256":"mVNAmfjFleUpJseTNjU5EhJAlfl5rjb7JJPG2UeH9eY"}],"valid_until_ts":1565756981005,"verify_keys":{"ed25519:auto":{"key":"Noi6WqcDj0QmPxCNQqgezwTlBKrfqehY1u2FyWP9uYw"}}}

We run the latest Synapse version on Linux already. Азат at #synapse:matrix.org confirmed it's a Synapse issue. Please help.

The text was updated successfully, but these errors were encountered:

richvdh · 2019-08-13T15:58:44Z

please could you fix the log formatting so that the lines aren't broken?

jans23 · 2019-08-13T17:07:08Z

@richvdh formatting is updated now.

richvdh · 2019-08-14T06:07:05Z

Firstly, it's not a 404, it's a timeout. It looks like it can't connect to matrix.org. It's possible you just caught it when matrix.org was having a bad time, but more likely there is something wrong with your networking, or possibly your server is very overloaded.

It would probably be worthwhile to turn the log level up to DEBUG so we can see where it's getting stuck.

benksio · 2019-08-14T12:22:31Z

hi @richvdh, i also deal with the above issue on the very same server. would you tell me which level line in log.yaml needs to be set do DEBUG? thx

richvdh · 2019-08-14T13:53:57Z

the log configuration file follows the standard format for python log configuration: https://docs.python.org/3/library/logging.config.html#dictionary-schema-details.

TL;DR: change one of the level lines.

benksio · 2019-08-16T16:40:44Z

@richvdh I get a very verbose log now. As there is sensitive data within it, i'd prefare to send it directly to you. Is that possible?

richvdh · 2019-08-16T22:26:03Z

you can reach me on matrix at @richvdh:sw1v.org

richvdh · 2019-08-17T11:10:41Z

Request from the matrix.org end shows:

2019-08-16 05:51:31,870 - synapse.http.matrixfederationclient - 520 - WARNING - federation_transaction_transmission_loop-2320408 - {PUT-O-1823760} [nitro.chat] Request failed: PUT matrix://nitro.chat/_matrix/federation/v1/send/1565867599575/: HttpResponseException("401: b'Unauthorized'")

gfiury · 2019-08-19T19:05:43Z

We fixed the problem doing the following:

Restarting the server that has Synapse 1.0.0 version
For some reason, I would like to confirm this fact with you guys, is that the key changed (and the
signature) after restarting the server (not Synapse but the CentOS)
The origin Server (where a user tries to invite another user from the Synapse 1.0.0) has 1.2.1
version. There is a section on the config to change the trusted keys. That sections is commented
by default, but the logs showed that first tries the request to a notary server (matrix.org) and then
proper server. We uncomment the property trusted_key_servers and set the proper server.

jans23 · 2019-08-20T06:20:12Z

As a user, the issue still exists and isn't solved for me.

richvdh · 2019-08-20T17:36:38Z

Again: please could somebody running a server which suffers from this problem share the DEBUG logs for a failing request so that we can investigate.

benksio · 2019-08-21T10:48:40Z

Hi, this seems the right message to me. If not, please give me a hint, what to grep for.

2019-08-21 12:08:26,074 - synapse.federation.transport.server - 288 - WARNING - PUT-19722- authenticate_request failed: 401: No key for jki.re with ids in ['ed25519:auto'] (min_validity 1566381852384)
2019-08-21 12:08:26,074 - synapse.http.server - 79 - INFO - PUT-19722- <XForwardedForRequest at 0x7fe4201b0f98 method='PUT' uri='/_matrix/federation/v1/send/1565688011035' clientproto='HTTP/1.0' site=8008> SynapseError: 401 - No key for jki.re with ids in ['ed25519:auto'] (min_validity 1566381852384)
2019-08-21 12:08:26,075 - synapse.http.server - 447 - WARNING - PUT-19722- Not sending response to request <XForwardedForRequest at 0x7fe4201b0f98 method='PUT' uri='/_matrix/federation/v1/send/1565688011035' clientproto='HTTP/1.0' site=8008>, already disconnected.
2019-08-21 12:08:26,075 - synapse.access.http.8008 - 302 - INFO - PUT-19722- 2a01:7e00::f03c:91ff:fe6e:411b - 8008 - {None} Processed request: 253.691sec/-206.697sec (0.006sec, 0.006sec) (0.001sec/0.036sec/3) 0B 200! "PUT /_matrix/federation/v1/send/1565688011035 HTTP/1.0" "Synapse/1.2.1 (b=erikj/lower_bound_ttl_well_known,8f33d49ab,dirty)" [0 dbevts]
2019-08-21 12:08:26,075 - synapse.crypto.keyring - 274 - DEBUG - PUT-19722- Releasing key lookup lock on jki.re
2019-08-21 12:08:26,076 - synapse.crypto.keyring - 258 - DEBUG - PUT-19731- Got key lookup lock on jki.re
2019-08-21 12:08:26,076 - synapse.crypto.keyring - 642 - INFO - PUT-19731- Requesting keys dict_items([('jki.re', {'ed25519:auto': 1566381903711})]) from notary server matrix.org
2019-08-21 12:08:26,076 - synapse.crypto.keyring - 313 - INFO - PUT-19744- Waiting for existing lookups for ['jki.re'] to complete [loop 2]
2019-08-21 12:08:26,077 - synapse.storage.txn - 408 - DEBUG - PUT-19731- [TXN START] {get_destination_retry_timings-d599}
2019-08-21 12:08:26,077 - synapse.storage.SQL - 164 - DEBUG - PUT-19731- [SQL] {get_destination_retry_timings-d599} SELECT destination, retry_last_ts, retry_interval FROM destinations WHERE destination = ?
2019-08-21 12:08:26,077 - synapse.storage.SQL - 169 - DEBUG - PUT-19731- [SQL values] {get_destination_retry_timings-d599} ['matrix.org']
2019-08-21 12:08:26,078 - synapse.storage.SQL - 183 - DEBUG - PUT-19731- [SQL time] {get_destination_retry_timings-d599} 0.000420 sec
2019-08-21 12:08:26,078 - synapse.storage.txn - 470 - DEBUG - PUT-19731- [TXN END] {get_destination_retry_timings-d599} 0.001383 sec
2019-08-21 12:08:26,079 - synapse.crypto.keyring - 594 - WARNING - PUT-19731- Key lookup failed from 'matrix.org': Failed to connect to remote server
2019-08-21 12:08:26,079 - synapse.http.matrixfederationclient - 404 - INFO - PUT-19731- {GET-O-1309} [jki.re] Sending request: GET matrix://jki.re/_matrix/key/v2/server/ed25519%3Aauto; timeout 10.000000s

[edited for formatting by @richvdh]

richvdh · 2019-08-21T13:49:10Z

@benksio there are several requests happening in parallel there. You can identify all the log lines for a given request by grepping for the PUT-nnnnn number, as per https://github.com/matrix-org/synapse/wiki#how-can-i-find-the-lines-corresponding-to-a-given-http-request-in-my-homeserver-log.

I can see a couple of things though:

The attempt to fetch the keys from matrix.org is failing because Synapse has marked matrix.org as 'down' due to an earlier failure. (The logging is confusing here; hopefully Improve error msg when key-fetch fails #5896 will improve it.) In order to see why it is blacklisted, we'd need to see the logs for that failure. You could try grepping for [matrix.org] Request failed to find the relevant line.
After giving up on matrix.org, it tries to get the key from jki.re. We can't see what happened there though: please can you show the rest of the logs for PUT-19731?

benksio · 2019-08-21T14:31:19Z

Here you are:

2019-08-21 12:05:03,711 - synapse.access.http.8008 - 233 - INFO - PUT-19731- 2a01:7e00::f03c:91ff:fe6e:411b - 8008 - Received request: PUT /_matrix/federation/v1/send/1565688011035
2019-08-21 12:05:03,711 - synapse.crypto.keyring - 210 - DEBUG - PUT-19731- Verifying Incoming request for jki.re with key_ids ['ed25519:auto'], min_validity 1566381903711
2019-08-21 12:05:03,712 - synapse.crypto.keyring - 313 - INFO - PUT-19731- Waiting for existing lookups for ['jki.re'] to complete [loop 1]
2019-08-21 12:06:03,643 - synapse.http.site - 203 - WARNING - PUT-19731- Error processing request <XForwardedForRequest at 0x7fe4205d4390 method='PUT' uri='/_matrix/federation/v1/send/1565688011035' clientproto='HTTP/1.0' site=8008>: <class 'twisted.internet.error.ConnectionDone'> Connection was closed cleanly.
2019-08-21 12:08:26,076 - synapse.crypto.keyring - 258 - DEBUG - PUT-19731- Got key lookup lock on jki.re
2019-08-21 12:08:26,076 - synapse.crypto.keyring - 642 - INFO - PUT-19731- Requesting keys dict_items([('jki.re', {'ed25519:auto': 1566381903711})]) from notary server matrix.org
2019-08-21 12:08:26,077 - synapse.storage.txn - 408 - DEBUG - PUT-19731- [TXN START] {get_destination_retry_timings-d599}
2019-08-21 12:08:26,077 - synapse.storage.SQL - 164 - DEBUG - PUT-19731- [SQL] {get_destination_retry_timings-d599} SELECT destination, retry_last_ts, retry_interval FROM destinations WHERE destination = ?
2019-08-21 12:08:26,077 - synapse.storage.SQL - 169 - DEBUG - PUT-19731- [SQL values] {get_destination_retry_timings-d599} ['matrix.org']
2019-08-21 12:08:26,078 - synapse.storage.SQL - 183 - DEBUG - PUT-19731- [SQL time] {get_destination_retry_timings-d599} 0.000420 sec
2019-08-21 12:08:26,078 - synapse.storage.txn - 470 - DEBUG - PUT-19731- [TXN END] {get_destination_retry_timings-d599} 0.001383 sec
2019-08-21 12:08:26,079 - synapse.crypto.keyring - 594 - WARNING - PUT-19731- Key lookup failed from 'matrix.org': Failed to connect to remote server
2019-08-21 12:08:26,079 - synapse.http.matrixfederationclient - 404 - INFO - PUT-19731- {GET-O-1309} [jki.re] Sending request: GET matrix://jki.re/_matrix/key/v2/server/ed25519%3Aauto; timeout 10.000000s
2019-08-21 12:08:36,081 - synapse.http.matrixfederationclient - 428 - INFO - PUT-19731- Failed to send request: (10.0, 'Deferred')
2019-08-21 12:08:36,082 - synapse.http.matrixfederationclient - 485 - WARNING - PUT-19731- {GET-O-1309} [jki.re] Request failed: GET matrix://jki.re/_matrix/key/v2/server/ed25519%3Aauto: TimeoutError(10.0, 'Deferred')
2019-08-21 12:08:36,082 - synapse.crypto.keyring - 773 - WARNING - PUT-19731- Error looking up keys {'ed25519:auto': 1566381903711} from jki.re: Failed to connect to remote server
2019-08-21 12:08:36,082 - synapse.federation.transport.server - 288 - WARNING - PUT-19731- authenticate_request failed: 401: No key for jki.re with ids in ['ed25519:auto'] (min_validity 1566381903711)
2019-08-21 12:08:36,082 - synapse.http.server - 79 - INFO - PUT-19731- <XForwardedForRequest at 0x7fe4205d4390 method='PUT' uri='/_matrix/federation/v1/send/1565688011035' clientproto='HTTP/1.0' site=8008> SynapseError: 401 - No key for jki.re with ids in ['ed25519:auto'] (min_validity 1566381903711)
2019-08-21 12:08:36,083 - synapse.http.server - 447 - WARNING - PUT-19731- Not sending response to request <XForwardedForRequest at 0x7fe4205d4390 method='PUT' uri='/_matrix/federation/v1/send/1565688011035' clientproto='HTTP/1.0' site=8008>, already disconnected.
2019-08-21 12:08:36,083 - synapse.access.http.8008 - 302 - INFO - PUT-19731- 2a01:7e00::f03c:91ff:fe6e:411b - 8008 - {None} Processed request: 212.372sec/-152.440sec (0.000sec, 0.003sec) (0.000sec/0.001sec/1) 0B 200! "PUT /_matrix/federation/v1/send/1565688011035 HTTP/1.0" "Synapse/1.2.1 (b=erikj/lower_bound_ttl_well_known,8f33d49ab,dirty)" [0 dbevts]
2019-08-21 12:08:36,083 - synapse.crypto.keyring - 274 - DEBUG - PUT-19731- Releasing key lookup lock on jki.re

benksio · 2019-08-21T14:38:24Z

here is the
... | grep "[matrix.org] Request failed"

2019-08-21 11:59:06,450 - synapse.http.matrixfederationclient - 485 - WARNING - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386: TimeoutError(60, 'Deferred')
2019-08-21 12:01:21,431 - synapse.http.matrixfederationclient - 485 - WARNING - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386: TimeoutError(60, 'Deferred')
2019-08-21 12:03:27,044 - synapse.http.matrixfederationclient - 485 - WARNING - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386: TimeoutError(60, 'Deferred')
2019-08-21 12:05:12,390 - synapse.http.matrixfederationclient - 485 - WARNING - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386: CancelledError()
2019-08-21 12:05:12,391 - synapse.http.matrixfederationclient - 485 - WARNING - PUT-19722- {POST-O-1306} [matrix.org] Request failed: POST matrix://matrix.org/_matrix/key/v2/query: TimeoutError(60, 'Deferred')
2019-08-21 12:06:13,031 - synapse.http.matrixfederationclient - 485 - WARNING - PUT-19722- {POST-O-1306} [matrix.org] Request failed: POST matrix://matrix.org/_matrix/key/v2/query: TimeoutError(60, 'Deferred')
2019-08-21 12:07:14,264 - synapse.http.matrixfederationclient - 485 - WARNING - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386: CancelledError()
2019-08-21 12:07:14,265 - synapse.http.matrixfederationclient - 485 - WARNING - PUT-19722- {POST-O-1306} [matrix.org] Request failed: POST matrix://matrix.org/_matrix/key/v2/query: TimeoutError(60, 'Deferred')
2019-08-21 12:08:16,063 - synapse.http.matrixfederationclient - 485 - WARNING - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386: CancelledError()
2019-08-21 12:08:16,065 - synapse.http.matrixfederationclient - 485 - WARNING - PUT-19722- {POST-O-1306} [matrix.org] Request failed: POST matrix://matrix.org/_matrix/key/v2/query: TimeoutError(60, 'Deferred')

zfnmxt · 2019-08-21T21:00:10Z

I'm also getting a 401 error, although I'm too unfamiliar to tell if it's for key reasons. Didn't want to open another issue unnecessarily, though. Here's my log if you can glimmer anything out of it:

https://gist.githubusercontent.com/zfnmxt/267ad8c18cfaf61f507d2be6754a05af/raw/0350c223bd0e734092d64b9afd9efcc12926fe89/synapse.txt

zfnmxt · 2019-08-22T09:49:53Z

Seems like I only have issues with matrix.org. I'm able to join rooms on other servers without issue.

jans23 · 2019-08-22T09:50:36Z

This is the same for me.

richvdh · 2019-08-22T10:13:06Z

@benksio: so it looks like outbound requests (to both jki.re and matrix.org) are timing out, which is a bit odd. I don't see those requests arriving at the matrix.org end. Can you share the results of grep federation_transaction_transmission_loop-1873 ?

(Also: what timezone are your logs in? Looks like UTC+3 ?)

jans23 · 2019-08-22T10:15:39Z

Just a random idea: Might this issue be related to IPv6?

richvdh · 2019-08-22T10:18:55Z

@jans23 plausibly

richvdh · 2019-08-22T10:23:14Z

@zfnmxt I think your issue is unrelated: the 401 in your logs is coming from matrix.org, though I can't see the failure on the matrix.org side. Please remember to tell us what timezone your logs are in. Also, note that your logs contain some secret access tokens, which you should consider compromised: log out your client to invalidate the access token.

zfnmxt · 2019-08-22T10:28:34Z

@richvdh I figured re: tokens. Timezone is GMT+2.

benksio · 2019-08-22T10:29:35Z

the Timezone ist CEST

... | grep "federation_transaction_transmission_loop-1873"

2019-08-21 11:59:06,450 - synapse.http.matrixfederationclient - 428 - INFO - federation_transaction_transmission_loop-1873- Failed to send request: (60, 'Deferred')
2019-08-21 11:59:06,450 - synapse.http.matrixfederationclient - 485 - WARNING - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386: TimeoutError(60, 'Deferred')
2019-08-21 11:59:06,450 - synapse.http.matrixfederationclient - 505 - DEBUG - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Waiting 74.97580974660222s before re-sending...
2019-08-21 12:00:21,428 - synapse.http.matrixfederationclient - 404 - INFO - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Sending request: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386; timeout 60.000000s
2019-08-21 12:01:21,431 - synapse.http.matrixfederationclient - 428 - INFO - federation_transaction_transmission_loop-1873- Failed to send request: (60, 'Deferred')
2019-08-21 12:01:21,431 - synapse.http.matrixfederationclient - 485 - WARNING - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386: TimeoutError(60, 'Deferred')
2019-08-21 12:01:21,432 - synapse.http.matrixfederationclient - 505 - DEBUG - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Waiting 65.60553046220608s before re-sending...
2019-08-21 12:02:27,040 - synapse.http.matrixfederationclient - 404 - INFO - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Sending request: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386; timeout 60.000000s
2019-08-21 12:03:27,044 - synapse.http.matrixfederationclient - 428 - INFO - federation_transaction_transmission_loop-1873- Failed to send request: (60, 'Deferred')
2019-08-21 12:03:27,044 - synapse.http.matrixfederationclient - 485 - WARNING - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386: TimeoutError(60, 'Deferred')
2019-08-21 12:03:27,044 - synapse.http.matrixfederationclient - 505 - DEBUG - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Waiting 64.91518843273639s before re-sending...
2019-08-21 12:04:31,961 - synapse.http.matrixfederationclient - 404 - INFO - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Sending request: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386; timeout 60.000000s
2019-08-21 12:05:12,390 - synapse.http.matrixfederationclient - 428 - INFO - federation_transaction_transmission_loop-1873- Failed to send request: 
2019-08-21 12:05:12,390 - synapse.http.matrixfederationclient - 485 - WARNING - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386: CancelledError()
2019-08-21 12:05:12,390 - synapse.http.matrixfederationclient - 505 - DEBUG - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Waiting 83.23851162831703s before re-sending...
2019-08-21 12:06:35,630 - synapse.http.matrixfederationclient - 404 - INFO - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Sending request: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386; timeout 60.000000s
2019-08-21 12:07:14,264 - synapse.http.matrixfederationclient - 428 - INFO - federation_transaction_transmission_loop-1873- Failed to send request: 
2019-08-21 12:07:14,264 - synapse.http.matrixfederationclient - 485 - WARNING - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386: CancelledError()
2019-08-21 12:07:14,265 - synapse.http.matrixfederationclient - 505 - DEBUG - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Waiting 48.31573290159327s before re-sending...
2019-08-21 12:08:02,583 - synapse.http.matrixfederationclient - 404 - INFO - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Sending request: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386; timeout 60.000000s
2019-08-21 12:08:16,062 - synapse.http.matrixfederationclient - 428 - INFO - federation_transaction_transmission_loop-1873- Failed to send request: 
2019-08-21 12:08:16,063 - synapse.http.matrixfederationclient - 485 - WARNING - federation_transaction_transmission_loop-1873- {PUT-O-1305} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v1/send/1566201506386: CancelledError()
2019-08-21 12:08:16,063 - synapse.util.retryutils - 212 - INFO - federation_transaction_transmission_loop-1873- Connection to matrix.org was unsuccessful (<class 'synapse.api.errors.RequestSendFailed'>(Failed to send request: CancelledError: )); backoff now 3000000
2019-08-21 12:08:16,064 - synapse.federation.sender.per_destination_queue - 318 - WARNING - federation_transaction_transmission_loop-1873- TX [matrix.org] Failed to send transaction: Failed to send request: CancelledError: 
2019-08-21 12:08:16,064 - synapse.storage.txn - 408 - DEBUG - federation_transaction_transmission_loop-1873- [TXN START] {set_destination_retry_timings-d58f}
2019-08-21 12:08:16,065 - synapse.storage.SQL - 164 - DEBUG - federation_transaction_transmission_loop-1873- [SQL] {set_destination_retry_timings-d58f} INSERT INTO destinations (destination, retry_last_ts, retry_interval) VALUES (?, ?, ?) ON CONFLICT (destination) DO UPDATE SET retry_last_ts = EXCLUDED.retry_last_ts, retry_interval = EXCLUDED.retry_interval WHERE EXCLUDED.retry_interval = 0 OR destinations.retry_interval < EXCLUDED.retry_interval
2019-08-21 12:08:16,065 - synapse.storage.SQL - 169 - DEBUG - federation_transaction_transmission_loop-1873- [SQL values] {set_destination_retry_timings-d58f} ('matrix.org', 1566382096063, 3000000)
2019-08-21 12:08:16,067 - synapse.storage.SQL - 183 - DEBUG - federation_transaction_transmission_loop-1873- [SQL time] {set_destination_retry_timings-d58f} 0.000747 sec
2019-08-21 12:08:16,081 - synapse.storage.txn - 470 - DEBUG - federation_transaction_transmission_loop-1873- [TXN END] {set_destination_retry_timings-d58f} 0.017097 sec
2019-08-21 12:08:16,082 - synapse.logging.context - 500 - DEBUG - federation_transaction_transmission_loop-1873- Restoring dead context: federation_transaction_transmission_loop-1873

jans23 · 2019-08-27T12:36:17Z

@richvdh Is there anything we could help you with solving this issue?

richvdh · 2019-08-27T13:06:25Z

That's odd. I could have sworn I'd replied here.

It looks to me like the DNS lookups might be timing out. Please could you show the results of:

dig -t SRV _matrix._tcp.matrix.org

benksio · 2019-08-27T19:42:46Z

dig -t SRV _matrix._tcp.matrix.org


; <<>> DiG 9.10.3-P4-Debian <<>> -t SRV _matrix._tcp.matrix.org
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 24833
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;_matrix._tcp.matrix.org.	IN	SRV

;; ANSWER SECTION:
_matrix._tcp.matrix.org. 220	IN	SRV	10 5 8443 matrix.org.cdn.cloudflare.net.

;; Query time: 0 msec
;; SERVER: fe80::3285:a9ff:fea6:1ee7%65#53(fe80::3285:a9ff:fea6:1ee7%65)
;; WHEN: Tue Aug 27 21:41:39 CEST 2019
;; MSG SIZE  rcvd: 101

richvdh · 2019-08-28T08:59:20Z

That looks fine, though I'm wondering if the link-local IPv6 DNS server could be causing problems. Are you able to test using a DNS server on an IPv4 address or a global IPv6 address?

benksio · 2019-09-06T08:41:31Z

I configured the server to use an IPv4 DNS Server. Although I think the former one is not guilty.

dig -t SRV _matrix._tcp.matrix.org

; <<>> DiG 9.10.3-P4-Debian <<>> -t SRV _matrix._tcp.matrix.org
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 53627
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 512
;; QUESTION SECTION:
;_matrix._tcp.matrix.org.	IN	SRV

;; ANSWER SECTION:
_matrix._tcp.matrix.org. 12	IN	SRV	10 5 8443 matrix.org.cdn.cloudflare.net.

;; Query time: 12 msec
;; SERVER: 9.9.9.9#53(9.9.9.9)
;; WHEN: Fri Sep 06 10:33:38 CEST 2019
;; MSG SIZE  rcvd: 101

Can we provide any other information, to figure out why federation doesn't work?

richvdh · 2019-09-06T09:31:42Z

I configured the server to use an IPv4 DNS Server

And you're still having the same problem? Do the logs look the same?

jans23 · 2019-09-06T09:46:58Z

Now for the first time I can send messages between both instances. However at matrix.org I experienced several "server error" in Riot and I had to try resending several times until my message got through to nitro.chat. The other direction (from nitro.chat to matrix.org) didn't had this issue. It feels a bit shaky so I'm not sure this issue is entirely solved or not.
@benksio A look in the log might help.

richvdh · 2019-09-06T10:35:25Z

sounds like a different problem then. I suggest seeking support in #synapse:matrix.org in the first instance, and if you find a bug, raising a new issue with the new symptoms.

richvdh · 2019-09-06T12:36:29Z

Have raised this as a bug in twisted at https://twistedmatrix.com/trac/ticket/9704.

benksio · 2019-09-10T18:35:26Z

Thx for your hints. The Issue seems to be solved now by having changed the DNS Server.

jans23 · 2019-09-10T18:38:51Z

IMHO we just found a workaround and the actual (implementation) issue isn't solved. In this case this issue ticket should remain open, right?

sudwhiwdh · 2020-05-22T10:49:34Z

@richvdh Hello, what does it take to solve this issue?

pranaysashank · 2020-05-22T21:42:06Z

I have the same issue and my dns server is on ipv4 not ipv6

richvdh · 2020-06-01T12:17:16Z

@richvdh Hello, what does it take to solve this issue?

a fix to the upstream issue. Follow the links; maybe try the suggested fix.

I have the same issue and my dns server is on ipv4 not ipv6

if your dns server isn't on a link-local IPv6 address, it is a different issue.

richvdh changed the title ~~federation fails with 404 related to keys~~ federation fails with 401 related to keys Aug 17, 2019

richvdh mentioned this issue Aug 19, 2019

401 Unauthorized when trying to federate with another federate server #5869

Closed

neilisfragile added the info-needed label Aug 19, 2019

richvdh changed the title ~~federation fails with 401 related to keys~~ federation fails with "401: No key for <server>" Aug 22, 2019

richvdh changed the title ~~federation fails with "401: No key for <server>"~~ Federation fails when using a DNS server on a link-local IPv6 address Sep 6, 2019

richvdh removed the info-needed label Sep 6, 2019

clokep added the Z-Upstream-Bug This issue requires a fix in an upstream dependency. label Jun 1, 2020

clokep mentioned this issue Aug 18, 2020

Federation errors when DNS server is on same IP #8118

Closed

Sursur123 mentioned this issue Sep 23, 2020

"logging error" in logs #8389

Closed

MadLittleMods added A-Federation T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. labels May 16, 2022

dklimpel mentioned this issue Jun 20, 2022

Enable full IPv6 support for synapse #13107

Open

matrixbot mentioned this issue Dec 21, 2023

Federation fails when using a DNS server on a link-local IPv6 address element-hq/synapse#5846

Open

Federation fails when using a DNS server on a link-local IPv6 address #5846

Federation fails when using a DNS server on a link-local IPv6 address #5846

Comments

jans23 commented Aug 13, 2019 • edited Loading

richvdh commented Aug 13, 2019

jans23 commented Aug 13, 2019

richvdh commented Aug 14, 2019

benksio commented Aug 14, 2019

richvdh commented Aug 14, 2019

benksio commented Aug 16, 2019

richvdh commented Aug 16, 2019

richvdh commented Aug 17, 2019

gfiury commented Aug 19, 2019

jans23 commented Aug 20, 2019

richvdh commented Aug 20, 2019

benksio commented Aug 21, 2019 • edited by richvdh Loading

richvdh commented Aug 21, 2019

benksio commented Aug 21, 2019

benksio commented Aug 21, 2019

zfnmxt commented Aug 21, 2019

zfnmxt commented Aug 22, 2019

jans23 commented Aug 22, 2019 via email

richvdh commented Aug 22, 2019

jans23 commented Aug 22, 2019

richvdh commented Aug 22, 2019

richvdh commented Aug 22, 2019

zfnmxt commented Aug 22, 2019

benksio commented Aug 22, 2019

jans23 commented Aug 27, 2019

richvdh commented Aug 27, 2019

benksio commented Aug 27, 2019

richvdh commented Aug 28, 2019

benksio commented Sep 6, 2019

richvdh commented Sep 6, 2019

jans23 commented Sep 6, 2019

richvdh commented Sep 6, 2019

richvdh commented Sep 6, 2019

benksio commented Sep 10, 2019

jans23 commented Sep 10, 2019

sudwhiwdh commented May 22, 2020

pranaysashank commented May 22, 2020

richvdh commented Jun 1, 2020

jans23 commented Aug 13, 2019 •

edited

Loading

benksio commented Aug 21, 2019 •

edited by richvdh

Loading