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

[anoadragon453]

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 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 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(!):

   synapse/synapse/federation/federation_client.py

   Lines 557 to 567 in 95a038c

   	res = None
   	try:
   	res = await self._check_sigs_and_hash(room_version, pdu)
   	except SynapseError:
   	pass
   	if not res:
   	# Check local db.
   	res = await self.store.get_event(
   	pdu.event_id, allow_rejected=True, allow_none=True
   	)

   (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 💥

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 <FrozenEventV3 event_id=$LQUaZrePI5jGOg4e6rmMidB4XRf1jnH-M9f7nIzblCM, type=m.room.member, state_key=@wesle_kori:matrix.flash-messenger.ml, outlier=False>
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 <FrozenEventV3 event_id=$7Qya4ytKy7jX0eyCJrXDrwPUXg5Xv7lrGFv-wah4Cko, type=m.room.member, state_key=@wesle_kori:matrix.flash-messenger.ml, outlier=False>
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 <FrozenEventV3 event_id=$RV-jx4JYX3NYbZIpuZvMRRJM2gk1Odbj8alhSr86T6A, type=m.room.member, state_key=@swor_blank:bmw12.nl, outlier=False>
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 <FrozenEventV3 event_id=$5j3tfwPZQwh4NEDM_udHzg9k5KwOZHn1KNvcTvaMAdU, type=m.room.member, state_key=@bartaleedis:bmw12.nl, outlier=False>
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 <FrozenEventV3 event_id=$0ltL9VxHXFv_5zxN-G1WEDdBZfqV5PE5aOBEn4Ktw2o, type=m.room.member, state_key=@orfieldharvie:bmw12.nl, outlier=False>
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 <FrozenEventV3 event_id=$So6n2se1cX5tb4fnTWWKpCjv5XL_qvA-rBlvIx0XpH0, type=m.room.member, state_key=@kristyn_youngran:bmw12.nl, outlier=False>
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 <FrozenEventV3 event_id=$EysLi3HhoGiuQ142A6VoD8Y7F8qv2okN9sW74lIXV3M, type=m.room.member, state_key=@<redacted>: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 <module>
    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=<nacl.signing.VerifyKey object at 0x7f5bf87a0e18>, 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<redacted>?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 - <XForwardedForRequest at 0x7f5b23368418 method='GET' uri='/_matrix/client/r0/rooms/!<redacted>/messages?limit=20&dir=b&from=t6489-2850476275_757284974_15537852_1328795633_1335340334_3199469_473258176_3478033587_212413&filter=%7B%22lazy_load_members%22%3Atrue%7D' clientproto='HTTP/1.1' site='11106'> 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 - {@<redacted>:matrix.org} Processed request: 105.632sec/0.123sec (0.527sec, 0.040sec) (0.789sec/0.458sec/29) 53B 403 "GET /_matrix/client/r0/rooms/!<redacted>/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 #3736, and is unrelated to this issue).

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

[andinue]

yes, my matrix.cpn.so is down, because key lose. now, i changed the key and domain of my server. i'm constantly getting error messages, but I couldn't server infomation

[anoadragon453]

@andinue If possible, could you remove the https://matrix.cpn.so/.well-known/matrix/server file (or stop it from pointing to espr.moe) as this confuses other homeservers due to espr.moe not using matrix.cpn.so as its server name?

[andinue]

@andinue If possible, could you remove the https://matrix.cpn.so/.well-known/matrix/server file (or stop it from pointing to espr.moe) as this confuses other homeservers due to espr.moe not using matrix.cpn.so as its server name?

now, removed

[anoadragon453]

@andinue Thank you. Note that it may take some time (on the order of hours) for remote servers to re-check your well-known details and flush it from their cache. If you still see errors after 48hrs, feel free to create a new issue, or ask in #synapse:matrix.org and we can try and track them down.

[anonfloppa]

I have the same issue on my server from many different other homeservers.

[richvdh]

Although the particular problem noted above concerns events from a specific homeserver (matrix.cpn.so), it is generally true for any event where the signature is invalidated (by replacing or expiring the key) once that event has been accepted as an outlier.