Federation spams 404 response warnings until disk is full

[bessw]

Description

Since the update to v1.90.0 Synapse sometimes logs more than 50 lines of federation warnings per second until my disk is full (ca. 7 gigabytes in a few hours). This is the second time in a few days that this happens.

It looks like its endlessly retrying to send a message to a server that responds with 404.

Steps to reproduce

• run synapse v1.90.0 and don't look at disk usage

expected:

• Synapse should not generate that many warnings
• If a server returns 404 synapse should backoff and try later. Also mentioned in we should backoff on 40x errors #5442

Homeserver

Private homeserver

Synapse Version

v1.90.0

Installation Method

Docker (matrixdotorg/synapse)

Database

single PostgreSQL server, ported from SQLite using "matrix-docker-ansible-deploy"s "import-synapse-sqlite-db" (uses portdb script internally)

Workers

Single process

Platform

Debian, vServer

installed with matrix-docker-ansible-deploy

Configuration

# data path
matrix_base_data_path: '/opt/matrix'

matrix_playbook_docker_installation_enabled: false

# The bare domain name which represents your Matrix identity.
# Matrix user ids for your server will be of the form (`@user:<matrix-domain>`).
#
# Note: this playbook does not touch the server referenced here.
# Installation happens on another server ("matrix.<matrix-domain>").
matrix_domain: mydomain.tld

##############################
# reverse proxy config

## enable trafik
matrix_playbook_reverse_proxy_type: playbook-managed-traefik

# automatic ACME / Let's Encrypt cert renewal.
devture_traefik_config_certificatesResolvers_acme_enabled: true
devture_traefik_config_certificatesResolvers_acme_use_staging: false
devture_traefik_config_certificatesResolvers_acme_email: myemail@example.com

#
#[removed additional custom certificatesResolver because this is not relevant for the issue]
#

# end reverse proxy config
#############################

# A list of 3PID types which users must supply when registering (possible values: email, msisdn).
matrix_synapse_registrations_require_3pid: [
  'email'
]

# Whether clients can request to include message content in push notifications
# sent through third party servers. Setting this to false requires mobile clients
# to load message content directly from the homeserver.
matrix_synapse_push_include_content: false

## public room directory to allow userers to view spaces
matrix_synapse_allow_public_rooms_without_auth: true
matrix_synapse_allow_public_rooms_over_federation: true

######################
## my optional configs
######################

# decrease disk usage by system journal
matrix_nginx_proxy_access_log_enabled: false
devture_traefik_config_accessLog_enabled: false

matrix_bot_maubot_enabled: true
matrix_bot_maubot_admins:
  - me: <redacted>

######################
# secrets
######################

# A shared secret (between Coturn and Synapse) used for authentication.
matrix_coturn_turn_static_auth_secret: <redacted>

# A secret used to protect access keys issued by the server.
matrix_synapse_macaroon_secret_key: <redacted>

# Update from 1.48.0 to 1.49.1 requires matrix_homeserver_generic_secret_key, for backword compatibility set it to matrix_synapse_macaroon_secret_key
matrix_homeserver_generic_secret_key: "{{ matrix_synapse_macaroon_secret_key }}"

# A Postgres password to use for the superuser Postgres user (called `matrix` by default).
#
# The playbook creates additional Postgres users and databases (one for each enabled service)
# using this superuser account.
devture_postgres_connection_password: <redacted>

Relevant log output

Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,282 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843687 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,316 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126244 - {PUT-O-19748951} [khoa.cool] Request failed: PUT matrix-federation://khoa.cool/_matrix/federation/v1/send/1692749941951: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,317 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126244 - TX [khoa.cool] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,324 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126245 - {PUT-O-19748952} [lazycat.casa] Request failed: PUT matrix-federation://lazycat.casa/_matrix/federation/v1/send/1692749941952: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,325 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126245 - TX [lazycat.casa] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,333 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843688 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,337 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843689 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,355 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126246 - {PUT-O-19748953} [khoa.cool] Request failed: PUT matrix-federation://khoa.cool/_matrix/federation/v1/send/1692749941953: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,356 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126246 - TX [khoa.cool] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,359 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126247 - {PUT-O-19748954} [lazycat.casa] Request failed: PUT matrix-federation://lazycat.casa/_matrix/federation/v1/send/1692749941954: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,359 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126247 - TX [lazycat.casa] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,381 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843690 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,397 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843691 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,419 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126248 - {PUT-O-19748955} [khoa.cool] Request failed: PUT matrix-federation://khoa.cool/_matrix/federation/v1/send/1692749941955: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,420 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126248 - TX [khoa.cool] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,430 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126249 - {PUT-O-19748956} [lazycat.casa] Request failed: PUT matrix-federation://lazycat.casa/_matrix/federation/v1/send/1692749941956: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,431 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126249 - TX [lazycat.casa] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,435 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843692 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,443 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843693 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,459 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126250 - {PUT-O-19748957} [khoa.cool] Request failed: PUT matrix-federation://khoa.cool/_matrix/federation/v1/send/1692749941957: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,460 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126250 - TX [khoa.cool] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,463 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126251 - {PUT-O-19748958} [lazycat.casa] Request failed: PUT matrix-federation://lazycat.casa/_matrix/federation/v1/send/1692749941958: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,464 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126251 - TX [lazycat.casa] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,483 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843694 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,494 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843695 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,517 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126252 - {PUT-O-19748959} [khoa.cool] Request failed: PUT matrix-federation://khoa.cool/_matrix/federation/v1/send/1692749941959: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,518 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126252 - TX [khoa.cool] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,520 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126253 - {PUT-O-19748960} [lazycat.casa] Request failed: PUT matrix-federation://lazycat.casa/_matrix/federation/v1/send/1692749941960: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,521 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126253 - TX [lazycat.casa] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,535 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843696 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,541 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843697 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,557 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126254 - {PUT-O-19748961} [khoa.cool] Request failed: PUT matrix-federation://khoa.cool/_matrix/federation/v1/send/1692749941961: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,558 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126254 - TX [khoa.cool] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,561 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126255 - {PUT-O-19748962} [lazycat.casa] Request failed: PUT matrix-federation://lazycat.casa/_matrix/federation/v1/send/1692749941962: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,562 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126255 - TX [lazycat.casa] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,571 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843698 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,576 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843699 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,605 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126257 - {PUT-O-19748963} [lazycat.casa] Request failed: PUT matrix-federation://lazycat.casa/_matrix/federation/v1/send/1692749941963: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,605 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126257 - TX [lazycat.casa] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,610 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126256 - {PUT-O-19748964} [khoa.cool] Request failed: PUT matrix-federation://khoa.cool/_matrix/federation/v1/send/1692749941964: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,611 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126256 - TX [khoa.cool] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,619 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843700 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,624 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843701 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,646 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126258 - {PUT-O-19748965} [lazycat.casa] Request failed: PUT matrix-federation://lazycat.casa/_matrix/federation/v1/send/1692749941965: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,647 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126258 - TX [lazycat.casa] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,649 - synapse.http.matrixfederationclient - 805 - WARNING - federation_transaction_transmission_loop-19126259 - {PUT-O-19748966} [khoa.cool] Request failed: PUT matrix-federation://khoa.cool/_matrix/federation/v1/send/1692749941966: HttpResponseException('404: Not Found')
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,650 - synapse.federation.sender.per_destination_queue - 399 - WARNING - federation_transaction_transmission_loop-19126259 - TX [khoa.cool] Received 404 response to transaction: 404: Not Found
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,659 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843702 - Dropping command as not connected: 'REMOTE_SERVER_UP'
Aug 27 00:00:38 v22018117241777004 matrix-synapse[1244]: 2023-08-26 22:00:38,664 - synapse.replication.tcp.handler - 733 - WARNING - store_retry_timings-18843703 - Dropping command as not connected: 'REMOTE_SERVER_UP'

Anything else that would be useful to know?

No response

[gabrc52]

I'm unsure if it's the same cause but I do have several federation log lines and

$ du -sh /var/log/matrix-synapse/
44G	/var/log/matrix-synapse/

[DMRobertson]

This looks like #16101 which is should be fixed by #16156. The fix should arrive in Synapse 1.91, which is due to be released today. When it's released, could you try upgrading to that version and confirm that it stops the log spam?

[xundeenergie]

I run obviously into the same bug with 1.78 from debian bookworm repo.

Updated to 1.91 vom matrix repo for debian bookworm, and it seems, this fixed the problem.

[bessw]

matrix-docker-ansible-deploy did a config level fix shortly before 1.91 came out so I can't tell for sure what fixed it, but it doesn't spam the logs any more. Thanks for your effort.