Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Federation sender started spamming requests #16101

Closed
tulir opened this issue Aug 11, 2023 · 16 comments · Fixed by #16156
Closed

Federation sender started spamming requests #16101

tulir opened this issue Aug 11, 2023 · 16 comments · Fixed by #16156
Assignees
Labels
A-Federation A-Performance Performance, both client-facing and admin-facing O-Frequent Affects or can be seen by most users regularly or impacts most users' first experience S-Major Major functionality / product severely impaired, no satisfactory workaround. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.

Comments

@tulir
Copy link
Member

tulir commented Aug 11, 2023

Description

Two of my three federation senders are spamming two specific servers very quickly. Restarting them solved it temporarily, but they quickly started spamming the same two hosts again, possibly after sending an event to a room the hosts were in. After that I tried adding

federation:
  destination_min_retry_interval: 10m
  destination_retry_multiplier: 5
  destination_max_retry_interval: 365d

to the config and restarting. After that it didn't start spamming again, but I'm not sure if it was the config or if it just wanted to be restarted twice, as it had updated the destinations table with a new retry_last_ts and retry_interval (the new interval being the maximum)

Homeserver

maunium.net

Synapse Version

1.90.0rc1

Database

PostgreSQL

Workers

Multiple workers

Platform

Docker (custom image)

Relevant log output

2023-08-11 08:25:42,906 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-26175- TX [matrix.buffadoo.nl] Received 401 response to transaction: 401: Unauthorized
2023-08-11 08:25:42,915 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-5959- Streaming: caches -> 18455011
2023-08-11 08:25:42,917 - synapse.federation.sender.per_destination_queue - 486 - INFO - federation_transaction_transmission_loop-26176- Catching up destination matrix.buffadoo.nl with 1 PDUs
2023-08-11 08:25:42,919 - synapse.federation.sender.per_destination_queue - 568 - INFO - federation_transaction_transmission_loop-26176- Catching up rooms to matrix.buffadoo.nl: '!ehXvUhWNASUkSLvAGP:matrix.org'
2023-08-11 08:25:42,919 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-26176- TX [matrix.buffadoo.nl] {1691741868425} Sending transaction [1691741868425], (PDUs: 1, EDUs: 0)
2023-08-11 08:25:42,956 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-26176- {PUT-O-15600} [matrix.buffadoo.nl] Got response headers: 401 Unauthorized
2023-08-11 08:25:42,956 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-26176- {PUT-O-15600} [matrix.buffadoo.nl] Request failed: PUT matrix-federation://matrix.buffadoo.nl/_matrix/federation/v1/send/1691741868425: HttpResponseException('401: Unauthorized')
2023-08-11 08:25:42,956 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-26176- Connection to matrix.buffadoo.nl was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(401: Unauthorized)); backoff now 604800000
2023-08-11 08:25:42,957 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-26176- TX [matrix.buffadoo.nl] {1691741868425} got 401 response
2023-08-11 08:25:42,957 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-26176- TX [matrix.buffadoo.nl] Received 401 response to transaction: 401: Unauthorized
2023-08-11 08:25:42,958 - synapse.federation.sender - 979 - INFO - wake_destinations_needing_catchup-1- Destination matrix.holms.place has outstanding catch-up, waking up.
2023-08-11 08:25:42,960 - synapse.federation.sender.per_destination_queue - 486 - INFO - federation_transaction_transmission_loop-26177- Catching up destination matrix.fuzuki.dev with 1 PDUs
2023-08-11 08:25:42,963 - synapse.federation.sender.per_destination_queue - 568 - INFO - federation_transaction_transmission_loop-26177- Catching up rooms to matrix.fuzuki.dev: '!SMloEYlhCiqKwRLAgY:fachschaften.org'
2023-08-11 08:25:42,963 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-26177- TX [matrix.fuzuki.dev] {1691741868426} Sending transaction [1691741868426], (PDUs: 1, EDUs: 0)
2023-08-11 08:25:42,965 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-5960- Streaming: caches -> 18455012
2023-08-11 08:25:42,966 - synapse.federation.sender.per_destination_queue - 486 - INFO - federation_transaction_transmission_loop-26178- Catching up destination matrix.buffadoo.nl with 1 PDUs
2023-08-11 08:25:42,969 - synapse.federation.sender.per_destination_queue - 568 - INFO - federation_transaction_transmission_loop-26178- Catching up rooms to matrix.buffadoo.nl: '!ehXvUhWNASUkSLvAGP:matrix.org'
2023-08-11 08:25:42,969 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-26178- TX [matrix.buffadoo.nl] {1691741868427} Sending transaction [1691741868427], (PDUs: 1, EDUs: 0)
2023-08-11 08:25:43,015 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-26178- {PUT-O-15602} [matrix.buffadoo.nl] Got response headers: 401 Unauthorized
2023-08-11 08:25:43,015 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-26178- {PUT-O-15602} [matrix.buffadoo.nl] Request failed: PUT matrix-federation://matrix.buffadoo.nl/_matrix/federation/v1/send/1691741868427: HttpResponseException('401: Unauthorized')
2023-08-11 08:25:43,015 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-26178- Connection to matrix.buffadoo.nl was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(401: Unauthorized)); backoff now 604800000
2023-08-11 08:25:43,016 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-26178- TX [matrix.buffadoo.nl] {1691741868427} got 401 response
2023-08-11 08:25:43,016 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-26178- TX [matrix.buffadoo.nl] Received 401 response to transaction: 401: Unauthorized
2023-08-11 08:25:43,022 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-5961- Streaming: caches -> 18455013
2023-08-11 08:25:43,025 - synapse.federation.sender.per_destination_queue - 486 - INFO - federation_transaction_transmission_loop-26179- Catching up destination matrix.buffadoo.nl with 1 PDUs
2023-08-11 08:25:43,027 - synapse.federation.sender.per_destination_queue - 568 - INFO - federation_transaction_transmission_loop-26179- Catching up rooms to matrix.buffadoo.nl: '!ehXvUhWNASUkSLvAGP:matrix.org'
2023-08-11 08:25:43,027 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-26179- TX [matrix.buffadoo.nl] {1691741868428} Sending transaction [1691741868428], (PDUs: 1, EDUs: 0)
2023-08-11 08:25:43,066 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-26179- {PUT-O-15603} [matrix.buffadoo.nl] Got response headers: 401 Unauthorized
2023-08-11 08:25:43,067 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-26179- {PUT-O-15603} [matrix.buffadoo.nl] Request failed: PUT matrix-federation://matrix.buffadoo.nl/_matrix/federation/v1/send/1691741868428: HttpResponseException('401: Unauthorized')
2023-08-11 08:25:43,067 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-26179- Connection to matrix.buffadoo.nl was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(401: Unauthorized)); backoff now 604800000
2023-08-11 08:25:43,067 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-26179- TX [matrix.buffadoo.nl] {1691741868428} got 401 response
2023-08-11 08:25:43,067 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-26179- TX [matrix.buffadoo.nl] Received 401 response to transaction: 401: Unauthorized
2023-08-11 08:25:43,073 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-5962- Streaming: caches -> 18455014
2023-08-11 08:25:43,075 - synapse.federation.sender.per_destination_queue - 486 - INFO - federation_transaction_transmission_loop-26180- Catching up destination matrix.buffadoo.nl with 1 PDUs
2023-08-11 08:25:43,077 - synapse.federation.sender.per_destination_queue - 568 - INFO - federation_transaction_transmission_loop-26180- Catching up rooms to matrix.buffadoo.nl: '!ehXvUhWNASUkSLvAGP:matrix.org'
2023-08-11 08:25:43,078 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-26180- TX [matrix.buffadoo.nl] {1691741868429} Sending transaction [1691741868429], (PDUs: 1, EDUs: 0)
2023-08-11 08:25:43,114 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-26180- {PUT-O-15604} [matrix.buffadoo.nl] Got response headers: 401 Unauthorized
2023-08-11 08:25:43,115 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-26180- {PUT-O-15604} [matrix.buffadoo.nl] Request failed: PUT matrix-federation://matrix.buffadoo.nl/_matrix/federation/v1/send/1691741868429: HttpResponseException('401: Unauthorized')
2023-08-11 08:25:43,115 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-26180- Connection to matrix.buffadoo.nl was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(401: Unauthorized)); backoff now 604800000
2023-08-11 08:25:43,115 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-26180- TX [matrix.buffadoo.nl] {1691741868429} got 401 response
2023-08-11 08:25:43,115 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-26180- TX [matrix.buffadoo.nl] Received 401 response to transaction: 401: Unauthorized
2023-08-11 08:25:43,121 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-26177- {PUT-O-15601} [matrix.fuzuki.dev] Got response headers: 400 Bad Request
2023-08-11 08:25:43,121 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-26177- {PUT-O-15601} [matrix.fuzuki.dev] Request failed: PUT matrix-federation://matrix.fuzuki.dev/_matrix/federation/v1/send/1691741868426: HttpResponseException('400: Bad Request')
2023-08-11 08:25:43,122 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-26177- TX [matrix.fuzuki.dev] {1691741868426} got 400 response
2023-08-11 08:25:43,122 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-26177- TX [matrix.fuzuki.dev] Received 400 response to transaction: 400: Bad Request
2023-08-11 08:25:43,122 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-5963- Streaming: caches -> 18455015
2023-08-11 08:25:43,124 - synapse.federation.sender.per_destination_queue - 486 - INFO - federation_transaction_transmission_loop-26181- Catching up destination matrix.buffadoo.nl with 1 PDUs
2023-08-11 08:25:43,127 - synapse.federation.sender.per_destination_queue - 568 - INFO - federation_transaction_transmission_loop-26181- Catching up rooms to matrix.buffadoo.nl: '!ehXvUhWNASUkSLvAGP:matrix.org'
2023-08-11 08:25:43,127 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-26181- TX [matrix.buffadoo.nl] {1691741868430} Sending transaction [1691741868430], (PDUs: 1, EDUs: 0)
2023-08-11 08:25:43,162 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-26181- {PUT-O-15605} [matrix.buffadoo.nl] Got response headers: 401 Unauthorized
2023-08-11 08:25:43,162 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-26181- {PUT-O-15605} [matrix.buffadoo.nl] Request failed: PUT matrix-federation://matrix.buffadoo.nl/_matrix/federation/v1/send/1691741868430: HttpResponseException('401: Unauthorized')
2023-08-11 08:25:43,162 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-26181- Connection to matrix.buffadoo.nl was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(401: Unauthorized)); backoff now 604800000
2023-08-11 08:25:43,163 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-26181- TX [matrix.buffadoo.nl] {1691741868430} got 401 response
2023-08-11 08:25:43,163 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-26181- TX [matrix.buffadoo.nl] Received 401 response to transaction: 401: Unauthorized
2023-08-11 08:25:43,169 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-5964- Streaming: caches -> 18455016
2023-08-11 08:25:43,171 - synapse.federation.sender.per_destination_queue - 486 - INFO - federation_transaction_transmission_loop-26182- Catching up destination matrix.buffadoo.nl with 1 PDUs
2023-08-11 08:25:43,173 - synapse.federation.sender.per_destination_queue - 568 - INFO - federation_transaction_transmission_loop-26182- Catching up rooms to matrix.buffadoo.nl: '!ehXvUhWNASUkSLvAGP:matrix.org'
2023-08-11 08:25:43,173 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-26182- TX [matrix.buffadoo.nl] {1691741868431} Sending transaction [1691741868431], (PDUs: 1, EDUs: 0)
2023-08-11 08:25:43,213 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-26182- {PUT-O-15606} [matrix.buffadoo.nl] Got response headers: 401 Unauthorized
2023-08-11 08:25:43,213 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-26182- {PUT-O-15606} [matrix.buffadoo.nl] Request failed: PUT matrix-federation://matrix.buffadoo.nl/_matrix/federation/v1/send/1691741868431: HttpResponseException('401: Unauthorized')

image

@tulir
Copy link
Member Author

tulir commented Aug 13, 2023

This just happened again, this time only one of the three federation senders and it started spamming two destinations. I had left destination_max_retry_interval: 365d in the config, so I guess that didn't help and it was the restarts that solved it previously.

image

The retry_last_ts in the database didn't seem to be updating at first:

synapse=# SELECT * FROM destinations WHERE destination IN ('matrix.vasgard.com', 'matrix.theyosh.nl');
    destination     | retry_last_ts | retry_interval |  failure_ts   | last_successful_stream_ordering 
--------------------+---------------+----------------+---------------+---------------------------------
 matrix.theyosh.nl  | 1642089421167 |    49759811330 | 1628349106929 |                                
 matrix.vasgard.com | 1636311172751 |    55548052388 | 1624598553475 |                        24381138
(2 rows)

Restarted a few times, the spam restarts when I type in #synapse:matrix.org or #element-web:matrix.org (the servers are participating in those rooms)

A bit later when I didn't send anything in those rooms, one of the destinations updated, but the retry interval went way down for some reason

synapse=# SELECT * FROM destinations WHERE destination IN ('matrix.vasgard.com', 'matrix.theyosh.nl');
    destination     | retry_last_ts | retry_interval |  failure_ts   | last_successful_stream_ordering 
--------------------+---------------+----------------+---------------+---------------------------------
 matrix.theyosh.nl  | 1642089421167 |    49759811330 | 1628349106929 |                                
 matrix.vasgard.com | 1691918505198 |         600000 | 1691918505198 |                        24381138
(2 rows)

edit: the next day, one of the servers still hasn't updated its retry_last_ts and is spamming requests again

synapse=# SELECT * FROM destinations WHERE destination IN ('matrix.vasgard.com', 'matrix.theyosh.nl');
    destination     | retry_last_ts | retry_interval |  failure_ts   | last_successful_stream_ordering 
--------------------+---------------+----------------+---------------+---------------------------------
 matrix.theyosh.nl  | 1642089421167 |    49759811330 | 1628349106929 |                                
 matrix.vasgard.com | 1691961970937 |       43882073 | 1691918505198 |                        24381138
(2 rows)

@tulir
Copy link
Member Author

tulir commented Aug 13, 2023

Looking at the ordinary logs a bit more (when it isn't spamming requests at 40hz), I noticed that my server is trying to send stuff to ditto.chat repeatedly, a server which has been down for a long time. It's not spamming as quickly, but it is restarting the attempt ("Catching up destination ditto.chat") immediately after the previous attempt finishes.

https://gist.github.com/tulir/99a8074ccf5e7dedbd7ae958ee2968d0

The destination says the last retry was ages ago and the retry interval is very big

synapse=# SELECT * FROM destinations WHERE destination='ditto.chat';
 destination | retry_last_ts | retry_interval |  failure_ts   | last_successful_stream_ordering 
-------------+---------------+----------------+---------------+---------------------------------
 ditto.chat  | 1659164773360 |    32425238713 | 1652899717490 |                        32630841
(1 row)

@tulir
Copy link
Member Author

tulir commented Aug 13, 2023

There's a suspicious increase (2-3x) in the background rate of failed transactions on July 3rd, which I think is when I updated to 1.87.0rc1

image

Beeper had an even more noticeable jump on August 1st (around when it updated from 1.85.2 to 1.88.0)

image

@villepeh
Copy link
Contributor

villepeh commented Aug 13, 2023

I have the same issue on 1.90.0rc1.

When running redis-cli and starting monitoring with the MONITORING command I could see lots of spam with REMOTE_SERVER_UP followed by PUBLISH" "homeserver.tld" "RDATA caches worker2 14161307 [\"get_destination_retry_timings\",[\"remote.host\"],1691934663227] (edit: spam = as in tens of lines per one second, non-stop).

Adding the configuration lines from the OP seems solve the issue for me at least.

@tulir
Copy link
Member Author

tulir commented Aug 14, 2023

I can confirm that my redis is also getting spammed with those requests (one of the servers it started spamming requests to yesterday still hasn't recovered)

1692005283.507293 [0] "PUBLISH" "maunium.net" "REMOTE_SERVER_UP matrix.theyosh.nl"
1692005283.510280 [0] "PUBLISH" "maunium.net" "RDATA caches federation_sender_3 21668192 [\"get_destination_retry_timings\",[\"matrix.theyosh.nl\"],1692005283504]"

@cremesk
Copy link
Contributor

cremesk commented Aug 14, 2023

looks like i have the same issue..

image

image
( MONITOR in redis-cli spamming REMOTE_SERVER_UP + RDATA caches for get_destination_retry_timings )

@tulir
Copy link
Member Author

tulir commented Aug 14, 2023

Manually updating retry_last_ts in the database seems to make the spam stop immediately (even without restarting the worker)

@cremesk
Copy link
Contributor

cremesk commented Aug 14, 2023

Manually updating retry_last_ts in the database seems to make the spam stop immediately (even without restarting the worker)

can confirm it!

@villepeh
Copy link
Contributor

More news:

This seems to happen on 1.90.0rc1 without any workers or redis.

2023-08-14 18:42:51,593 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-1816122 - TX [pfaff.dev] {1691757187756} Sending transaction [1691757187756], (PDUs: 0, EDUs: 1)
2023-08-14 18:42:51,717 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-1816122 - {PUT-O-1663372} [pfaff.dev] Got response headers: 404 Not Found
2023-08-14 18:42:51,717 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-1816122 - {PUT-O-1663372} [pfaff.dev] Request failed: PUT matrix-federation://pfaff.dev/_matrix/federation/v1/send/1691757187756: HttpResponseException('404: Not Found')
2023-08-14 18:42:51,717 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-1816122 - Connection to pfaff.dev was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(404: Not Found)); backoff now 604800000
2023-08-14 18:42:51,717 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-1816122 - TX [pfaff.dev] {1691757187756} got 404 response
2023-08-14 18:42:51,717 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-1816122 - TX [pfaff.dev] Received 404 response to transaction: 404: Not Found
2023-08-14 18:42:51,725 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-1816123 - TX [pfaff.dev] {1691757187757} Sending transaction [1691757187757], (PDUs: 0, EDUs: 1)
2023-08-14 18:42:51,834 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-1816123 - {PUT-O-1663373} [pfaff.dev] Got response headers: 404 Not Found
2023-08-14 18:42:51,835 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-1816123 - {PUT-O-1663373} [pfaff.dev] Request failed: PUT matrix-federation://pfaff.dev/_matrix/federation/v1/send/1691757187757: HttpResponseException('404: Not Found')
2023-08-14 18:42:51,836 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-1816123 - Connection to pfaff.dev was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(404: Not Found)); backoff now 604800000
2023-08-14 18:42:51,836 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-1816123 - TX [pfaff.dev] {1691757187757} got 404 response
2023-08-14 18:42:51,836 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-1816123 - TX [pfaff.dev] Received 404 response to transaction: 404: Not Found
2023-08-14 18:42:51,852 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-1816124 - TX [pfaff.dev] {1691757187758} Sending transaction [1691757187758], (PDUs: 0, EDUs: 1)
2023-08-14 18:42:51,962 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-1816124 - {PUT-O-1663374} [pfaff.dev] Got response headers: 404 Not Found
2023-08-14 18:42:51,963 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-1816124 - {PUT-O-1663374} [pfaff.dev] Request failed: PUT matrix-federation://pfaff.dev/_matrix/federation/v1/send/1691757187758: HttpResponseException('404: Not Found')
2023-08-14 18:42:51,963 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-1816124 - Connection to pfaff.dev was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(404: Not Found)); backoff now 604800000
2023-08-14 18:42:51,963 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-1816124 - TX [pfaff.dev] {1691757187758} got 404 response
2023-08-14 18:42:51,964 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-1816124 - TX [pfaff.dev] Received 404 response to transaction: 404: Not Found
2023-08-14 18:42:51,977 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-1816125 - TX [pfaff.dev] {1691757187759} Sending transaction [1691757187759], (PDUs: 0, EDUs: 1)
2023-08-14 18:42:52,087 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-1816125 - {PUT-O-1663375} [pfaff.dev] Got response headers: 404 Not Found
2023-08-14 18:42:52,087 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-1816125 - {PUT-O-1663375} [pfaff.dev] Request failed: PUT matrix-federation://pfaff.dev/_matrix/federation/v1/send/1691757187759: HttpResponseException('404: Not Found')
2023-08-14 18:42:52,088 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-1816125 - Connection to pfaff.dev was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(404: Not Found)); backoff now 604800000
2023-08-14 18:42:52,088 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-1816125 - TX [pfaff.dev] {1691757187759} got 404 response
2023-08-14 18:42:52,088 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-1816125 - TX [pfaff.dev] Received 404 response to transaction: 404: Not Found
2023-08-14 18:42:52,103 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-1816126 - TX [pfaff.dev] {1691757187760} Sending transaction [1691757187760], (PDUs: 0, EDUs: 1)
2023-08-14 18:42:52,212 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-1816126 - {PUT-O-1663376} [pfaff.dev] Got response headers: 404 Not Found
2023-08-14 18:42:52,213 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-1816126 - {PUT-O-1663376} [pfaff.dev] Request failed: PUT matrix-federation://pfaff.dev/_matrix/federation/v1/send/1691757187760: HttpResponseException('404: Not Found')
2023-08-14 18:42:52,214 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-1816126 - Connection to pfaff.dev was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(404: Not Found)); backoff now 604800000
2023-08-14 18:42:52,214 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-1816126 - TX [pfaff.dev] {1691757187760} got 404 response
2023-08-14 18:42:52,214 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-1816126 - TX [pfaff.dev] Received 404 response to transaction: 404: Not Found
2023-08-14 18:42:52,234 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-1816127 - TX [pfaff.dev] {1691757187761} Sending transaction [1691757187761], (PDUs: 0, EDUs: 1)
2023-08-14 18:42:52,344 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-1816127 - {PUT-O-1663377} [pfaff.dev] Got response headers: 404 Not Found
2023-08-14 18:42:52,345 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-1816127 - {PUT-O-1663377} [pfaff.dev] Request failed: PUT matrix-federation://pfaff.dev/_matrix/federation/v1/send/1691757187761: HttpResponseException('404: Not Found')
2023-08-14 18:42:52,345 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-1816127 - Connection to pfaff.dev was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(404: Not Found)); backoff now 604800000
2023-08-14 18:42:52,346 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-1816127 - TX [pfaff.dev] {1691757187761} got 404 response
2023-08-14 18:42:52,346 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-1816127 - TX [pfaff.dev] Received 404 response to transaction: 404: Not Found
2023-08-14 18:42:52,361 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-1816128 - TX [pfaff.dev] {1691757187762} Sending transaction [1691757187762], (PDUs: 0, EDUs: 1)
2023-08-14 18:42:52,471 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-1816128 - {PUT-O-1663378} [pfaff.dev] Got response headers: 404 Not Found
2023-08-14 18:42:52,472 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-1816128 - {PUT-O-1663378} [pfaff.dev] Request failed: PUT matrix-federation://pfaff.dev/_matrix/federation/v1/send/1691757187762: HttpResponseException('404: Not Found')
2023-08-14 18:42:52,472 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-1816128 - Connection to pfaff.dev was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(404: Not Found)); backoff now 604800000
2023-08-14 18:42:52,473 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-1816128 - TX [pfaff.dev] {1691757187762} got 404 response
2023-08-14 18:42:52,473 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-1816128 - TX [pfaff.dev] Received 404 response to transaction: 404: Not Found
2023-08-14 18:42:52,488 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-1816130 - TX [pfaff.dev] {1691757187764} Sending transaction [1691757187764], (PDUs: 0, EDUs: 1)
2023-08-14 18:42:52,598 - synapse.http.matrixfederationclient - 715 - INFO - federation_transaction_transmission_loop-1816130 - {PUT-O-1663380} [pfaff.dev] Got response headers: 404 Not Found
2023-08-14 18:42:52,599 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-1816130 - {PUT-O-1663380} [pfaff.dev] Request failed: PUT matrix-federation://pfaff.dev/_matrix/federation/v1/send/1691757187764: HttpResponseException('404: Not Found')
2023-08-14 18:42:52,599 - synapse.util.retryutils - 234 - INFO - federation_transaction_transmission_loop-1816130 - Connection to pfaff.dev was unsuccessful (<class 'synapse.api.errors.HttpResponseException'>(404: Not Found)); backoff now 604800000
2023-08-14 18:42:52,600 - synapse.federation.sender.transaction_manager - 171 - INFO - federation_transaction_transmission_loop-1816130 - TX [pfaff.dev] {1691757187764} got 404 response
2023-08-14 18:42:52,600 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-1816130 - TX [pfaff.dev] Received 404 response to transaction: 404: Not Found
2023-08-14 18:42:52,616 - synapse.federation.sender.transaction_manager - 121 - INFO - federation_transaction_transmission_loop-1816131 - TX [pfaff.dev] {1691757187765} Sending transaction [1691757187765], (PDUs: 0, EDUs: 1)
2023-08-14 18:42:52,889 - synapse.http.matrixfederationclient - 758 - INFO - federation_transaction_transmission_loop-1816131 - {PUT-O-1663381} [pfaff.dev] Request failed: PUT matrix-federation://pfaff.dev/_matrix/federation/v1/send/1691757187765: ResponseNeverReceived:[ConnectionLost('Connection lost')]

There were other servers too obviously.

Here's how many times this server has been hammered during the past ~18 hours (well, sort of):

# grep pfaff.dev homeserver.log|wc -l
3077086

@tulir
Copy link
Member Author

tulir commented Aug 14, 2023

Just spotted #15743 in the 1.87.0 release notes which sounds suspicious, haven't found anything else that would seem related

@reivilibre reivilibre added A-Federation A-Performance Performance, both client-facing and admin-facing S-Major Major functionality / product severely impaired, no satisfactory workaround. labels Aug 15, 2023
@villepeh
Copy link
Contributor

villepeh commented Aug 15, 2023

It looks like downgrading to 1.89.0 might "fix" the issue. So it could be #15743 combined with the changes between 1.89 and 1.90rc1.

....But also remember I was celebrating early when I thought adding the configuration lines from @tulir 's first post would fix the issue. :)

I downgraded yesterday (Aug 14th).

Monolithic Synapse (no workers or Redis). Also this is a single user server

# grep federation -c homeserver.log*
homeserver.log:495866 (today)
homeserver.log.2023-08-12:603980
homeserver.log.2023-08-13:4555881
homeserver.log.2023-08-14:3794734

Note: By "today" I mean the 17 hours the day's been going on since the logs rotate midnight.

My larger Synapse HS log structure is more complicated so it was difficult to include. But downgrade seemed to help with that too.

@reivilibre it's just three of us in this thread but could this be already considered a release blocker for 1.90.0?

@waclaw66
Copy link

waclaw66 commented Aug 16, 2023

Same on my side after upgrade to 1.90.0...
obrazek

@villepeh
Copy link
Contributor

Two days into downgrading to 1.89.0.

The spam hasn't started again; Neither with my monolithic Synapse nor my other server running with workers.

@reivilibre reivilibre self-assigned this Aug 17, 2023
@Szwendacz99
Copy link

On my side there is a spam from other servers to a domain on which I had some time ago (months) server for a few days, and I was the only user there with few chats joined. Now on the same wildcard domain, but different subdomain I have another server, and it is being spammed for a few days now with more and more requests each day on port 8448 ending in 401. After I made this old domain return 403 forcibly, it calmed down.
image
The blue chart is for requests to the old domain.

I realize that dirty server/domain shutdown was not a good idea, but I did not expected such spam.

@tonkku107
Copy link

This 401 response occurring because the server has been moved to a different server name (while the old server name still directly points to the homeserver) seems to be the common link across all these cases

@clokep clokep added O-Frequent Affects or can be seen by most users regularly or impacts most users' first experience T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. labels Aug 21, 2023
@deepbluev7
Copy link
Contributor

deepbluev7 commented Aug 22, 2023

Yeah, I am experiencing this now too. These are the top servers I see in my redis in about 1 minute:

    897 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"conduit.ipflermatrix.synology.me\"],]"
    877 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP conduit.ipflermatrix.synology.me"
    694 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"lclhst.org\"],]"
    690 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP lclhst.org"
    607 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"computerlie.be\"],]"
    602 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP computerlie.be"
    571 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"alpinelinux.org\"],]"
    554 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP alpinelinux.org"
    513 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"matrix.buffadoo.nl\"],]"
    511 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP matrix.buffadoo.nl"
    500 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"mawby.eu\"],]"
    498 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"yak.atomized.org\"],]"
    488 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP mawby.eu"
    485 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP yak.atomized.org"
    238 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP chat.hypertextwaterfowl.com"
    238 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"chat.hypertextwaterfowl.com\"],]"
    226 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"matrix.helv.io\"],]"
    224 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP matrix.helv.io"
    206 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"appcenter.io\"],]"
    205 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP appcenter.io"
    158 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"ibsgaard.io\"],]"
    155 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP ibsgaard.io"
    135 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"ryu.org\"],]"
    134 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP vdh.za.net"
    134 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"vdh.za.net\"],]"
    129 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP ryu.org"
    125 . [ ...:] "PUBLISH" "neko.dev" "RDATA caches federation_sender  [\"get_destination_retry_timings\",[\"infogulch.com\"],]"
    122 . [ ...:] "PUBLISH" "neko.dev" "REMOTE_SERVER_UP infogulch.com"

(Filtered with | tr -d '[:digit:]' | sort | uniq -c | sort -r | less to remove the changing numbers for timestamps and retry timings)

deepbluev7 added a commit to deepbluev7/synapse that referenced this issue Aug 22, 2023
This was broken in 1.90 when the maximum retry interval got changed from
almost infinite to a week (and made configurable).

fixes matrix-org#16101

Signed-off-by: Nicolas Werner <[email protected]>
deepbluev7 added a commit to deepbluev7/synapse that referenced this issue Aug 22, 2023
This was broken in 1.90 when the maximum retry interval got changed from
almost infinite to a week (and made configurable).

fixes matrix-org#16101

Signed-off-by: Nicolas Werner <[email protected]>
deepbluev7 added a commit to deepbluev7/synapse that referenced this issue Aug 22, 2023
This was broken in 1.87 when the maximum retry interval got changed from
almost infinite to a week (and made configurable).

fixes matrix-org#16101

Signed-off-by: Nicolas Werner <[email protected]>
erikjohnston pushed a commit that referenced this issue Aug 23, 2023
…#16156)

* Properly update retry_last_ts when hitting the maximum retry interval

This was broken in 1.87 when the maximum retry interval got changed from
almost infinite to a week (and made configurable).

fixes #16101

Signed-off-by: Nicolas Werner <[email protected]>

* Add changelog

* Change fix + add test

* Add comment

---------

Signed-off-by: Nicolas Werner <[email protected]>
Co-authored-by: Mathieu Velten <[email protected]>
spantaleev added a commit to spantaleev/matrix-docker-ansible-deploy that referenced this issue Aug 30, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
A-Federation A-Performance Performance, both client-facing and admin-facing O-Frequent Affects or can be seen by most users regularly or impacts most users' first experience S-Major Major functionality / product severely impaired, no satisfactory workaround. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

9 participants