Unrejectable invite from oftc room #8091

Flexmaen · 2020-08-14T12:04:03Z

This bug was reportet here and here.
However it seems to be a server issue, so I report it here:

Description

I'm using a third party matrix server (here) and tried to join #_oftc_#realraum:matrix.org which causes an undefined error.
However, @_oftc_r3bot:matrix.org tries to contact me afterwards. I can neither accept, nor ignore this. ("Denieing failed. Not a known user). So I'll stuck in the invitation loop, and always have 1 unread message.

Steps to reproduce

The result was not the same everywhere, but it caused different issues:

Using an account on an other server than matrix.org (in my case gemeinsam.jetzt)
Trying /join #_oftc_#realraum:matrix.org

Describe how what happens differs from what you expected.

You'd be able to join the room.
However if this does not work because of some server issues (maybe this is a synapse bug?), Element-Web should not be stuck in this kind of invitation-look.

Version information

Platform: web

For the web app:

Browser: Vivaldi
OS: Windows 10
URL: gemeinsam.jetzt, Riot/Element 1.7.1

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

Flexmaen · 2020-08-16T09:40:58Z

By the way: There you can see the server version used on the other server:
https://matrix.gemeinsam.jetzt/_matrix/federation/v1/version (currently 1.18.0).

clokep · 2020-08-17T13:42:33Z

I'm unsure if you have access to the server logs or not, but if you do it would be interesting to see the errors in the above situations.

I see three spots that might be useful:

Error from the trying to join #_oftc_#realraum:matrix.org
Error when attempting to accept the invite
Error when attempting to reject the invite

This sounds somewhat like #2181, but that was fixed in 1.17.0.

mir06 · 2020-08-17T18:31:41Z

Hi @clokep, I am running this server and I will provide the relevant lines from synapse log:

2020-08-13 13:01:01,082 - synapse.federation.federation_client - 493 - WARNING - POST-2456819 - Failed to send_join via matrix.org
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 474, in _try_destination_list
    res = await callback(destination)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 615, in send_request
    content = await self._do_send_join(destination, pdu)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 710, in _do_send_join
    content=pdu.get_pdu_json(time_now),
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/transport/client.py", line 262, in send_join_v2
    destination=destination, path=path, data=content
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 670, in put_json
    self.reactor, self.default_timeout, request, response
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 144, in _handle_json_response
    body = yield make_deferred_yieldable(d)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/util/async_helpers.py", line 478, in convert_cancelled
    return to_call(value, timeout)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/util/async_helpers.py", line 425, in _cancelled_to_timed_out_error
    raise defer.TimeoutError(timeout, "Deferred")
twisted.internet.defer.TimeoutError: (60, 'Deferred')
2020-08-13 13:01:01,083 - synapse.http.server - 524 - WARNING - POST-2456819 - Not sending response to request <XForwardedForRequest at 0x7f380bff8d30 method='POST' uri='/_matrix/client/r0/join/%23_oftc_%23
realraum%3Amatrix.org' clientproto='HTTP/1.0' site=8008>, already disconnected.

mir06 · 2020-08-17T18:33:40Z

I just upgraded to synapse 1.19.0. This changed the error in the log to

2020-08-17 20:15:10,308 - synapse.http.server - 84 - ERROR - GET-40863 - Failed handle request via 'ClientDirectoryServer': <XForwardedForRequest at 0x7f13095f1668 method='GET' uri='/_matrix/client/r0/directory/room/%23_oftc_%23realraum%3Amatrix.org' clientproto='HTTP/1.0' site=8008>
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 472, in _send_request
    response = await request_deferred
twisted.web._newclient.ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.defer.CancelledError: >]

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/server.py", line 229, in _async_render_wrapper
    callback_return = await self._async_render(request)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/server.py", line 406, in _async_render
    callback_return = await raw_callback_return
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/rest/client/v1/directory.py", line 52, in on_GET
    res = await dir_handler.get_association(room_alias)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/handlers/directory.py", line 241, in get_association
    ignore_backoff=True,
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/transport/client.py", line 178, in make_query
    ignore_backoff=ignore_backoff,
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 839, in get_json
    timeout=timeout,
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 289, in _send_request_with_optional_trailing_slash
    response = await self._send_request(request, **send_request_args)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 478, in _send_request
    raise RequestSendFailed(e, can_retry=True) from e
synapse.api.errors.RequestSendFailed: Failed to send request: ResponseNeverReceived: [<twisted.python.failure.Failure twisted.internet.defer.CancelledError: >]
2020-08-17 20:15:10,338 - synapse.access.http.8008 - 311 - INFO - GET-40863 - 37.186.9.113 - 8008 - {None} Processed request: 10.034sec/0.003sec (0.003sec, 0.000sec) (0.000sec/0.000sec/0) 67B 500 "GET /_matrix/client/r0/directory/room/%23_oftc_%23realraum%3Amatrix.org HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/83.0.4103.116 Safari/537.36" [0 dbevts]

mir06 · 2020-08-17T18:53:47Z

Trying for a few times the above exception did not occure anymore, but I just get the following log-line

2020-08-17 20:47:03,507 - synapse.http.matrixfederationclient - 543 - INFO - POST-64456 - {PUT-O-34358} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v2/send_join/%21MQgfkmjcDaXGjEVyLh%3Amatrix.org/%2415976899639souPd%3Agemeinsam.jetzt: ResponseNeverReceived:[CancelledError()]

And some minutes later:

2020-08-17 20:49:27,672 - synapse.http.matrixfederationclient - 502 - INFO - POST-64456 - {PUT-O-34358} [matrix.org] Got response headers: 520 Origin Error
2020-08-17 20:49:27,673 - synapse.http.matrixfederationclient - 578 - WARNING - POST-64456 - {PUT-O-34358} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v2/send_join/%21MQgfkmjcDaX
GjEVyLh%3Amatrix.org/%2415976899639souPd%3Agemeinsam.jetzt: HttpResponseException('520: Origin Error')
2020-08-17 20:49:27,673 - synapse.util.retryutils - 215 - INFO - POST-64456 - Connection to matrix.org was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(520: Origin Error)); backoff now 6
00000
2020-08-17 20:49:27,687 - synapse.federation.federation_client - 493 - WARNING - POST-64456 - Failed to send_join via matrix.org
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 710, in _do_send_join
    content=pdu.get_pdu_json(time_now),
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/transport/client.py", line 257, in send_join_v2
    destination=destination, path=path, data=content
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 703, in put_json
    timeout=timeout,
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 289, in _send_request_with_optional_trailing_slash
    response = await self._send_request(request, **send_request_args)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 533, in _send_request
    raise e
synapse.api.errors.HttpResponseException: 520: Origin Error

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 474, in _try_destination_list
    res = await callback(destination)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 615, in send_request
    content = await self._do_send_join(destination, pdu)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 724, in _do_send_join
    raise e.to_synapse_error()
synapse.api.errors.ProxiedRequestError: 520: Origin Error
2020-08-17 20:49:27,689 - synapse.http.server - 75 - INFO - POST-64456 - <XForwardedForRequest at 0x7f12fee54c50 method='POST' uri='/_matrix/client/r0/join/%23_oftc_%23realraum%3Amatrix.org' clientproto='HT
TP/1.0' site=8008> SynapseError: 502 - Failed to send_join via any server
2020-08-17 20:49:27,689 - synapse.http.server - 531 - WARNING - POST-64456 - Not sending response to request <XForwardedForRequest at 0x7f12fee54c50 method='POST' uri='/_matrix/client/r0/join/%23_oftc_%23realraum%3Amatrix.org' clientproto='HTTP/1.0' site=8008>, already disconnected.

richvdh · 2020-08-18T12:13:18Z

@clokep it's possible that the matrix.org logs might be enlightening on this issue.

mir06 · 2020-08-18T12:46:59Z

update: just got the invitation from r3bot (more than 12 hours later). I accepted without problem (no loop like @Flexmaen), but nothing more happens, ie. I am never joined to the realraum.

clokep · 2020-08-18T15:24:34Z

@clokep it's possible that the matrix.org logs might be enlightening on this issue.

Looking at the logs from the 520 error:

2020-08-17 17:53:42,200 - synapse.access.http.8101 - 311 - INFO - PUT-8570 - 85.237.8.141 - 8101 - {gemeinsam.jetzt} Processed request: 47.729sec/292.437sec (8.963sec, 0.789sec) (0.615sec/5.118sec/21) 266391011B 200 "PUT /_matrix/federation/v2/send_join/%21MQgfkmjcDaXGjEVyLh%3Amatrix.org/%2415976864805aFNNf%3Agemeinsam.jetzt HTTP/1.1" "Synapse/1.19.0" [18528 dbevts]

Is it possible that this response was just really slow (~48 seconds) and that's why Cloudflare returned an error?

The 520 error seems to be a Cloudflare error:

Error 520 occurs when the origin server returns an empty, unknown, or unexpected response to Cloudflare.

It seems Cloudflare is having issues, but that does not seem related since it is recent: https://www.cloudflarestatus.com/incidents/xz2rwk8gsbyp

clokep · 2020-08-19T11:58:09Z

It seems that matrix.org had been having some issues handling incoming federation over the past couple of days. I'd be curious if this is working better today.

Flexmaen · 2020-08-19T13:14:31Z

Does still not work. Just tried few minutes ago, around 15:11.

Also the error message is useless it says: "Entering room faild - there was an error".

mir06 · 2020-08-19T17:59:06Z

That's the log of @Flexmaen's join attempt

2020-08-19 15:12:33,988 - synapse.http.matrixfederationclient - 187 - WARNING - POST-221752 - {PUT-O-86859} [matrix.org] Error reading response PUT matrix://matrix.org/_matrix/federation/v2/send_join/%21MQgfkmjcDaXGjEVyLh%3Amatrix.org/%24159784266837BXsMz%3Agemeinsam.jetzt: (60, 'Deferred')
2020-08-19 15:12:33,988 - synapse.federation.federation_client - 493 - WARNING - POST-221752 - Failed to send_join via matrix.org
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 474, in _try_destination_list
    res = await callback(destination)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 615, in send_request
    content = await self._do_send_join(destination, pdu)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 710, in _do_send_join
    content=pdu.get_pdu_json(time_now),
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/transport/client.py", line 257, in send_join_v2
    destination=destination, path=path, data=content
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 707, in put_json
    self.reactor, self.default_timeout, request, response, start_ms
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 170, in _handle_json_response
    body = await make_deferred_yieldable(d)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/util/async_helpers.py", line 478, in convert_cancelled
    return to_call(value, timeout)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/util/async_helpers.py", line 425, in _cancelled_to_timed_out_error
    raise defer.TimeoutError(timeout, "Deferred")
twisted.internet.defer.TimeoutError: (60, 'Deferred')
2020-08-19 15:12:33,989 - synapse.http.server - 75 - INFO - POST-221752 - <XForwardedForRequest at 0x7f085dc20eb8 method='POST' uri='/_matrix/client/r0/join/%23_oftc_%23realraum%3Amatrix.org' clientproto='HTTP/1.0' site=8008> SynapseError: 502 - Failed to send_join via any server
2020-08-19 15:12:33,989 - synapse.http.server - 531 - WARNING - POST-221752 - Not sending response to request <XForwardedForRequest at 0x7f085dc20eb8 method='POST' uri='/_matrix/client/r0/join/%23_oftc_%23realraum%3Amatrix.org' clientproto='HTTP/1.0' site=8008>, already disconnected.
2020-08-19 15:12:33,989 - synapse.access.http.8008 - 311 - INFO - POST-221752 - 194.118.24.243 - 8008 - {@flexman:gemeinsam.jetzt} Processed request: 85.864sec/-25.864sec (0.005sec, 0.000sec) (0.002sec/0.005sec/4) 0B 200! "POST /_matrix/client/r0/join/%23_oftc_%23realraum%3Amatrix.org HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:79.0) Gecko/20100101 Firefox/79.0" [0 dbevts]

mir06 · 2020-08-19T18:00:26Z

@clokep I am not sure if this is a general federation problem at matrix.org but just (or at least) with matrix.gemeinsam.jetzt. I joined from another homeserver (matrix.g24.at) without any problems within some seconds.

Natureshadow · 2020-08-25T21:06:29Z

I can confirm this issue on matrix.teckids.org, using synapse 1.19.0.

babolivier · 2020-08-26T11:43:29Z

I can confirm this issue on matrix.teckids.org, using synapse 1.19.0.

I had a look at matrix.org's logs and it looks like it's also a case of a timeout before the HS responded:

2020-08-25 20:51:27,289 - synapse.util.ratelimitutils - 130 - INFO - PUT-198727- - Ratelimiter: queueing request (queue now 1 items)
2020-08-25 20:52:37,082 - synapse.http.client - 339 - INFO - PUT-198727--- - Received response to POST http://[...]/_synapse/replication/fed_send_events/OiglwNuenX: 200
2020-08-25 20:52:37,495 - synapse.http.client - 339 - INFO - PUT-198727--- - Received response to POST http://[...]/_synapse/replication/membership_change/%21[...]%3Amatrix.org/%40nik%3Amatrix.teckids.org/joined: 200
2020-08-25 20:54:31,656 - synapse.http.site - 217 - INFO - PUT-198727 - Connection from client lost before response was sent
2020-08-25 20:54:41,982 - synapse.http.server - 604 - WARNING - PUT-198727 - Not sending response to request <XForwardedForRequest at 0x7ff8e375c390 method='PUT' uri='/_matrix/federation/v2/send_join/%21[...]%3Amatrix.org/%2415983884971gEUeQ%3Amatrix.teckids.org' clientproto='HTTP/1.1' site=8084>, already disconnected.
2020-08-25 20:54:42,879 - synapse.access.http.8084 - 311 - INFO - PUT-198727 - 2a01:198:10:2800::22 - 8084 - {matrix.teckids.org} Processed request: 195.597sec/-11.223sec (50.922sec, 2.479sec) (1.086sec/86.781sec/34) 0B 200! "PUT /_matrix/federation/v2/send_join/%21[...]%3Amatrix.org/%2415983884971gEUeQ%3Amatrix.teckids.org HTTP/1.1" "Synapse/1.19.0" [263806 dbevts]

Can you check your server's logs (if you have access to them) to see if there's a TimeoutError for this request?

babolivier · 2020-08-26T14:27:48Z

It sounds like most of these issues are due to matrix.org responding to send_join requests after the remote party times out, which ties into the issue we already know about on room joins being slow in big rooms. I'm not sure if the next step to up the timeout on these requests until we get to working on the join time issue, or something else.

richvdh · 2020-08-26T14:34:47Z

I am surprised this leads to a stuck invite. Even if the join fails, you ought to be able to reject the invite?

babolivier · 2020-08-26T14:56:48Z

I am surprised this leads to a stuck invite. Even if the join fails, you ought to be able to reject the invite?

I've changed the name of the issue because it better matches what the reporter is describing. I don't know for a fact that it causes a stuck invite, as I can't see any make_leave or send_leave request from this HS in matrix.org's logs (and it looks like I've forgotten to mention this here).

On top of that, it's unclear what happens when an attempt to reject the invite is made, @mir06 would you be able to provide logs of what happens then from your side (as clokep asked) please?

Natureshadow · 2020-08-26T15:53:34Z

Is increasing the join timeout something I can do on my HS?

babolivier · 2020-08-27T13:41:48Z

Related: #7671

richvdh · 2020-08-28T09:33:17Z

It's really unclear what this issue is about.

There seem to be at least three different problems:

joins time out. This is a somewhat known issue, related mostly to load on the joining or remote server. Some of matrix.org's federation_readers have been a bit busy recently (cf /_matrix/federation/v1/state_ids/ is heavy #7893) which might be related. Still, I'd expect it to work most of the time.
Attempts to reject invites fail. Apparently the error message here is "Denieing failed. Not a known user", but I don't believe that, because that's not how you spell "denying". Either way, this is very much not a known issue: even if the target server is overloaded, you should be able to reject an invite, at least as of recent Synapse versions.
According to @Natureshadow, this issue causes the oftc bridge will re-invite you. This makes even less sense to me (if the attempt to join fails, you still have a pending invite? How can it reinvite you?)

since the first issue is known, and @babolivier has changed the summary of the issue to "Timing out on send_join leads to stuck invites", I suggest we use this issue to track the second problem: the stuck invite. @Flexmaen: please share logs from your server when an attempt to reject an invite fails.

People struggling to join rooms: sorry :/. We're planning a focus on making joins over federation suck less (#7671) within the next few months. In the meantime, I can't really suggest much other than being patient.

Flexmaen · 2020-08-28T10:39:03Z

Attempts to reject invites fail. Apparently the error message here is "Denieing failed. Not a known user", but I don't believe that, because that's not how you spell "denying".

Since I get the messages in German I don't know the exact message I'd get in English. So my error messages are rough translations that should transport the meaning of the mssage.

since the first issue is known, and @babolivier has changed the summary of the issue to "Timing out on send_join leads to stuck invites", I suggest we use this issue to track the second problem: the stuck invite. @Flexmaen: please share logs from your server when an attempt to reject an invite fails.

It's the server of @mir06 who does not always seem to get the same result. So I'll try to join again and he'll post the log.

We're planning a focus on making joins over federation suck less (#7671) within the next few months. In the meantime, I can't really suggest much other than being patient.

Thank you.

mir06 · 2020-08-28T14:55:36Z

Hi,
this is the log from @Flexmaen's recent try at 12:41 to join #_oftc_#realraum:matrix.org. Same problem as before. But this seems to be related to #7893
Anyway here is the log

2020-08-28 12:41:26,507 - synapse.http.matrixfederationclient - 187 - WARNING - POST-3680350 - {PUT-O-2814084} [matrix.org] Error reading response PUT matrix://matrix.org/_matrix/federation/v2/send_join/%21MQgfkmjcDaXGjEVyLh%3Amatrix.org/%241598611194183NlwQS%3Agemeinsam.jetzt: (60, 'Deferred')
2020-08-28 12:41:26,511 - synapse.federation.federation_client - 493 - WARNING - POST-3680350 - Failed to send_join via matrix.org
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 474, in _try_destination_list
    res = await callback(destination)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 615, in send_request
    content = await self._do_send_join(destination, pdu)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 710, in _do_send_join
    content=pdu.get_pdu_json(time_now),
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/transport/client.py", line 257, in send_join_v2
    destination=destination, path=path, data=content
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 707, in put_json
    self.reactor, self.default_timeout, request, response, start_ms
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 170, in _handle_json_response
    body = await make_deferred_yieldable(d)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/util/async_helpers.py", line 478, in convert_cancelled
    return to_call(value, timeout)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/util/async_helpers.py", line 425, in _cancelled_to_timed_out_error
    raise defer.TimeoutError(timeout, "Deferred")
twisted.internet.defer.TimeoutError: (60, 'Deferred')
2020-08-28 12:41:26,520 - synapse.http.server - 75 - INFO - POST-3680350 - <XForwardedForRequest at 0x7f080f4dc860 method='POST' uri='/_matrix/client/r0/join/%23_oftc_%23realraum%3Amatrix.org' clientproto='HTTP/1.0' site=8008> SynapseError: 502 - Failed to send_join via any server
2020-08-28 12:41:26,520 - synapse.http.server - 531 - WARNING - POST-3680350 - Not sending response to request <XForwardedForRequest at 0x7f080f4dc860 method='POST' uri='/_matrix/client/r0/join/%23_oftc_%23realraum%3Amatrix.org' clientproto='HTTP/1.0' site=8008>, already disconnected.
2020-08-28 12:41:26,520 - synapse.access.http.8008 - 311 - INFO - POST-3680350 - 129.27.82.13 - 8008 - {@flexman:gemeinsam.jetzt} Processed request: 91.929sec/-31.927sec (0.015sec, 0.004sec) (0.002sec/0.006sec/4) 0B 200! "POST /_matrix/client/r0/join/%23_oftc_%23realraum%3Amatrix.org HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.135 Safari/537.36" [0 dbevts]

mir06 · 2020-08-28T15:18:03Z

While searching for the "Not a known user"-related lines in the logs I retried to join myself and got another exception:

2020-08-28 16:56:58,404 - synapse.http.matrixfederationclient - 502 - INFO - POST-3780529 - {PUT-O-2879584} [matrix.org] Got response headers: 500 Internal Server Error
2020-08-28 16:56:58,405 - synapse.http.matrixfederationclient - 578 - WARNING - POST-3780529 - {PUT-O-2879584} [matrix.org] Request failed: PUT matrix://matrix.org/_matrix/federation/v2/send_join/%21MQgfkmjcDa
XGjEVyLh%3Amatrix.org/%241598626602202Blywc%3Agemeinsam.jetzt: HttpResponseException('500: Internal Server Error')
2020-08-28 16:56:58,405 - synapse.util.retryutils - 215 - INFO - POST-3780529 - Connection to matrix.org was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(500: Internal Server Error)); backo
ff now 600000
2020-08-28 16:56:58,405 - synapse.federation.federation_client - 493 - WARNING - POST-3780529 - Failed to send_join via matrix.org
Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 710, in _do_send_join
    content=pdu.get_pdu_json(time_now),
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/transport/client.py", line 257, in send_join_v2
    destination=destination, path=path, data=content
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 703, in put_json
    timeout=timeout,
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 289, in _send_request_with_optional_trailing_slash
    response = await self._send_request(request, **send_request_args)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 533, in _send_request
    raise e
synapse.api.errors.HttpResponseException: 500: Internal Server Error

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 474, in _try_destination_list
    res = await callback(destination)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 615, in send_request
    content = await self._do_send_join(destination, pdu)
  File "/opt/venvs/matrix-synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 724, in _do_send_join
    raise e.to_synapse_error()
synapse.api.errors.ProxiedRequestError: 500: Internal server error
2020-08-28 16:56:58,407 - synapse.http.server - 75 - INFO - POST-3780529 - <XForwardedForRequest at 0x7f083948d6d8 method='POST' uri='/_matrix/client/r0/join/%23_oftc_%23realraum%3Amatrix.org' clientproto='HTTP/1.0' site=8008> SynapseError: 502 - Failed to send_join via any server
2020-08-28 16:56:58,408 - synapse.access.http.8008 - 311 - INFO - POST-3780529 - 37.186.9.113 - 8008 - {@mir:gemeinsam.jetzt} Processed request: 16.306sec/0.000sec (0.009sec, 0.002sec) (0.003sec/0.011sec/4) 83B 502 "POST /_matrix/client/r0/join/%23_oftc_%23realraum%3Amatrix.org HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.4 Chrome/83.0.4103.122 Electron/9.1.2 Safari/537.36" [0 dbevts]

richvdh · 2020-08-28T17:37:39Z

ok, I'm not seeing any attempts to reject the invite there. As I said earlier:

since the first issue is known, and @babolivier has changed the summary of the issue to "Timing out on send_join leads to stuck invites", I suggest we use this issue to track the second problem: the stuck invite. @Flexmaen: please share logs from your server when an attempt to reject an invite fails.

please note: reject an invite. The fact that a join times out or sometimes fails with a 500 is a known issue.

Flexmaen · 2020-08-28T20:44:48Z

It seems that I don't get the accept/reject-dialogue anymore. At the moment i get the error message like shown above but afterwards just get the option to click on a "try again" button.

richvdh · 2020-08-30T08:59:52Z

ok I'm going to close this because the fact that joins can fail is known, and I'm not seeing any evidence of invite rejections failing.

mir06 · 2020-09-05T18:18:55Z

Sorry, I could not follow this issue the last days.
But now I was able to reproduce @Flexmaen's problem on our HS with a join-attempt to another otfc channel. The r3bot sends an invitation which I can never accept nor reject.
On rejecting I get the following synapse log (and element error dialog below)

2020-09-05 20:08:07,267 - synapse.handlers.room_member - 513 - INFO - POST-6727791 - @mir:gemeinsam.jetzt sent a leave request to !uXUAkDKWNpzZLvVnKx:matrix.org, but that is not an active room on this server, a
nd there is no pending invite
2020-09-05 20:08:07,267 - synapse.http.server - 75 - INFO - POST-6727791 - <XForwardedForRequest at 0x7f0823354518 method='POST' uri='/_matrix/client/r0/rooms/!uXUAkDKWNpzZLvVnKx%3Amatrix.org/leave' clientproto='HTTP/1.0' site=8008> SynapseError: 404 - Not a known room
2020-09-05 20:08:07,267 - synapse.access.http.8008 - 311 - INFO - POST-6727791 - 37.186.9.113 - 8008 - {@mir:gemeinsam.jetzt} Processed request: 0.005sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.002sec/1) 66B 404 "POST /_matrix/client/r0/rooms/!uXUAkDKWNpzZLvVnKx%3Amatrix.org/leave HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.4 Chrome/83.0.4103.122 Electron/9.1.2 Safari/537.36" [0 dbevts]

Accepting leads to this error in the synapse log:

2020-09-05 20:14:15,876 - synapse.http.server - 75 - INFO - POST-6729404 - <XForwardedForRequest at 0x7f081b4270b8 method='POST' uri='/_matrix/client/r0/join/!uXUAkDKWNpzZLvVnKx%3Amatrix.org' clientproto='HTTP/
1.0' site=8008> SynapseError: 404 - No known servers
2020-09-05 20:14:15,877 - synapse.access.http.8008 - 311 - INFO - POST-6729404 - 37.186.9.113 - 8008 - {@mir:gemeinsam.jetzt} Processed request: 0.008sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.004sec/3) 66B 
404 "POST /_matrix/client/r0/join/!uXUAkDKWNpzZLvVnKx%3Amatrix.org HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.7.4 Chrome/83.0.4103.122 Electron/9.1.2 Safari/537.
36" [0 dbevts]

mir06 · 2020-09-05T18:21:41Z

Bye the way, I can leave this loop by clearing the cache in All settings / Help & About / Clear cache and reload.

Flexmaen · 2020-09-06T13:31:17Z

@richvdh ok it seems that this is reproducable. That bot is an IRC-Bot.

richvdh · 2020-09-06T20:24:21Z

please can you share all the logs from the homeserver, between the invite being received and the failure to reject.

mir06 · 2020-09-07T08:25:52Z

@richvdh yes I can do this but I do not have time before Wednesday. I will post it here!

mir06 · 2020-09-18T15:02:57Z

I cannot provide the entire logs as my last try to join the room is more than a week ago. And just a couple of minutes ago I got the invitation from r3bot (PM on irc.oftc.net). Clicking Accept or Reject leads to the same behavior as described above (also the server-logs). Probably the bot really does not exist anymore when the invitation takes that long.

richvdh · 2020-09-21T11:16:05Z

And just a couple of minutes ago I got the invitation from r3bot (PM on irc.oftc.net). Clicking Accept or Reject leads to the same behavior as described above

please share the complete server logs between the invite arriving and your attempt to reject.

richvdh · 2020-10-21T21:15:26Z

closing for lack of useful logs.

Flexmaen · 2020-11-19T14:09:55Z

Similar problem via Mozillas Matrix-Server. Maybe a problem of the OFTC bridge? Is it possible to re-open this bug on the right place?

mir06 · 2020-11-19T15:05:11Z

On matrix.g24.at I got the invitation problably after a couple of hours (last log-in at the end of August) and could accept it some months later (today) without a problem. This opened a private chat with @_oftc_r3bot:matrix.org and the room #_oftc_#realraum:matrix.org.

richvdh · 2020-11-19T15:29:29Z

This issue is super unclear. If you are still seeing problems, I suggest opening new issues. Please note:

being unable to join a room after receiving an invite, and being unable to reject an invite, are different problems. If you're seeing both, open separate issues.
avoid assuming that somebody with superficially similar-sounding symptoms is seeing the same problem. In general, it's better to open a new issue: it's much easier for us to merge duplicate bugs than it is for us to tease out separate bugs which have got mixed up together.
For this sort of problem, it's really important for us to have as much information as possible. Please be as clear as possible about exactly what you are seeing:
- Supply screenshots where possible.
- Tell us the exact text you are seeing, even if it's not in English.
- If you run your own server, please provide logs (letting us know the timezone).
- If you're seeing the problem on matrix.org or EMS (eg mozilla.org), give us enough info to track it down in the logs (what time you had the problem, what your mxid is).

Flexmaen mentioned this issue Aug 14, 2020

Rejoining a deserted room can lead to a loop element-hq/element-web#13919

Open

clokep added the info-needed label Aug 17, 2020

richvdh removed the info-needed label Aug 26, 2020

richvdh assigned babolivier Aug 26, 2020

babolivier removed their assignment Aug 26, 2020

babolivier changed the title ~~Invitation loop with external server~~ Timing out on send_join leads to stuck invites Aug 26, 2020

richvdh added info-needed A-Federated-Join joins over federation generally suck labels Aug 27, 2020

richvdh closed this as completed Aug 30, 2020

richvdh reopened this Sep 6, 2020

richvdh changed the title ~~Timing out on send_join leads to stuck invites~~ Unrejectable invite from oftc room Sep 6, 2020

anoadragon453 added the A-Stuck-Invite Incoming invitations that won't go away label Sep 24, 2020

richvdh closed this as completed Oct 21, 2020

Unrejectable invite from oftc room #8091

Unrejectable invite from oftc room #8091

Comments

Flexmaen commented Aug 14, 2020

Description

Steps to reproduce

Describe how what happens differs from what you expected.

Version information

Flexmaen commented Aug 16, 2020

clokep commented Aug 17, 2020

mir06 commented Aug 17, 2020

mir06 commented Aug 17, 2020

mir06 commented Aug 17, 2020 • edited Loading

richvdh commented Aug 18, 2020

mir06 commented Aug 18, 2020

clokep commented Aug 18, 2020 • edited Loading

clokep commented Aug 19, 2020

Flexmaen commented Aug 19, 2020 • edited Loading

mir06 commented Aug 19, 2020

mir06 commented Aug 19, 2020

Natureshadow commented Aug 25, 2020

babolivier commented Aug 26, 2020 • edited Loading

babolivier commented Aug 26, 2020

richvdh commented Aug 26, 2020

babolivier commented Aug 26, 2020

Natureshadow commented Aug 26, 2020

babolivier commented Aug 27, 2020

richvdh commented Aug 28, 2020

Flexmaen commented Aug 28, 2020 • edited Loading

mir06 commented Aug 28, 2020

mir06 commented Aug 28, 2020

richvdh commented Aug 28, 2020

Flexmaen commented Aug 28, 2020

richvdh commented Aug 30, 2020

mir06 commented Sep 5, 2020

mir06 commented Sep 5, 2020

Flexmaen commented Sep 6, 2020

richvdh commented Sep 6, 2020

mir06 commented Sep 7, 2020

mir06 commented Sep 18, 2020

richvdh commented Sep 21, 2020

richvdh commented Oct 21, 2020

Flexmaen commented Nov 19, 2020

mir06 commented Nov 19, 2020

richvdh commented Nov 19, 2020

mir06 commented Aug 17, 2020 •

edited

Loading

clokep commented Aug 18, 2020 •

edited

Loading

Flexmaen commented Aug 19, 2020 •

edited

Loading

babolivier commented Aug 26, 2020 •

edited

Loading

Flexmaen commented Aug 28, 2020 •

edited

Loading