'NoneType' object has no attribute start|stop exceptions from logging context code

[turt2live]

2020-03-30 22:03:18,603 - twisted - 192 - CRITICAL -  - Unhandled Error
Traceback (most recent call last):
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/app/_base.py", line 114, in run
    run_command()
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/base.py", line 1283, in run
    self.mainLoop()
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/base.py", line 1295, in mainLoop
    self.doIteration(t)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/epollreactor.py", line 235, in doPoll
    log.callWithLogger(selectable, _drdw, selectable, fd, event)
--- <exception caught here> ---
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/python/log.py", line 103, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/python/log.py", line 86, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/python/context.py", line 122, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/python/context.py", line 85, in callWithContext
    return func(*args,**kw)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/posixbase.py", line 627, in _doReadOrWrite
    self._disconnectSelectable(selectable, why, inRead)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/posixbase.py", line 255, in _disconnectSelectable
    selectable.connectionLost(f)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/tcp.py", line 327, in connectionLost
    protocol.connectionLost(reason)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/web/http.py", line 2433, in connectionLost
    request.connectionLost(reason)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/http/site.py", line 201, in connectionLost
    with PreserveLoggingContext(self.logcontext):
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/logging/context.py", line 506, in __enter__
    self.current_context = set_current_context(self.new_context)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/logging/context.py", line 547, in set_current_context
    context.start()
builtins.AttributeError: 'NoneType' object has no attribute 'start'

2020-03-30 22:03:19,662 - synapse.util - 123 - ERROR -  - Looping call died
Traceback (most recent call last):
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 151, in maybeDeferred
    result = f(*args, **kw)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/metrics/background_process_metrics.py", line 236, in wrap_as_background_process_inner_2
    return run_as_background_process(desc, func, *args, **kwargs)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/metrics/background_process_metrics.py", line 222, in run_as_background_process
    with PreserveLoggingContext():
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/logging/context.py", line 506, in __enter__
    self.current_context = set_current_context(self.new_context)
  File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/logging/context.py", line 545, in set_current_context
    current.stop()
AttributeError: 'NoneType' object has no attribute 'stop'

The setup here is a Synapse with a single worker (federation sender). The federation sender appears to be fine, though I can't confirm because the master keeps throwing back 500 errors. The stacktrace above is all that was found after seemingly normal traffic (a single client syncing, doing nothing else).

Prior to upgrading, the following was run (with results which get the following output):

(.synapse) matrix@matrix:~/.synapse$ pip install 'Twisted>=20.3.0'
Requirement already satisfied: Twisted>=20.3.0 in ./lib/python3.6/site-packages (20.3.0)
Requirement already satisfied: hyperlink>=17.1.1 in ./lib/python3.6/site-packages (from Twisted>=20.3.0) (18.0.0)
Requirement already satisfied: constantly>=15.1 in ./lib/python3.6/site-packages (from Twisted>=20.3.0) (15.1.0)
Requirement already satisfied: Automat>=0.3.0 in ./lib/python3.6/site-packages (from Twisted>=20.3.0) (0.7.0)
Requirement already satisfied: incremental>=16.10.1 in ./lib/python3.6/site-packages (from Twisted>=20.3.0) (17.5.0)
Requirement already satisfied: PyHamcrest!=1.10.0,>=1.9.0 in ./lib/python3.6/site-packages (from Twisted>=20.3.0) (1.9.0)
Requirement already satisfied: zope.interface>=4.4.2 in ./lib/python3.6/site-packages (from Twisted>=20.3.0) (4.6.0)
Requirement already satisfied: attrs>=19.2.0 in ./lib/python3.6/site-packages (from Twisted>=20.3.0) (19.3.0)
Requirement already satisfied: idna>=2.5 in ./lib/python3.6/site-packages (from hyperlink>=17.1.1->Twisted>=20.3.0) (2.9)
Requirement already satisfied: six in ./lib/python3.6/site-packages (from Automat>=0.3.0->Twisted>=20.3.0) (1.14.0)
Requirement already satisfied: setuptools in ./lib/python3.6/site-packages (from PyHamcrest!=1.10.0,>=1.9.0->Twisted>=20.3.0) (40.8.0)

Unsure if this happens on master/release.

[richvdh]

Right, I think this is introduced by #7120, and I don't think it's related to twisted 20.3.0

[anoadragon453]

Fixed by #7181