Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Federation sender worker not federating messages when using multiple stream writers #14928

Open
matrixbot opened this issue Dec 20, 2023 · 0 comments
Open

Federation sender worker not federating messages when using multiple stream writers #14928

matrixbot opened this issue Dec 20, 2023 · 0 comments
Labels
A-Workers O-Uncommon S-Major T-Defect

Comments

@matrixbot
Copy link
Collaborator

matrixbot commented Dec 20, 2023 •
edited
Loading

This issue has been migrated from #14928.

Description

My federation sender worker hasn't been federating outgoing messages since updating to 1.76.0rc1. Even messages sent before doing the first faster join haven't gone through. Presence and typing notifications do seem to go through. Incoming messages are being received normally.

This only happens when multiple event stream writers are configured.

Steps to reproduce

  • set up at least one federation sender
  • add multiple generic workers as event stream writers
  • try to send messages

Homeserver

tonkku.me

Synapse Version

1.76.0rc1

Installation Method

Docker (matrixdotorg/synapse)

Database

single postgresql database

Workers

Multiple workers

Platform

Running in docker containers on a server with Ubuntu 20.04.5, AMD Ryzen 5 3600, 64GB RAM.

Configuration

Using a worker setup with one main synapse instance, 4 generic workers and 1 federation sender. Presence is enabled.
Experimental features enabled:

msc3026_enabled: true
msc2815_enabled: true
msc3773_enabled: true
msc3882_enabled: true
msc3886_endpoint: 'https://rendezvous.lab.element.dev'
msc3912_enabled: true

worker configuration:

send_federation: false
federation_sender_instances:
  - federation_sender1
instance_map:
  generic_worker1:
    host: generic-worker1
    port: 9111
  generic_worker2:
    host: generic-worker2
    port: 9112
  generic_worker3:
    host: generic-worker3
    port: 9113
  generic_worker4:
    host: generic-worker4
    port: 9114
stream_writers:
  events:
    - generic_worker1
    - generic_worker2
    - generic_worker3
    - generic_worker4
redis:
  enabled: true
  host: redis

worker_app: synapse.app.federation_sender
worker_name: federation_sender1

worker_replication_host: synapse
worker_replication_http_port: 9100

worker_log_config: "/data/tonkku.me.log.config"

Relevant log output

tonkku-matrix-server-generic-worker-4 | 2023-01-27 07:50:29,215 - synapse.replication.http.send_events - 147 - INFO - POST-31712 - Got batch of events to send, last ID of batch is: $1Kq2JWRsQNYq3BdNb_D1vUPeJciH7j39-l7dFyDqhWE, sending into room: !KibRmKHfMtoXfmIqBP:tonkku.me
tonkku-matrix-server-generic-worker-4 | 2023-01-27 07:50:29,232 - synapse.access.http.9114 - 460 - INFO - POST-31712 - ::ffff:192.168.240.6 - 9114 - {None} Processed request: 0.017sec/0.001sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 149B 200 "POST /_synapse/replication/send_events/frDXoxQLuc HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:29,233 - synapse.http.client - 460 - INFO - PUT-10818 - Received response to POST http://generic-worker4:9114/_synapse/replication/send_events/frDXoxQLuc: 200
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:29,233 - synapse.replication.tcp.client - 372 - INFO - PUT-10818 - Waiting for repl stream 'events' to reach 817572 (generic_worker4)
tonkku-matrix-server-generic-worker-4 | 2023-01-27 07:50:29,237 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-725 - Streaming: events -> 817572
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:29,239 - synapse.replication.tcp.client - 384 - INFO - PUT-10818 - Finished waiting for repl stream 'events' to reach 817572 (generic_worker4)
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:29,240 - synapse.access.http.9102 - 460 - INFO - PUT-10818 - [redacted IP] - 9102 - {@tonkku:tonkku.me} Processed request: 0.049sec/0.000sec (0.005sec, 0.001sec) (0.003sec/0.013sec/15) 59B 200 "PUT /_matrix/client/r0/rooms/!KibRmKHfMtoXfmIqBP%3Atonkku.me/send/m.room.encrypted/m1674805828912.7 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.11.20 Chrome/108.0.5359.179 Electron/22.0.3 Safari/537.36" [3 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,259 - synapse.access.http.9101 - 460 - INFO - GET-12340 - [redacted IP] - 9101 - {@tonkku:tonkku.me} Processed request: 4.449sec/0.000sec (0.007sec, 0.002sec) (0.024sec/0.045sec/18) 1272B 200 "GET /_matrix/client/r0/sync?filter=6&timeout=30000&since=m788039%7E3.817456%7E1.817571%7E2.817568_20566155_2601_2123712_33123_30_7014_2345778_0_3 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.11.20 Chrome/108.0.5359.179 Electron/22.0.3 Safari/537.36" [1 dbevts]
tonkku-matrix-server  | 2023-01-27 07:50:29,452 - synapse.access.http.9100 - 460 - INFO - POST-64485 - ::ffff:192.168.240.7 - 9100 - {None} Processed request: 0.000sec/0.001sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,453 - synapse.http.client - 460 - INFO - GET-12342 - Received response to POST http://synapse:9100/_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me: 200
tonkku-matrix-server  | 2023-01-27 07:50:29,463 - synapse.access.http.8008 - 460 - INFO - POST-64484 - [redacted IP] - 8008 - {@tonkku:tonkku.me} Processed request: 0.012sec/0.001sec (0.000sec, 0.001sec) (0.001sec/0.008sec/4) 2B 200 "POST /_matrix/client/r0/rooms/!KibRmKHfMtoXfmIqBP%3Atonkku.me/read_markers HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.11.20 Chrome/108.0.5359.179 Electron/22.0.3 Safari/537.36" [0 dbevts]
tonkku-matrix-server  | 2023-01-27 07:50:29,464 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-109167 - Streaming: account_data -> 33124
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,471 - synapse.access.http.9101 - 460 - INFO - GET-12342 - [redacted IP] - 9101 - {@tonkku:tonkku.me} Processed request: 0.021sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.003sec/4) 729B 200 "GET /_matrix/client/r0/sync?filter=6&timeout=30000&since=m788039%7E3.817456%7E1.817572%7E2.817568_20566155_2601_2123712_33123_30_7014_2345778_0_3 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.11.20 Chrome/108.0.5359.179 Electron/22.0.3 Safari/537.36" [0 dbevts]
tonkku-matrix-server  | 2023-01-27 07:50:29,590 - synapse.access.http.9100 - 460 - INFO - POST-64486 - ::ffff:192.168.240.7 - 9100 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,591 - synapse.http.client - 460 - INFO - GET-12344 - Received response to POST http://synapse:9100/_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me: 200
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,892 - synapse.federation.transport.server.federation - 103 - INFO - PUT-12345 - Received txn 1673813262285 from matrix.hadallen.ca. (PDUs: 0, EDUs: 1)
tonkku-matrix-server  | 2023-01-27 07:50:29,896 - synapse.replication.http.federation - 186 - INFO - POST-64487 - Got 'm.presence' edu from matrix.hadallen.ca
tonkku-matrix-server  | 2023-01-27 07:50:29,897 - synapse.access.http.9100 - 460 - INFO - POST-64487 - ::ffff:192.168.240.7 - 9100 - {None} Processed request: 0.001sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/fed_send_edu/m.presence/jtnpiXDrUe HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,897 - synapse.http.client - 460 - INFO - PUT-12345 - Received response to POST http://synapse:9100/_synapse/replication/fed_send_edu/m.presence/jtnpiXDrUe: 200
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,907 - synapse.access.http.9101 - 460 - INFO - PUT-12345 - 24.68.83.130 - 9101 - {matrix.hadallen.ca} Processed request: 0.015sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.009sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1673813262285 HTTP/1.0" "Synapse/1.73.0" [0 dbevts]
tonkku-matrix-server-federation-sender-1 | 2023-01-27 07:50:30,172 - synapse.http.matrixfederationclient - 672 - INFO - federation_transaction_transmission_loop-393797 - {PUT-O-181577} [bancino.net] Request failed: PUT matrix://bancino.net/_matrix/federation/v1/send/1674746060146: ResponseNeverReceived:[CancelledError()]
tonkku-matrix-server-generic-worker-3 | 2023-01-27 07:50:30,760 - synapse.federation.transport.server.federation - 103 - INFO - PUT-14201 - Received txn 1674755342297 from matrix.org. (PDUs: 0, EDUs: 4)
tonkku-matrix-server  | 2023-01-27 07:50:30,764 - synapse.replication.http.federation - 186 - INFO - POST-64488 - Got 'm.device_list_update' edu from matrix.org
tonkku-matrix-server  | 2023-01-27 07:50:30,765 - synapse.replication.http.federation - 186 - INFO - POST-64489 - Got 'm.device_list_update' edu from matrix.org
tonkku-matrix-server  | 2023-01-27 07:50:30,766 - synapse.replication.http.federation - 186 - INFO - POST-64490 - Got 'm.device_list_update' edu from matrix.org
tonkku-matrix-server  | 2023-01-27 07:50:30,767 - synapse.replication.http.federation - 186 - INFO - POST-64491 - Got 'm.receipt' edu from matrix.org
tonkku-matrix-server  | 2023-01-27 07:50:30,769 - synapse.handlers.device - 1111 - INFO - POST-64488 - Received device list update for @hannahbarbarian:matrix.org, requiring resync: True. Devices: HMJZNAGOZS
tonkku-matrix-server  | 2023-01-27 07:50:30,770 - synapse.handlers.device - 1111 - INFO - POST-64489 - Received device list update for @lr7:matrix.org, requiring resync: True. Devices: WVPPLBOOFW
tonkku-matrix-server  | 2023-01-27 07:50:30,783 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-109168 - Streaming: receipts -> 2123713
tonkku-matrix-server  | 2023-01-27 07:50:30,788 - synapse.access.http.9100 - 460 - INFO - POST-64491 - ::ffff:192.168.240.5 - 9100 - {None} Processed request: 0.021sec/0.000sec (0.001sec, 0.001sec) (0.002sec/0.015sec/5) 279B 200 "POST /_synapse/replication/fed_send_edu/m.receipt/TtOesxZXle HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-3 | 2023-01-27 07:50:30,789 - synapse.http.client - 460 - INFO - PUT-14201 - Received response to POST http://synapse:9100/_synapse/replication/fed_send_edu/m.receipt/TtOesxZXle: 200
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:30,794 - synapse.access.http.9101 - 460 - INFO - GET-12344 - [redacted IP] - 9101 - {@tonkku:tonkku.me} Processed request: 1.205sec/0.000sec (0.003sec, 0.000sec) (0.001sec/0.006sec/4) 780B 200 "GET /_matrix/client/r0/sync?filter=6&timeout=30000&since=m788039%7E3.817456%7E1.817572%7E2.817568_20566155_2601_2123712_33124_30_7014_2345778_0_3 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.11.20 Chrome/108.0.5359.179 Electron/22.0.3 Safari/537.36" [0 dbevts]
tonkku-matrix-server-federation-sender-1 | 2023-01-27 07:50:30,864 - synapse.http.matrixfederationclient - 672 - INFO - federation_transaction_transmission_loop-392140 - {PUT-O-180948} [synapsis.nadir.org] Request failed: PUT matrix://synapsis.nadir.org/_matrix/federation/v1/send/1674746059517: ResponseNeverReceived:[CancelledError()]
tonkku-matrix-server  | 2023-01-27 07:50:30,939 - synapse.access.http.9100 - 460 - INFO - POST-64492 - ::ffff:192.168.240.7 - 9100 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:30,940 - synapse.http.client - 460 - INFO - GET-12347 - Received response to POST http://synapse:9100/_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me: 200
tonkku-matrix-server  | 2023-01-27 07:50:31,086 - synapse.access.http.8008 - 460 - INFO - GET-64493 - 2a00:1098:84:1c8::158 - 8008 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 301B 200 "GET /_matrix/key/v2/server HTTP/1.0" "Synapse/1.76.0rc1 (b=matrix-org-hotfixes,484db60cd6)" [0 dbevts]
tonkku-matrix-server  | 2023-01-27 07:50:31,149 - synapse.http.matrixfederationclient - 299 - INFO - POST-64488 - {GET-O-141113} [matrix.org] Completed request: 200 OK in 0.38 secs, got 1892 bytes - GET matrix://matrix.org/_matrix/federation/v1/user/devices/%40hannahbarbarian%3Amatrix.org
tonkku-matrix-server  | 2023-01-27 07:50:31,150 - root - 1352 - INFO - POST-64488 - Skipping device list resync for @hannahbarbarian:matrix.org, as our cache matches already
tonkku-matrix-server  | 2023-01-27 07:50:31,151 - synapse.access.http.9100 - 460 - INFO - POST-64488 - ::ffff:192.168.240.5 - 9100 - {None} Processed request: 0.387sec/0.000sec (0.001sec, 0.001sec) (0.001sec/0.002sec/3) 279B 200 "POST /_synapse/replication/fed_send_edu/m.device_list_update/eIFEReVCkH HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-3 | 2023-01-27 07:50:31,152 - synapse.http.client - 460 - INFO - PUT-14201 - Received response to POST http://synapse:9100/_synapse/replication/fed_send_edu/m.device_list_update/eIFEReVCkH: 200
tonkku-matrix-server-federation-sender-1 | 2023-01-27 07:50:31,312 - synapse.http.federation.matrix_federation_agent - 363 - INFO - federation_transaction_transmission_loop-396260 - Failed to connect to eggy.cc:8448: User timeout caused connection failure.
tonkku-matrix-server-federation-sender-1 | 2023-01-27 07:50:31,313 - synapse.http.matrixfederationclient - 672 - INFO - federation_transaction_transmission_loop-396260 - {PUT-O-182682} [eggy.cc] Request failed: PUT matrix://eggy.cc/_matrix/federation/v1/send/1674746061248: TimeoutError('')
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:31,967 - synapse.federation.transport.server.federation - 103 - INFO - PUT-12348 - Received txn 1673566981718 from gruenhage.xyz. (PDUs: 0, EDUs: 1)
tonkku-matrix-server  | 2023-01-27 07:50:31,970 - synapse.replication.http.federation - 186 - INFO - POST-64494 - Got 'm.presence' edu from gruenhage.xyz
tonkku-matrix-server  | 2023-01-27 07:50:31,971 - synapse.access.http.9100 - 460 - INFO - POST-64494 - ::ffff:192.168.240.7 - 9100 - {None} Processed request: 0.001sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/fed_send_edu/m.presence/mwocLhmkrK HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:31,971 - synapse.http.client - 460 - INFO - PUT-12348 - Received response to POST http://synapse:9100/_synapse/replication/fed_send_edu/m.presence/mwocLhmkrK: 200
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:31,985 - synapse.access.http.9101 - 460 - INFO - PUT-12348 - 109.250.36.91 - 9101 - {gruenhage.xyz} Processed request: 0.019sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.013sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1673566981718 HTTP/1.0" "Synapse/1.74.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:32,695 - synapse.federation.transport.server.federation - 103 - INFO - PUT-10819 - Received txn 1674647102137 from strahlungsfrei.de. (PDUs: 0, EDUs: 1)
tonkku-matrix-server  | 2023-01-27 07:50:32,698 - synapse.replication.http.federation - 186 - INFO - POST-64495 - Got 'm.presence' edu from strahlungsfrei.de
tonkku-matrix-server  | 2023-01-27 07:50:32,710 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-109169 - Streaming: presence -> 20566156
tonkku-matrix-server  | 2023-01-27 07:50:32,713 - synapse.access.http.9100 - 460 - INFO - POST-64495 - ::ffff:192.168.240.6 - 9100 - {None} Processed request: 0.015sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.011sec/3) 279B 200 "POST /_synapse/replication/fed_send_edu/m.presence/tAVsrPDqdu HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:32,714 - synapse.http.client - 460 - INFO - PUT-10819 - Received response to POST http://synapse:9100/_synapse/replication/fed_send_edu/m.presence/tAVsrPDqdu: 200
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:32,716 - synapse.access.http.9101 - 460 - INFO - GET-12347 - [redacted IP] - 9101 - {@tonkku:tonkku.me} Processed request: 1.779sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.002sec/3) 425B 200 "GET /_matrix/client/r0/sync?filter=6&timeout=30000&since=m788039%7E3.817456%7E1.817572%7E2.817568_20566155_2601_2123713_33124_30_7014_2345778_0_3 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.11.20 Chrome/108.0.5359.179 Electron/22.0.3 Safari/537.36" [0 dbevts]
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:32,717 - synapse.access.http.9102 - 460 - INFO - PUT-10819 - 37.221.197.227 - 9102 - {strahlungsfrei.de} Processed request: 0.022sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.002sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1674647102137 HTTP/1.0" "Synapse/1.75.0" [0 dbevts]
tonkku-matrix-server  | 2023-01-27 07:50:32,952 - synapse.access.http.9100 - 460 - INFO - POST-64496 - ::ffff:192.168.240.7 - 9100 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:32,952 - synapse.http.client - 460 - INFO - GET-12350 - Received response to POST http://synapse:9100/_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me: 200
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:33,864 - synapse.federation.transport.server.federation - 103 - INFO - PUT-10820 - Received txn 1674646692320 from roastburry.com. (PDUs: 0, EDUs: 1)
tonkku-matrix-server  | 2023-01-27 07:50:33,867 - synapse.replication.http.federation - 186 - INFO - POST-64497 - Got 'm.presence' edu from roastburry.com
tonkku-matrix-server  | 2023-01-27 07:50:33,868 - synapse.access.http.9100 - 460 - INFO - POST-64497 - ::ffff:192.168.240.6 - 9100 - {None} Processed request: 0.001sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/fed_send_edu/m.presence/LBeYTSWDXP HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:33,869 - synapse.http.client - 460 - INFO - PUT-10820 - Received response to POST http://synapse:9100/_synapse/replication/fed_send_edu/m.presence/LBeYTSWDXP: 200
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:33,875 - synapse.access.http.9102 - 460 - INFO - PUT-10820 - 99.46.147.41 - 9102 - {roastburry.com} Processed request: 0.012sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.006sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1674646692320 HTTP/1.0" "Synapse/1.74.0" [0 dbevts]tonkku-matrix-server-generic-worker-4 | 2023-01-27 07:50:29,215 - synapse.replication.http.send_events - 147 - INFO - POST-31712 - Got batch of events to send, last ID of batch is: $1Kq2JWRsQNYq3BdNb_D1vUPeJciH7j39-l7dFyDqhWE, sending into room: !KibRmKHfMtoXfmIqBP:tonkku.me
tonkku-matrix-server-generic-worker-4 | 2023-01-27 07:50:29,232 - synapse.access.http.9114 - 460 - INFO - POST-31712 - ::ffff:192.168.240.6 - 9114 - {None} Processed request: 0.017sec/0.001sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 149B 200 "POST /_synapse/replication/send_events/frDXoxQLuc HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:29,233 - synapse.http.client - 460 - INFO - PUT-10818 - Received response to POST http://generic-worker4:9114/_synapse/replication/send_events/frDXoxQLuc: 200
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:29,233 - synapse.replication.tcp.client - 372 - INFO - PUT-10818 - Waiting for repl stream 'events' to reach 817572 (generic_worker4)
tonkku-matrix-server-generic-worker-4 | 2023-01-27 07:50:29,237 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-725 - Streaming: events -> 817572
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:29,239 - synapse.replication.tcp.client - 384 - INFO - PUT-10818 - Finished waiting for repl stream 'events' to reach 817572 (generic_worker4)
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:29,240 - synapse.access.http.9102 - 460 - INFO - PUT-10818 - [redacted IP] - 9102 - {@tonkku:tonkku.me} Processed request: 0.049sec/0.000sec (0.005sec, 0.001sec) (0.003sec/0.013sec/15) 59B 200 "PUT /_matrix/client/r0/rooms/!KibRmKHfMtoXfmIqBP%3Atonkku.me/send/m.room.encrypted/m1674805828912.7 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.11.20 Chrome/108.0.5359.179 Electron/22.0.3 Safari/537.36" [3 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,259 - synapse.access.http.9101 - 460 - INFO - GET-12340 - [redacted IP] - 9101 - {@tonkku:tonkku.me} Processed request: 4.449sec/0.000sec (0.007sec, 0.002sec) (0.024sec/0.045sec/18) 1272B 200 "GET /_matrix/client/r0/sync?filter=6&timeout=30000&since=m788039%7E3.817456%7E1.817571%7E2.817568_20566155_2601_2123712_33123_30_7014_2345778_0_3 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.11.20 Chrome/108.0.5359.179 Electron/22.0.3 Safari/537.36" [1 dbevts]
tonkku-matrix-server  | 2023-01-27 07:50:29,452 - synapse.access.http.9100 - 460 - INFO - POST-64485 - ::ffff:192.168.240.7 - 9100 - {None} Processed request: 0.000sec/0.001sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,453 - synapse.http.client - 460 - INFO - GET-12342 - Received response to POST http://synapse:9100/_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me: 200
tonkku-matrix-server  | 2023-01-27 07:50:29,463 - synapse.access.http.8008 - 460 - INFO - POST-64484 - [redacted IP] - 8008 - {@tonkku:tonkku.me} Processed request: 0.012sec/0.001sec (0.000sec, 0.001sec) (0.001sec/0.008sec/4) 2B 200 "POST /_matrix/client/r0/rooms/!KibRmKHfMtoXfmIqBP%3Atonkku.me/read_markers HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.11.20 Chrome/108.0.5359.179 Electron/22.0.3 Safari/537.36" [0 dbevts]
tonkku-matrix-server  | 2023-01-27 07:50:29,464 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-109167 - Streaming: account_data -> 33124
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,471 - synapse.access.http.9101 - 460 - INFO - GET-12342 - [redacted IP] - 9101 - {@tonkku:tonkku.me} Processed request: 0.021sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.003sec/4) 729B 200 "GET /_matrix/client/r0/sync?filter=6&timeout=30000&since=m788039%7E3.817456%7E1.817572%7E2.817568_20566155_2601_2123712_33123_30_7014_2345778_0_3 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.11.20 Chrome/108.0.5359.179 Electron/22.0.3 Safari/537.36" [0 dbevts]
tonkku-matrix-server  | 2023-01-27 07:50:29,590 - synapse.access.http.9100 - 460 - INFO - POST-64486 - ::ffff:192.168.240.7 - 9100 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,591 - synapse.http.client - 460 - INFO - GET-12344 - Received response to POST http://synapse:9100/_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me: 200
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,892 - synapse.federation.transport.server.federation - 103 - INFO - PUT-12345 - Received txn 1673813262285 from matrix.hadallen.ca. (PDUs: 0, EDUs: 1)
tonkku-matrix-server  | 2023-01-27 07:50:29,896 - synapse.replication.http.federation - 186 - INFO - POST-64487 - Got 'm.presence' edu from matrix.hadallen.ca
tonkku-matrix-server  | 2023-01-27 07:50:29,897 - synapse.access.http.9100 - 460 - INFO - POST-64487 - ::ffff:192.168.240.7 - 9100 - {None} Processed request: 0.001sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/fed_send_edu/m.presence/jtnpiXDrUe HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,897 - synapse.http.client - 460 - INFO - PUT-12345 - Received response to POST http://synapse:9100/_synapse/replication/fed_send_edu/m.presence/jtnpiXDrUe: 200
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:29,907 - synapse.access.http.9101 - 460 - INFO - PUT-12345 - 24.68.83.130 - 9101 - {matrix.hadallen.ca} Processed request: 0.015sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.009sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1673813262285 HTTP/1.0" "Synapse/1.73.0" [0 dbevts]
tonkku-matrix-server-federation-sender-1 | 2023-01-27 07:50:30,172 - synapse.http.matrixfederationclient - 672 - INFO - federation_transaction_transmission_loop-393797 - {PUT-O-181577} [bancino.net] Request failed: PUT matrix://bancino.net/_matrix/federation/v1/send/1674746060146: ResponseNeverReceived:[CancelledError()]
tonkku-matrix-server-generic-worker-3 | 2023-01-27 07:50:30,760 - synapse.federation.transport.server.federation - 103 - INFO - PUT-14201 - Received txn 1674755342297 from matrix.org. (PDUs: 0, EDUs: 4)
tonkku-matrix-server  | 2023-01-27 07:50:30,764 - synapse.replication.http.federation - 186 - INFO - POST-64488 - Got 'm.device_list_update' edu from matrix.org
tonkku-matrix-server  | 2023-01-27 07:50:30,765 - synapse.replication.http.federation - 186 - INFO - POST-64489 - Got 'm.device_list_update' edu from matrix.org
tonkku-matrix-server  | 2023-01-27 07:50:30,766 - synapse.replication.http.federation - 186 - INFO - POST-64490 - Got 'm.device_list_update' edu from matrix.org
tonkku-matrix-server  | 2023-01-27 07:50:30,767 - synapse.replication.http.federation - 186 - INFO - POST-64491 - Got 'm.receipt' edu from matrix.org
tonkku-matrix-server  | 2023-01-27 07:50:30,769 - synapse.handlers.device - 1111 - INFO - POST-64488 - Received device list update for @hannahbarbarian:matrix.org, requiring resync: True. Devices: HMJZNAGOZS
tonkku-matrix-server  | 2023-01-27 07:50:30,770 - synapse.handlers.device - 1111 - INFO - POST-64489 - Received device list update for @lr7:matrix.org, requiring resync: True. Devices: WVPPLBOOFW
tonkku-matrix-server  | 2023-01-27 07:50:30,783 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-109168 - Streaming: receipts -> 2123713
tonkku-matrix-server  | 2023-01-27 07:50:30,788 - synapse.access.http.9100 - 460 - INFO - POST-64491 - ::ffff:192.168.240.5 - 9100 - {None} Processed request: 0.021sec/0.000sec (0.001sec, 0.001sec) (0.002sec/0.015sec/5) 279B 200 "POST /_synapse/replication/fed_send_edu/m.receipt/TtOesxZXle HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-3 | 2023-01-27 07:50:30,789 - synapse.http.client - 460 - INFO - PUT-14201 - Received response to POST http://synapse:9100/_synapse/replication/fed_send_edu/m.receipt/TtOesxZXle: 200
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:30,794 - synapse.access.http.9101 - 460 - INFO - GET-12344 - [redacted IP] - 9101 - {@tonkku:tonkku.me} Processed request: 1.205sec/0.000sec (0.003sec, 0.000sec) (0.001sec/0.006sec/4) 780B 200 "GET /_matrix/client/r0/sync?filter=6&timeout=30000&since=m788039%7E3.817456%7E1.817572%7E2.817568_20566155_2601_2123712_33124_30_7014_2345778_0_3 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.11.20 Chrome/108.0.5359.179 Electron/22.0.3 Safari/537.36" [0 dbevts]
tonkku-matrix-server-federation-sender-1 | 2023-01-27 07:50:30,864 - synapse.http.matrixfederationclient - 672 - INFO - federation_transaction_transmission_loop-392140 - {PUT-O-180948} [synapsis.nadir.org] Request failed: PUT matrix://synapsis.nadir.org/_matrix/federation/v1/send/1674746059517: ResponseNeverReceived:[CancelledError()]
tonkku-matrix-server  | 2023-01-27 07:50:30,939 - synapse.access.http.9100 - 460 - INFO - POST-64492 - ::ffff:192.168.240.7 - 9100 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:30,940 - synapse.http.client - 460 - INFO - GET-12347 - Received response to POST http://synapse:9100/_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me: 200
tonkku-matrix-server  | 2023-01-27 07:50:31,086 - synapse.access.http.8008 - 460 - INFO - GET-64493 - 2a00:1098:84:1c8::158 - 8008 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 301B 200 "GET /_matrix/key/v2/server HTTP/1.0" "Synapse/1.76.0rc1 (b=matrix-org-hotfixes,484db60cd6)" [0 dbevts]
tonkku-matrix-server  | 2023-01-27 07:50:31,149 - synapse.http.matrixfederationclient - 299 - INFO - POST-64488 - {GET-O-141113} [matrix.org] Completed request: 200 OK in 0.38 secs, got 1892 bytes - GET matrix://matrix.org/_matrix/federation/v1/user/devices/%40hannahbarbarian%3Amatrix.org
tonkku-matrix-server  | 2023-01-27 07:50:31,150 - root - 1352 - INFO - POST-64488 - Skipping device list resync for @hannahbarbarian:matrix.org, as our cache matches already
tonkku-matrix-server  | 2023-01-27 07:50:31,151 - synapse.access.http.9100 - 460 - INFO - POST-64488 - ::ffff:192.168.240.5 - 9100 - {None} Processed request: 0.387sec/0.000sec (0.001sec, 0.001sec) (0.001sec/0.002sec/3) 279B 200 "POST /_synapse/replication/fed_send_edu/m.device_list_update/eIFEReVCkH HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-3 | 2023-01-27 07:50:31,152 - synapse.http.client - 460 - INFO - PUT-14201 - Received response to POST http://synapse:9100/_synapse/replication/fed_send_edu/m.device_list_update/eIFEReVCkH: 200
tonkku-matrix-server-federation-sender-1 | 2023-01-27 07:50:31,312 - synapse.http.federation.matrix_federation_agent - 363 - INFO - federation_transaction_transmission_loop-396260 - Failed to connect to eggy.cc:8448: User timeout caused connection failure.
tonkku-matrix-server-federation-sender-1 | 2023-01-27 07:50:31,313 - synapse.http.matrixfederationclient - 672 - INFO - federation_transaction_transmission_loop-396260 - {PUT-O-182682} [eggy.cc] Request failed: PUT matrix://eggy.cc/_matrix/federation/v1/send/1674746061248: TimeoutError('')
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:31,967 - synapse.federation.transport.server.federation - 103 - INFO - PUT-12348 - Received txn 1673566981718 from gruenhage.xyz. (PDUs: 0, EDUs: 1)
tonkku-matrix-server  | 2023-01-27 07:50:31,970 - synapse.replication.http.federation - 186 - INFO - POST-64494 - Got 'm.presence' edu from gruenhage.xyz
tonkku-matrix-server  | 2023-01-27 07:50:31,971 - synapse.access.http.9100 - 460 - INFO - POST-64494 - ::ffff:192.168.240.7 - 9100 - {None} Processed request: 0.001sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/fed_send_edu/m.presence/mwocLhmkrK HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:31,971 - synapse.http.client - 460 - INFO - PUT-12348 - Received response to POST http://synapse:9100/_synapse/replication/fed_send_edu/m.presence/mwocLhmkrK: 200
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:31,985 - synapse.access.http.9101 - 460 - INFO - PUT-12348 - 109.250.36.91 - 9101 - {gruenhage.xyz} Processed request: 0.019sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.013sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1673566981718 HTTP/1.0" "Synapse/1.74.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:32,695 - synapse.federation.transport.server.federation - 103 - INFO - PUT-10819 - Received txn 1674647102137 from strahlungsfrei.de. (PDUs: 0, EDUs: 1)
tonkku-matrix-server  | 2023-01-27 07:50:32,698 - synapse.replication.http.federation - 186 - INFO - POST-64495 - Got 'm.presence' edu from strahlungsfrei.de
tonkku-matrix-server  | 2023-01-27 07:50:32,710 - synapse.replication.tcp.resource - 193 - INFO - replication_notifier-109169 - Streaming: presence -> 20566156
tonkku-matrix-server  | 2023-01-27 07:50:32,713 - synapse.access.http.9100 - 460 - INFO - POST-64495 - ::ffff:192.168.240.6 - 9100 - {None} Processed request: 0.015sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.011sec/3) 279B 200 "POST /_synapse/replication/fed_send_edu/m.presence/tAVsrPDqdu HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:32,714 - synapse.http.client - 460 - INFO - PUT-10819 - Received response to POST http://synapse:9100/_synapse/replication/fed_send_edu/m.presence/tAVsrPDqdu: 200
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:32,716 - synapse.access.http.9101 - 460 - INFO - GET-12347 - [redacted IP] - 9101 - {@tonkku:tonkku.me} Processed request: 1.779sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.002sec/3) 425B 200 "GET /_matrix/client/r0/sync?filter=6&timeout=30000&since=m788039%7E3.817456%7E1.817572%7E2.817568_20566155_2601_2123713_33124_30_7014_2345778_0_3 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.11.20 Chrome/108.0.5359.179 Electron/22.0.3 Safari/537.36" [0 dbevts]
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:32,717 - synapse.access.http.9102 - 460 - INFO - PUT-10819 - 37.221.197.227 - 9102 - {strahlungsfrei.de} Processed request: 0.022sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.002sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1674647102137 HTTP/1.0" "Synapse/1.75.0" [0 dbevts]
tonkku-matrix-server  | 2023-01-27 07:50:32,952 - synapse.access.http.9100 - 460 - INFO - POST-64496 - ::ffff:192.168.240.7 - 9100 - {None} Processed request: 0.000sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-1 | 2023-01-27 07:50:32,952 - synapse.http.client - 460 - INFO - GET-12350 - Received response to POST http://synapse:9100/_synapse/replication/presence_set_state/%40tonkku%3Atonkku.me: 200
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:33,864 - synapse.federation.transport.server.federation - 103 - INFO - PUT-10820 - Received txn 1674646692320 from roastburry.com. (PDUs: 0, EDUs: 1)
tonkku-matrix-server  | 2023-01-27 07:50:33,867 - synapse.replication.http.federation - 186 - INFO - POST-64497 - Got 'm.presence' edu from roastburry.com
tonkku-matrix-server  | 2023-01-27 07:50:33,868 - synapse.access.http.9100 - 460 - INFO - POST-64497 - ::ffff:192.168.240.6 - 9100 - {None} Processed request: 0.001sec/0.000sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 279B 200 "POST /_synapse/replication/fed_send_edu/m.presence/LBeYTSWDXP HTTP/1.1" "Synapse/1.76.0rc1" [0 dbevts]
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:33,869 - synapse.http.client - 460 - INFO - PUT-10820 - Received response to POST http://synapse:9100/_synapse/replication/fed_send_edu/m.presence/LBeYTSWDXP: 200
tonkku-matrix-server-generic-worker-2 | 2023-01-27 07:50:33,875 - synapse.access.http.9102 - 460 - INFO - PUT-10820 - 99.46.147.41 - 9102 - {roastburry.com} Processed request: 0.012sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.006sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1674646692320 HTTP/1.0" "Synapse/1.74.0" [0 dbevts]

Anything else that would be useful to know?

The logs are a snippet of a few seconds starting from sending a message to a room with members from matrix.org and kde.org. You can see that an outgoing federation request is never even attempted to either of those servers
@matrixbot matrixbot changed the title Dummy issue Federation sender worker not federating messages when using multiple stream writers Dec 21, 2023
@matrixbot matrixbot reopened this Dec 21, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
A-Workers O-Uncommon S-Major T-Defect
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@matrixbot