Joining a large room timed out, and subsequent attempts ISE

[Half-Shot]

I'm running latest develop, and the room in question is #freenode_#kubuntu:matrix.org.

Logs:

2019-07-17 17:00:38,652 - synapse.access.http.9593 - 233 - INFO - POST-31338- 127.0.0.1 - 9593 - Received request: POST /_synapse/replication/remote_join/%21YYtOqtdMtFNanKzfuQ%3Amatrix.org/%40Half-Shot%3Ahalf-shot.uk/uEnfCJGgwL
2019-07-17 17:00:38,652 - synapse.util.caches.response_cache - 148 - INFO - POST-31338- [repl.remote_join]: no cached result for [uEnfCJGgwL], calculating new one
2019-07-17 17:00:38,652 - synapse.replication.http.membership - 80 - INFO - POST-31338- remote_join: @Half-Shot:half-shot.uk into room: !YYtOqtdMtFNanKzfuQ:matrix.org
2019-07-17 17:00:38,653 - synapse.http.matrixfederationclient - 387 - INFO - POST-31338- {GET-O-248} [matrix.org] Sending request: GET matrix://matrix.org/_matrix/federation/v1/make_join/%21YYtOqtdMtFNanKzfuQ%3Amatrix.org/%40Half-Shot%3Ahalf-shot.uk?ver=1&ver=2&ver=3&ver=4&ver=5; timeout 20.000000s
2019-07-17 17:00:39,373 - synapse.http.matrixfederationclient - 419 - INFO - POST-31338- {GET-O-248} [matrix.org] Got response headers: 200 OK
2019-07-17 17:00:39,374 - synapse.http.matrixfederationclient - 158 - INFO - POST-31338- {GET-O-248} [matrix.org] Completed: 200 OK
2019-07-17 17:00:39,376 - synapse.http.server - 108 - ERROR - POST-31338- Failed handle request via 'ReplicationRemoteJoinRestServlet': <SynapseRequest at 0x7f5413cfa160 method='POST' uri='/_synapse/replication/remote_join/%21YYtOqtdMtFNanKzfuQ%3Amatrix.org/%40Half-Shot%3Ahalf-shot.uk/uEnfCJGgwL' clientproto='HTTP/1.1' site=9593>
Traceback (most recent call last):
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/srv/matrix/synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 160, in _handle_json_response
    defer.returnValue(body)
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: {'event': {'auth_events': [['$1552140485995566ZhcyW:matrix.org', {'sha256': '5K3AVkfDSsFRS5wSvNuklyU/pEugZZ1a/7bad7V/2Pc'}], ['$1463839933347564rlCBF:matrix.org', {'sha256': 'oknt0HmYi6Ux6h7H+yr7Tyu+YwNyeQSwmgZBWfkzos4'}], ['$1463839933347572YdgcU:matrix.org', {'sha256': '1d1E4nEHoO0ylshiOFm0ObluX/K3uIBO2p2bBiU0AJ8'}]], 'prev_events': [['$15633756321504LbJId:kde.org', {'sha256': 'RMZY4SXqqmkuNmzk9KmpdV1ROYLJNFLihHDicdIkpIg'}], ['$15633754720AKPbe:half-shot.uk', {'sha256': 'Dsxh5fkMyOGql0ELID3CeSfpugQqAlkUlQCg7EXLRVE'}]], 'type': 'm.room.member', 'room_id': '!YYtOqtdMtFNanKzfuQ:matrix.org', 'sender': '@Half-Shot:half-shot.uk', 'content': {'membership': 'join', 'avatar_url': 'mxc://half-shot.uk/6fc3fb176d5246f1e7cf7d89ad4248b8', 'displayname': 'Half-Shot'}, 'depth': 241293, 'prev_state': [], 'state_key': '@Half-Shot:half-shot.uk', 'event_id': '$15633756393eYEdQ:half-shot.uk', 'origin': 'half-shot.uk', 'origin_server_ts': 1563375639263, 'hashes': {'sha256': '9FBE0pL0C3EzHVUxjTXX/ITehzTlBUnfIE0eK7xcg3c'}, 'signatures': {'matrix.org': {'ed25519:auto': '2cmyXWz1X4TKtvJZt/oesHWRhFu7F3kGBWa5ArPd6edWMfo/9UTrzdVIHhml4XDfsrCQ6FhCM8aYd+nTe+dKCQ'}, 'half-shot.uk': {'ed25519:a_fBAF': 'Bl/Ytf9ENfRxCEnh2Cs4IXhlOtsgt0vw247CVZSHLEQLIE3vIeDvkcqSOQYwOUyIFHfO5Qn34NCiLOMw5U4CBQ'}}, 'unsigned': {'replaces_state': '$15633754720AKPbe:half-shot.uk', 'age_ts': 1563375639305}}, 'room_version': '1'}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/srv/matrix/synapse/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 761, in get_json
    defer.returnValue(body)
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: {'event': {'auth_events': [['$1552140485995566ZhcyW:matrix.org', {'sha256': '5K3AVkfDSsFRS5wSvNuklyU/pEugZZ1a/7bad7V/2Pc'}], ['$1463839933347564rlCBF:matrix.org', {'sha256': 'oknt0HmYi6Ux6h7H+yr7Tyu+YwNyeQSwmgZBWfkzos4'}], ['$1463839933347572YdgcU:matrix.org', {'sha256': '1d1E4nEHoO0ylshiOFm0ObluX/K3uIBO2p2bBiU0AJ8'}]], 'prev_events': [['$15633756321504LbJId:kde.org', {'sha256': 'RMZY4SXqqmkuNmzk9KmpdV1ROYLJNFLihHDicdIkpIg'}], ['$15633754720AKPbe:half-shot.uk', {'sha256': 'Dsxh5fkMyOGql0ELID3CeSfpugQqAlkUlQCg7EXLRVE'}]], 'type': 'm.room.member', 'room_id': '!YYtOqtdMtFNanKzfuQ:matrix.org', 'sender': '@Half-Shot:half-shot.uk', 'content': {'membership': 'join', 'avatar_url': 'mxc://half-shot.uk/6fc3fb176d5246f1e7cf7d89ad4248b8', 'displayname': 'Half-Shot'}, 'depth': 241293, 'prev_state': [], 'state_key': '@Half-Shot:half-shot.uk', 'event_id': '$15633756393eYEdQ:half-shot.uk', 'origin': 'half-shot.uk', 'origin_server_ts': 1563375639263, 'hashes': {'sha256': '9FBE0pL0C3EzHVUxjTXX/ITehzTlBUnfIE0eK7xcg3c'}, 'signatures': {'matrix.org': {'ed25519:auto': '2cmyXWz1X4TKtvJZt/oesHWRhFu7F3kGBWa5ArPd6edWMfo/9UTrzdVIHhml4XDfsrCQ6FhCM8aYd+nTe+dKCQ'}, 'half-shot.uk': {'ed25519:a_fBAF': 'Bl/Ytf9ENfRxCEnh2Cs4IXhlOtsgt0vw247CVZSHLEQLIE3vIeDvkcqSOQYwOUyIFHfO5Qn34NCiLOMw5U4CBQ'}}, 'unsigned': {'replaces_state': '$15633754720AKPbe:half-shot.uk', 'age_ts': 1563375639305}}, 'room_version': '1'}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/srv/matrix/synapse/lib/python3.7/site-packages/synapse/federation/transport/client.py", line 262, in make_membership_event
    defer.returnValue(content)
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: {'event': {'auth_events': [['$1552140485995566ZhcyW:matrix.org', {'sha256': '5K3AVkfDSsFRS5wSvNuklyU/pEugZZ1a/7bad7V/2Pc'}], ['$1463839933347564rlCBF:matrix.org', {'sha256': 'oknt0HmYi6Ux6h7H+yr7Tyu+YwNyeQSwmgZBWfkzos4'}], ['$1463839933347572YdgcU:matrix.org', {'sha256': '1d1E4nEHoO0ylshiOFm0ObluX/K3uIBO2p2bBiU0AJ8'}]], 'prev_events': [['$15633756321504LbJId:kde.org', {'sha256': 'RMZY4SXqqmkuNmzk9KmpdV1ROYLJNFLihHDicdIkpIg'}], ['$15633754720AKPbe:half-shot.uk', {'sha256': 'Dsxh5fkMyOGql0ELID3CeSfpugQqAlkUlQCg7EXLRVE'}]], 'type': 'm.room.member', 'room_id': '!YYtOqtdMtFNanKzfuQ:matrix.org', 'sender': '@Half-Shot:half-shot.uk', 'content': {'membership': 'join', 'avatar_url': 'mxc://half-shot.uk/6fc3fb176d5246f1e7cf7d89ad4248b8', 'displayname': 'Half-Shot'}, 'depth': 241293, 'prev_state': [], 'state_key': '@Half-Shot:half-shot.uk', 'event_id': '$15633756393eYEdQ:half-shot.uk', 'origin': 'half-shot.uk', 'origin_server_ts': 1563375639263, 'hashes': {'sha256': '9FBE0pL0C3EzHVUxjTXX/ITehzTlBUnfIE0eK7xcg3c'}, 'signatures': {'matrix.org': {'ed25519:auto': '2cmyXWz1X4TKtvJZt/oesHWRhFu7F3kGBWa5ArPd6edWMfo/9UTrzdVIHhml4XDfsrCQ6FhCM8aYd+nTe+dKCQ'}, 'half-shot.uk': {'ed25519:a_fBAF': 'Bl/Ytf9ENfRxCEnh2Cs4IXhlOtsgt0vw247CVZSHLEQLIE3vIeDvkcqSOQYwOUyIFHfO5Qn34NCiLOMw5U4CBQ'}}, 'unsigned': {'replaces_state': '$15633754720AKPbe:half-shot.uk', 'age_ts': 1563375639305}}, 'room_version': '1'}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/srv/matrix/synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 618, in send_request
    defer.returnValue((destination, ev, event_format))
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: ('matrix.org', <FrozenEvent event_id='$15633756393eYEdQ:half-shot.uk', type='m.room.member', state_key='@Half-Shot:half-shot.uk'>, 1)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/srv/matrix/synapse/lib/python3.7/site-packages/synapse/federation/federation_client.py", line 524, in _try_destination_list
    defer.returnValue(res)
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: ('matrix.org', <FrozenEvent event_id='$15633756393eYEdQ:half-shot.uk', type='m.room.member', state_key='@Half-Shot:half-shot.uk'>, 1)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/srv/matrix/synapse/lib/python3.7/site-packages/synapse/handlers/federation.py", line 1410, in _make_and_verify_event
    defer.returnValue((origin, event, format_ver))
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1362, in returnValue
    raise _DefGen_Return(val)
twisted.internet.defer._DefGen_Return: ('matrix.org', <FrozenEvent event_id='$15633756393eYEdQ:half-shot.uk', type='m.room.member', state_key='@Half-Shot:half-shot.uk'>, 1)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/srv/matrix/synapse/lib/python3.7/site-packages/synapse/http/server.py", line 76, in wrapped_request_handler
    await h(self, request)
  File "/srv/matrix/synapse/lib/python3.7/site-packages/synapse/http/server.py", line 301, in _async_render
    callback_return = await callback_return
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/srv/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 "/srv/matrix/synapse/lib/python3.7/site-packages/synapse/replication/http/membership.py", line 83, in _handle_request
    remote_room_hosts, room_id, user_id, event_content
  File "/srv/matrix/synapse/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/srv/matrix/synapse/lib/python3.7/site-packages/synapse/handlers/federation.py", line 1123, in do_invite_join
    assert room_id not in self.room_queues
AssertionError
2019-07-17 17:00:39,435 - synapse.access.http.9593 - 302 - INFO - POST-31338- 127.0.0.1 - 9593 - {@Half-Shot:half-shot.uk} Processed request: 0.782sec/0.001sec (0.009sec, 0.000sec) (0.000sec/0.000sec/0) 55B 500 "POST /_synapse/replication/remote_join/%21YYtOqtdMtFNanKzfuQ%3Amatrix.org/%40Half-Shot%3Ahalf-shot.uk/uEnfCJGgwL HTTP/1.1" "Synapse/1.1.0" [0 dbevts]

[richvdh]

@Half-Shot do you know if this is still a problem?

[Half-Shot]

I've not experienced it recently. Please close and I'll reopen if I spot it again.

[sijanec]

Yup, I have this problem when synapse is behind a nginx reverse proxy that timed out due to the slowness. Wouldn't it be better to use 1xx Continue responses for room joining instead of not responding to HTTP requests, which can cause problems with timeouts?