matrix-org / synapse

Synapse: Matrix homeserver written in Python/Twisted.
https://matrix-org.github.io/synapse
Apache License 2.0
11.79k stars 2.13k forks source link

After joining and leaving a huge room, CPU usage and outgoing HTTP requests increased massively and stayed up #14119

Open janonym1 opened 1 year ago

janonym1 commented 1 year ago

Description

We have a big Synapse-Server with a lot of workers (for generic, federation, etc) running with open federation and it has been working fine so far. However, I recently joined the BlackArch Room (on the matrix.org server) to test how fast it can join a really big room with more than 30k+ users.

After the usual initial high CPU usage (for about 15-20m) it worked and I joined the room as expected but afterwards, the server permanently consumed about 1/3th of the CPU power available (we have 12 cores and 20GB Ram), even days later and when everyone was idle (e.g. over weekends). I didn't have any issues with "smaller" rooms before, (like the ArchLinux or RaspberryPi rooms, and they still have about 10k users) so I investigated some more. I noticed the following things:

After joining the BlackArch room, one of my federation worker permanently used about ~1/3 of my CPUs: federation_sender_cpu_usage After restarting said federation_worker, the CPU usage dropped and stayed low for a few days, after which it picked up ~1/3 of our CPU usage again. I restarted it again and it stayed low for a few days after the same thing happens again. I am not sure, what exactly triggers the high CPU usage in the federation_worker.

The overall CPU usage of the master process (specifcally: master_0_maybe_retry_device_sync) increased by about 5%, which isnt a huge deal but still bad for just joining (and leaving) a room: master_0_maybe_retry_device_sync

I think, the overall increase of the CPU usage is caused by the outgoing HTTP request rate (master-0 GET(federation)), which increased massively to about 10 req/s, and that value is way above our average. It also is permanently staying at 10req/s permanently since then, regardless of time, date or usage. mater-0_GET(federation)

I am not sure how to fix this exactly, it doesnt matter if I rejoin or leave the room. After leaving it, I also tried deleting the room (with the synapse-admin webGUI) but to no avail. I read somewhere about deleting some live DB tables but that sounds risky too me, especially in a live prod environment.

I assume, this is happening because some homeservers/accounts in those big rooms are not existing anymore and our synapse server keeps trying to reconnect to them (see logs). I cannot tell, why this has become relevant only now, since we have a lot federated rooms joined (a few with 10k+ users) for a long time now. This massive increase in sustained CPU usage however happened, after joining the BlackArch room. Since then, the outoing http req/s and CPU usage is off the charts

What can I do against that? Since we are openly federated (and want to stay that way) I can only try to ban certain problematic rooms (like the mainHQ) and hope, others wont become problematic soon. However, since the damage is already done, what can I do now? I already restarted everything and have my global_cache_factor increased to about 5.0. Deleting said room from my HS doesnt seem to help, since the maybe_retry_device_sync keeps churning away regardless. For now, I manually restart the federation_worker once it falls back into the superhigh CPU usage, which is happening about 2x/week.

Is there a error_backoff_timer or something similar, I can set? Can I ban/ignore the hosts, causing the federation_transaction_transmission_loop somewhere? Isnt this also a possible DDOS scenario? Maybe deleting the DB tables (see https://github.com/matrix-org/synapse/issues/11807) will help but the problem will probably pop up again (also, I didnt suddenly start whitelisting or changing some configs)

Steps to reproduce

Homeserver

another synapse homeserver

Synapse Version

1.68

Installation Method

Other (please mention below)

Platform

Server: Ubuntu 20.04 LTS 12 cores, 20GB RAM, 1GBit/s Network, dedicated postgreSQL DB cluster presence disabled, cache_factor 5.0 installed with Slavis ansible playbook running on a VM it worked fine so far and is still usable for everything

Relevant log output

some logs of the federation worker: 

2022-10-10 10:10:01,185 - synapse.federation.sender.per_destination_queue - 368 - WARNING - federation_transaction_transmission_loop-8130 - TX [matrix.selfhosted.games] Failed to send transaction: Failed to send request: ConnectionRefusedError: Connection was refused by other side: 111: Connection refused.
2022-10-10 10:17:15,231 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8139 - {PUT-O-4026} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077650: HttpResponseException('404: Not Found')
2022-10-10 10:17:15,232 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8139 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 10:19:17,917 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8142 - {PUT-O-4027} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077651: HttpResponseException('404: Not Found')
2022-10-10 10:19:17,917 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8142 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 10:27:16,957 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8150 - {PUT-O-4029} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077653: HttpResponseException('404: Not Found')
2022-10-10 10:27:16,958 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8150 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 10:28:44,054 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8152 - {PUT-O-4030} [matrix.appsforce.org] Request failed: PUT matrix://matrix.appsforce.org/_matrix/federation/v1/send/1665133077654: HttpResponseException('403: Forbidden')
2022-10-10 10:28:44,055 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8152 - TX [matrix.appsforce.org] Received 403 response to transaction: 403: Forbidden
2022-10-10 10:29:35,730 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8153 - {PUT-O-4031} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077655: HttpResponseException('404: Not Found')
2022-10-10 10:29:35,730 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8153 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 10:29:48,647 - synapse.federation.sender.per_destination_queue - 368 - WARNING - federation_transaction_transmission_loop-8144 - TX [thedoodleproject.net] Failed to send transaction: Failed to send request: ConnectionRefusedError: Connection was refused by other side: 111: Connection refused.
2022-10-10 10:37:18,352 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8160 - {PUT-O-4033} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077657: HttpResponseException('404: Not Found')
2022-10-10 10:37:18,352 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8160 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 10:39:37,155 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8162 - {PUT-O-4034} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077658: HttpResponseException('404: Not Found')
2022-10-10 10:39:37,156 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8162 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 10:47:36,342 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8169 - {PUT-O-4035} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077659: HttpResponseException('404: Not Found')
2022-10-10 10:47:36,343 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8169 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 10:49:38,817 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8171 - {PUT-O-4036} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077660: HttpResponseException('404: Not Found')
2022-10-10 10:49:38,817 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8171 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 10:57:37,906 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8176 - {PUT-O-4038} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077662: HttpResponseException('404: Not Found')
2022-10-10 10:57:37,906 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8176 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 10:58:17,716 - synapse.federation.sender.per_destination_queue - 368 - WARNING - federation_transaction_transmission_loop-8173 - TX [matrix.selfhosted.games] Failed to send transaction: Failed to send request: ConnectionRefusedError: Connection was refused by other side: 111: Connection refused.
2022-10-10 10:59:42,603 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8179 - {PUT-O-4039} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077663: HttpResponseException('404: Not Found')
2022-10-10 10:59:42,603 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8179 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 11:07:40,630 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8182 - {PUT-O-4041} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077665: HttpResponseException('404: Not Found')
2022-10-10 11:07:40,631 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8182 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 11:10:03,597 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8185 - {PUT-O-4042} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077666: HttpResponseException('404: Not Found')
2022-10-10 11:10:03,598 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8185 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 11:17:41,500 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8193 - {PUT-O-4044} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077668: HttpResponseException('404: Not Found')
2022-10-10 11:17:41,501 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8193 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 11:18:04,127 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8195 - {PUT-O-4045} [akuj.in] Request failed: PUT matrix://akuj.in/_matrix/federation/v1/send/1665133077669: HttpResponseException('403: Forbidden')
2022-10-10 11:18:04,127 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8195 - TX [akuj.in] Received 403 response to transaction: 403: Forbidden
2022-10-10 11:19:57,188 - synapse.federation.sender.per_destination_queue - 368 - WARNING - federation_transaction_transmission_loop-8187 - TX [thedoodleproject.net] Failed to send transaction: Failed to send request: ConnectionRefusedError: Connection was refused by other side: 111: Connection refused.
2022-10-10 11:20:06,251 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8197 - {PUT-O-4046} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077670: HttpResponseException('404: Not Found')
2022-10-10 11:20:06,252 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8197 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 11:27:42,908 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8203 - {PUT-O-4048} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077672: HttpResponseException('404: Not Found')
2022-10-10 11:27:42,909 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8203 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 11:30:08,539 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8205 - {PUT-O-4049} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077673: HttpResponseException('404: Not Found')
2022-10-10 11:30:08,539 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8205 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 11:37:44,376 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8212 - {PUT-O-4050} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077674: HttpResponseException('404: Not Found')
2022-10-10 11:37:44,376 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8212 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 11:40:10,177 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8215 - {PUT-O-4052} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077676: HttpResponseException('404: Not Found')
2022-10-10 11:40:10,178 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8215 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 11:47:45,685 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8219 - {PUT-O-4053} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077677: HttpResponseException('404: Not Found')
2022-10-10 11:47:45,685 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8219 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 11:49:44,939 - synapse.federation.sender.per_destination_queue - 368 - WARNING - federation_transaction_transmission_loop-8214 - TX [matrix.selfhosted.games] Failed to send transaction: Failed to send request: ConnectionRefusedError: Connection was refused by other side: 111: Connection refused.
2022-10-10 11:50:11,748 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8222 - {PUT-O-4054} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077678: HttpResponseException('404: Not Found')
2022-10-10 11:50:11,749 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8222 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 11:57:49,841 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8225 - {PUT-O-4056} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077680: HttpResponseException('404: Not Found')
2022-10-10 11:57:49,842 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8225 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 12:00:12,822 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8229 - {PUT-O-4057} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077681: HttpResponseException('404: Not Found')
2022-10-10 12:00:12,822 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8229 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 12:07:50,923 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8237 - {PUT-O-4059} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077683: HttpResponseException('404: Not Found')
2022-10-10 12:07:50,923 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8237 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 12:07:55,131 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8239 - {PUT-O-4060} [akuj.in] Request failed: PUT matrix://akuj.in/_matrix/federation/v1/send/1665133077684: HttpResponseException('403: Forbidden')
2022-10-10 12:07:55,132 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8239 - TX [akuj.in] Received 403 response to transaction: 403: Forbidden
2022-10-10 12:09:27,130 - synapse.federation.sender.per_destination_queue - 368 - WARNING - federation_transaction_transmission_loop-8231 - TX [thedoodleproject.net] Failed to send transaction: Failed to send request: ConnectionRefusedError: Connection was refused by other side: 111: Connection refused.
2022-10-10 12:10:15,508 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8241 - {PUT-O-4061} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077685: HttpResponseException('404: Not Found')
2022-10-10 12:10:15,508 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8241 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 12:18:07,891 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8246 - {PUT-O-4063} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077687: HttpResponseException('404: Not Found')
2022-10-10 12:18:07,892 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8246 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 12:20:17,268 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8249 - {PUT-O-4065} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077689: HttpResponseException('404: Not Found')
2022-10-10 12:20:17,269 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8249 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found
2022-10-10 12:28:09,187 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8256 - {PUT-O-4066} [matrix.chacah.io] Request failed: PUT matrix://matrix.chacah.io/_matrix/federation/v1/send/1665133077690: HttpResponseException('404: Not Found')
2022-10-10 12:28:09,187 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8256 - TX [matrix.chacah.io] Received 404 response to transaction: 404: Not Found
2022-10-10 12:30:03,858 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8259 - {PUT-O-4068} [akuj.in] Request failed: PUT matrix://akuj.in/_matrix/federation/v1/send/1665133077692: HttpResponseException('403: Forbidden')
2022-10-10 12:30:03,859 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8259 - TX [akuj.in] Received 403 response to transaction: 403: Forbidden
2022-10-10 12:30:18,341 - synapse.http.matrixfederationclient - 709 - WARNING - federation_transaction_transmission_loop-8260 - {PUT-O-4069} [patchysicp.xyz] Request failed: PUT matrix://patchysicp.xyz/_matrix/federation/v1/send/1665133077693: HttpResponseException('404: Not Found')
2022-10-10 12:30:18,342 - synapse.federation.sender.per_destination_queue - 360 - WARNING - federation_transaction_transmission_loop-8260 - TX [patchysicp.xyz] Received 404 response to transaction: 404: Not Found

some matrix-synapse main process logs:

2022-10-10 13:11:12,270 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @80jlvljt0p:rthome.me: 403: Forbidden
2022-10-10 13:11:12,438 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83536824} [synapse.glester.com] Request failed: GET matrix://synapse.glester.com/_matrix/federation/v1/user/devices/%406fa0nky106%3Asynapse.glester.com: HttpResponseException('403: Forbidden')
2022-10-10 13:11:12,438 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @6fa0nky106:synapse.glester.com: 403: Forbidden
2022-10-10 13:11:12,749 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83536868} [rthome.me] Request failed: GET matrix://rthome.me/_matrix/federation/v1/user/devices/%402ffkhch2co%3Arthome.me: HttpResponseException('403: Forbidden')
2022-10-10 13:11:12,749 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @2ffkhch2co:rthome.me: 403: Forbidden
2022-10-10 13:11:13,060 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83536897} [rthome.me] Request failed: GET matrix://rthome.me/_matrix/federation/v1/user/devices/%40dvax4psmcy%3Arthome.me: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,060 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @dvax4psmcy:rthome.me: 403: Forbidden
2022-10-10 13:11:13,096 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83536902} [metavoxx-mx.net] Request failed: GET matrix://metavoxx-mx.net/_matrix/federation/v1/user/devices/%403c5oqtqvfw%3Ametavoxx-mx.net: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,096 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @3c5oqtqvfw:metavoxx-mx.net: 403: Forbidden
2022-10-10 13:11:13,131 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83536905} [metavoxx-mx.net] Request failed: GET matrix://metavoxx-mx.net/_matrix/federation/v1/user/devices/%409rsmgkj4l2%3Ametavoxx-mx.net: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,132 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @9rsmgkj4l2:metavoxx-mx.net: 403: Forbidden
2022-10-10 13:11:13,272 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83536947} [synapse.solarinet.org] Request failed: GET matrix://synapse.solarinet.org/_matrix/federation/v1/user/devices/%40llnyrncmdx%3Asynapse.solarinet.org: HttpResponseException('302: Found')
2022-10-10 13:11:13,272 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @llnyrncmdx:synapse.solarinet.org: 302: Found
2022-10-10 13:11:13,318 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83536964} [abxy.fr] Request failed: GET matrix://abxy.fr/_matrix/federation/v1/user/devices/%40xrqhubzi55%3Aabxy.fr: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,318 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @xrqhubzi55:abxy.fr: 403: Forbidden
2022-10-10 13:11:13,345 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83536979} [matrix.irishpirates.org] Request failed: GET matrix://matrix.irishpirates.org/_matrix/federation/v1/user/devices/%40dwuazffkp0%3Amatrix.irishpirates.org: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,345 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @dwuazffkp0:matrix.irishpirates.org: 403: Forbidden
2022-10-10 13:11:13,400 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537050} [matrix.fjolstad.no] Request failed: GET matrix://matrix.fjolstad.no/_matrix/federation/v1/user/devices/%40uj4r7zsg7p%3Amatrix.fjolstad.no: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,400 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @uj4r7zsg7p:matrix.fjolstad.no: 403: Forbidden
2022-10-10 13:11:13,456 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537053} [matrix.fjolstad.no] Request failed: GET matrix://matrix.fjolstad.no/_matrix/federation/v1/user/devices/%40mwppy187at%3Amatrix.fjolstad.no: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,457 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @mwppy187at:matrix.fjolstad.no: 403: Forbidden
2022-10-10 13:11:13,486 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537055} [app.ecosphere.chat] Request failed: GET matrix://app.ecosphere.chat/_matrix/federation/v1/user/devices/%40fpicd57kg4%3Aapp.ecosphere.chat: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,487 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @fpicd57kg4:app.ecosphere.chat: 403: Forbidden
2022-10-10 13:11:13,515 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537104} [matrix.irishpirates.org] Request failed: GET matrix://matrix.irishpirates.org/_matrix/federation/v1/user/devices/%40k8niu1qyf4%3Amatrix.irishpirates.org: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,515 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @k8niu1qyf4:matrix.irishpirates.org: 403: Forbidden
2022-10-10 13:11:13,538 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537118} [famisoft.pl] Request failed: GET matrix://famisoft.pl/_matrix/federation/v1/user/devices/%40r251waugi6%3Afamisoft.pl: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,538 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @r251waugi6:famisoft.pl: 403: Forbidden
2022-10-10 13:11:13,704 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537143} [synapse.glester.com] Request failed: GET matrix://synapse.glester.com/_matrix/federation/v1/user/devices/%408ncr7m3e35%3Asynapse.glester.com: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,704 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @8ncr7m3e35:synapse.glester.com: 403: Forbidden
2022-10-10 13:11:13,755 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537169} [matrix.fjolstad.no] Request failed: GET matrix://matrix.fjolstad.no/_matrix/federation/v1/user/devices/%40b6n39kfqo1%3Amatrix.fjolstad.no: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,755 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @b6n39kfqo1:matrix.fjolstad.no: 403: Forbidden
2022-10-10 13:11:13,806 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537195} [matrix.fjolstad.no] Request failed: GET matrix://matrix.fjolstad.no/_matrix/federation/v1/user/devices/%40n86uqa7m56%3Amatrix.fjolstad.no: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,806 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @n86uqa7m56:matrix.fjolstad.no: 403: Forbidden
2022-10-10 13:11:13,855 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537200} [matrix.fjolstad.no] Request failed: GET matrix://matrix.fjolstad.no/_matrix/federation/v1/user/devices/%40ur9afac7vb%3Amatrix.fjolstad.no: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,855 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @ur9afac7vb:matrix.fjolstad.no: 403: Forbidden
2022-10-10 13:11:13,885 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537212} [app.ecosphere.chat] Request failed: GET matrix://app.ecosphere.chat/_matrix/federation/v1/user/devices/%40hccanfthiz%3Aapp.ecosphere.chat: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,885 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @hccanfthiz:app.ecosphere.chat: 403: Forbidden
2022-10-10 13:11:13,911 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537217} [matrix.irishpirates.org] Request failed: GET matrix://matrix.irishpirates.org/_matrix/federation/v1/user/devices/%40rdxdvdqinu%3Amatrix.irishpirates.org: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,911 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @rdxdvdqinu:matrix.irishpirates.org: 403: Forbidden
2022-10-10 13:11:13,937 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537221} [matrix.irishpirates.org] Request failed: GET matrix://matrix.irishpirates.org/_matrix/federation/v1/user/devices/%4040j01o745y%3Amatrix.irishpirates.org: HttpResponseException('403: Forbidden')
2022-10-10 13:11:13,937 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @40j01o745y:matrix.irishpirates.org: 403: Forbidden
2022-10-10 13:11:14,067 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537229} [synapse.solarinet.org] Request failed: GET matrix://synapse.solarinet.org/_matrix/federation/v1/user/devices/%40tgrhlxv3ko%3Asynapse.solarinet.org: HttpResponseException('302: Found')
2022-10-10 13:11:14,067 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @tgrhlxv3ko:synapse.solarinet.org: 302: Found
2022-10-10 13:11:14,196 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537249} [synapse.solarinet.org] Request failed: GET matrix://synapse.solarinet.org/_matrix/federation/v1/user/devices/%40ty5br3fw2s%3Asynapse.solarinet.org: HttpResponseException('302: Found')
2022-10-10 13:11:14,196 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @ty5br3fw2s:synapse.solarinet.org: 302: Found
2022-10-10 13:11:14,331 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537264} [synapse.solarinet.org] Request failed: GET matrix://synapse.solarinet.org/_matrix/federation/v1/user/devices/%40c18f7nu3s8%3Asynapse.solarinet.org: HttpResponseException('302: Found')
2022-10-10 13:11:14,332 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @c18f7nu3s8:synapse.solarinet.org: 302: Found
2022-10-10 13:11:14,459 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537275} [synapse.solarinet.org] Request failed: GET matrix://synapse.solarinet.org/_matrix/federation/v1/user/devices/%40fmfkhb25xx%3Asynapse.solarinet.org: HttpResponseException('302: Found')
2022-10-10 13:11:14,459 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @fmfkhb25xx:synapse.solarinet.org: 302: Found
2022-10-10 13:11:14,483 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537303} [matrix.chaoshome.net] Request failed: GET matrix://matrix.chaoshome.net/_matrix/federation/v1/user/devices/%407za1pocjqy%3Amatrix.chaoshome.net: HttpResponseException('403: Forbidden')
2022-10-10 13:11:14,483 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @7za1pocjqy:matrix.chaoshome.net: 403: Forbidden
2022-10-10 13:11:14,793 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537310} [rthome.me] Request failed: GET matrix://rthome.me/_matrix/federation/v1/user/devices/%40b3avvgsnty%3Arthome.me: HttpResponseException('403: Forbidden')
2022-10-10 13:11:14,793 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @b3avvgsnty:rthome.me: 403: Forbidden
2022-10-10 13:11:15,102 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537345} [rthome.me] Request failed: GET matrix://rthome.me/_matrix/federation/v1/user/devices/%40i6jkkt83m5%3Arthome.me: HttpResponseException('403: Forbidden')
2022-10-10 13:11:15,102 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @i6jkkt83m5:rthome.me: 403: Forbidden
2022-10-10 13:11:15,125 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537350} [famisoft.pl] Request failed: GET matrix://famisoft.pl/_matrix/federation/v1/user/devices/%40lj71ilt7ze%3Afamisoft.pl: HttpResponseException('403: Forbidden')
2022-10-10 13:11:15,125 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @lj71ilt7ze:famisoft.pl: 403: Forbidden
2022-10-10 13:11:15,152 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537378} [matrix.irishpirates.org] Request failed: GET matrix://matrix.irishpirates.org/_matrix/federation/v1/user/devices/%40nl45pggqtv%3Amatrix.irishpirates.org: HttpResponseException('403: Forbidden')
2022-10-10 13:11:15,152 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @nl45pggqtv:matrix.irishpirates.org: 403: Forbidden
2022-10-10 13:11:15,622 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537398} [swirl.funny.cl] Request failed: GET matrix://swirl.funny.cl/_matrix/federation/v1/user/devices/%401948_your_tlv_homo_1488%3Aswirl.funny.cl: HttpResponseException('403: Forbidden')
2022-10-10 13:11:15,622 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @1948_your_tlv_homo_1488:swirl.funny.cl: 403: Forbidden
2022-10-10 13:11:15,644 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537408} [matrix.chaoshome.net] Request failed: GET matrix://matrix.chaoshome.net/_matrix/federation/v1/user/devices/%406vhg8z8gvn%3Amatrix.chaoshome.net: HttpResponseException('403: Forbidden')
2022-10-10 13:11:15,644 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @6vhg8z8gvn:matrix.chaoshome.net: 403: Forbidden
2022-10-10 13:11:15,673 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537420} [matrix.cker.io] Request failed: GET matrix://matrix.cker.io/_matrix/federation/v1/user/devices/%400pzif2zlml%3Amatrix.cker.io: HttpResponseException('403: Forbidden')
2022-10-10 13:11:15,673 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @0pzif2zlml:matrix.cker.io: 403: Forbidden
2022-10-10 13:11:15,728 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537441} [matrix.fjolstad.no] Request failed: GET matrix://matrix.fjolstad.no/_matrix/federation/v1/user/devices/%40zhw9e3n1vc%3Amatrix.fjolstad.no: HttpResponseException('403: Forbidden')
2022-10-10 13:11:15,728 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @zhw9e3n1vc:matrix.fjolstad.no: 403: Forbidden
2022-10-10 13:11:15,782 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537449} [matrix.fjolstad.no] Request failed: GET matrix://matrix.fjolstad.no/_matrix/federation/v1/user/devices/%40w7yxpu656v%3Amatrix.fjolstad.no: HttpResponseException('403: Forbidden')
2022-10-10 13:11:15,783 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @w7yxpu656v:matrix.fjolstad.no: 403: Forbidden
2022-10-10 13:11:15,809 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537461} [matrix.irishpirates.org] Request failed: GET matrix://matrix.irishpirates.org/_matrix/federation/v1/user/devices/%40qr6n25cyv2%3Amatrix.irishpirates.org: HttpResponseException('403: Forbidden')
2022-10-10 13:11:15,809 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @qr6n25cyv2:matrix.irishpirates.org: 403: Forbidden
2022-10-10 13:11:15,832 - synapse.http.matrixfederationclient - 709 - WARNING - _maybe_retry_device_resync-4703 - {GET-O-83537463} [matrix.chaoshome.net] Request failed: GET matrix://matrix.chaoshome.net/_matrix/federation/v1/user/devices/%40zmt0s1cg2n%3Amatrix.chaoshome.net: HttpResponseException('403: Forbidden')
2022-10-10 13:11:15,832 - synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-4703 - Failed to handle device list update for @zmt0s1cg2n:matrix.chaoshome.net: 403: Forbidden
janonym1 commented 1 year ago

some more before/after metrics: you can see the increased/spiking CPU usage and HTTP requests starting when joining said room in the beginning of the graphs (at about 10/3): synapse_more_logs

I also noticed, that when the CPU usage of a federation_worker explodes, it causes a lot of DB txn: DB_transaction_when_federation_worker_increases

janonym1 commented 1 year ago

The initial huge CPU/DB txn spikes (in the first week) didnt occur again but the server CPU usage is still increased by about +5% permanently and the outgoing HTTP requests (~10/s) are still persisting. At this point, I can live with the +5% CPU usage for now but the all the resync warnings are flooding my logs with synapse.handlers.device - 1014 - WARNING - _maybe_retry_device_resync-9855 - Failed to handle device list update for X warnings which makes it hard to see other relevant warnings. I am still not seeing the room listed on my homeserver (synapse-admin)

Any advice? I dont think, manually clearing some DB tables is a solution because this can just happen again, if any user on my homeserver is joining said room.

Maybe I can manually add the failed resync servers to a banlist? I am also wondering If I should just blanket ban the biggest rooms on matrix.org (the mainHQ and BlackArch at least) if any user joining them can trigger said problems

yingziwu commented 1 year ago

I meet the same problem with you.

After joining the Matrix HQ room, my synapse is constantly under heavy load. The federation_transaction_transmission_loop is found to cause a sustained high load on the CPU through grafana graph.

image image image image image

janonym1 commented 1 year ago

@yingziwu joining a huge room will take a lot of resources and can take some time, depending on the system you are using (maybe even days?). I think this behavior is expected but the CPU usage should die down some time after joining.

What I am specifically interested in, is the outgoing HTTP requests, which seem to fluctuate on your server and is normal in the beginning. After joining (and leaving) the room, are there still a lot of outgoing HTTP requests? On my system I have a "noise floor" of about 5-6 requests per second, which correlates to my log showing a failed connection to homeservers like: synapse.handlers.device - 1191 - WARNING - _maybe_retry_device_resync-70 - Failed to handle device list update for @zmvibdrwb0:abxy.fr: 403

It seems, this doesnt happen on your system, since you sometimes seem to have 0 outgoing HTTP requests.

btw: the average CPU usage from all the churning maybe_retry_device_resyncs has decreased to about 2-3% now (using synapse 1.74) but the log is still getting spammed with the said warnings