element-hq / element-hq/synapse

`/messages` pagination fails with `AssertionError: pulled event unexpectedly flagged as outlier` if an event has a broken signature

Open
#12,584 0 comments 0 reactions 0 assignees View on GitHub
A-Messages-Endpoint S-Major T-Defect
Dominant language
Python
Stars
4.6k
Forks
600
Avg merge
5d 22h
Merged PRs (30d)
51

Description

This issue has been migrated from [#12584](https://github.com/matrix-org/synapse/issues/12584).

---

Sentry link (internal access only): https://sentry.matrix.org/sentry/synapse-matrixorg/issues/248052

We are repeatedly returning 403's to [`GET /_matrix/client/r0/rooms/{roomId}/messages`](https://spec.matrix.org/v1.2/client-server-api/#get_matrixclientv3roomsroomidmessages) requests due to trying to backfill old events in the room, before then choking on an event with an invalid signature, which we already have in our database (as an outlier).

What happens:

1. A client hit `GET /_matrix/client/r0/rooms/{roomId}/messages` for a room ID beginning with `!lPCpzTqvU...` (room version 6).
2. matrix.org tried to gather events to service the request, and in doing so needed to `/backfill` from another homeserver in the room.
3. The `/backfill` response included event ID `$EysLi3HhoGiuQ142A6VoD8Y7F8qv2okN9sW74lIXV3M`, which was created by someone on `matrix.cpn.so`. It is a `m.room.member` event for a (non-3pid) invite from one user on `matrix.cpn.so` to another.

This event is signed with `matrix.cpn.so`'s key `ed25519:a_sWZq`. We have a copy of this key in our database, but it has a `ts_valid_until_ms` of 500000 (Thu Jan 1 01:08:20 1970), so we attempt to fetch a fresher copy of the key.
4. matrix.org attempts to reach out to `matrix.cpn.so` to download its server keys, but fails with `ServerKeyFetcher-2245 - Error looking up keys ['ed25519:a_sWZq'] from matrix.cpn.so: Expected a response for server 'matrix.cpn.so' not 'espr.moe'`. [matrix.cpn.so's server well-known](https://matrix.cpn.so/.well-known/matrix/server) points to `espr.moe:443`, but querying https://espr.moe/_matrix/key/v2/server/ed25519:a_sWZq returns `"server_name":"espr.moe"`(!).
5. Since we can't find a copy of the signing key that was valid at the time the event was created, validation fails.
6. We then attempt to pull an event with the same event ID from the database(!):

https://github.com/matrix-org/synapse/blob/95a038c1069de6c0507eb2c2d9a783c5033a70ec/synapse/federation/federation_client.py#L557-L567

(We're hitting the `except SynapseError: pass` bit.)

Now, this event is marked as an outlier in matrix.org's database. Thus, the event gets the `outlier=True` bit of internal metadata.
7. The outlier event is passed to `FederationEventHandler._process_pulled_events` and `FederationEventHandler._process_pulled_event`. We then run into the assertion :boom:

So the problem in short:

* When we first received this event (Fri Apr 1 11:06:36 2022, ftr), its signature was valid, and we accepted it as an outlier.
* The key has since become invalid (it has been republished with a broken expiry time).
* Now `matrix.cpn.so`'s federation is broken (it points to a homeserver with different keys), so attempting to validate the event while backfilling it fails.
* The event *should* just be dropped from backfill, but because we find the same event in our database (an outlier), we try using that copy of the event instead.
* This causes us to hit an assertion (backfilled events cannot be outliers!), and the whole `/messages` call fails.

full stacktrace and logs

```
2022-04-28 16:52:16,866 - synapse.http.matrixfederationclient - 294 - INFO - ServerKeyFetcher-2245 - {GET-O-262726} [matrix.cpn.so] Completed request: 200 OK in 0.63 secs, got 299 bytes - GET matrix://matrix.cpn.so/_matrix/key/v2/server/ed25519%3Aa_sWZq
2022-04-28 16:52:16,866 - synapse.crypto.keyring - 826 - WARNING - ServerKeyFetcher-2245 - Error looking up keys ['ed25519:a_sWZq'] from matrix.cpn.so: Expected a response for server 'matrix.cpn.so' not 'espr.moe'
2022-04-28 16:52:16,867 - synapse.federation.federation_base - 73 - WARNING - GET-2657888 - Signature check failed for $EysLi3HhoGiuQ142A6VoD8Y7F8qv2okN9sW74lIXV3M: 403: event id $EysLi3HhoGiuQ142A6VoD8Y7F8qv2okN9sW74lIXV3M: unable to verify signature for sender matrix.cpn.so: 401: Failed to find any key to satisfy: _FetchKeyRequest(server_name='matrix.cpn.so', minimum_valid_until_ts=1648802567492, key_ids=['ed25519:a_sWZq'])
...2022-04-28 16:52:16,887 - synapse.handlers.federation_event - 740 - INFO - GET-2657888-$FDePrl4Q0jEun6IhKGJiiGvkSOdQXeDiEdnfdfo8kts - Ignoring received event $FDePrl4Q0jEun6IhKGJiiGvkSOdQXeDiEdnfdfo8kts which we have already seen
2022-04-28 16:52:16,887 - synapse.handlers.federation_event - 724 - INFO - GET-2657888-$LQUaZrePI5jGOg4e6rmMidB4XRf1jnH-M9f7nIzblCM - Processing pulled event
2022-04-28 16:52:16,887 - synapse.handlers.federation_event - 740 - INFO - GET-2657888-$LQUaZrePI5jGOg4e6rmMidB4XRf1jnH-M9f7nIzblCM - Ignoring received event $LQUaZrePI5jGOg4e6rmMidB4XRf1jnH-M9f7nIzblCM which we have already seen
2022-04-28 16:52:16,887 - synapse.handlers.federation_event - 724 - INFO - GET-2657888-$7Qya4ytKy7jX0eyCJrXDrwPUXg5Xv7lrGFv-wah4Cko - Processing pulled event
2022-04-28 16:52:16,887 - synapse.handlers.federation_event - 740 - INFO - GET-2657888-$7Qya4ytKy7jX0eyCJrXDrwPUXg5Xv7lrGFv-wah4Cko - Ignoring received event $7Qya4ytKy7jX0eyCJrXDrwPUXg5Xv7lrGFv-wah4Cko which we have already seen
2022-04-28 16:52:16,887 - synapse.handlers.federation_event - 724 - INFO - GET-2657888-$RV-jx4JYX3NYbZIpuZvMRRJM2gk1Odbj8alhSr86T6A - Processing pulled event
2022-04-28 16:52:16,887 - synapse.handlers.federation_event - 740 - INFO - GET-2657888-$RV-jx4JYX3NYbZIpuZvMRRJM2gk1Odbj8alhSr86T6A - Ignoring received event $RV-jx4JYX3NYbZIpuZvMRRJM2gk1Odbj8alhSr86T6A which we have already seen
2022-04-28 16:52:16,888 - synapse.handlers.federation_event - 724 - INFO - GET-2657888-$5j3tfwPZQwh4NEDM_udHzg9k5KwOZHn1KNvcTvaMAdU - Processing pulled event
2022-04-28 16:52:16,888 - synapse.handlers.federation_event - 740 - INFO - GET-2657888-$5j3tfwPZQwh4NEDM_udHzg9k5KwOZHn1KNvcTvaMAdU - Ignoring received event $5j3tfwPZQwh4NEDM_udHzg9k5KwOZHn1KNvcTvaMAdU which we have already seen
2022-04-28 16:52:16,888 - synapse.handlers.federation_event - 724 - INFO - GET-2657888-$0ltL9VxHXFv_5zxN-G1WEDdBZfqV5PE5aOBEn4Ktw2o - Processing pulled event
2022-04-28 16:52:16,888 - synapse.handlers.federation_event - 740 - INFO - GET-2657888-$0ltL9VxHXFv_5zxN-G1WEDdBZfqV5PE5aOBEn4Ktw2o - Ignoring received event $0ltL9VxHXFv_5zxN-G1WEDdBZfqV5PE5aOBEn4Ktw2o which we have already seen
2022-04-28 16:52:16,888 - synapse.handlers.federation_event - 724 - INFO - GET-2657888-$So6n2se1cX5tb4fnTWWKpCjv5XL_qvA-rBlvIx0XpH0 - Processing pulled event
2022-04-28 16:52:16,888 - synapse.handlers.federation_event - 740 - INFO - GET-2657888-$So6n2se1cX5tb4fnTWWKpCjv5XL_qvA-rBlvIx0XpH0 - Ignoring received event $So6n2se1cX5tb4fnTWWKpCjv5XL_qvA-rBlvIx0XpH0 which we have already seen
...
2022-04-28 16:52:16,899 - synapse.handlers.federation_event - 724 - INFO - GET-2657888-$EysLi3HhoGiuQ142A6VoD8Y7F8qv2okN9sW74lIXV3M - Processing pulled event :matrix.cpn.so, outlier=True>
2022-04-28 16:52:16,899 - synapse.handlers.federation - 399 - ERROR - GET-2657888 - Failed to backfill from half-shot.uk because pulled event unexpectedly flagged as outlier
Capture point (most recent call last):
File "/usr/local/lib/python3.7/runpy.py", line 193, in _run_module_as_main
"__main__", mod_spec)
File "/usr/local/lib/python3.7/runpy.py", line 85, in _run_code
exec(code, run_globals)
File "/home/synapse/src/synapse/app/generic_worker.py", line 514, in
main()
File "/home/synapse/src/synapse/app/generic_worker.py", line 510, in main
start(sys.argv[1:])
File "/home/synapse/src/synapse/app/generic_worker.py", line 505, in start
_base.start_worker_reactor("synapse-generic-worker", config)
File "/home/synapse/src/synapse/app/_base.py", line 125, in start_worker_reactor
run_command=run_command,
File "/home/synapse/src/synapse/app/_base.py", line 180, in start_reactor
run()
File "/home/synapse/src/synapse/app/_base.py", line 162, in run
run_command()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 1315, in run
self.mainLoop()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 1328, in mainLoop
reactorBaseSelf.doIteration(t)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/epollreactor.py", line 244, in doPoll
log.callWithLogger(selectable, _drdw, selectable, fd, event)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/log.py", line 96, in callWithLogger
return callWithContext({"system": lp}, func, *args, **kw)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/log.py", line 80, in callWithContext
return context.call({ILogContext: newCtx}, func, *args, **kw)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/context.py", line 117, in callWithContext
return self.currentContext().callWithContext(ctx, func, *args, **kw)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/context.py", line 82, in callWithContext
return func(*args, **kw)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/posixbase.py", line 683, in _doReadOrWrite
why = selectable.doRead()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/tcp.py", line 248, in doRead
return self._dataReceived(data)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/tcp.py", line 253, in _dataReceived
rval = self.protocol.dataReceived(data)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/endpoints.py", line 147, in dataReceived
return self._wrappedProtocol.dataReceived(data)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/protocols/tls.py", line 330, in dataReceived
self._flushReceiveBIO()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/protocols/tls.py", line 296, in _flushReceiveBIO
ProtocolWrapper.dataReceived(self, bytes)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/protocols/policies.py", line 110, in dataReceived
self.wrappedProtocol.dataReceived(data)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/web/_newclient.py", line 1651, in dataReceived
self._parser.dataReceived(bytes)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/web/_newclient.py", line 384, in dataReceived
HTTPParser.dataReceived(self, data)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/protocols/basic.py", line 555, in dataReceived
why = self.rawDataReceived(data)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/web/_newclient.py", line 302, in rawDataReceived
self.bodyDecoder.dataReceived(data)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/web/http.py", line 1984, in dataReceived
goOn = getattr(self, "_dataReceived_" + self.state)()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/web/http.py", line 1943, in _dataReceived_TRAILER
self.finishCallback(data)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/web/_newclient.py", line 445, in _finished
self.finisher(rest)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/web/_newclient.py", line 1043, in dispatcher
return func(*args, **kwargs)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/web/_newclient.py", line 1609, in _finishResponse_WAITING
self._disconnectParser(reason)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/web/_newclient.py", line 1633, in _disconnectParser
parser.connectionLost(reason)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/web/_newclient.py", line 555, in connectionLost
self.response._bodyDataFinished()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/web/_newclient.py", line 1043, in dispatcher
return func(*args, **kwargs)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/web/_newclient.py", line 1283, in _bodyDataFinished_CONNECTED
self._bodyProtocol.connectionLost(reason)
File "/home/synapse/src/synapse/http/client.py", line 871, in connectionLost
self.deferred.callback(self.length)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 661, in callback
self._startRunCallbacks(result)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 763, in _startRunCallbacks
self._runCallbacks()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 858, in _runCallbacks
current.result, *args, **kwargs
File "/home/synapse/src/synapse/util/async_helpers.py", line 648, in success_cb
new_d.callback(val)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 661, in callback
self._startRunCallbacks(result)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 763, in _startRunCallbacks
self._runCallbacks()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 858, in _runCallbacks
current.result, *args, **kwargs
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1750, in gotResult
current_context.run(_inlineCallbacks, r, gen, status)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1663, in _inlineCallbacks
status.deferred.callback(getattr(e, "value", None))
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 661, in callback
self._startRunCallbacks(result)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 763, in _startRunCallbacks
self._runCallbacks()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 858, in _runCallbacks
current.result, *args, **kwargs
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1337, in _cbDeferred
self.callback(cast(_DeferredListResultListT, self.resultList))
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 661, in callback
self._startRunCallbacks(result)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 763, in _startRunCallbacks
self._runCallbacks()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 858, in _runCallbacks
current.result, *args, **kwargs
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1750, in gotResult
current_context.run(_inlineCallbacks, r, gen, status)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
result = current_context.run(gen.send, result)
File "/home/synapse/src/synapse/metrics/background_process_metrics.py", line 243, in run
return await func(*args, **kwargs)
File "/home/synapse/src/synapse/util/batching_queue.py", line 166, in _process_queue
deferred.callback(results)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 661, in callback
self._startRunCallbacks(result)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 763, in _startRunCallbacks
self._runCallbacks()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 858, in _runCallbacks
current.result, *args, **kwargs
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1750, in gotResult
current_context.run(_inlineCallbacks, r, gen, status)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1663, in _inlineCallbacks
status.deferred.callback(getattr(e, "value", None))
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 661, in callback
self._startRunCallbacks(result)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 763, in _startRunCallbacks
self._runCallbacks()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 858, in _runCallbacks
current.result, *args, **kwargs
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1337, in _cbDeferred
self.callback(cast(_DeferredListResultListT, self.resultList))
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 661, in callback
self._startRunCallbacks(result)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 763, in _startRunCallbacks
self._runCallbacks()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 858, in _runCallbacks
current.result, *args, **kwargs
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1750, in gotResult
current_context.run(_inlineCallbacks, r, gen, status)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
result = current_context.run(gen.send, result)
File "/home/synapse/src/synapse/metrics/background_process_metrics.py", line 243, in run
return await func(*args, **kwargs)
File "/home/synapse/src/synapse/util/batching_queue.py", line 166, in _process_queue
deferred.callback(results)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 661, in callback
self._startRunCallbacks(result)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 763, in _startRunCallbacks
self._runCallbacks()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 858, in _runCallbacks
current.result, *args, **kwargs
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1750, in gotResult
current_context.run(_inlineCallbacks, r, gen, status)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1663, in _inlineCallbacks
status.deferred.callback(getattr(e, "value", None))
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 661, in callback
self._startRunCallbacks(result)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 763, in _startRunCallbacks
self._runCallbacks()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 858, in _runCallbacks
current.result, *args, **kwargs
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1337, in _cbDeferred
self.callback(cast(_DeferredListResultListT, self.resultList))
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 661, in callback
self._startRunCallbacks(result)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 763, in _startRunCallbacks
self._runCallbacks()
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 858, in _runCallbacks
current.result, *args, **kwargs
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1750, in gotResult
current_context.run(_inlineCallbacks, r, gen, status)
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
result = current_context.run(gen.send, result)
File "/home/synapse/src/synapse/http/server.py", line 195, in wrapped_async_request_handler
await h(self, request)
File "/home/synapse/src/synapse/http/server.py", line 268, in _async_render_wrapper
callback_return = await self._async_render(request)
File "/home/synapse/src/synapse/http/server.py", line 470, in _async_render
callback_return = await raw_callback_return
File "/home/synapse/src/synapse/rest/client/room.py", line 590, in on_GET
File "/home/synapse/src/synapse/handlers/pagination.py", line 500, in get_messages
limit=pagin_config.limit,
File "/home/synapse/src/synapse/handlers/federation.py", line 177, in maybe_backfill
return await self._maybe_backfill_inner(room_id, current_depth, limit)
File "/home/synapse/src/synapse/handlers/federation.py", line 404, in _maybe_backfill_inner
success = await try_backfill(likely_domains)
Traceback (most recent call last):
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
result = current_context.run(gen.send, result)
StopIteration

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
result = current_context.run(gen.send, result)
StopIteration: {'ed25519:a_sWZq': FetchKeyResult(verify_key=, valid_until_ts=500000)}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks
result = current_context.run(gen.send, result)
StopIteration

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/home/synapse/src/synapse/handlers/federation.py", line 368, in try_backfill
dom, room_id, limit=100, extremities=extremities_to_request
File "/home/synapse/src/synapse/handlers/federation_event.py", line 561, in backfill
backfilled=True,
File "/home/synapse/src/synapse/handlers/federation_event.py", line 700, in _process_pulled_events
await self._process_pulled_event(origin, ev, backfilled=backfilled)
File "/home/synapse/src/synapse/handlers/federation_event.py", line 729, in _process_pulled_event
), "pulled event unexpectedly flagged as outlier"
AssertionError: pulled event unexpectedly flagged as outlier
...
2022-04-28 16:52:18,110 - synapse.http.matrixfederationclient - 679 - WARNING - GET-2657888- - {GET-O-262727} [federator.dev] Request failed: GET matrix://federator.dev/_matrix/federation/v1/backfill/%21?v=%24ydwxtRhz3KaNX6tgpfnkQ_eB1Blllr-90puB3VytC6o&v=%24EysLi3HhoGiuQ142A6VoD8Y7F8qv2okN9sW74lIXV3M&v=%24BagjXULXHrFEHIVDBp_6Ho0vj_QRzJG2v_BAXTx8R-o&v=%24WaQdWFlVcLC_899-lZe_kzGG1WE-maZG2QSw02x1Pfs&v=%24dr55k1cwQyvxjAm3FADZg4OcWgmSLegsd2-c6awFnY0&limit=100: HttpResponseException('403: Forbidden')
2022-04-28 16:52:18,111 - synapse.http.server - 95 - INFO - GET-2657888 - SynapseError: 403 - Host not in room.
2022-04-28 16:52:18,235 - synapse.access.http.11106 - 448 - INFO - GET-2657888 - 2a01:4f8:c17:7230::1 - 11106 - {@:matrix.org} Processed request: 105.632sec/0.123sec (0.527sec, 0.040sec) (0.789sec/0.458sec/29) 53B 403 "GET /_matrix/client/r0/rooms/!/messages?limit=20&dir=b&from=t6489-2850476275_757284974_15537852_1328795633_1335340334_3199469_473258176_3478033587_212413&filter=%7B%22lazy_load_members%22%3Atrue%7D HTTP/1.1" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:99.0) Gecko/20100101 Firefox/99.0" [0 dbevts]
```

(Note that the `Host not in room.` error in the logs is due to https://github.com/matrix-org/synapse/issues/3736, and is unrelated to this issue).

This one outlier event is causing many of these stacktraces to pop up every few seconds.

Contributor guide

Open the contributing guide

Research direction

Start with synapse/federation/federation_client.py around the linked lines 557-567, then trace FederationEventHandler._process_pulled_events and _process_pulled_event from the stack trace. Reproduce the GET /_matrix/client/r0/rooms/{roomId}/messages backfill path with an invalid-signature event already stored as an outlier. Done means the event is dropped without triggering the assertion or failing the /messages request.

Written by the indexing model from the issue text.

Assessment

Tech stack
python
Domain
backend, networking
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.