/messages returns the 4XX status code and error of a remote homeserver when backfilling, which is confusing

[krombel]

Description

/messages returns 500 Internal Server Error when backfilling #matrix-dev:matrix.org from a server which has removed that room from their database

Steps to reproduce

• Try backfilling #matrix-dev:matrix.org

Version information

• Homeserver: another homeserver
• Version: 0.33.2

Logs

2018-08-22 13:25:17,093 - synapse.handlers.federation - 790 - ERROR - GET-66416 - Failed to backfill from chat.weho.st because FirstError[#0, [Failure instance: Traceback: <class 'synapse.api.errors.SynapseError'>: 403: Room '!XqBunHwQIXUiqCaoxq:matrix.org' does not exist
/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py:1418:_inlineCallbacks
synapse/handlers/federation.py:1607:_prep_event
/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py:1613:unwindGenerator
/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py:1529:_cancellableInlineCallbacks
--- <exception caught here> ---
synapse/handlers/federation.py:1607:_prep_event
/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py:1418:_inlineCallbacks
synapse/handlers/federation.py:1903:do_auth
synapse/api/auth.py:90:check
synapse/event_auth.py:95:check
]]
Traceback (most recent call last):
  File "synapse/handlers/federation.py", line 760, in try_backfill
    extremities=extremities,
FirstError: FirstError[#0, [Failure instance: Traceback: <class 'synapse.api.errors.SynapseError'>: 403: Room '!XqBunHwQIXUiqCaoxq:matrix.org' does not exist
/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py:1418:_inlineCallbacks
synapse/handlers/federation.py:1607:_prep_event
/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py:1613:unwindGenerator
/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py:1529:_cancellableInlineCallbacks
--- <exception caught here> ---
synapse/handlers/federation.py:1607:_prep_event
/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py:1418:_inlineCallbacks
synapse/handlers/federation.py:1903:do_auth
synapse/api/auth.py:90:check
synapse/event_auth.py:95:check
]]
2018-08-22 13:25:17,096 - synapse.handlers.federation - 782 - INFO - GET-66416 - Not retrying server catalk.xyz.
2018-08-22 13:25:17,100 - synapse.handlers.federation - 782 - INFO - GET-66416 - Not retrying server klen.site.
2018-08-22 13:25:17,101 - synapse.handlers.federation - 782 - INFO - GET-66416 - Not retrying server onat.edu.ua.
2018-08-22 13:25:17,103 - synapse.handlers.federation - 782 - INFO - GET-66416 - Not retrying server moulticast.net.
2018-08-22 13:25:17,112 - synapse.handlers.federation - 782 - INFO - GET-66416 - Not retrying server dawninglight.net.
2018-08-22 13:25:17,114 - synapse.handlers.federation - 782 - INFO - GET-66416 - Not retrying server yannikenss.de.
2018-08-22 13:25:17,116 - synapse.handlers.federation - 782 - INFO - GET-66416 - Not retrying server aerens.be.
2018-08-22 13:25:17,118 - synapse.handlers.federation - 782 - INFO - GET-66416 - Not retrying server lvps.eu.
2018-08-22 13:25:17,119 - synapse.handlers.federation - 782 - INFO - GET-66416 - Not retrying server matrix.cigliola.com.
2018-08-22 13:25:17,120 - synapse.handlers.federation - 782 - INFO - GET-66416 - Not retrying server veeedo.com.
2018-08-22 13:25:17,121 - synapse.handlers.federation - 782 - INFO - GET-66416 - Not retrying server pawelmandera.com.
2018-08-22 13:25:17,123 - synapse.handlers.federation - 782 - INFO - GET-66416 - Not retrying server home.shrike.me.
2018-08-22 13:25:17,123 - synapse.http.outbound - 164 - INFO - GET-66416 - {GET-O-77660} [fiksel.info] Sending request: GET matrix://fiksel.info/_matrix/federation/v1/backfill/%21XqBunHwQIXUiqCaoxq%3Amatrix.org/?limit=100&v=%241416421050073wSUwI%3Amatrix.org&v=%241416420914590avyez%3Ajki.re&v=%241416420914880oFczF%3Ajki.re&v=%241416421009533vfDhR%3Amatrix.org&v=%241416420916528LUXWH%3Amatrix.org
2018-08-22 13:25:17,125 - synapse.http.endpoint - 332 - INFO - GET-66416 - Connecting to matrix.fiksel.info:8448
2018-08-22 13:25:17,293 - synapse.http.outbound - 246 - INFO - GET-66416 - {GET-O-77660} [fiksel.info] Result: 403 Forbidden
2018-08-22 13:25:17,296 - synapse.http.server - 98 - ERROR - GET-66416 - Failed handle request via <function _async_render at 0x7f84b8855ed8>: <XForwardedForRequest at 0x7f84575264d0 method='GET' uri='/_matrix/client/r0/rooms/!XqBunHwQIXUiqCaoxq%3Amatrix.org/messages?from=s600799_25561883_851_986906_54160_68_13448_75210_14&limit=20&dir=b' clientproto='HTTP/1.1' site=8008>: Traceback (most recent call last):
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
--- <exception caught here> ---
  File "synapse/http/server.py", line 78, in wrapped_request_handler
    yield h(self, request)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "synapse/http/server.py", line 313, in _async_render
    callback_return = yield callback(request, **kwargs)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "synapse/rest/client/v1/room.py", line 450, in on_GET
    event_filter=event_filter,
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "synapse/handlers/pagination.py", line 221, in get_messages
    room_id, max_topo
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "synapse/handlers/federation.py", line 796, in maybe_backfill
    success = yield try_backfill(likely_domains)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "synapse/handlers/federation.py", line 760, in try_backfill
    extremities=extremities,
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "synapse/handlers/federation.py", line 518, in backfill
    extremities=extremities,
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "synapse/federation/federation_client.py", line 189, in backfill
    dest, context, extremities, limit)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "synapse/http/matrixfederationclient.py", line 486, in get_json
    ignore_backoff=ignore_backoff,
  File "/srv/synapse/env/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "synapse/http/matrixfederationclient.py", line 257, in _request
    response.code, response.phrase, body
synapse.api.errors.HttpResponseException: 403: Forbidden
2018-08-22 13:25:17,297 - synapse.access.http.8008 - 139 - INFO - GET-66416 - 212.204.110.133 - 8008 - {@me:myserver.net} Processed request: 9.264sec (1.064sec, 0.280sec) (0.257sec/1.272sec/90) 55B 500 "GET /_matrix/client/r0/rooms/!XqBunHwQIXUiqCaoxq%3Amatrix.org/messages?from=s600799_25561883_851_986906_54160_68_13448_75210_14&limit=20&dir=b HTTP/1.1" "<UserAgent>" [43 dbevts]

[richvdh]

As another datapoint: attempts to backfill !PcCidzjUKXHKImhTrB:matrix.org (#mozilla_#rust:matrix.org) on matrix.org are currently failing with a 500, because matrix.org has decided to try to backfill from vanpetegem.me, which is responding with {"errcode": "M_FORBIDDEN", "error": "Host not in room."}.

[tanriol]

I don't have a good understanding of backfill... is this a possible DoS vector by which a malicious server could effectively disable a public room and require admin intervention to fix?

[anoadragon453]

Since https://github.com/matrix-org/synapse/pull/7556, if you receive a 4XX from the remote server, the client will be passed the same status code (i.e. 403) - no longer always a 500.

https://github.com/matrix-org/synapse/blob/17d99f758a768b886842cf496ff236fbe3829236/synapse/handlers/federation.py#L366-L382