Synapse does not recover correctly after a database server outage

[richvdh]

Earlier today our database server restarted. The database recovered itself; Synapse did not. In particular we saw "in flight requests" stacking up:

... and the reverse-proxy returned 429s for many requests.

[richvdh]

I think that if the event-fetch job fails with an exception (as it did), _event_fetch_ongoing is not correctly decremented, so no new event-fetch jobs are restarted.

[richvdh]

also: we should export _event_fetch_ongoing as a prometheus metric

[squahtx]

Event fetches explain most of the stuck requests.

There's one class of stuck request that I can't explain yet: GET FederationUserDevicesQueryServlet requests were piling up on federation_reader-1 and don't read any events as far as I can tell. Perhaps it's something to do with the @cachedList on _get_bare_e2e_cross_signing_keys_bulk? The code for @cachedList is tricky to understand but looks sound...

[squahtx]

In testing, @cachedList handled exceptions just fine. I can't reproduce the pile up of FederationUserDevicesQueryServlet requests.

[richvdh]

yeah, very odd. I'm also at a loss to explain it.

[squahtx]

Fixed by #11240, except for the FederationUserDevicesQueryServlet requests which I can't reproduce.

[richvdh]

Let's close this for now, then.

[richvdh]

Sadly I think we still have wedging event fetch queries. https://prometheus.matrix.org/graph?g0.expr=min_over_time(synapse_event_fetch_ongoing%5B10m%5D)%3E%200&g0.tab=0&g0.stacked=0&g0.show_exemplars=0&g0.range_input=17m2s852ms&g0.end_input=2021-11-17%2008%3A28%3A10&g0.moment_input=2021-11-17%2008%3A28%3A10:

[richvdh]

I think the problem here is that we increment _event_fetch_ongoing in the main thread, but decrement it in the event fetch thread.

Apart from the fact that integer increment/decrement operations aren't atomic in Python (so decrementing it without holding the lock is racy), we also have the problem that if we're unable to get a connection to the database (eg, because it is shutting down...), runWithConnection will fail without calling _do_fetch - hence the counter is incremented but not decremented.