Joining replacement room over federation fails with make_join error

[dkasak]

Description

I'm a member of #ruma:matrix.org (with an account on a personal homeserver, info below) which recently got tombstoned. I tried joining the replacement
room using Riot Desktop 1.5.15. This nearly instantaneously failed with Failed to make_join via any server.

The following lines appeared in the synapse log:

2020-04-16 12:37:11,275 - synapse.federation.federation_client:929 | ERROR - POST-233666 - Failed to fetch room complexity via matrix.org for !XfqLiaavxVgyMSiRwK:matrix.org
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 915, in get_room_complexity
    destination=destination, room_id=room_id
synapse.util.retryutils.NotRetryingDestination: Not retrying server matrix.org.
2020-04-16 12:37:11,277 - synapse.federation.federation_client:405 | WARNING - POST-233666 - Failed to make_join via matrix.org
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 386, in _try_destination_list
    res = yield callback(destination)
synapse.util.retryutils.NotRetryingDestination: Not retrying server matrix.org.
2020-04-16 12:37:13,557 - synapse.federation.federation_client:929 | ERROR - POST-233671 - Failed to fetch room complexity via matrix.org for !XfqLiaavxVgyMSiRwK:matrix.org
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 915, in get_room_complexity
    destination=destination, room_id=room_id
synapse.util.retryutils.NotRetryingDestination: Not retrying server matrix.org.
2020-04-16 12:37:13,560 - synapse.federation.federation_client:405 | WARNING - POST-233671 - Failed to make_join via matrix.org
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
StopIteration: mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 386, in _try_destination_list
    res = yield callback(destination)
synapse.util.retryutils.NotRetryingDestination: Not retrying server matrix.org.
2020-04-16 12:37:34,140 - synapse.crypto.keyring:587 | WARNING - PUT-233716 - Key lookup failed from 'matrix.org': Not retrying server matrix.org.

Apparently mxc://termina.org.uk/GZLyTGACVOyuzABpftmsbEoA is my avatar.

I tried a few more times and while most of the time the error message is the
same, sometimes the failure takes longer (~10 seconds) and then the error
message is No key for termina.org.uk with ids in ['ed25519:a_RZLi'] (min_validity 1587032954483).

The log then contained:

2020-04-16 12:53:10,508 - synapse.http.matrixfederationclient:526 | WARNING - POST-236855 - {GET-O-117737} [matrix.org] Request failed: GET matrix://matrix.org/_matrix/federation/v1/make_join/%21XfqLiaavxVgyMSiRwK%3Amatrix.org/%40dkasak%3Atermina.org.uk?ver=1&ver=2&ver=3&ver=4&ver=5&ver=org.matrix.msc2260: HttpResponseException("401: b'Unauthorized'")

This is the tombstone event:

{
  "content": {
    "body": "This room has been replaced",
    "replacement_room": "!XfqLiaavxVgyMSiRwK:matrix.org"
  },
  "event_id": "$1580544874605BBkoe:matrix.org",
  "origin_server_ts": 1580544874762,
  "sender": "@jimmycuadra:matrix.org",
  "state_key": "",
  "type": "m.room.tombstone",
  "unsigned": {
    "age": 3009
  },
  "room_id": "!wzHrsErnsyaqbpFiRQ:matrix.org"
}

Steps to reproduce

1. Be a member of the tombstoned #ruma:matrix.org room
   (!wzHrsErnsyaqbpFiRQ:matrix.org).
2. Click The conversation continues here link at the bottom from Riot.

I expect to be joined into the room, but the join fails.

Version information

• Homeserver: termina.org.uk
• Version: 1.10.0
• Install method: package manager (pkg on FreeBSD)
• Platform: Freebsd 12.1

[richvdh]

synapse.util.retryutils.NotRetryingDestination: Not retrying server matrix.org.

This means that your server has previously attempted to talk to matrix.org, failed, and blacklisted it. It's therefore something of a red herring: we need to find out why the original failure took place. So your other error is more interesting:

2020-04-16 12:53:10,508 - synapse.http.matrixfederationclient:526 | WARNING - POST-236855 - {GET-O-117737} [matrix.org] Request failed: GET matrix://matrix.org/_matrix/federation/v1/make_join/%21XfqLiaavxVgyMSiRwK%3Amatrix.org/%40dkasak%3Atermina.org.uk?ver=1&ver=2&ver=3&ver=4&ver=5&ver=org.matrix.msc2260: HttpResponseException("401: b'Unauthorized'")

Looking at this request from the matrix.org side:

federation_reader2.log-20200416.gz:2020-04-16 10:53:00,481 - synapse.http.matrixfederationclient - 408 - INFO - GET-343316 - {GET-O-3920} [termina.org.uk] Sending request: GET matrix://termina.org.uk/_matrix/key/v2/server/ed25519%3Aa_RZLi; timeout 10.000000s
federation_reader2.log-20200416.gz:2020-04-16 10:53:00,483 - synapse.http.federation.matrix_federation_agent - 242 - INFO - GET-343316 - Connecting to matrix.termina.org.uk:8448
federation_reader2.log-20200416.gz:2020-04-16 10:53:10,486 - synapse.http.federation.matrix_federation_agent - 253 - INFO - GET-343316 - Failed to connect to matrix.termina.org.uk:8448: HostnameAddress(hostname=b'matrix.termina.org.uk', port=8448)
federation_reader2.log-20200416.gz:2020-04-16 10:53:10,487 - synapse.http.matrixfederationclient - 434 - INFO - GET-343316 - Failed to send request: HostnameAddress(hostname=b'matrix.termina.org.uk', port=8448)
federation_reader2.log-20200416.gz:2020-04-16 10:53:10,487 - synapse.http.matrixfederationclient - 491 - WARNING - GET-343316 - {GET-O-3920} [termina.org.uk] Request failed: GET matrix://termina.org.uk/_matrix/key/v2/server/ed25519%3Aa_RZLi: ConnectingCancelledError(HostnameAddress(hostname=b'matrix.termina.org.uk', port=8448))
federation_reader2.log-20200416.gz:2020-04-16 10:53:10,488 - synapse.crypto.keyring - 765 - WARNING - GET-343316 - Error looking up keys {'ed25519:a_RZLi': 1587034380480} from termina.org.uk: Failed to send request: ConnectingCancelledError: HostnameAddress(hostname=b'matrix.termina.org.uk', port=8448)
federation_reader2.log-20200416.gz:2020-04-16 10:53:10,488 - synapse.federation.transport.server - 315 - WARNING - GET-343316 - authenticate_request failed: 401: No key for termina.org.uk with ids in ['ed25519:a_RZLi'] (min_validity 1587034380480)
federation_reader2.log-20200416.gz:2020-04-16 10:53:10,488 - synapse.http.server - 81 - INFO - GET-343316 - <XForwardedForRequest at 0x7f26d3434240 method='GET' uri='/_matrix/federation/v1/make_join/%21XfqLiaavxVgyMSiRwK%3Amatrix.org/%40dkasak%3Atermina.org.uk?ver=1&ver=2&ver=3&ver=4&ver=5&ver=org.matrix.msc2260' clientproto='HTTP/1.1' site=8101> SynapseError: 401 - No key for termina.org.uk with ids in ['ed25519:a_RZLi'] (min_validity 1587034380480)
federation_reader2.log-20200416.gz:2020-04-16 10:53:10,492 - synapse.access.http.8101 - 302 - INFO - GET-343316 - 2a01:4f8:1c1c:5014::1:4 - 8101 - {None} Processed request: 10.009sec/0.003sec (0.003sec, 0.000sec) (0.000sec/0.000sec/0) 124B 401 "GET /_matrix/federation/v1/make_join/%21XfqLiaavxVgyMSiRwK%3Amatrix.org/%40dkasak%3Atermina.org.uk?ver=1&ver=2&ver=3&ver=4&ver=5&ver=org.matrix.msc2260 HTTP/1.1" "Synapse/1.10.0" [0 dbevts]

... it timed out while trying to connect to your server (actually I think it was the DNS lookup that failed).

This looks like a situation that persisted until about 5:00 UTC this morning. So could you try again and see if the situation persists?

I've raised #7297 and #7298 to track giving better errors in these situations.

For future reference: I'd recommend making sure that you have not disabled INFO-level logging when attempting to debug any sort of issue (although I'm not sure it would actually have helped in this case).

[dkasak]

I tried to join the room again (on the day of your comment but I forgot to respond) and it indeed succeeded.

For future reference: I'd recommend making sure that you have not disabled INFO-level logging when attempting to debug any sort of issue (although I'm not sure it would actually have helped in this case).

Yeah, sorry about that, I was in a hurry when submitting the report and completely forgot I turned it off at some point to make the logs more readable. Noted.

Given that it's working now and you've created those new issues, I think we can close this?

[richvdh]

agreed. thanks.