Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

AssertionError: No forward extremities left! #5090

Closed
richvdh opened this issue Apr 22, 2019 · 11 comments
Closed

AssertionError: No forward extremities left! #5090

richvdh opened this issue Apr 22, 2019 · 11 comments
Assignees
@richvdh
Labels
z-bug (Deprecated Label)

Comments

@richvdh
Copy link
Member

richvdh commented Apr 22, 2019 •
edited
Loading

This can't be good:

2019-04-22 01:18:17,013 - synapse.http.server - 112 - ERROR - POST-16014877 - Failed handle request via 'ReplicationFederationSendEventsRestServlet': <SynapseRequest at 0x7fc87ed2abe0 method='POST' uri='/_synapse/replication/fed_send_events/TloUSGYPDO' clientproto='HTTP/1.1' site=9092>
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/homeserver.py", line 661, in <module>
    main()
  File "/home/synapse/src/synapse/app/homeserver.py", line 657, in main
    run(hs)
  File "/home/synapse/src/synapse/app/homeserver.py", line 648, in run
    logger=logger,
  File "/home/synapse/src/synapse/app/_base.py", line 141, in start_reactor
    daemon.start()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/daemonize.py", line 248, in start
    self.action(*privileged_action_result)
  File "/home/synapse/src/synapse/app/_base.py", line 127, in run
    reactor.run()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 1272, in run
    self.mainLoop()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 1281, in mainLoop
    self.runUntilCurrent()
  File "/home/synapse/src/synapse/metrics/__init__.py", line 347, in f
    ret = func(*args, **kwargs)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/base.py", line 875, in runUntilCurrent
    f(*a, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1461, in _inlineCallbacks
    status.deferred.callback(e.value)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1461, in _inlineCallbacks
    status.deferred.callback(e.value)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1461, in _inlineCallbacks
    status.deferred.callback(e.value)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1461, in _inlineCallbacks
    status.deferred.callback(e.value)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 460, in callback
    self._startRunCallbacks(result)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1464, in _inlineCallbacks
    status.deferred.errback()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1464, in _inlineCallbacks
    status.deferred.errback()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1464, in _inlineCallbacks
    status.deferred.errback()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/synapse/src/synapse/storage/events.py", line 166, in handle_queue_loop
    item.deferred.errback()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/src/synapse/util/async_helpers.py", line 75, in errback
    self._observers.pop().errback(f)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1114, in _cbDeferred
    self.errback(failure.Failure(FirstError(result, index)))
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1464, in _inlineCallbacks
    status.deferred.errback()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1464, in _inlineCallbacks
    status.deferred.errback()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1464, in _inlineCallbacks
    status.deferred.errback()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/src/synapse/util/async_helpers.py", line 75, in errback
    self._observers.pop().errback(f)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1464, in _inlineCallbacks
    status.deferred.errback()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 501, in errback
    self._startRunCallbacks(fail)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
    self._runCallbacks()
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult
    _inlineCallbacks(r, g, status)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/synapse/src/synapse/http/server.py", line 112, in wrapped_request_handler
    exc_info=(f.type, f.value, f.getTracebackObject()),
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1412, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1519, in _log
    self.handle(record)
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1529, in handle
    self.callHandlers(record)
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1591, in callHandlers
    hdlr.handle(record)
  File "/usr/local/lib/python3.7/logging/__init__.py", line 905, in handle
    self.emit(record)
  File "/usr/local/lib/python3.7/logging/handlers.py", line 1234, in emit
    self.flush()
  File "/usr/local/lib/python3.7/logging/handlers.py", line 1310, in flush
    self.target.handle(record)
  File "/usr/local/lib/python3.7/logging/__init__.py", line 905, in handle
    self.emit(record)
  File "/usr/local/lib/python3.7/logging/handlers.py", line 70, in emit
    logging.FileHandler.emit(self, record)
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1132, in emit
    StreamHandler.emit(self, record)
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1034, in emit
    msg = self.format(record)
  File "/usr/local/lib/python3.7/logging/__init__.py", line 880, in format
    return fmt.format(record)
  File "/usr/local/lib/python3.7/logging/__init__.py", line 627, in format
    record.exc_text = self.formatException(record.exc_info)
  File "/home/synapse/src/synapse/util/logformatter.py", line 45, in formatException
    traceback.print_stack(tb.tb_frame.f_back, None, sio)
Traceback (most recent call last):
  File "/home/synapse/src/synapse/http/server.py", line 81, in wrapped_request_handler
    yield h(self, request)
  File "/home/synapse/src/synapse/http/server.py", line 316, in _async_render
    callback_return = yield callback(request, **kwargs)
  File "/home/synapse/src/synapse/replication/http/federation.py", line 117, in _handle_request
    event_and_contexts, backfilled,
  File "/home/synapse/src/synapse/handlers/federation.py", line 2662, in persist_events_and_notify
    backfilled=backfilled,
  File "/home/synapse/src/synapse/storage/events.py", line 287, in persist_events
    defer.gatherResults(deferreds, consumeErrors=True)
twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <class 'AssertionError'>: No forward extremities left!
/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py:654:_runCallbacks
/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py:1475:gotResult
/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
--- <exception caught here> ---
/home/synapse/src/synapse/storage/events.py:163:handle_queue_loop
/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/home/synapse/src/synapse/storage/events.py:324:persisting_queue
/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/synapse/env-py37/lib/python3.7/site-packages/twisted/python/failure.py:512:throwExceptionIntoGenerator
/home/synapse/src/synapse/storage/events.py:205:f
/home/synapse/env-py37/lib/python3.7/site-packages/twisted/internet/defer.py:1418:_inlineCallbacks
/home/synapse/src/synapse/storage/events.py:416:_persist_events
]]

(holy stacktrace, batman)

No clues as to which event/room is causing the problem
@richvdh
Copy link
Member Author

richvdh commented Apr 22, 2019

(this is happening fairly regularly in the matrix.org logs)

@turt2live
Copy link
Member

I'm also seeing this now, and it appears to be preventing federation with matrix.org

@neilisfragile neilisfragile added p1 z-bug (Deprecated Label) labels Apr 30, 2019
@neilisfragile
Copy link
Contributor

Quoting from a matrix conversation with @turt2live who has evidence that this bug is preventing larger home server instances federating with matrix.org.

The reason I think it's breaking federation between t2bot.io and those servers is tracing the requests over replication shows that the federation reader handling the inbound transaction is able to get a huge number of events (thousands), and then sends 256 over replication to the master process which then fails the whole request due to the error.
So my theory is that the line length limit of replication means that the master process isn't able to verify the auth chain because the homeserver is thousands of events behind, and isn't able to deduce the chain with the events it was given.

@turt2live
Copy link
Member

fwiw the trace is a bit smaller in my environment for some reason:

Master process:

homeserver_1 - 2019-05-02 20:16:39,199 - synapse.http.server - 112 - ERROR - POST-979005 - Failed handle request via 'ReplicationFederationSendEventsRestServlet': <SynapseRequest at 0x7f03c7d6ff28 method='POST' uri='/_synapse/replication/fed_send_events/GduMgKuTJv' clientproto='HTTP/1.1' site=9091>
Traceback (most recent call last):
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/http/server.py", line 81, in wrapped_request_handler
    yield h(self, request)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/http/server.py", line 316, in _async_render
    callback_return = yield callback(request, **kwargs)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/replication/http/federation.py", line 117, in _handle_request
    event_and_contexts, backfilled,
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/handlers/federation.py", line 2665, in persist_events_and_notify
    backfilled=backfilled,
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events.py", line 277, in persist_events
    defer.gatherResults(deferreds, consumeErrors=True)
twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <class 'AssertionError'>: No forward extremities left!
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py:654:_runCallbacks
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py:1475:gotResult
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py:491:throwExceptionIntoGenerator
--- <exception caught here> ---
/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events.py:157:handle_queue_loop
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py:491:throwExceptionIntoGenerator
/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events.py:316:persisting_queue
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py:491:throwExceptionIntoGenerator
/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events.py:198:f
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py:1418:_inlineCallbacks
/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events.py:409:_persist_events
]]

Lining it up by the txnId, here's the federation reader:

federation_reader_3 - 2019-05-02 20:16:39,203 - synapse.federation.federation_server - 245 - ERROR - PUT-6016-$[redacted]bxG:[redacted]- Failed to handle PDU $[redacted]bxG:[redacted]
Traceback (most recent call last):
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/replication/http/_base.py", line 162, in send_request
    result = yield request_func(uri, data)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
    result = g.send(result)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/http/client.py", line 390, in post_json_get_json
    raise HttpResponseException(response.code, response.phrase, body)
synapse.api.errors.HttpResponseException: 500: b'Internal Server Error'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/federation/federation_server.py", line 233, in process_pdus_for_room
    origin, pdu
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/federation/federation_server.py", line 688, in _handle_received_pdu
    origin, pdu, sent_to_us_directly=True,
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/handlers/federation.py", line 270, in on_receive_pdu
    room_id, event_id,
  File "/usr/lib/python3.5/contextlib.py", line 77, in __exit__
    self.gen.throw(type, value, traceback)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/util/async_helpers.py", line 216, in _ctx_manager
    yield
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/handlers/federation.py", line 260, in on_receive_pdu
    origin, pdu, prevs, min_depth
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/handlers/federation.py", line 530, in _get_missing_events_for_pdu
    sent_to_us_directly=False,
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/handlers/federation.py", line 420, in on_receive_pdu
    auth_chain=auth_chain,
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/handlers/federation.py", line 587, in _process_received_pdu
    yield self._handle_new_events(origin, event_infos)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/handlers/federation.py", line 1693, in _handle_new_events
    backfilled=backfilled,
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/handlers/federation.py", line 2660, in persist_events_and_notify
    backfilled=backfilled
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py", line 491, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/replication/http/_base.py", line 177, in send_request
    raise e.to_synapse_error()
synapse.api.errors.ProxiedRequestError: 500: Internal server error

This was the federation reader trying to persist 80 "newly-received auth/state events" by its own admission. Synapse appears to think it was missing 1 prev event and went out hunting for it non-recursively, and somehow that blew up into 80 requests for individual events - likely due to the call to get_missing_events which revealed more that were missing?

@turt2live
Copy link
Member

turt2live commented May 2, 2019 •
edited
Loading

the above is also a smaller instance of this happening. For a bit of context, a transaction containing just 4 PDUs is taking minutes, resulting in a POST to the master with 3788 events - this kinda tells me that it is probably not a line length problem and more something around the state resolution algorithm itself? Possibly the federation reader and master aren't doing the same thing or the reader isn't disclosing enough events to the master?

Edit: for my reference so I can find it in logs:

homeserver_1 - 2019-05-02 20:16:58,865 - synapse.access.http.9091 - 233 - INFO - POST-979112 - 127.0.0.1 - 9091 - Received request: POST /_synapse/replication/fed_send_events/OrkvtoqWGw
homeserver_1 - 2019-05-02 20:16:58,865 - synapse.util.caches.response_cache - 151 - INFO - POST-979112 - [repl.fed_send_events]: no cached result for [OrkvtoqWGw], calculating new one
homeserver_1 - 2019-05-02 20:16:59,031 - synapse.replication.http.federation - 113 - INFO - POST-979112 - Got 3788 events from federation

@turt2live
Copy link
Member

Skipping the federation reader and throwing transactions at the master process don't help reduce the errors, so the theory of the two processes doing resolution differently is probably wrong.

richvdh added a commit that referenced this issue May 6, 2019
@richvdh
Exclude soft-failed events from fwd-extremity candidates.
b6709b0 
When considering the candidates to be forward-extremities, we must exclude soft
failures.

Hopefully fixes #5090.
@richvdh richvdh mentioned this issue May 6, 2019
Merged
@richvdh
Copy link
Member Author

richvdh commented May 6, 2019

The problem seems to be to do with soft-failed events: in particular, when we end up with all of the forward-extremities in a room being soft-failed. #5146 is an (as yet totally untested) patch.

@turt2live
Copy link
Member

turt2live commented May 8, 2019 •
edited
Loading

for the historical record: I've deployed #5146 (t2bot@aa32643) to t2bot.io as of roughly 21:10 UTC today - will see how it goes/recovers (if at all).

@turt2live
Copy link
Member

Still getting this after a few days of catch up, however not as common. This appears to be preventing t2bot.io from catching up to matrix.org transactions.

homeserver_1 - 2019-05-11 16:37:57,890 - synapse.http.server - 112 - ERROR - POST-11985 - Failed handle request via 'ReplicationFederationSendEventsRestServlet': <SynapseRequest at 0x7fb708d12dd8 method='POST' uri='/_synapse/replication/fed_send_events/JjpnoGeBAd' clientproto='HTTP/1.1' site=9091>
Traceback (most recent call last):
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/http/server.py", line 81, in wrapped_request_handler
    yield h(self, request)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/http/server.py", line 316, in _async_render
    callback_return = yield callback(request, **kwargs)
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/replication/http/federation.py", line 117, in _handle_request
    event_and_contexts, backfilled,
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/handlers/federation.py", line 2665, in persist_events_and_notify
    backfilled=backfilled,
  File "/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events.py", line 277, in persist_events
    defer.gatherResults(deferreds, consumeErrors=True)
twisted.internet.defer.FirstError: FirstError[#0, [Failure instance: Traceback: <class 'AssertionError'>: No forward extremities left!
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py:654:_runCallbacks
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py:1475:gotResult
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py:491:throwExceptionIntoGenerator
--- <exception caught here> ---
/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events.py:157:handle_queue_loop
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py:491:throwExceptionIntoGenerator
/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events.py:316:persisting_queue
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py:1416:_inlineCallbacks
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/python/failure.py:491:throwExceptionIntoGenerator
/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events.py:198:f
/home/matrix/.synapse-py3/lib/python3.5/site-packages/twisted/internet/defer.py:1418:_inlineCallbacks
/home/matrix/.synapse-py3/lib/python3.5/site-packages/synapse/storage/events.py:409:_persist_events
]]

That translates to this transaction from matrix.org:

federation_reader_3 - 2019-05-11 16:37:56,998 - synapse.federation.transport.server - 367 - INFO - PUT-15285- Received txn 1557251314269 from matrix.org. (PDUs: 50, Accepted EDUs: 0, Ignored EDUs: 1)

Specifically a membership event of someone else on a different homeserver which got pulled in by state resolution.

@Half-Shot
Copy link
Collaborator

Joining the club of people having this issue, I don't believe I have any new information to add.

@richvdh richvdh self-assigned this May 16, 2019
@richvdh richvdh mentioned this issue May 21, 2019
Merged
richvdh added a commit that referenced this issue May 21, 2019
@richvdh
Exclude soft-failed events from fwd-extremity candidates. (#5146)
c4aef54 
When considering the candidates to be forward-extremities, we must exclude soft
failures.

Hopefully fixes #5090.
@richvdh
Copy link
Member Author

richvdh commented May 22, 2019

fixed by #5146, I hope

@richvdh richvdh closed this as completed May 22, 2019
@jomat jomat mentioned this issue Jan 14, 2020
Closed
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@richvdh richvdh

Labels
z-bug (Deprecated Label)
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@neilisfragile @turt2live @richvdh @Half-Shot