Synapse: Synapse stops responding after Twisted 20.3.0 upgrade

[AluisioASG]

Description

After upgrading a FreeBSD server to Synapse 1.12.4 and Twisted 20.3.0, the status page endpoint (/_matrix/static/) stops responding and Riot thinks it's offline a few minutes after the server starts. Rolling Twisted back to 18.9.0 and restarting Synapse makes it work again.

I've traced the error to the following call; reason sometimes lacks the type attribute and causes a critical, unhandled error. Removing the reference to reason.type fixed it for me, even after re-upgrading Twisted to 20.3.0.

https://github.com/matrix-org/synapse/blob/ce9b62e13f7d653e5099ae4a159c0e5cde419cf8/synapse/http/site.py#L202-L204

Oddly enough, errors logged after fixing that line do seem to have a type; I'm guessing it may be masquerading an incompatibility somewhere else.

Steps to reproduce

• Upgrade Twisted to 20.3.0
• Start the server
• Wait a few minutes; it will stop responding to (some) requests

Stack trace

The TWISTED DEBUG lines output type(reason), repr(reason) and dir(reason), and are printed just before the previous snippet.

2020-05-06 13:39:51,471 - synapse.http.site - 202 - WARNING - GET-208- TWISTED DEBUG(type = <class 'twisted.internet.error.ConnectionLost'>, repr = ConnectionLost('Stream reset with code ErrorCodes.CANCEL',), dir = ['__cause__', '__class__', '__context__', '__delattr__', '__dict__', '__dir__', '__doc__', '__eq__', '__format__', '__ge__', '__getattribute__', '__gt__', '__hash__', '__init__', '__init_subclass__', '__le__', '__lt__', '__module__', '__ne__', '__new__', '__reduce__', '__reduce_ex__', '__repr__', '__setattr__', '__setstate__', '__sizeof__', '__str__', '__subclasshook__', '__suppress_context__', '__traceback__', '__weakref__', 'args', 'with_traceback'])
2020-05-06 13:39:51,479 - twisted - 192 - CRITICAL - - Unhandled Error
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/twisted/python/log.py", line 103, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/usr/local/lib/python3.6/site-packages/twisted/python/log.py", line 86, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/usr/local/lib/python3.6/site-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/local/lib/python3.6/site-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/posixbase.py", line 614, in _doReadOrWrite
    why = selectable.doRead()
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/tcp.py", line 243, in doRead
    return self._dataReceived(data)
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/tcp.py", line 249, in _dataReceived
    rval = self.protocol.dataReceived(data)
  File "/usr/local/lib/python3.6/site-packages/twisted/protocols/tls.py", line 330, in dataReceived
    self._flushReceiveBIO()
  File "/usr/local/lib/python3.6/site-packages/twisted/protocols/tls.py", line 295, in _flushReceiveBIO
    ProtocolWrapper.dataReceived(self, bytes)
  File "/usr/local/lib/python3.6/site-packages/twisted/protocols/policies.py", line 120, in dataReceived
    self.wrappedProtocol.dataReceived(data)
  File "/usr/local/lib/python3.6/site-packages/twisted/web/http.py", line 3024, in dataReceived
    return self._channel.dataReceived(data)
  File "/usr/local/lib/python3.6/site-packages/twisted/web/_http2.py", line 196, in dataReceived
    self._requestAborted(event)
  File "/usr/local/lib/python3.6/site-packages/twisted/web/_http2.py", line 528, in _requestAborted
    ConnectionLost("Stream reset with code %s" % event.error_code)
  File "/usr/local/lib/python3.6/site-packages/twisted/web/_http2.py", line 1077, in connectionLost
    self._request.connectionLost(reason)
  File "/usr/local/lib/python3.6/site-packages/synapse/http/site.py", line 204, in connectionLost
    "Error processing request %r: %s %s", self, reason.type, reason.value
builtins.AttributeError: 'ConnectionLost' object has no attribute 'type'

2020-05-06 13:39:51,480 - synapse.http.site - 202 - WARNING - GET-140- TWISTED DEBUG(type = <class 'twisted.internet.error.ConnectionLost'>, repr = ConnectionLost('Producing stopped',), dir = ['__cause__', '__class__', '__context__', '__delattr__', '__dict__', '__dir__', '__doc__', '__eq__', '__format__', '__ge__', '__getattribute__', '__gt__', '__hash__', '__init__', '__init_subclass__', '__le__', '__lt__', '__module__', '__ne__', '__new__', '__reduce__', '__reduce_ex__', '__repr__', '__setattr__', '__setstate__', '__sizeof__', '__str__', '__subclasshook__', '__suppress_context__', '__traceback__', '__weakref__', 'args', 'with_traceback'])
2020-05-06 13:39:51,484 - twisted - 192 - CRITICAL - - Unhandled Error
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/synapse/app/_base.py", line 114, in run
    run_command()
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/base.py", line 1283, in run
    self.mainLoop()
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/base.py", line 1295, in mainLoop
    self.doIteration(t)
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/pollreactor.py", line 169, in doPoll
    log.callWithLogger(selectable, _drdw, selectable, fd, event)
--- <exception caught here> ---
  File "/usr/local/lib/python3.6/site-packages/twisted/python/log.py", line 103, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/usr/local/lib/python3.6/site-packages/twisted/python/log.py", line 86, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/usr/local/lib/python3.6/site-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/local/lib/python3.6/site-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/posixbase.py", line 627, in _doReadOrWrite
    self._disconnectSelectable(selectable, why, inRead)
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/posixbase.py", line 258, in _disconnectSelectable
    selectable.connectionLost(failure.Failure(why))
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/tcp.py", line 321, in connectionLost
    abstract.FileDescriptor.connectionLost(self, reason)
  File "/usr/local/lib/python3.6/site-packages/twisted/internet/abstract.py", line 205, in connectionLost
    self.producer.stopProducing()
  File "/usr/local/lib/python3.6/site-packages/twisted/protocols/tls.py", line 111, in stopProducing
    self._producer.stopProducing()
  File "/usr/local/lib/python3.6/site-packages/twisted/web/_http2.py", line 353, in stopProducing
    self.connectionLost(ConnectionLost("Producing stopped"))
  File "/usr/local/lib/python3.6/site-packages/twisted/web/_http2.py", line 290, in connectionLost
    stream.connectionLost(reason)
  File "/usr/local/lib/python3.6/site-packages/twisted/web/_http2.py", line 1077, in connectionLost
    self._request.connectionLost(reason)
  File "/usr/local/lib/python3.6/site-packages/synapse/http/site.py", line 204, in connectionLost
    "Error processing request %r: %s %s", self, reason.type, reason.value
builtins.AttributeError: 'ConnectionLost' object has no attribute 'type'

Version information

• Homeserver: matrix.aasg.name

• Version: 1.12.4

• Install method: FreeBSD ports

• Platform: FreeBSD 11.3 jail, with Python 3.6.9

[nakal]

I'd like to confirm problems with Twisted 20.3.0 on FreeBSD. I downgraded to the previous version and it works again. Thanks for the hint @AluisioASG.

[richvdh]

hrm. It looks like this is a bug in twisted's http2 code: it should not be calling connectionLost with ConnectionLost, but rather wrapping it in a Failure.

It's easy enough to work around I suppose.

Honestly we don't really test http2, so I'm not surprised you find bugs there!

[clokep]

Filed an upstream issue about this: https://twistedmatrix.com/trac/ticket/9817 (and a fix at twisted/twisted#1265).

[richvdh]

I can't quite figure out why this would be new in twisted 20.3.0. it looks like the codepath in question hasn't changed in a few years?

[anoadragon453]

A workaround in Synapse for this upstream bug has been merged in https://github.com/matrix-org/synapse/pull/7473. It will be included in Synapse v1.14.0.

[clokep]

FYI The upstream fix went in too, I think we'll need to leave the workaround until we bump the Twisted version.