Failed handle request via 'PublicRoomListRestServlet' #243

[typokign]

Description

Synapse is returning a 500 for _matrix/client/r0/publicRooms?server=matrix.org about 75% of the time with this error:

Aug 12 01:17:38 casa matrix-synapse[3271]: 2019-08-12 01:17:38,086 - synapse.http.server - 108 - ERROR - POST-351 - Failed handle request via 'PublicRoomListRestServlet': <XForwardedForRequest at 0x7f6a467dddd0 method='POST' uri='/_matrix/client/r0/publicRooms?server=matrix.org' clientproto='HTTP/1.0' site=8008>
Aug 12 01:17:38 casa matrix-synapse[3271]: Traceback (most recent call last):
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/synapse/http/server.py", line 76, in wrapped_request_handler
Aug 12 01:17:38 casa matrix-synapse[3271]:     await h(self, request)
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/synapse/http/server.py", line 315, in _async_render
Aug 12 01:17:38 casa matrix-synapse[3271]:     callback_return = await callback_return
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/synapse/logging/opentracing.py", line 480, in _trace_servlet_inner
Aug 12 01:17:38 casa matrix-synapse[3271]:     result = yield defer.maybeDeferred(func, request, *args, **kwargs)
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/synapse/rest/client/v1/room.py", line 398, in on_POST
Aug 12 01:17:38 casa matrix-synapse[3271]:     third_party_instance_id=third_party_instance_id,
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/synapse/handlers/room_list.py", line 498, in get_remote_public_room_list
Aug 12 01:17:38 casa matrix-synapse[3271]:     third_party_instance_id=third_party_instance_id,
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
Aug 12 01:17:38 casa matrix-synapse[3271]:     result = result.throwExceptionIntoGenerator(g)
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
Aug 12 01:17:38 casa matrix-synapse[3271]:     return g.throw(self.type, self.value, self.tb)
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/synapse/federation/transport/client.py", line 339, in get_public_rooms
Aug 12 01:17:38 casa matrix-synapse[3271]:     destination=remote_server, path=path, args=args, ignore_backoff=True
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
Aug 12 01:17:38 casa matrix-synapse[3271]:     result = result.throwExceptionIntoGenerator(g)
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
Aug 12 01:17:38 casa matrix-synapse[3271]:     return g.throw(self.type, self.value, self.tb)
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 774, in get_json
Aug 12 01:17:38 casa matrix-synapse[3271]:     timeout=timeout,
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
Aug 12 01:17:38 casa matrix-synapse[3271]:     result = result.throwExceptionIntoGenerator(g)
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
Aug 12 01:17:38 casa matrix-synapse[3271]:     return g.throw(self.type, self.value, self.tb)
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 241, in _send_request_with_optional_trailing_slash
Aug 12 01:17:38 casa matrix-synapse[3271]:     response = yield self._send_request(request, **send_request_args)
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
Aug 12 01:17:38 casa matrix-synapse[3271]:     result = g.send(result)
Aug 12 01:17:38 casa matrix-synapse[3271]:   File "/usr/local/lib/python3.7/site-packages/synapse/http/matrixfederationclient.py", line 475, in _send_request
Aug 12 01:17:38 casa matrix-synapse[3271]:     raise e
Aug 12 01:17:38 casa matrix-synapse[3271]: synapse.api.errors.HttpResponseException: 500: b'Internal Server Error'

Steps to reproduce

• Open Riot, select Room Directory
• Select matrix.org as the server to load the directory for
• See Riot failed to get the public room list. Internal server error in Riot
• See above message in Synapse logs

Version information

• Homeserver: typokign.com

If not matrix.org:

• Version: v1.2.1

• Install method: spantaleev/matrix-docker-ansible-deploy (issue: Failed handle request via 'PublicRoomListRestServlet' spantaleev/matrix-docker-ansible-deploy#243)

• Platform: matrixdotorg/synapse:v1.2.1 Docker container on Ubuntu 18.04 LTS

[typokign]

Fixed by adding a new SRV record as described here: #5086

Drat, I spoke too soon. After adding the SRV record, things seemed stable for a good 5 or 6 times in a row, but now it's back to before.

[neVERberleRfellerER]

M yobservation is, that when it fails, it keeps failing for some time for all servers. After some unmeasured time elapses, it starts working again until it randomly fails.

[richvdh]

please could you include more logs for the request in question?

[typokign]

please could you include more logs for the request in question?

will try to if I'm able to get to the room directory again. for now, are the logs in the OP enough to investigate?

[richvdh]

are the logs in the OP enough to investigate?

no, I'd like to see the logs leading up to the error.

[neVERberleRfellerER]

Turns out, that my observation is caused by weird riot-web behavior: when it gets "Internal server error", it keeps showing that message even when I want to browse different server than one that returned 500. Also, it says "Internal server error", even when server returns "Unauthorized".

UPDATE
Server I was trying to connect to is misconfigured and others work correctly, so no problem on my side after all.

[typokign]

seems to be resolved on my end too. must have been a temporary misconfiguration on matrix.org's side

[richvdh]

possible it was fixed when we deployed #5851

[neVERberleRfellerER]

@richvdh You are probably right. When I try to connnect to servers that are still on synapse 1.2.1, it still causes error from OP.