Outgoing HTTP request bodies stop being sent after a logcontext leak (wedged Cooperator)

[PietG1]

hit this in production: after a while, all push notifications from a busy homeserver started failing with

twisted.web._newclient.RequestGenerationFailed: [CancelledError()]

A packet capture showed the POSTs going out with headers and a correct Content-Length, but no body, and then getting cancelled by the request timeout ~60s later. It never recovered on its own — only a restart fixed it.

The cause is an interaction between the body-streaming Cooperator and Clock.call_later.

Outgoing request bodies are streamed by a FileBodyProducer driven by a Cooperator, and that cooperator's scheduler goes through Clock.call_later (_make_scheduler in synapse/http/client.py, used by both SimpleHttpClient and MatrixFederationHttpClient). Clock.call_later wraps the callback and asserts the reactor handed it the sentinel logcontext — but it does that before running the callback:

assert context.current_context() is context.SENTINEL_CONTEXT, (...)   # runs first
...
context.run_in_background(callback, ...)                              # the real tick

That assertion is a tripwire for logcontext leaks. The problem is what happens when it actually fires. A Twisted Cooperator only schedules its next tick from inside the current tick:

def _tick(self):
    self._delayedCall = None     # cleared at the top
    ...
    self._reschedule()           # arms the next tick

def _reschedule(self):
    if self._delayedCall is None and self._tasks:
        self._delayedCall = self._scheduler(self._tick)

So if the assertion raises before _tick runs, _delayedCall is never cleared and _reschedule is never called. The guard if self._delayedCall is None is now permanently false, and the cooperator never schedules another tick again. It's wedged for the life of the process.

The trigger is any logcontext leak somewhere else in the process — i.e. some code returning to the reactor without restoring the sentinel context. That's exactly what the assertion is meant to catch. The trouble is it's fail-closed: instead of just reporting the leak, it raises and drops the scheduled callback. For most call_later callbacks that means one missed timer; for the cooperator it means the whole thing stops, permanently.

And because the HTTP client (and its cooperator) is a @cache_in_self singleton, one wedge takes out every body-producing request through that client — all pushes, or all outbound federation transactions, depending on which client is producing a body when the leak lands on its tick. Bodyless GETs keep working, which makes it look selective. On a busy server it never self-heals, because the one recovery path (_removeTask clearing _delayedCall when the task queue empties) only triggers when there's nothing left to send.

This used to be harmless. Before #18828 the cooperator scheduled on a bare reactor.callLater, which always runs the callback. #18828 switched it to Clock.call_later, which turned a previously-benign logcontext leak into a fatal, unrecoverable wedge.

Reproducing

The wedge needs a leak to land on a cooperator tick, which is timing-dependent. To show the mechanism deterministically, make one tick raise before running, e.g. in _make_scheduler:

def _scheduler(x):
    def maybe_skip():
        if os.path.exists("/tmp/skip_one_tick"):   # one-shot
            os.remove("/tmp/skip_one_tick")
            raise AssertionError("simulated skipped tick")
        return x()
    return clock.call_later(_EPSILON, maybe_skip)

On an idle worker: touch /tmp/skip_one_tick, send one push, watch it hang and fail after 60s — then watch every later push fail the same way even though the flag was already consumed. Restart to recover.

Suggested fix

Either of these works; we'd suggest both:

1. Make the logcontext check in Clock.call_later (and looping_call) fail open: log it via logcontext_error, reset to the sentinel, and still run the callback. That keeps the leak signal without ever silently dropping a callback. (assert is also stripped under python -O, so the current behaviour already depends on interpreter flags.)

2. Don't route the cooperator's scheduler through Clock.call_later at all. The tick is internal Twisted machinery that needs no logcontext and must never be droppable, so schedule it on the bare reactor as before Cleanly shutdown SynapseHomeServer object #18828:

   def _scheduler(x):
       return clock._reactor.callLater(_EPSILON.as_secs(), x)

Seen on 1.153.0; the code is the same on develop.

Homeserver

matrix

Synapse Version

synapse version: 1.153.0

Installation Method

Docker (matrixdotorg/synapse)

Database

postgressql

Workers

Multiple workers

Platform

Linux

Configuration

No response

Relevant log output

twisted.web._newclient.RequestGenerationFailed: [CancelledError()]

Anything else that would be useful to know?

Was tested on single and multiple workers

[reivilibre]

Do you have any logs from during the wedge? Full INFO (or noisier) logs would be especially useful

There should hopefully be more context around the outbound requests that are being made.