Synapse 1.44.0 hangs up every few minutes

[Whodiduexpect]

Description

Ever since updating to 1.44.0 from 1.43.0, I've experienced frequent hanging from Synapse that lasts 10 seconds to 3 minutes. During this "hanging" period all requests (including client api, federation, static web page, etc) time out, with the rare request getting a response after a few seconds. It does not starve server resources at all, though it causes large Synapse CPU usage spikes up to 50% (average usage is around 5%). While this issue is not taking place, the homeserver performs well even in larger federated rooms.

Steps to reproduce

• Let a device in a few large federated rooms do an initial sync or wait a few minutes
• Homeserver freezes up for a little bit

I expect the server to not freeze up and perform normally like it does when this issue does not happen. The occasional errors I get when this happens are just a byproduct of a connection to a client timing out unexpectedly. Looking at Grafana, it all correlates to large spikes in the federation transmission loop.

Version information

• Homeserver: jepcraft.ddns.net:443

• Version: Synapse 1.44.0
• Install method: latest matrixdotorg/synapse Docker build
• No separate Synapse workers
• Uses both IPv4 and IPv6

• Platform:

• Debian GNU/Linux 10 (buster) x86_64
• Physical server that runs applications in Docker

[Iamsomeguy]

I have noticed similar problems on my server since the upgrade to 1.44.0 and I think I have managed to isolate the cause to dns request storms sent by the matrix server. I could match timeout errors in the nginx proxy log to thousands of dns request in our dns server query log. During these events the dns server can receive around 4000 queries per minute.

I have mitigated the problem somewhat by installing a nameservice cache daemon on the matrix server but it still happens from time to time. Specifically when clients start to connect in the morning.

Let me know if I can provide any more info that can be of use.

[babolivier]

Grafana screenshots shared by @Whodiduexpect in Synapse Admins yesterday:

With extra info, also from Synapse Admins yesterday:

this spike pattern matches up with when it all breaks

What are the name of the background jobs that's spiking here? (i.e. what's the label associated with the purple spikes)

federation transmission loop

https://matrix.to/#/!ehXvUhWNASUkSLvAGP:matrix.org/$A_cYK1J2Qlxplek3vbgPDB-JOGDy-cM1Cate7x2FTDw?via=matrix.org&via=matrix.breakpointingbad.com&via=libera.chat

[erikjohnston]

Thanks for the graphs, @Whodiduexpect: it would be useful to see the graphs under "Per-block metrics" and "Federation", which should hopefully give us a better idea of exactly what it's doing.

Based on the symptoms reported by @Iamsomeguy my guess would be that it's related to sending out presence updates to all the servers, which is known to be very heavyweight, but I can't see why that would start being an issue in 1.44.0.

[Whodiduexpect]

Time period is the same as the original screenshots

[Whodiduexpect]

After setting up proper client and federation workers, this issue just vanished (I hope I'm not speaking too soon but it's been quite a while and it hasn't happened). So it seems whatever was happening it's an issue with the main Synapse process only and does not affect any of the workers.

After that larger spike a bit past 18:40 is when the workers got fully setup to take all supported client and federation requests and from there, there are only much smaller infrequent CPU spikes that don't effect the server, towards the end I was trying to deliberately cause the issue to happen.

[Iamsomeguy]

A small update regarding my situation. Yesterday I turned off presence:

presence:
       enabled: false

This has reduced the number of dns queries to about half (~2000/min for two minutes), but I still see upstream timeouts in the nginx log:

2021/10/13 08:11:15 [error] 11304#11304: *992382 no live upstreams while connecting to upstream, client: 1.2.3.4, server: matrix.synap.se, request: "OPTIONS /_matrix/client/r0/joined_groups HTTP/1.1", upstream: "http://localhost/_matrix/client/r0/joined_groups", host: "matrix.synap.se"
2021/10/13 08:11:16 [error] 11304#11304: *992379 no live upstreams while connecting to upstream, client: 2.3.4.5, server: matrix.synap.se, request: "OPTIONS /_matrix/client/r0/sync?filter=2&timeout=0&since=s1025296_101588561_2162_2117272_722109_53_39010_1805136_2 HTTP/1.1", upstream: "http://localhost/_matrix/client/r0/sync?filter=2&timeout=0&since=s1025296_101588561_2162_2117272_722109_53_39010_1805136_2", host: "matrix.synap.se"

There were 61 such messages during 90 seconds this morning.
In the homeserver log, at the same time, I see around 1500 messages like this:

2021-10-13 08:11:38,412 - synapse.logging.context - 70 - WARNING - federation_transaction_transmission_loop-2733 - Re-starting finished log context federation_transaction_transmission_loop-2733
2021-10-13 08:11:38,412 - synapse.logging.context - 70 - WARNING - federation_transaction_transmission_loop-2733 - Re-starting finished log context federation_transaction_transmission_loop-2733

Nothing else that looks suspicious.
I haven't set up workers on this host.

[DMRobertson]

@Whodiduexpect Thank you for the graphs. I'm glad to hear workers made things better. Unfortunately I don't think there are any smoking guns there. @Iamsomeguy thank you for the update too.

We're not aware of anything in between 1.43 and 1.44 that would cause this, so this is a bit of a thorny problem to track down. Would either of you be willing to roll back synapse to 1.43 and confirm that you don't see these symptoms any more? (There shouldn't be any problems doing so, e.g. we didn't have any database migrations between those two versions.)

[DMRobertson]

Cross-referencing: @richvdh wondered if someone else was affected, see https://matrix.to/#/!ehXvUhWNASUkSLvAGP:matrix.org/$aTlgICUGpU30pfGVrbrwpBZxBB-0lu3D_x_sp3twifk?via=matrix.org&via=libera.chat&via=underzsea.com

[Iamsomeguy]

I'm now running 1.43.0 since 07:43 UTC and so far I haven't seen any upstream timeouts in the nginx log. There are lots of DNS requests though and about 5500 "Re-starting finished log context" messages in homeserver.log. This was just after startup. Seems to have calmed down now.
I have also re-enabled presence.

[Iamsomeguy]

I just got 20 upstream timeouts in the nginx log during 2 minutes after about 20 minutes of running. So, maybe it is not version related. I will keep an eye on it during the day.

[Whodiduexpect]

I've noticed even with workers a few things depend on the state of the Synapse main process, even if the requests are not going to the master process, notably sending messages. So the lockup will occur and you can sync, scroll up in the room and the history keeps up, etc but event sending does not work. This is blatantly obvious when you upload an image and it uploads instantly to the media repo but it never really sends the event and Element's UI bugs out a little bit but regardless of what it says the image doesn't actually get sent until the lockup has ended. Everything that doesn't go to workers doesn't work during the lockup either, like seeing message edit history.

[Whodiduexpect]

In terms of whether or not it's a regression specifically in 1.44.0 I now recall this kind of issue happening before but it was nowhere near as bad as it was when I updated and I feel that was more performance related rather than the main process freezing up every 1 in 4 initial syncs on accounts in federated rooms like it currently does. I haven't tested downgrading to 1.43.0, it's possible the issue comes from earlier.

[Whodiduexpect]

I've narrowed it down even further, I had a generic worker assigned to federation requests but I never had an actual federation sender worker, I added it and now the CPU usage never goes above 5% and the issue is gone for real. I'm not sure how helpful this is but I've confirmed it's in the federation sender part of Synapse.

[Iamsomeguy]

Just checked and this morning I had only one upstream timeout error in the nginx log and there was one on Saturday. It feels as if it happens when clients first connect in the morning. Our server is private but federated and we are about 10 users. I'm the only user connected to large rooms.

We are still on 1.43.0

[Iamsomeguy]

Three more timeouts this morning at 08:23-08:24 local time which corresponds to about 5000 requests to our dns cache server.
But overall it looks much better than with 1.44.0

[reivilibre]

Someone else in Synapse Admins seems to be saying they are affected.

[callahad]

@Iamsomeguy What installation method are you using? (Docker? other?)

[Iamsomeguy]

@callahad Deb package from https://packages.matrix.org/debian/ on Debian 10 buster

[Iamsomeguy]

A little more info: I have changed our DNS environment a little by setting up an unbound resolver closer to the synapse server but this does not seem to help with the nginx upstream timeouts. I'm the only one on this server that is in large federated rooms and I can see a lot of DNS traffic when I start up the client in the morning. It looks as if it is trying to resolve an SRV record for every server in the room. I got around 1500 requests during about one minute. During this time there were no other DNS requests which could be due to the local name service cache on the server. If i select another large federated room in element, I immediately get a lot of SRV queries in the resolver log. This, as far as I can tell only happens when you first connect after a longer absence. So I would look into how excessive DNS server traffic could affect synapse. Maybe there could be recommendations for how to set up your DNS infrastructure to deal with this.

I have now upgraded to 1.45.1 and so far I have not seen any big difference, a few proxy timeouts when the server first started but since then it has been rather calm.

As I said, it is possible that my changes in the DNS infrastructure and the local name service cache has helped with my situation so it may not be related to the synapse upgrade.

Also, this is a production server so I'm reluctant to use it for testing.

[richvdh]

I can see a lot of DNS traffic when I start up the client in the morning. It looks as if it is trying to resolve an SRV record for every server in the room

This is very much expected behaviour: when you first connect your client, Synapse will send out a presence update to all servers that you share a room with. To do that, it needs to find those servers, which requires (at least) a SRV lookup and an A-record lookup.

It's known that presence can be heavyweight (cf #9478), but this isn't something that changed between Synapse 1.43 and 1.44.

[Iamsomeguy]

@richvdh OK, so I suppose my problems are then caused by an underdimensioned DNS server. As I remember, around the same time I changed our DNS cache server from a forwarder to a resolver. That could possibly have contributed to the issue. Sorry for not mentioning this before.

Do you have an opinion on running a local resolver on the synapse server?

[richvdh]

As I remember, around the same time I changed our DNS cache server from a forwarder to a resolver.

well, that might explain it for you. Sadly it doesn't explain why @Whodiduexpect, @HarHarLinks, and a number of others have also seen problems when upgrading to v1.44 ://

Do you have an opinion on running a local resolver on the synapse server?

In general, we've not found this necessary, but certainly the DNS traffic can be high, and having a DNS cache such as nscd or unbound either on the same box or at least within close network distance is probably a good idea.

[HarHarLinks]

(remember I'm back on 1.43.0 where I used to not have these problems!)

I just logged out from one of my Element sessions because it was broken (element-hq/element-desktop#829).

Trying to log back in immediately I entered my hs into the sign in form. Element's feedback was to hang a minute and eventually tell me there is no hs there. Trying to check things out I was greeted by grafana with exploding CPU and a log consisting exclusively of federation_transaction_transmission_loop-37019- Re-starting finished log context federation_transaction_transmission_loop-37019 30 times every second and nothing else.

Now after 10 minutes the CPU has started to settle back down, the log still gives a lot of these errors, but not exclusively anymore. Element now recognizes there is a hs at my domain.

First try logging in failed: "There was a problem communicating with the homeserver, please try again later." My other clients are also unresponsive. Restarting the server got rid of (judging by the calmed down log) lingering federation stuff going on, I have just been able to log back in.

Update: am unable to start federated DMs, likely due to dns overload.

[richvdh]

Thanks to @HarHarLinks for giving me access to their prometheus. Some interesting graphs for the period they were running Synapse >1.43.0 (09:30 UTC to 11:45 UTC, roughly):

Clients have decided that they need to send a lot of to-device requests:

... which causes a large number of wakeups for the to_device notification stream:

And a large number of requests to /sync, presumably receiving all those to-device messages:

The CPU is being burned mostly by /sync, /messages, and /sendToDevice (top to bottom respectively in the graph below):

There's also a lot of presence stuff going on, but that may be a symptom of all the syncing rather than a cause:

Federation traffic looks relatively normal, so I think that the problems observed related to federation are more likely to be symptoms caused by general CPU starvation.

I'll try to understand what could cause all those to-device message requests.

[HarHarLinks]

There's also a lot of presence stuff going on

I wanna mention that this server has use_presence: False [sic!] set, which apparently is now a legacy setting (the server and most of it config is as old as April 2017 or so). Not to worry, I'm updating the config asap (by migrating to matrix-docker-ansible-deploy). I'm updating the presence syntax now anyway, see if it does anything.

[richvdh]

Some more information, having seen @HarHarLinks' logs:

the period they were running Synapse >1.43.0 (09:30 UTC to 11:45 UTC, roughly):

This is incorrect. They upgraded to 1.45.1 at 10:32, which was initially problematic due to #11153. The server was then successfully restarted on 1.45.1 at 10:38 and a couple more times after that, before being downgraded to 1.43 at 11:48.

The sendToDevice messages are room key requests, apparently from a new Element-web session. This appears to have stopped at 10:25, seven minutes before the upgrade to 1.45.1. In other words... all those graphs above are complete red herrings as far as problems with 1.44 and above go.

Of more interest are some extremely slow responses to /versions:

2021-10-21 10:41:39,407 - synapse.access.http.8008 - 400 - INFO - GET-1039- <...> - 8008 - {None} Processed request: 0.001sec/59.962sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 0B 200! "GET /_matrix/client/versions HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element-Nightly/2021102001 Chrome/91.0.4472.164 Electron/>

There are lots of these, during the period this server was running 1.45.1. This corresponds to reports of "timeouts in the reverse-proxy" and "Unable to log in".

---

💡 this is presumably due to #10905, which means that JSON responses (even simple ones like the response to /versions) are now encoded in the threadpool. That threadpool (10 threads) is shared with DNS lookups - so if we're doing millions of DNS lookups for federation traffic, JSON responses won't get a look-in.

That also explains why moving the federation traffic to a worker solved the problem for @Whodiduexpect, and why making the DNS resolver faster solved it for @Iamsomeguy.

[richvdh]

TL;DR: putting JSON-response-encoding in a separate threadpool to DNS lookups will hopefully fix everything!

[callahad]

@Whodiduexpect, @Iamsomeguy , @HarHarLinks : Would any of you be willing to update to the 1.46.0rc1 release candidate and see if this resolves itself?

[Whodiduexpect]

How would I switch to the release candidate with the Synapse Docker image? If that's possible I'm going to test it.

[callahad]

Where you would normally specify the image as matrixdotorg/synapse or matrixdotorg/synapse:latest you should be able to use matrixdotorg/synapse:v1.46.0rc1