search

matrix-org / synapse

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

Clients repeatedly losing connection for up to a minute #12547

Closed prurigro closed 2 years ago

prurigro commented 2 years ago

Apologies if this isn't actually a bug, but my server had been running well until updating a couple of weeks ago. Unfortunately I didn't catch the exact version as I was travelling and didn't notice the issue between a number of updates.

Description

Throughout the day, clients will show a message saying that they can't connect to the server for ~30 seconds to a minute. Every time I've checked the current log to see what's up it's shown the following:

synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 1
synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 2

Steps to reproduce

I've noticed that synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 1 will appear in the logs on its own and I won't have any connectivity issues when that happens.

Version information

I could probably provide more information about behaviour if I know what I'm looking for.

Thanks for your time and for all the work on this project!

H-Shay commented 2 years ago

Thanks for reporting! A little more information might be helpful: can you tell me what client(s) you are using? Approximately how long do you need to be connected before this error occurs? How often is this occurring? Can you add some logs showing the lines before and after the lines you have provided, so that there is a little context on what is happening? Do you happen to know what version of python the homeserver is running on?

prurigro commented 2 years ago

Hi, thanks for the speedy response!

Everyone I've confirmed is experiencing this (including myself) is using element on android or desktop (macos, windows and linux).

The outages occur periodically throughout the day, sometimes multiple times per hour, sometimes once every few hours. One person noticed that if I haven't restarted the server for a few days the issues will occur more frequently around the same times each day (I haven't been tracking them closely enough to confirm this is the case).

I noticed the issue at 2:48pm today and found the gc lines in the log so I'm fairly certain these are the ones, but let's hold off on assuming these are definitely associated with the issue and wait until I catch the logging out put while it's in the act. (I'm just sharing in case you notice something unexpected in there).

2022-04-26 14:48:12,540 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
2022-04-26 14:48:12,699 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
2022-04-26 14:48:16,649 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
2022-04-26 14:48:16,653 - synapse.federation.transport.server.federation - 102 - INFO - PUT-75127 - Received txn 1650493047374 from ravne.land. (PDUs: 0, EDUs: 1)
2022-04-26 14:48:16,666 - synapse.access.http.8008 - 427 - INFO - PUT-75127 - redacted - 8008 - {ravne.land} Processed request: 0.015sec/0.001sec (0.003sec, 0.000sec) (0.001sec/0.009sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650493047374 HTTP/1.0" "Synapse/1.57.
2022-04-26 14:48:17,880 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
2022-04-26 14:48:17,882 - synapse.federation.transport.server.federation - 102 - INFO - PUT-75128 - Received txn 1650996433009 from fachschaften.org. (PDUs: 0, EDUs: 1)
2022-04-26 14:48:17,889 - synapse.access.http.8008 - 427 - INFO - PUT-75128 - redacted - 8008 - {fachschaften.org} Processed request: 0.007sec/0.000sec (0.002sec, 0.000sec) (0.001sec/0.003sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650996433009 HTTP/1.0" "Synapse
2022-04-26 14:48:18,026 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
2022-04-26 14:48:18,029 - synapse.federation.transport.server.federation - 102 - INFO - PUT-75129 - Received txn 1650403458056 from chapo.chat. (PDUs: 0, EDUs: 1)
2022-04-26 14:48:18,042 - synapse.access.http.8008 - 427 - INFO - PUT-75129 - redacted - 8008 - {chapo.chat} Processed request: 0.014sec/0.000sec (0.001sec, 0.002sec) (0.001sec/0.009sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650403458056 HTTP/1.0" "Synapse/1.47.1
2022-04-26 14:48:18,693 - synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 1
2022-04-26 14:48:18,793 - synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 2
2022-04-26 14:48:29,128 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
2022-04-26 14:48:29,130 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
2022-04-26 14:48:29,131 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https

The version of python is 3.10.4

Thanks again!

EDIT: So far today all the drops have been short enough that messages don't even seem delayed- I'm waiting for downtime like last night to happen again where it's unresponsive for half a minute or more.

prurigro commented 2 years ago

OK, finally caught a minute-long disconnect in progress! 11:44:12,393 is the timestamp I caught while everything was completely locked up:

Apr 27 11:44:11 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:11,845 - synapse.http.matrixfederationclient - 285 - INFO - federation_transaction_transmission_loop-60791 - {PUT-O-303980} [synod.im] Completed request: 200 OK in 0.36 secs, got 11 bytes - PUT matrix://synod.im/_matrix/federation/v1/send/1650947504872
Apr 27 11:44:11 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:11,846 - synapse.federation.sender.transaction_manager - 170 - INFO - federation_transaction_transmission_loop-60791 - TX [synod.im] {1650947504872} got 200 response
Apr 27 11:44:11 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:11,857 - synapse.http.federation.well_known_resolver - 197 - INFO - federation_transaction_transmission_loop-60792 - Error parsing well-known for b'snappo.club': Non-200 response 404
Apr 27 11:44:11 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:11,864 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 11:44:11 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:11,897 - synapse.http.matrixfederationclient - 285 - INFO - federation_transaction_transmission_loop-60794 - {PUT-O-303984} [unimportantdomain.xyz] Completed request: 200 OK in 0.06 secs, got 11 bytes - PUT matrix://unimportantdomain.xyz/_matrix/federation/v1/send/1650947504876
Apr 27 11:44:11 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:11,897 - synapse.federation.sender.transaction_manager - 170 - INFO - federation_transaction_transmission_loop-60794 - TX [unimportantdomain.xyz] {1650947504876} got 200 response
Apr 27 11:44:12 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:12,042 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 11:44:12 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:12,044 - synapse.federation.sender.transaction_manager - 120 - INFO - federation_transaction_transmission_loop-60796 - TX [matrix.cs.vsb.cz] {1650947504877} Sending transaction [1650947504877], (PDUs: 0, EDUs: 1)
Apr 27 11:44:12 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:12,045 - synapse.http.federation.well_known_resolver - 253 - INFO - federation_transaction_transmission_loop-60796 - Fetching https://matrix.cs.vsb.cz/.well-known/matrix/server
Apr 27 11:44:12 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:12,047 - synapse.federation.transport.server.federation - 102 - INFO - PUT-172527 - Received txn 1651021382185 from das-labor.org. (PDUs: 0, EDUs: 1)
Apr 27 11:44:12 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:12,048 - synapse.util.caches.response_cache - 254 - INFO - PUT-172527 - [fed_txn_handler]: using completed cached result for [('das-labor.org', '1651021382185')]
Apr 27 11:44:12 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:12,049 - synapse.access.http.8008 - 427 - INFO - PUT-172527 - redacted - 8008 - {das-labor.org} Processed request: 0.005sec/0.001sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 11B 200 "PUT /_matrix/federation/v1/send/1651021382185 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 11:44:12 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:12,134 - synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 1
Apr 27 11:44:12 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:12,356 - synapse.http.matrixfederationclient - 285 - INFO - federation_transaction_transmission_loop-60792 - {PUT-O-303982} [snappo.club] Completed request: 200 OK in 0.73 secs, got 11 bytes - PUT matrix://snappo.club/_matrix/federation/v1/send/1650947504874
Apr 27 11:44:12 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:12,357 - synapse.federation.sender.transaction_manager - 170 - INFO - federation_transaction_transmission_loop-60792 - TX [snappo.club] {1650947504874} got 200 response
Apr 27 11:44:12 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:12,358 - synapse.federation.sender.transaction_manager - 120 - INFO - federation_transaction_transmission_loop-60797 - TX [fairydust.space] {1650947504878} Sending transaction [1650947504878], (PDUs: 0, EDUs: 1)
Apr 27 11:44:12 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:44:12,393 - synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 2
Apr 27 11:46:18 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:18,283 - synapse.http.matrixfederationclient - 285 - INFO - federation_transaction_transmission_loop-60774 - {PUT-O-303969} [librem.one] Completed request: 200 OK in 127.98 secs, got 11 bytes - PUT matrix://librem.one/_matrix/federation/v1/send/1650947504861
Apr 27 11:46:18 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:18,327 - synapse.federation.sender.transaction_manager - 170 - INFO - federation_transaction_transmission_loop-60774 - TX [librem.one] {1650947504861} got 200 response
Apr 27 11:46:18 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:18,387 - synapse.http.site - 353 - INFO - GET-172524 - Connection from client lost before response was sent
Apr 27 11:46:18 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:18,387 - synapse.http.site - 353 - INFO - GET-172526 - Connection from client lost before response was sent
Apr 27 11:46:19 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:19,825 - synapse.util.caches.lrucache - 154 - INFO - LruCache._expire_old_entries-4021 - Dropped 1 items from caches
Apr 27 11:46:20 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:20,927 - synapse.rest.client.sync - 203 - INFO - GET-172524 - Client has disconnected; not serializing response.
Apr 27 11:46:21 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:21,028 - synapse.http.server - 690 - WARNING - GET-172524 - Not sending response to request <XForwardedForRequest at 0x7f3411935930 method='GET' uri='/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916458_29610402_7454_2429381_623907_134_278313_1659935_2' clientproto='HTTP/1.0' site='8008'>, already disconnected.
Apr 27 11:46:21 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:21,069 - synapse.access.http.8008 - 427 - INFO - GET-172524 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 129.333sec/-2.683sec (0.007sec, 0.000sec) (0.001sec/0.003sec/2) 0B 200! "GET /_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916458_29610402_7454_2429381_623907_134_278313_1659935_2 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.10 Chrome/98.0.4758.141 Electron/17.4.0 Safari/537.36" [0 dbevts]
Apr 27 11:46:21 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:21,305 - synapse.rest.client.sync - 203 - INFO - GET-172526 - Client has disconnected; not serializing response.
Apr 27 11:46:21 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:21,305 - synapse.http.server - 690 - WARNING - GET-172526 - Not sending response to request <XForwardedForRequest at 0x7f3448151180 method='GET' uri='/_matrix/client/r0/sync?access_token=<redacted>&since=s2916458_29610402_7454_2429381_623907_134_278313_1659935_2&timeout=30000&filter=%7B%22room%22:%7B%22state%22:%7B%22lazy_load_members%22:true%7D%7D%7D' clientproto='HTTP/1.0' site='8008'>, already disconnected.
Apr 27 11:46:21 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:21,306 - synapse.access.http.8008 - 427 - INFO - GET-172526 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 129.441sec/-2.918sec (0.008sec, 0.000sec) (0.001sec/0.001sec/2) 0B 200! "GET /_matrix/client/r0/sync?access_token=<redacted>&since=s2916458_29610402_7454_2429381_623907_134_278313_1659935_2&timeout=30000&filter=%7B%22room%22:%7B%22state%22:%7B%22lazy_load_members%22:true%7D%7D%7D HTTP/1.0" "Python/3.10 aiohttp/3.8.1" [0 dbevts]
Apr 27 11:46:21 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:21,388 - synapse.appservice.scheduler - 489 - INFO - as-recoverer-whatsapp-141 - Starting retries on whatsapp
Apr 27 11:46:21 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:21,491 - synapse.handlers.presence - 771 - INFO - persist_presence_changes-2057 - Persisting 22 unpersisted presence updates
Apr 27 11:46:22 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:22,300 - synapse.http.matrixfederationclient - 638 - INFO - federation_transaction_transmission_loop-60793 - {PUT-O-303983} [foxden.party] Request failed: PUT matrix://foxden.party/_matrix/federation/v1/send/1650947504875: RequestGenerationFailed:[CancelledError()]
Apr 27 11:46:22 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:22,308 - synapse.http.federation.well_known_resolver - 284 - INFO - federation_transaction_transmission_loop-60796 - Error fetching https://matrix.cs.vsb.cz/.well-known/matrix/server: HostnameAddress(hostname=b'matrix.cs.vsb.cz', port=443)
Apr 27 11:46:22 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:22,318 - synapse.http.matrixfederationclient - 638 - INFO - federation_transaction_transmission_loop-60796 - {PUT-O-303985} [matrix.cs.vsb.cz] Request failed: PUT matrix://matrix.cs.vsb.cz/_matrix/federation/v1/send/1650947504877: TimeoutError('Timed out after 60s')
Apr 27 11:46:22 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:22,322 - synapse.http.federation.matrix_federation_agent - 364 - INFO - federation_transaction_transmission_loop-60797 - Failed to connect to matrix.fairydust.space:443: HostnameAddress(hostname=b'matrix.fairydust.space', port=443)
Apr 27 11:46:22 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:22,323 - synapse.http.matrixfederationclient - 638 - INFO - federation_transaction_transmission_loop-60797 - {PUT-O-303986} [fairydust.space] Request failed: PUT matrix://fairydust.space/_matrix/federation/v1/send/1650947504878: ConnectingCancelledError(HostnameAddress(hostname=b'matrix.fairydust.space', port=443))
Apr 27 11:46:22 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:46:22,451 - synapse.storage.databases.main.metrics - 471 - INFO - generate_user_daily_visits-421 - Calling _generate_user_daily_visits

EDIT: and I'm currently in the middle of another one

Apr 27 11:54:36 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:36,364 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 11:54:36 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:36,448 - synapse.federation.transport.server.federation - 102 - INFO - PUT-173654 - Received txn 1629841247961 from netsoc.ie. (PDUs: 0, EDUs: 1)
Apr 27 11:54:36 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:36,582 - synapse.access.http.8008 - 427 - INFO - PUT-173654 - redacted - 8008 - {netsoc.ie} Processed request: 0.217sec/0.001sec (0.004sec, 0.001sec) (0.001sec/0.166sec/3) 11B 200 "PUT /_matrix/federation/v1/send/1629841247961 HTTP/1.0" "Synapse/1.41.0" [0 dbevts]
Apr 27 11:54:38 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:38,608 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 11:54:38 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:38,612 - synapse.federation.transport.server.federation - 102 - INFO - PUT-173655 - Received txn 1651072979510 from vector.modular.im. (PDUs: 0, EDUs: 1)
Apr 27 11:54:38 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:38,847 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 11:54:38 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:38,851 - synapse.federation.transport.server.federation - 102 - INFO - PUT-173656 - Received txn 1648990722564 from rc8.eu. (PDUs: 0, EDUs: 1)
Apr 27 11:54:38 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:38,863 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 11:54:38 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:38,865 - synapse.federation.transport.server.federation - 102 - INFO - PUT-173657 - Received txn 1651046553793 from poa.st. (PDUs: 0, EDUs: 1)
Apr 27 11:54:38 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:38,996 - synapse.access.http.8008 - 427 - INFO - PUT-173655 - redacted - 8008 - {vector.modular.im} Processed request: 0.270sec/0.114sec (0.005sec, 0.002sec) (0.003sec/0.242sec/5) 11B 200 "PUT /_matrix/federation/v1/send/1651072979510 HTTP/1.0" "Synapse/1.57.1" [0 dbevts]
Apr 27 11:54:38 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:38,999 - synapse.access.http.8008 - 427 - INFO - PUT-173656 - redacted - 8008 - {rc8.eu} Processed request: 0.148sec/0.002sec (0.002sec, 0.002sec) (0.003sec/0.016sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1648990722564 HTTP/1.0" "Synapse/1.54.0" [0 dbevts]
Apr 27 11:54:39 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:39,007 - synapse.access.http.8008 - 427 - INFO - PUT-173657 - redacted - 8008 - {poa.st} Processed request: 0.134sec/0.009sec (0.002sec, 0.002sec) (0.004sec/0.115sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1651046553793 HTTP/1.0" "Synapse/1.57.1" [0 dbevts]
Apr 27 11:54:39 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:39,883 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 11:54:39 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:39,886 - synapse.federation.transport.server.federation - 102 - INFO - PUT-173658 - Received txn 1650589761258 from halogen.city. (PDUs: 0, EDUs: 1)
Apr 27 11:54:40 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:40,080 - synapse.access.http.8008 - 427 - INFO - PUT-173658 - redacted - 8008 - {halogen.city} Processed request: 0.195sec/0.001sec (0.004sec, 0.001sec) (0.001sec/0.184sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650589761258 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 11:54:41 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:41,720 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 11:54:41 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:41,782 - synapse.federation.transport.server.federation - 102 - INFO - PUT-173659 - Received txn 1651058790082 from supercable.onl. (PDUs: 0, EDUs: 1)
Apr 27 11:54:41 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:41,806 - synapse.access.http.8008 - 427 - INFO - PUT-173659 - redacted - 8008 - {supercable.onl} Processed request: 0.084sec/0.001sec (0.003sec, 0.000sec) (0.001sec/0.019sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1651058790082 HTTP/1.0" "Synapse/1.58.0rc2" [0 dbevts]
Apr 27 11:54:43 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:43,162 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 11:54:43 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:43,165 - synapse.federation.transport.server.federation - 102 - INFO - PUT-173660 - Received txn 1650976992952 from matrix.org. (PDUs: 0, EDUs: 2)
Apr 27 11:54:43 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:43,172 - synapse.handlers.typing - 343 - INFO - PUT-173660 - Ignoring typing update for room '!zjYxZkVEqwWcQQhXxc:techlore.net' from server matrix.org as we're not in the room
Apr 27 11:54:43 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:43,174 - synapse.handlers.receipts - 71 - INFO - PUT-173660 - Ignoring receipt for room '!zjYxZkVEqwWcQQhXxc:techlore.net' from server matrix.org as we're not in the room
Apr 27 11:54:43 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:43,179 - synapse.access.http.8008 - 427 - INFO - PUT-173660 - redacted - 8008 - {matrix.org} Processed request: 0.015sec/0.001sec (0.003sec, 0.001sec) (0.001sec/0.007sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650976992952 HTTP/1.0" "Synapse/1.58.0rc1" [0 dbevts]
Apr 27 11:54:43 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:43,993 - synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 1
Apr 27 11:54:44 canode.darkcloud.ca synapse[7679]: 2022-04-27 11:54:44,094 - synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 2
prurigro commented 2 years ago

Here's another one-- this time there was only gc 1 and there was output after while still disconnected (unless the client just took a second to retry) but it was still offline for about 30 seconds. Confirmed offline timestamp for this one is 14:11:28,238:

Apr 27 14:10:23 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:23,942 - synapse.access.http.8008 - 427 - INFO - PUT-11502 - redacted - 8008 - {violoncello.ch} Processed request: 0.021sec/0.001sec (0.003sec, 0.000sec) (0.001sec/0.013sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650327834269 HTTP/1.0" "Synapse/1.56.0" [0 dbevts]
Apr 27 14:10:23 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:23,962 - synapse.access.http.8008 - 427 - INFO - PUT-11503 - redacted - 8008 - {utwente.io} Processed request: 0.040sec/0.000sec (0.003sec, 0.001sec) (0.001sec/0.031sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1645223909805 HTTP/1.0" "Synapse/1.50.2" [0 dbevts]
Apr 27 14:10:24 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:24,295 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 14:10:24 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:24,298 - synapse.federation.transport.server.federation - 102 - INFO - PUT-11504 - Received txn 1650589927792 from halogen.city. (PDUs: 0, EDUs: 1)
Apr 27 14:10:24 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:24,306 - synapse.access.http.8008 - 427 - INFO - PUT-11504 - redacted - 8008 - {halogen.city} Processed request: 0.010sec/0.001sec (0.004sec, 0.000sec) (0.001sec/0.004sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650589927792 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 14:10:25 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:25,343 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 14:10:25 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:25,370 - synapse.crypto.keyring - 664 - INFO - PerspectivesKeyFetcher-59 - Requesting keys [_FetchKeyRequest(server_name='matrixim.cc', minimum_valid_until_ts=1651083025344, key_ids=['ed25519:a_DbYb'])] from notary server matrix.org
Apr 27 14:10:25 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:25,541 - synapse.http.matrixfederationclient - 285 - INFO - PerspectivesKeyFetcher-59 - {POST-O-17636} [matrix.org] Completed request: 200 OK in 0.17 secs, got 442 bytes - POST matrix://matrix.org/_matrix/key/v2/query
Apr 27 14:10:25 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:25,663 - synapse.federation.transport.server.federation - 102 - INFO - PUT-11505 - Received txn 1650555065527 from matrixim.cc. (PDUs: 0, EDUs: 1)
Apr 27 14:10:25 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:25,710 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 14:10:25 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:25,715 - synapse.federation.transport.server.federation - 102 - INFO - PUT-11506 - Received txn 1651046606176 from poa.st. (PDUs: 0, EDUs: 1)
Apr 27 14:10:25 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:25,737 - synapse.access.http.8008 - 427 - INFO - PUT-11506 - redacted - 8008 - {poa.st} Processed request: 0.025sec/0.001sec (0.005sec, 0.000sec) (0.001sec/0.015sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1651046606176 HTTP/1.0" "Synapse/1.57.1" [0 dbevts]
Apr 27 14:10:25 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:25,752 - synapse.access.http.8008 - 427 - INFO - PUT-11505 - redacted - 8008 - {matrixim.cc} Processed request: 0.407sec/0.001sec (0.010sec, 0.002sec) (0.008sec/0.067sec/7) 11B 200 "PUT /_matrix/federation/v1/send/1650555065527 HTTP/1.0" "Synapse/1.55.2" [0 dbevts]
Apr 27 14:10:28 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:28,759 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 14:10:28 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:28,762 - synapse.federation.transport.server.federation - 102 - INFO - PUT-11507 - Received txn 1651040601195 from cyberdruids.club. (PDUs: 0, EDUs: 1)
Apr 27 14:10:28 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:28,777 - synapse.access.http.8008 - 427 - INFO - PUT-11507 - redacted - 8008 - {cyberdruids.club} Processed request: 0.017sec/0.000sec (0.003sec, 0.000sec) (0.001sec/0.013sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1651040601195 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 14:10:31 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:31,214 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 14:10:31 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:31,217 - synapse.federation.transport.server.federation - 102 - INFO - PUT-11508 - Received txn 1650723060136 from nightshade.fun. (PDUs: 0, EDUs: 1)
Apr 27 14:10:31 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:31,233 - synapse.access.http.8008 - 427 - INFO - PUT-11508 - redacted - 8008 - {nightshade.fun} Processed request: 0.017sec/0.000sec (0.004sec, 0.000sec) (0.001sec/0.011sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650723060136 HTTP/1.0" "Synapse/1.57.1" [0 dbevts]
Apr 27 14:10:35 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:35,398 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 14:10:35 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:35,401 - synapse.federation.transport.server.federation - 102 - INFO - PUT-11509 - Received txn 1650977215302 from matrix.org. (PDUs: 0, EDUs: 1)
Apr 27 14:10:35 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:35,413 - synapse.handlers.typing - 365 - INFO - PUT-11509 - Got typing update from @redacted:matrix.org: {'room_id': '!JgvlSftYxvnARNONxm:matrix.org', 'typing': True, 'user_id': '@redacted:matrix.org'}
Apr 27 14:10:35 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:35,421 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 14:10:35 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:35,423 - synapse.access.http.8008 - 427 - INFO - PUT-11509 - redacted - 8008 - {matrix.org} Processed request: 0.021sec/0.002sec (0.005sec, 0.000sec) (0.001sec/0.014sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650977215302 HTTP/1.0" "Synapse/1.58.0rc1" [0 dbevts]
Apr 27 14:10:35 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:35,425 - synapse.federation.transport.server.federation - 102 - INFO - PUT-11510 - Received txn 1649982779267 from stratum0.org. (PDUs: 0, EDUs: 1)
Apr 27 14:10:35 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:35,451 - synapse.access.http.8008 - 427 - INFO - PUT-11510 - redacted - 8008 - {stratum0.org} Processed request: 0.029sec/0.000sec (0.001sec, 0.002sec) (0.001sec/0.023sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1649982779267 HTTP/1.0" "Synapse/1.56.0" [0 dbevts]
Apr 27 14:10:35 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:35,898 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 14:10:35 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:35,900 - synapse.federation.transport.server.federation - 102 - INFO - PUT-11511 - Received txn 1650403452584 from sigint.club. (PDUs: 0, EDUs: 1)
Apr 27 14:10:35 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:35,934 - synapse.access.http.8008 - 427 - INFO - PUT-11511 - redacted - 8008 - {sigint.club} Processed request: 0.035sec/0.000sec (0.004sec, 0.000sec) (0.001sec/0.030sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650403452584 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 14:10:36 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:36,020 - synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 1
Apr 27 14:10:36 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:36,376 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 14:10:36 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:36,379 - synapse.federation.transport.server.federation - 102 - INFO - PUT-11512 - Received txn 1648313864179 from matrix.debian.social. (PDUs: 0, EDUs: 1)
Apr 27 14:10:36 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:36,478 - synapse.access.http.8008 - 427 - INFO - PUT-11512 - redacted - 8008 - {matrix.debian.social} Processed request: 0.101sec/0.000sec (0.005sec, 0.000sec) (0.002sec/0.093sec/5) 11B 200 "PUT /_matrix/federation/v1/send/1648313864179 HTTP/1.0" "Synapse/1.43.0" [0 dbevts]
Apr 27 14:10:37 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:37,662 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 14:10:37 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:37,665 - synapse.federation.transport.server.federation - 102 - INFO - PUT-11513 - Received txn 1650880976220 from phys.ethz.ch. (PDUs: 0, EDUs: 1)
Apr 27 14:10:37 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:37,824 - synapse.access.http.8008 - 427 - INFO - PUT-11513 - redacted - 8008 - {phys.ethz.ch} Processed request: 0.160sec/0.001sec (0.006sec, 0.001sec) (0.002sec/0.132sec/5) 11B 200 "PUT /_matrix/federation/v1/send/1650880976220 HTTP/1.0" "Synapse/1.57.1" [0 dbevts]
Apr 27 14:10:39 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:39,156 - synapse.handlers.presence - 771 - INFO - persist_presence_changes-116 - Persisting 22 unpersisted presence updates
Apr 27 14:10:39 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:39,221 - synapse.util.caches.lrucache - 154 - INFO - LruCache._expire_old_entries-231 - Dropped 0 items from caches
Apr 27 14:10:39 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:39,238 - synapse.storage.databases.main.metrics - 471 - INFO - generate_user_daily_visits-23 - Calling _generate_user_daily_visits
Apr 27 14:10:39 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:39,242 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 14:10:39 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:39,255 - synapse.federation.transport.server.federation - 102 - INFO - PUT-11514 - Received txn 1650484072009 from snug.moe. (PDUs: 0, EDUs: 1)
Apr 27 14:10:39 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:39,323 - synapse.http.matrixfederationclient - 595 - INFO - _maybe_retry_device_resync-224 - {GET-O-17651} [matrix.thecovrigs.net] Got response headers: 403 Forbidden
Apr 27 14:10:39 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:39,324 - synapse.http.matrixfederationclient - 673 - WARNING - _maybe_retry_device_resync-224 - {GET-O-17651} [matrix.thecovrigs.net] Request failed: GET matrix://matrix.thecovrigs.net/_matrix/federation/v1/user/devices/%40baylorjosias%3Amatrix.thecovrigs.net: HttpResponseException('403: Forbidden')
Apr 27 14:10:39 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:39,325 - synapse.handlers.device - 987 - WARNING - _maybe_retry_device_resync-224 - Failed to handle device list update for @redacted:matrix.thecovrigs.net: 403: Forbidden
Apr 27 14:10:39 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:39,377 - synapse.http.matrixfederationclient - 595 - INFO - _maybe_retry_device_resync-224 - {GET-O-17699} [matrix.thecovrigs.net] Got response headers: 403 Forbidden
Apr 27 14:10:39 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:39,378 - synapse.http.matrixfederationclient - 673 - WARNING - _maybe_retry_device_resync-224 - {GET-O-17699} [matrix.thecovrigs.net] Request failed: GET matrix://matrix.thecovrigs.net/_matrix/federation/v1/user/devices/%40zeidmanmatelda%3Amatrix.thecovrigs.net: HttpResponseException('403: Forbidden')
Apr 27 14:10:39 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:39,379 - synapse.handlers.device - 987 - WARNING - _maybe_retry_device_resync-224 - Failed to handle device list update for @redacted:matrix.thecovrigs.net: 403: Forbidden
Apr 27 14:10:39 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:39,480 - synapse.access.http.8008 - 427 - INFO - PUT-11514 - redacted - 8008 - {snug.moe} Processed request: 0.237sec/0.000sec (0.007sec, 0.001sec) (0.002sec/0.207sec/7) 11B 200 "PUT /_matrix/federation/v1/send/1650484072009 HTTP/1.0" "Synapse/1.57.1" [0 dbevts]
Apr 27 14:10:40 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:40,111 - synapse.http.matrixfederationclient - 595 - INFO - renew_attestations-3 - {POST-O-17700} [matrix.org] Got response headers: 400 Bad Request
Apr 27 14:10:40 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:40,113 - synapse.http.matrixfederationclient - 673 - WARNING - renew_attestations-3 - {POST-O-17700} [matrix.org] Request failed: POST matrix://matrix.org/_matrix/federation/v1/groups/%2Bcyberdeck%3Amatrix.org/renew_attestation/%40kmacmartin%3Amatrix.darkcloud.ca: HttpResponseException('400: Bad Request')
Apr 27 14:10:40 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:40,115 - synapse.groups.attestations - 209 - WARNING - renew_attestations-3 - Failed to renew attestation of '@redacted:matrix.darkcloud.ca' in '+cyberdeck:matrix.org': 400: Bad Request
Apr 27 14:10:42 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:42,590 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 14:10:42 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:42,601 - synapse.federation.transport.server.federation - 102 - INFO - PUT-11515 - Received txn 1650386456882 from pains-perdus.fr. (PDUs: 0, EDUs: 1)
Apr 27 14:10:42 canode.darkcloud.ca synapse[292]: 2022-04-27 14:10:42,638 - synapse.access.http.8008 - 427 - INFO - PUT-11515 - redacted - 8008 - {pains-perdus.fr} Processed request: 0.046sec/0.001sec (0.001sec, 0.002sec) (0.001sec/0.014sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650386456882 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 14:11:28 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:28,238 - synapse.state - 459 - INFO - _process_incoming_pdus_in_room_inner-1-$waJu4cqDC4sQiMIkANcUWlfKsd0QFvpf-P0YMDy3HZw-$iZO0QxgBIr_faC18kUEJEw3i7BbGkVW12TJ3jxTWxAI - Resolving state for !mKkDdfCLCtkTyqcxEc:nerdsin.space with 20 groups
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,625 - synapse.handlers.typing - 242 - INFO - typing._handle_timeouts-1229 - Timing out typing for: @redacted:matrix.org
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,682 - synapse.util.caches.lrucache - 154 - INFO - LruCache._expire_old_entries-232 - Dropped 15 items from caches
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,715 - synapse.handlers.presence - 771 - INFO - persist_presence_changes-117 - Persisting 2 unpersisted presence updates
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,826 - synapse.http.site - 353 - INFO - GET-11492 - Connection from client lost before response was sent
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,827 - synapse.access.http.8008 - 427 - INFO - GET-11492 - redacted - 8008 - {@redactedmatrix.darkcloud.ca} Processed request: 95.819sec/0.157sec (0.004sec, 0.000sec) (0.000sec/0.001sec/2) 0B 200! "GET /_matrix/client/r0/sync?timeout=30000&since=s2916688_29616187_363_2429826_624022_134_278326_1660394_2&filter=7&set_presence=offline HTTP/1.0" "mautrix-facebook/0.3.3 mautrix-python/0.14.10 aiohttp/3.8.1 Python/3.10.4" [0 dbevts]
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,828 - synapse.http.site - 353 - INFO - GET-11495 - Connection from client lost before response was sent
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,829 - synapse.access.http.8008 - 427 - INFO - GET-11495 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 95.766sec/0.157sec (0.005sec, 0.001sec) (0.000sec/0.001sec/2) 0B 200! "GET /_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916688_29616187_363_2429826_624022_134_278326_1660394_2 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.10 Chrome/98.0.4758.141 Electron/17.4.0 Safari/537.36" [0 dbevts]
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,829 - synapse.http.site - 353 - INFO - GET-11496 - Connection from client lost before response was sent
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,830 - synapse.access.http.8008 - 427 - INFO - GET-11496 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 95.753sec/0.157sec (0.003sec, 0.001sec) (0.005sec/0.001sec/2) 0B 200! "GET /_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916688_29616187_363_2429826_624022_134_278326_1660394_2 HTTP/1.0" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.11 Chrome/98.0.4758.74 Electron/17.0.0 Safari/537.36" [0 dbevts]
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,830 - synapse.http.site - 353 - INFO - GET-11497 - Connection from client lost before response was sent
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,831 - synapse.access.http.8008 - 427 - INFO - GET-11497 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 95.631sec/0.157sec (0.005sec, 0.001sec) (0.001sec/0.002sec/2) 0B 200! "GET /_matrix/client/r0/sync?access_token=<redacted>&since=s2916688_29616187_363_2429826_624022_134_278326_1660394_2&timeout=30000&filter=%7B%22room%22:%7B%22state%22:%7B%22lazy_load_members%22:true%7D%7D%7D HTTP/1.0" "Python/3.10 aiohttp/3.8.1" [0 dbevts]
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,833 - synapse.http.server - 594 - INFO - GET-11495 - Connection disconnected before response was written: AttributeError("'NoneType' object has no attribute 'registerProducer'")
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,875 - synapse.http.server - 594 - INFO - GET-11496 - Connection disconnected before response was written: AttributeError("'NoneType' object has no attribute 'registerProducer'")
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,875 - synapse.http.server - 594 - INFO - GET-11497 - Connection disconnected before response was written: AttributeError("'NoneType' object has no attribute 'registerProducer'")
Apr 27 14:11:52 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:52,876 - synapse.http.server - 594 - INFO - GET-11492 - Connection disconnected before response was written: AttributeError("'NoneType' object has no attribute 'registerProducer'")
Apr 27 14:11:53 canode.darkcloud.ca synapse[292]: 2022-04-27 14:11:53,021 - synapse.storage.txn - 640 - WARNING - persist_presence_changes-117 - [TXN OPERROR] {update_presence-10226} could not serialize access due to concurrent delete
prurigro commented 2 years ago

Looks like at least one user on element for iOS has seen the issue with that client too-- she gets a timeout after a lengthy period of syncing

prurigro commented 2 years ago

Both of these were taken during a connectivity drop (so it was down during the last line) -- interestingly the first one doesn't have the gc lines:

Apr 27 15:02:43 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:43,465 - synapse.http.matrixfederationclient - 595 - INFO - federation_transaction_transmission_loop-8593 - {PUT-O-25756} [matrix.piter.chatv3.ru] Got response headers: 502 Bad Gateway
Apr 27 15:02:43 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:43,466 - synapse.http.matrixfederationclient - 638 - INFO - federation_transaction_transmission_loop-8593 - {PUT-O-25756} [matrix.piter.chatv3.ru] Request failed: PUT matrix://matrix.piter.chatv3.ru/_matrix/federation/v1/send/1651075844221: HttpResponseException('502: Bad Gateway')
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,497 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,500 - synapse.federation.transport.server.federation - 102 [0-9][0-9]*\.[0-9][0-9]*\.[0-9][0-9]*\.[0-9][0-9]*- INFO - PUT-18567 - Received txn 1650626897631 from waifuhunter.club. (PDUs: 0, EDUs: 1)
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,507 - synapse.access.http.8008 - 427 - INFO - PUT-18567 - redacted - 8008 - {waifuhunter.club} Processed request: 0.008sec/0.001sec (0.004sec, 0.000sec) (0.001sec/0.003sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650626897631 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,534 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,537 - synapse.federation.transport.server.federation - 102 - INFO - PUT-18568 - Received txn 1650464492984 from bubu1.eu. (PDUs: 0, EDUs: 1)
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,552 - synapse.access.http.8008 - 427 - INFO - PUT-18568 - redacted - 8008 - {bubu1.eu} Processed request: 0.017sec/0.000sec (0.006sec, 0.000sec) (0.002sec/0.009sec/5) 11B 200 "PUT /_matrix/federation/v1/send/1650464492984 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,748 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,750 - synapse.federation.transport.server.federation - 102 - INFO - PUT-18569 - Received txn 1650155938289 from schizo.cafe. (PDUs: 0, EDUs: 1)
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,797 - synapse.access.http.8008 - 427 - INFO - PUT-18569 - redacted - 8008 - {schizo.cafe} Processed request: 0.047sec/0.000sec (0.004sec, 0.000sec) (0.001sec/0.043sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650155938289 HTTP/1.0" "Synapse/1.55.0" [0 dbevts]
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,905 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,907 - synapse.federation.transport.server.federation - 102 - INFO - PUT-18570 - Received txn 1650977316626 from matrix.org. (PDUs: 0, EDUs: 1)
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,910 - synapse.handlers.typing - 365 - INFO - PUT-18570 - Got typing update from @redacted:matrix.org: {'room_id': '!vIRfubEFqsCRjEXMZd:matrix.org', 'typing': False, 'user_id': '@redacted:matrix.org'}
Apr 27 15:02:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:44,922 - synapse.access.http.8008 - 427 - INFO - PUT-18570 - redacted - 8008 - {matrix.org} Processed request: 0.016sec/0.000sec (0.004sec, 0.001sec) (0.001sec/0.010sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650977316626 HTTP/1.0" "Synapse/1.58.0rc1" [0 dbevts]
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,049 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,052 - synapse.federation.transport.server.federation - 102 - INFO - PUT-18571 - Received txn 1650977316632 from matrix.org. (PDUs: 0, EDUs: 1)
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,055 - synapse.handlers.typing - 365 - INFO - PUT-18571 - Got typing update from @redacted:matrix.org: {'room_id': '!vIRfubEFqsCRjEXMZd:matrix.org', 'typing': True, 'user_id': '@redacted:matrix.org'}
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,061 - synapse.access.http.8008 - 427 - INFO - PUT-18571 - redacted - 8008 - {matrix.org} Processed request: 0.011sec/0.000sec (0.001sec, 0.002sec) (0.001sec/0.004sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650977316632 HTTP/1.0" "Synapse/1.58.0rc1" [0 dbevts]
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,682 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,684 - synapse.federation.transport.server.federation - 102 - INFO - PUT-18572 - Received txn 1650977316692 from matrix.org. (PDUs: 0, EDUs: 1)
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,687 - synapse.handlers.typing - 365 - INFO - PUT-18572 - Got typing update from @redacted:matrix.org: {'room_id': '!lmoJhRvQcNTuGtHgry:kde.org', 'typing': True, 'user_id': '@redacted:matrix.org'}
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,754 - synapse.access.http.8008 - 427 - INFO - GET-18501 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 30.034sec/0.007sec (0.005sec, 0.001sec) (0.001sec/0.002sec/2) 261B 200 "GET /_matrix/client/r0/sync?filter=4&timeout=30000&since=s2917122_29618389_721_2430105_624114_134_278339_1660483_2 HTTP/1.0" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.11 Chrome/redacted Electron/17.0.0 Safari/537.36" [0 dbevts]
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,767 - synapse.access.http.8008 - 427 - INFO - PUT-18572 - redacted - 8008 - {matrix.org} Processed request: 0.072sec/0.012sec (0.004sec, 0.000sec) (0.001sec/0.004sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650977316692 HTTP/1.0" "Synapse/1.58.0rc1" [0 dbevts]
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,768 - synapse.access.http.8008 - 427 - INFO - GET-18563 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 3.215sec/0.007sec (0.007sec, 0.000sec) (0.006sec/0.006sec/4) 651B 200 "GET /_matrix/client/r0/sync?filter=3&timeout=30000&since=s2917122_29618426_729_2430107_624114_134_278339_1660483_2 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.10 Chrome/redacted Electron/17.4.0 Safari/537.36" [0 dbevts]
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,771 - synapse.access.http.8008 - 427 - INFO - GET-18561 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 3.267sec/0.011sec (0.007sec, 0.000sec) (0.009sec/0.005sec/4) 651B 200 "GET /_matrix/client/r0/sync?timeout=30000&since=s2917122_29618426_729_2430107_624114_134_278339_1660483_2&filter=7&set_presence=offline HTTP/1.0" "mautrix-facebook/0.3.3 mautrix-python/0.14.10 aiohttp/3.8.1 Python/3.10.4" [0 dbevts]
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,772 - synapse.access.http.8008 - 427 - INFO - GET-18566 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 3.084sec/0.006sec (0.009sec, 0.000sec) (0.003sec/0.005sec/4) 613B 200 "GET /_matrix/client/r0/sync?access_token=<redacted>&since=s2917122_29618426_729_2430107_624114_134_278339_1660483_2&timeout=30000&filter=%7B%22room%22:%7B%22state%22:%7B%22lazy_load_members%22:true%7D%7D%7D HTTP/1.0" "Python/3.10 aiohttp/3.8.1" [0 dbevts]
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,772 - synapse.access.http.8008 - 427 - INFO - GET-18565 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 3.121sec/0.006sec (0.007sec, 0.000sec) (0.005sec/0.006sec/4) 651B 200 "GET /_matrix/client/r0/sync?filter=3&timeout=30000&since=s2917122_29618426_729_2430107_624114_134_278339_1660483_2 HTTP/1.0" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.11 Chrome/redacted Electron/17.0.0 Safari/537.36" [0 dbevts]
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,778 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,830 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,854 - synapse.access.http.8008 - 427 - INFO - GET-18506 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 30.004sec/0.001sec (0.005sec, 0.000sec) (0.001sec/0.001sec/2) 261B 200 "GET /_matrix/client/r0/sync?filter=0&timeout=30000&since=s2917122_29618389_721_2430105_624114_134_278339_1660483_2 HTTP/1.0" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.11 Chrome/redacted Electron/17.0.0 Safari/537.36" [0 dbevts]
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,856 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,869 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,911 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,918 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,952 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,961 - synapse.access.http.8008 - 427 - INFO - GET-18579 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.007sec/0.001sec (0.005sec, 0.000sec) (0.001sec/0.002sec/2) 852B 200 "GET /_matrix/client/r0/sync?filter=4&timeout=30000&since=s2917122_29618389_721_2430105_624114_134_278339_1660483_2 HTTP/1.0" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.11 Chrome/redacted Electron/17.0.0 Safari/537.36" [0 dbevts]
Apr 27 15:02:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:45,974 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,005 - synapse.access.http.8008 - 427 - INFO - GET-18508 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 30.003sec/0.001sec (0.004sec, 0.000sec) (0.001sec/0.001sec/2) 261B 200 "GET /_matrix/client/r0/sync?filter=2&timeout=30000&since=s2917122_29618389_721_2430105_624114_134_278339_1660483_2 HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.10 Chrome/redacted Electron/17.0.0 Safari/537.36" [0 dbevts]
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,006 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,060 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,094 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,128 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,136 - synapse.access.http.8008 - 427 - INFO - GET-18584 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.007sec/0.001sec (0.004sec, 0.000sec) (0.001sec/0.002sec/2) 850B 200 "GET /_matrix/client/r0/sync?filter=0&timeout=30000&since=s2917122_29618389_721_2430105_624114_134_278339_1660483_2 HTTP/1.0" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.11 Chrome/redacted Electron/17.0.0 Safari/537.36" [0 dbevts]
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,166 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,172 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,200 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,280 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,298 - synapse.access.http.8008 - 427 - INFO - GET-18588 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.016sec/0.001sec (0.003sec, 0.002sec) (0.001sec/0.007sec/2) 849B 200 "GET /_matrix/client/r0/sync?filter=2&timeout=30000&since=s2917122_29618389_721_2430105_624114_134_278339_1660483_2 HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Element/1.10.10 Chrome/redacted Electron/17.0.0 Safari/537.36" [0 dbevts]
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,466 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:46 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:46,577 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:47 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:47,411 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:47 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:47,414 - synapse.federation.transport.server.federation - 102 - INFO - PUT-18591 - Received txn 1650968782899 from knaben.org. (PDUs: 0, EDUs: 1)
Apr 27 15:02:47 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:47,443 - synapse.access.http.8008 - 427 - INFO - PUT-18591 - redacted - 8008 - {knaben.org} Processed request: 0.030sec/0.001sec (0.003sec, 0.000sec) (0.001sec/0.025sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650968782899 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 15:02:48 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:48,171 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:48 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:48,174 - synapse.federation.transport.server.federation - 102 - INFO - PUT-18592 - Received txn 1649439132244 from matrix.odayacres.farm. (PDUs: 0, EDUs: 1)
Apr 27 15:02:48 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:48,209 - synapse.access.http.8008 - 427 - INFO - PUT-18592 - redacted - 8008 - {matrix.odayacres.farm} Processed request: 0.036sec/0.000sec (0.004sec, 0.001sec) (0.001sec/0.032sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1649439132244 HTTP/1.0" "Synapse/1.56.0" [0 dbevts]
Apr 27 15:02:51 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:51,676 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:51 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:51,680 - synapse.federation.transport.server.federation - 102 - INFO - PUT-18593 - Received txn 1650306936259 from melonbread.dev. (PDUs: 0, EDUs: 1)
Apr 27 15:02:51 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:51,717 - synapse.access.http.8008 - 427 - INFO - PUT-18593 - redacted - 8008 - {melonbread.dev} Processed request: 0.039sec/0.000sec (0.002sec, 0.003sec) (0.001sec/0.034sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650306936259 HTTP/1.0" "Synapse/1.56.0" [0 dbevts]
Apr 27 15:02:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:52,093 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:52,108 - synapse.federation.transport.server.federation - 102 - INFO - PUT-18594 - Received txn 1648426252233 from fajerski.name. (PDUs: 0, EDUs: 1)
Apr 27 15:02:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:52,109 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:02:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:52,112 - synapse.federation.transport.server.federation - 102 - INFO - PUT-18595 - Received txn 1651086171207-33 from jaminit.co.uk. (PDUs: 0, EDUs: 1)
Apr 27 15:02:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:52,125 - synapse.handlers.receipts - 71 - INFO - PUT-18595 - Ignoring receipt for room '!zjYxZkVEqwWcQQhXxc:techlore.net' from server jaminit.co.uk as we're not in the room
Apr 27 15:02:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:02:52,129 - synapse.access.http.8008 - 427 - INFO - PUT-18595 - redacted - 8008 - {jaminit.co.uk} Processed request: 0.019sec/0.001sec (0.003sec, 0.000sec) (0.001sec/0.003sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1651086171207-33 HTTP/1.0" "Dendrite/0.8.2" [0 dbevts]
Apr 27 15:10:42 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:42,850 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:42 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:42,872 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:44,976 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:44 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:44,979 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19197 - Received txn 1651021475730 from das-labor.org. (PDUs: 0, EDUs: 1)
Apr 27 15:10:45 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:45,006 - synapse.access.http.8008 - 427 - INFO - PUT-19197 - redacted - 8008 - {das-labor.org} Processed request: 0.029sec/0.000sec (0.004sec, 0.001sec) (0.002sec/0.022sec/5) 11B 200 "PUT /_matrix/federation/v1/send/1651021475730 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 15:10:48 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:48,018 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:48 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:48,021 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19198 - Received txn 1648900699097 from dark.fi. (PDUs: 0, EDUs: 1)
Apr 27 15:10:48 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:48,133 - synapse.access.http.8008 - 427 - INFO - PUT-19198 - redacted - 8008 - {dark.fi} Processed request: 0.114sec/0.000sec (0.005sec, 0.001sec) (0.003sec/0.099sec/5) 11B 200 "PUT /_matrix/federation/v1/send/1648900699097 HTTP/1.0" "Synapse/1.44.0" [0 dbevts]
Apr 27 15:10:51 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:51,374 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:51 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:51,424 - synapse.access.http.8008 - 427 - INFO - PUT-19199 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.048sec/0.001sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "PUT /_matrix/client/r0/rooms/!MrBiSgIYlhBDTOjtks:matrix.darkcloud.ca/typing/%40philjoannou%3Amatrix.darkcloud.ca HTTP/1.0" "Riot/1.6.5 (iPhone; iOS 14.7.1; Scale/2.00)" [0 dbevts]
Apr 27 15:10:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:52,724 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:52,726 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19200 - Received txn 1650977333947 from matrix.org. (PDUs: 0, EDUs: 2)
Apr 27 15:10:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:52,730 - synapse.handlers.receipts - 71 - INFO - PUT-19200 - Ignoring receipt for room '!PvQGNjiCNulFZsMPud:matrix.org' from server matrix.org as we're not in the room
Apr 27 15:10:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:52,731 - synapse.handlers.receipts - 71 - INFO - PUT-19200 - Ignoring receipt for room '!zjYxZkVEqwWcQQhXxc:techlore.net' from server matrix.org as we're not in the room
Apr 27 15:10:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:52,807 - synapse.handlers.device - 856 - INFO - PUT-19200 - Received device list update for @redacted:matrix.org, requiring resync: True. Devices: PDNYCZDNMS
Apr 27 15:10:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:52,878 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:52,881 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19201 - Received txn 1651086651262-16 from thisisplate.hackwithht.ml. (PDUs: 0, EDUs: 1)
Apr 27 15:10:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:52,884 - synapse.handlers.receipts - 71 - INFO - PUT-19201 - Ignoring receipt for room '!zjYxZkVEqwWcQQhXxc:techlore.net' from server thisisplate.hackwithht.ml as we're not in the room
Apr 27 15:10:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:52,888 - synapse.access.http.8008 - 427 - INFO - PUT-19201 - redacted - 8008 - {thisisplate.hackwithht.ml} Processed request: 0.008sec/0.000sec (0.003sec, 0.001sec) (0.001sec/0.003sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1651086651262-16 HTTP/1.0" "Dendrite/0.8.1+6d78c4d6" [0 dbevts]
Apr 27 15:10:52 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:52,925 - synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 1
Apr 27 15:10:53 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:53,792 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:53 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:53,795 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19202 - Received txn 1651086652574-34 from jaminit.co.uk. (PDUs: 0, EDUs: 3)
Apr 27 15:10:53 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:53,797 - synapse.handlers.receipts - 71 - INFO - PUT-19202 - Ignoring receipt for room '!zjYxZkVEqwWcQQhXxc:techlore.net' from server jaminit.co.uk as we're not in the room
Apr 27 15:10:53 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:53,797 - synapse.handlers.receipts - 71 - INFO - PUT-19202 - Ignoring receipt for room '!zjYxZkVEqwWcQQhXxc:techlore.net' from server jaminit.co.uk as we're not in the room
Apr 27 15:10:53 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:53,798 - synapse.handlers.receipts - 71 - INFO - PUT-19202 - Ignoring receipt for room '!zjYxZkVEqwWcQQhXxc:techlore.net' from server jaminit.co.uk as we're not in the room
Apr 27 15:10:53 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:53,803 - synapse.access.http.8008 - 427 - INFO - PUT-19202 - redacted - 8008 - {jaminit.co.uk} Processed request: 0.010sec/0.000sec (0.003sec, 0.001sec) (0.001sec/0.003sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1651086652574-34 HTTP/1.0" "Dendrite/0.8.2" [0 dbevts]
Apr 27 15:10:54 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:54,377 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:54 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:54,539 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19203 - Received txn 1649341910103 from matrix.geklautecloud.de. (PDUs: 0, EDUs: 1)
Apr 27 15:10:54 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:54,575 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:54 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:54,577 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19204 - Received txn 1650883839117 from midov.pl. (PDUs: 0, EDUs: 1)
Apr 27 15:10:54 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:54,646 - synapse.access.http.8008 - 427 - INFO - PUT-19203 - redacted - 8008 - {matrix.geklautecloud.de} Processed request: 0.268sec/0.000sec (0.004sec, 0.000sec) (0.001sec/0.103sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1649341910103 HTTP/1.0" "Synapse/1.56.0" [0 dbevts]
Apr 27 15:10:54 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:54,856 - synapse.http.matrixfederationclient - 285 - INFO - PUT-19200 - {GET-O-27187} [matrix.org] Completed request: 200 OK in 2.05 secs, got 14016 bytes - GET matrix://matrix.org/_matrix/federation/v1/user/devices/%40apostolosb%3Amatrix.org
Apr 27 15:10:54 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:54,879 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:54 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:54,906 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19205 - Received txn 1650794455930 from wu5.de. (PDUs: 0, EDUs: 1)
Apr 27 15:10:54 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:54,949 - synapse.access.http.8008 - 427 - INFO - PUT-19205 - redacted - 8008 - {wu5.de} Processed request: 0.068sec/0.000sec (0.004sec, 0.000sec) (0.001sec/0.029sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650794455930 HTTP/1.0" "Synapse/1.55.2" [0 dbevts]
Apr 27 15:10:55 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:55,308 - synapse.access.http.8008 - 427 - INFO - PUT-19204 - redacted - 8008 - {midov.pl} Processed request: 0.728sec/0.004sec (0.008sec, 0.001sec) (0.003sec/0.705sec/7) 11B 200 "PUT /_matrix/federation/v1/send/1650883839117 HTTP/1.0" "Synapse/1.54.0" [0 dbevts]
Apr 27 15:10:55 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:55,520 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:55 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:55,522 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19206 - Received txn 1650476933229 from catgirl.cloud. (PDUs: 0, EDUs: 1)
Apr 27 15:10:55 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:55,529 - synapse.access.http.8008 - 427 - INFO - PUT-19206 - redacted - 8008 - {catgirl.cloud} Processed request: 0.008sec/0.001sec (0.004sec, 0.000sec) (0.001sec/0.004sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650476933229 HTTP/1.0" "Synapse/1.57.1" [0 dbevts]
Apr 27 15:10:56 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:56,348 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:56 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:56,351 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19207 - Received txn 1651080282087 from envs.net. (PDUs: 0, EDUs: 2)
Apr 27 15:10:56 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:56,353 - synapse.handlers.receipts - 71 - INFO - PUT-19207 - Ignoring receipt for room '!zjYxZkVEqwWcQQhXxc:techlore.net' from server envs.net as we're not in the room
Apr 27 15:10:56 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:56,388 - synapse.access.http.8008 - 427 - INFO - PUT-19200 - redacted - 8008 - {matrix.org} Processed request: 3.663sec/0.000sec (0.020sec, 0.001sec) (0.109sec/1.820sec/13) 11B 200 "PUT /_matrix/federation/v1/send/1650977333947 HTTP/1.0" "Synapse/1.58.0rc1" [0 dbevts]
Apr 27 15:10:56 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:56,412 - synapse.access.http.8008 - 427 - INFO - PUT-19207 - redacted - 8008 - {envs.net} Processed request: 0.062sec/0.000sec (0.006sec, 0.002sec) (0.002sec/0.048sec/5) 11B 200 "PUT /_matrix/federation/v1/send/1651080282087 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 15:10:56 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:56,962 - synapse.http.federation.matrix_federation_agent - 364 - INFO - federation_transaction_transmission_loop-8853 - Failed to connect to matrix.srev.in:8448: Connection was refused by other side: 111: Connection refused.
Apr 27 15:10:56 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:56,963 - synapse.http.matrixfederationclient - 638 - INFO - federation_transaction_transmission_loop-8853 - {PUT-O-26007} [srev.in] Request failed: PUT matrix://srev.in/_matrix/federation/v1/send/1651075844409: ConnectionRefusedError('Connection refused')
Apr 27 15:10:59 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:59,698 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:10:59 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:59,701 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19208 - Received txn 1651067460053 from matrix.odenwilusenz.ch. (PDUs: 0, EDUs: 1)
Apr 27 15:10:59 canode.darkcloud.ca synapse[292]: 2022-04-27 15:10:59,758 - synapse.access.http.8008 - 427 - INFO - PUT-19208 - redacted - 8008 - {matrix.odenwilusenz.ch} Processed request: 0.058sec/0.000sec (0.005sec, 0.000sec) (0.002sec/0.050sec/5) 11B 200 "PUT /_matrix/federation/v1/send/1651067460053 HTTP/1.0" "Synapse/1.34.0" [0 dbevts]
Apr 27 15:11:00 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:00,937 - synapse.http.federation.matrix_federation_agent - 364 - INFO - federation_transaction_transmission_loop-8820 - Failed to connect to archgang.com:8448: User timeout caused connection failure.
Apr 27 15:11:00 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:00,938 - synapse.http.matrixfederationclient - 638 - INFO - federation_transaction_transmission_loop-8820 - {PUT-O-25980} [archgang.com] Request failed: PUT matrix://archgang.com/_matrix/federation/v1/send/1651075844382: TimeoutError('')
Apr 27 15:11:01 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:01,342 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:01 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:01,345 - synapse.access.http.8008 - 427 - INFO - PUT-19209 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.002sec/0.000sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "PUT /_matrix/client/r0/rooms/!MrBiSgIYlhBDTOjtks:matrix.darkcloud.ca/typing/%40philjoannou%3Amatrix.darkcloud.ca HTTP/1.0" "Riot/1.6.5 (iPhone; iOS 14.7.1; Scale/2.00)" [0 dbevts]
Apr 27 15:11:02 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:02,431 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:02 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:02,493 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19210 - Received txn 1648322438041 from ccc-ffm.de. (PDUs: 0, EDUs: 1)
Apr 27 15:11:02 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:02,561 - synapse.access.http.8008 - 427 - INFO - PUT-19210 - redacted - 8008 - {ccc-ffm.de} Processed request: 0.129sec/0.000sec (0.003sec, 0.000sec) (0.001sec/0.063sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1648322438041 HTTP/1.0" "Synapse/1.55.0" [0 dbevts]
Apr 27 15:11:03 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:03,348 - synapse.access.http.8008 - 427 - INFO - GET-19162 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 30.003sec/0.001sec (0.005sec, 0.000sec) (0.045sec/0.006sec/2) 261B 200 "GET /_matrix/client/r0/sync?filter=4&timeout=30000&since=s2917127_29618678_745_2430122_624116_134_278340_1660483_2 HTTP/1.0" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, lik>
Apr 27 15:11:03 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:03,352 - synapse.access.http.8008 - 427 - INFO - GET-19163 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 30.003sec/0.000sec (0.002sec, 0.000sec) (0.041sec/0.009sec/2) 261B 200 "GET /_matrix/client/r0/sync?filter=2&timeout=30000&since=s2917127_29618677_745_2430122_624116_134_278340_1660483_2 HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko)>
Apr 27 15:11:03 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:03,496 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:03 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:03,504 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:03 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:03,535 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:03 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:03,543 - synapse.access.http.8008 - 427 - INFO - GET-19213 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.006sec/0.001sec (0.004sec, 0.000sec) (0.001sec/0.002sec/2) 858B 200 "GET /_matrix/client/r0/sync?filter=4&timeout=30000&since=s2917127_29618691_746_2430122_624116_134_278340_1660483_2 HTTP/1.0" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like>
Apr 27 15:11:03 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:03,596 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:03 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:03,607 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:03 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:03,615 - synapse.access.http.8008 - 427 - INFO - GET-19215 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.006sec/0.001sec (0.004sec, 0.001sec) (0.001sec/0.002sec/2) 710B 200 "GET /_matrix/client/r0/sync?filter=2&timeout=30000&since=s2917127_29618691_746_2430122_624116_134_278340_1660483_2 HTTP/1.0" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) >
Apr 27 15:11:03 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:03,627 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:03 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:03,732 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:03 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:03,843 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:04 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:04,924 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:04 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:04,930 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19219 - Received txn 1651073393529 from kanp.ai. (PDUs: 0, EDUs: 1)
Apr 27 15:11:04 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:04,937 - synapse.access.http.8008 - 427 - INFO - PUT-19219 - redacted - 8008 - {kanp.ai} Processed request: 0.011sec/0.001sec (0.002sec, 0.000sec) (0.001sec/0.003sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1651073393529 HTTP/1.0" "Synapse/1.57.1" [0 dbevts]
Apr 27 15:11:05 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:05,406 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:05 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:05,424 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19220 - Received txn 1649346347184 from maschm.de. (PDUs: 0, EDUs: 1)
Apr 27 15:11:05 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:05,448 - synapse.access.http.8008 - 427 - INFO - PUT-19220 - redacted - 8008 - {maschm.de} Processed request: 0.040sec/0.001sec (0.004sec, 0.000sec) (0.001sec/0.019sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1649346347184 HTTP/1.0" "Synapse/1.51.0" [0 dbevts]
Apr 27 15:11:05 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:05,611 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:05 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:05,613 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19221 - Received txn 1650403712235 from matrix.cloudsupplies.de. (PDUs: 0, EDUs: 1)
Apr 27 15:11:05 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:05,634 - synapse.access.http.8008 - 427 - INFO - PUT-19221 - redacted - 8008 - {matrix.cloudsupplies.de} Processed request: 0.023sec/0.000sec (0.004sec, 0.000sec) (0.001sec/0.018sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650403712235 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 15:11:06 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:06,335 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:06 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:06,343 - synapse.access.http.8008 - 427 - INFO - PUT-19222 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.005sec/0.002sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "PUT /_matrix/client/r0/rooms/!MrBiSgIYlhBDTOjtks:matrix.darkcloud.ca/typing/%40philjoannou%3Amatrix.darkcloud.ca HTTP/1.0" "Riot/1.6.5 (iPhone; iOS 14.7.1; Scale/2.00)" [0 dbevts]
Apr 27 15:11:06 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:06,348 - synapse.access.http.8008 - 427 - INFO - GET-19188 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 24.811sec/0.002sec (0.008sec, 0.001sec) (0.002sec/0.004sec/4) 641B 200 "GET /_matrix/client/r0/sync?filter=1&since=s2917127_29618736_747_2430122_624116_134_278340_1660483_2&timeout=30000 HTTP/1.0" "Riot/1.6.5 (iPhone; iOS 14.7.1; Scale/2.00)" [0 dbevts]
Apr 27 15:11:06 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:06,356 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:06 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:06,358 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19223 - Received txn 1651068754279 from t2bot.io. (PDUs: 0, EDUs: 1)
Apr 27 15:11:06 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:06,384 - synapse.access.http.8008 - 427 - INFO - PUT-19223 - redacted - 8008 - {t2bot.io} Processed request: 0.027sec/0.001sec (0.004sec, 0.000sec) (0.001sec/0.022sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1651068754279 HTTP/1.0" "Synapse/1.56.0" [0 dbevts]
Apr 27 15:11:06 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:06,435 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:07 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:07,923 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:07 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:07,931 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:07 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:07,936 - synapse.access.http.8008 - 427 - INFO - POST-19226 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.003sec/0.002sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "POST /_matrix/client/r0/rooms/!oqwaeHPWUeAQEAPBDF:matrix.darkcloud.ca/read_markers HTTP/1.0" "Riot/1.8.13 (iPhone; iOS 15.4.1; Scale/2.00)" [0 dbevts]
Apr 27 15:11:07 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:07,937 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:07 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:07,939 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:07 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:07,941 - synapse.access.http.8008 - 427 - INFO - POST-19227 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.001sec/0.002sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "POST /_matrix/client/r0/rooms/!oqwaeHPWUeAQEAPBDF:matrix.darkcloud.ca/read_markers HTTP/1.0" "Riot/1.8.13 (iPhone; iOS 15.4.1; Scale/2.00)" [0 dbevts]
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,008 - synapse.access.http.8008 - 427 - INFO - GET-19193 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 25.288sec/0.002sec (0.007sec, 0.001sec) (0.019sec/0.006sec/4) 426B 200 "GET /_matrix/client/r0/sync?filter=3&timeout=30000&since=s2917127_29618738_747_2430122_624116_134_278340_1660483_2 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Eleme>
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,009 - synapse.access.http.8008 - 427 - INFO - GET-19195 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 25.150sec/0.002sec (0.004sec, 0.004sec) (0.023sec/0.007sec/4) 426B 200 "GET /_matrix/client/r0/sync?filter=3&timeout=30000&since=s2917127_29618738_747_2430122_624116_134_278340_1660483_2 HTTP/1.0" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, l>
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,010 - synapse.access.http.8008 - 427 - INFO - GET-19196 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 25.134sec/0.002sec (0.008sec, 0.001sec) (0.017sec/0.006sec/4) 388B 200 "GET /_matrix/client/r0/sync?access_token=<redacted>&since=s2917127_29618738_747_2430122_624116_134_278340_1660483_2&timeout=30000&filter=%7B%22room%22:%7B%22state%22:%7B%22lazy_load_members%22:true%7D%7>
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,067 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,319 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,463 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,472 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,475 - synapse.access.http.8008 - 427 - INFO - POST-19228 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.383sec/0.153sec (0.003sec, 0.003sec) (0.001sec/0.294sec/3) 4578B 200 "POST /_matrix/client/r0/keys/query HTTP/1.0" "Riot/1.8.13 (iPhone; iOS 15.4.1; Scale/2.00)" [0 dbevts]
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,482 - synapse.access.http.8008 - 427 - INFO - GET-19225 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.553sec/0.004sec (0.011sec, 0.001sec) (0.002sec/0.308sec/6) 570B 200 "GET /_matrix/client/r0/sync?filter=0&set_presence=online&since=s2917109_29617998_663_2430069_624113_134_278339_1660469_2&timeout=0 HTTP/1.0" "Riot/1.8.13 (iPhone; iOS 15.4.1; Scale/2.00)" [0 dbevts]
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,506 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,636 - synapse.util.caches.lrucache - 154 - INFO - LruCache._expire_old_entries-330 - Dropped 1 items from caches
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,670 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,674 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,676 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,682 - synapse.access.http.8008 - 427 - INFO - PUT-19234 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.001sec/0.010sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "PUT /_matrix/client/r0/presence/@redacted:matrix.darkcloud.ca/status HTTP/1.0" "Riot/1.8.13 (iPhone; iOS 15.4.1; Scale/2.00)" [0 dbevts]
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,698 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,719 - synapse.access.http.8008 - 427 - INFO - POST-19237 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.020sec/0.001sec (0.003sec, 0.000sec) (0.001sec/0.017sec/3) 4578B 200 "POST /_matrix/client/r0/keys/query HTTP/1.0" "Riot/1.8.13 (iPhone; iOS 15.4.1; Scale/2.00)" [0 dbevts]
Apr 27 15:11:08 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:08,916 - synapse.access.http.8008 - 427 - INFO - POST-19235 - redacted - 8008 - {@redacted:matrix.darkcloud.ca} Processed request: 0.241sec/0.001sec (0.003sec, 0.002sec) (0.002sec/0.232sec/5) 2B 200 "POST /_matrix/client/r0/pushers/set HTTP/1.0" "Riot/1.8.13 (iPhone; iOS 15.4.1; Scale/2.00)" [0 dbevts]
Apr 27 15:11:10 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:10,057 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:10 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:10,059 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19238 - Received txn 1650403460968 from sigint.club. (PDUs: 0, EDUs: 1)
Apr 27 15:11:10 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:10,067 - synapse.access.http.8008 - 427 - INFO - PUT-19238 - redacted - 8008 - {sigint.club} Processed request: 0.008sec/0.001sec (0.003sec, 0.001sec) (0.001sec/0.003sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650403460968 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 27 15:11:10 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:10,648 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 27 15:11:10 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:10,650 - synapse.federation.transport.server.federation - 102 - INFO - PUT-19239 - Received txn 1651067461305 from matrix.odenwilusenz.ch. (PDUs: 0, EDUs: 1)
Apr 27 15:11:10 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:10,685 - synapse.access.http.8008 - 427 - INFO - PUT-19239 - redacted - 8008 - {matrix.odenwilusenz.ch} Processed request: 0.036sec/0.000sec (0.005sec, 0.001sec) (0.002sec/0.028sec/5) 11B 200 "PUT /_matrix/federation/v1/send/1651067461305 HTTP/1.0" "Synapse/1.34.0" [0 dbevts]
Apr 27 15:11:11 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:11,421 - synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 1
Apr 27 15:11:11 canode.darkcloud.ca synapse[292]: 2022-04-27 15:11:11,520 - synapse.metrics._gc - 120 - INFO - sentinel - Collecting gc 2
prurigro commented 2 years ago

I was watching bandwidth usage on the server when connectivity is gone, and it was less than 10kb/s in either direction before jumping to 300kb/s download and 30kb/s up a second before connectivity was restored. This error appeared again during that outage:

Apr 27 15:38:42 canode.darkcloud.ca synapse[292]: 2022-04-27 15:38:42,511 - synapse.storage.txn - 640 - WARNING - persist_presence_changes-191 - [TXN OPERROR] {update_presence-1e416} could not serialize access due to concurrent delete
Apr 27 15:38:42 canode.darkcloud.ca synapse[292]:  0/5
H-Shay commented 2 years ago

Thanks for the logs, very helpful! I have a wild hunch that sync is implicated here but need to do more digging. One more thing-can you provide the exact error message the client is showing when connectivity is lost?

H-Shay commented 2 years ago

Specifically, I think that the processing of the /sync response is taking longer than the client timeout and the connection is getting dropped as a result.

prurigro commented 2 years ago

I think you might be right-- I hadn't realized the client included error logs, but it seems like they're full of sync errors:

2022-04-27T06:22:12.114Z E /sync error %s Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T06:22:12.159Z E Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T06:22:12.159Z I Number of consecutive failed sync requests: 1
2022-04-27T06:22:12.159Z I Starting keep-alive
2022-04-27T06:22:12.162Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T06:22:18.324Z I received to_device m.room.encrypted from: @redacted:matrix.darkcloud.ca id: undefined
2022-04-27T06:22:18.402Z I MatrixClient sync state => %s SYNCING
2022-04-27T06:22:18.418Z W Discarding an event, we don't have a call/peerConn m.room.encrypted
2022-04-27T06:22:18.476Z I decryptMessage: Olm Session ID Eg4yLNsmVWQysCqMPSlYnnmO3ix1QABr/MhmSrbgS5U from kdpqLiec9qoQpwlpRJO5IEV5UdGkxOAu3JyXQ/ayhyo: sender chain index: 0 receiver chain indices: 5 4 28 1 1 skipped message keys: 0
2022-04-27T06:22:18.495Z W Error decrypting event (id=$0lO7MJhAxOJzh_QlmogfogD2pD_7e3-367FL4Qh9lzQ): DecryptionError[msg: The sender's device has not sent us the keys for this message., session: kdpqLiec9qoQpwlpRJO5IEV5UdGkxOAu3JyXQ/ayhyo|tfuVj8IXp94+/HsSTZm2jgzYvTiUzfe0+7SpoGlLokM]
2022-04-27T06:22:18.518Z I enqueueing key request for !oqwaeHPWUeAQEAPBDF:matrix.darkcloud.ca / tfuVj8IXp94+/HsSTZm2jgzYvTiUzfe0+7SpoGlLokM
2022-04-27T06:22:18.607Z I Decrypted Olm message from kdpqLiec9qoQpwlpRJO5IEV5UdGkxOAu3JyXQ/ayhyo with session Eg4yLNsmVWQysCqMPSlYnnmO3ix1QABr/MhmSrbgS5U
2022-04-27T06:22:18.607Z I received to_device m.room_key from: @redacted:matrix.darkcloud.ca id: undefined
2022-04-27T06:22:18.714Z I Storing megolm session kdpqLiec9qoQpwlpRJO5IEV5UdGkxOAu3JyXQ/ayhyo/tfuVj8IXp94+/HsSTZm2jgzYvTiUzfe0+7SpoGlLokM with first index 0
2022-04-27T06:22:18.739Z I Retrying decryption on events [{"decrypted":{"type":"m.room.message","sender":"@redacted:matrix.darkcloud.ca","content":{"msgtype":"m.bad.encrypted","body":"** Unable to decrypt: The sender's device has not sent us the keys for this message. **"},"origin_server_ts":1651039659730,"unsigned":{"age":878663},"event_id":"$0lO7MJhAxOJzh_QlmogfogD2pD_7e3-367FL4Qh9lzQ","room_id":"!oqwaeHPWUeAQEAPBDF:matrix.darkcloud.ca"},"encrypted":{"type":"m.room.encrypted","sender":"@redacted:matrix.darkcloud.ca","content":{"algorithm":"m.megolm.v1.aes-sha2","sender_key":"kdpqLiec9qoQpwlpRJO5IEV5UdGkxOAu3JyXQ/ayhyo","ciphertext":"AwgAEvABbq6PmLUL/tN63woHYcGvM4kGaz6DD/aAYj1bqUGNyrsQ+j8lJ1BjW2awYLwx/5D5xKrfTmSvHlbncXahFyhSf73q6pD1JghirupaBrPh3AxEX5E04FVDBD5/FGAKKP89R0A4JpI9MeCDDXomtRrCbZ+ETif8RoD9eT/ypqCC3/+L0tcH9oeOzamI7JJyxRzDw8AoxlTzeJ8MLiA5W8Xdo9QyjCkpqC9DoKvzwGLwNWAWo752ns7uRymqtczHIjIWgLtmtZPcnduhdtnJTW/BUFOVwbma2X1AJcHXDcJRwJoT0lnT4p5oJ/WKoeSW5g170BQT4PmZgBK65ufhnCO2E7bqe0GAXJiXf9qdOyZT2eCVLSbabhoNVTc6wpDSCBL9l9DLbKZpkq4+xLWgogt0FxkAMGnTawME","session_id":"tfuVj8IXp94+/HsSTZm2jgzYvTiUzfe0+7SpoGlLokM","device_id":"AVNTJELQOV"},"origin_server_ts":1651039659730,"unsigned":"<$ cycle-trimmed $>","event_id":"$0lO7MJhAxOJzh_QlmogfogD2pD_7e3-367FL4Qh9lzQ","room_id":"!oqwaeHPWUeAQEAPBDF:matrix.darkcloud.ca"}}]
2022-04-27T06:22:18.770Z I Decrypted event on retry (id=$0lO7MJhAxOJzh_QlmogfogD2pD_7e3-367FL4Qh9lzQ)
2022-04-27T06:22:18.783Z I deleting unnecessary room key request for !oqwaeHPWUeAQEAPBDF:matrix.darkcloud.ca / tfuVj8IXp94+/HsSTZm2jgzYvTiUzfe0+7SpoGlLokM
2022-04-27T07:24:22.104Z E /sync error %s Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T07:24:22.145Z E Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T07:24:22.145Z I Number of consecutive failed sync requests: 1
2022-04-27T07:24:22.145Z I Starting keep-alive
2022-04-27T07:24:22.148Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T07:42:41.441Z I MatrixClient sync state => %s SYNCING
2022-04-27T09:43:12.234Z E /sync error %s Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T09:43:12.234Z E Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T09:43:12.234Z I Number of consecutive failed sync requests: 1
2022-04-27T09:43:12.234Z I Starting keep-alive
2022-04-27T09:43:12.237Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T09:43:20.732Z I MatrixClient sync state => %s SYNCING
2022-04-27T09:43:46.019Z E /sync error %s request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916254_29597147_6627_2428539_623860_134_278296_1658867_2
ConnectionError: request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916254_29597147_6627_2428539_623860_134_278296_1658867_2
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793665
    at Object.callback (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793285)
    at u (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:12111)
    at XMLHttpRequest.i.onreadystatechange (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:11541)
2022-04-27T09:43:46.276Z E request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916254_29597147_6627_2428539_623860_134_278296_1658867_2
ConnectionError: request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916254_29597147_6627_2428539_623860_134_278296_1658867_2
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793665
    at Object.callback (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793285)
    at u (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:12111)
    at XMLHttpRequest.i.onreadystatechange (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:11541)
2022-04-27T09:43:46.277Z I Number of consecutive failed sync requests: 1
2022-04-27T09:43:46.277Z I Starting keep-alive
2022-04-27T09:43:46.285Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T09:43:50.287Z I MatrixClient sync state => %s SYNCING
2022-04-27T09:53:49.112Z E /sync error %s Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T09:53:49.168Z E Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T09:53:49.168Z I Number of consecutive failed sync requests: 1
2022-04-27T09:53:49.168Z I Starting keep-alive
2022-04-27T09:53:49.171Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T10:28:41.230Z I MatrixClient sync state => %s SYNCING
2022-04-27T10:46:12.542Z E /sync error %s Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T10:46:12.591Z E Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T10:46:12.591Z I Number of consecutive failed sync requests: 1
2022-04-27T10:46:12.591Z I Starting keep-alive
2022-04-27T10:46:12.593Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T12:47:32.032Z I MatrixClient sync state => %s ERROR
2022-04-27T12:48:22.270Z I MatrixClient sync state => %s ERROR
2022-04-27T12:48:47.972Z I MatrixClient sync state => %s ERROR
2022-04-27T12:55:39.554Z I MatrixClient sync state => %s CATCHUP
2022-04-27T12:55:43.177Z I MatrixClient sync state => %s SYNCING
2022-04-27T12:56:35.729Z I TURN creds are valid for another 11028087 ms: not fetching new ones.
2022-04-27T13:06:37.200Z I TURN creds are valid for another 10426616 ms: not fetching new ones.
2022-04-27T13:10:38.106Z E /sync error %s request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916380_29604362_7147_2429057_623864_134_278299_1659585_2
ConnectionError: request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916380_29604362_7147_2429057_623864_134_278299_1659585_2
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793665
    at Object.callback (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793285)
    at u (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:12111)
    at XMLHttpRequest.i.onreadystatechange (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:11541)
2022-04-27T13:10:38.199Z E request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916380_29604362_7147_2429057_623864_134_278299_1659585_2
ConnectionError: request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916380_29604362_7147_2429057_623864_134_278299_1659585_2
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793665
    at Object.callback (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793285)
    at u (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:12111)
    at XMLHttpRequest.i.onreadystatechange (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:11541)
2022-04-27T13:10:38.199Z I Number of consecutive failed sync requests: 1
2022-04-27T13:10:38.199Z I Starting keep-alive
2022-04-27T13:10:38.201Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T13:11:03.468Z I MatrixClient sync state => %s ERROR
2022-04-27T13:11:33.046Z I MatrixClient sync state => %s ERROR
2022-04-27T13:13:34.945Z I MatrixClient sync state => %s ERROR
2022-04-27T13:14:02.179Z I MatrixClient sync state => %s ERROR
2022-04-27T13:14:24.492Z I MatrixClient sync state => %s ERROR
2022-04-27T13:14:53.180Z I MatrixClient sync state => %s ERROR
2022-04-27T13:15:34.451Z I MatrixClient sync state => %s ERROR
2022-04-27T13:16:48.476Z I TURN creds are valid for another 9815340 ms: not fetching new ones.
2022-04-27T13:17:47.624Z I MatrixClient sync state => %s ERROR
2022-04-27T13:18:46.548Z I MatrixClient sync state => %s CATCHUP
2022-04-27T13:18:46.815Z I MatrixClient sync state => %s SYNCING
2022-04-27T13:21:24.225Z E /sync error %s request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916384_29604729_7149_2429076_623864_134_278299_1659585_2
ConnectionError: request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916384_29604729_7149_2429076_623864_134_278299_1659585_2
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793665
    at Object.callback (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793285)
    at u (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:12111)
    at XMLHttpRequest.i.onreadystatechange (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:11541)
2022-04-27T13:21:24.258Z E request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916384_29604729_7149_2429076_623864_134_278299_1659585_2
ConnectionError: request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916384_29604729_7149_2429076_623864_134_278299_1659585_2
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793665
    at Object.callback (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793285)
    at u (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:12111)
    at XMLHttpRequest.i.onreadystatechange (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:11541)
2022-04-27T13:21:24.258Z I Number of consecutive failed sync requests: 1
2022-04-27T13:21:24.258Z I Starting keep-alive
2022-04-27T13:21:24.260Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T13:21:45.964Z I MatrixClient sync state => %s ERROR
2022-04-27T13:22:14.192Z I MatrixClient sync state => %s ERROR
2022-04-27T13:22:41.164Z I MatrixClient sync state => %s CATCHUP
2022-04-27T13:22:41.809Z I MatrixClient sync state => %s SYNCING
2022-04-27T13:26:34.684Z I TURN creds are valid for another 9229132 ms: not fetching new ones.
2022-04-27T13:34:42.884Z E /sync error %s request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916387_29605216_7153_2429108_623864_134_278299_1659585_2
ConnectionError: request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916387_29605216_7153_2429108_623864_134_278299_1659585_2
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793665
    at Object.callback (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793285)
    at u (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:12111)
    at XMLHttpRequest.i.onreadystatechange (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:11541)
2022-04-27T13:34:42.918Z E request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916387_29605216_7153_2429108_623864_134_278299_1659585_2
ConnectionError: request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916387_29605216_7153_2429108_623864_134_278299_1659585_2
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793665
    at Object.callback (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793285)
    at u (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:12111)
    at XMLHttpRequest.i.onreadystatechange (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:11541)
2022-04-27T13:34:42.918Z I Number of consecutive failed sync requests: 1
2022-04-27T13:34:42.918Z I Starting keep-alive
2022-04-27T13:34:42.920Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T13:35:10.226Z I MatrixClient sync state => %s ERROR
2022-04-27T13:35:38.215Z I MatrixClient sync state => %s ERROR
2022-04-27T13:36:55.228Z I TURN creds are valid for another 8608588 ms: not fetching new ones.
2022-04-27T13:37:47.260Z I MatrixClient sync state => %s ERROR
2022-04-27T13:38:51.826Z I MatrixClient sync state => %s CATCHUP
2022-04-27T13:38:52.462Z I MatrixClient sync state => %s SYNCING
2022-04-27T13:41:27.271Z E /sync error %s request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916394_29605495_7153_2429124_623864_134_278299_1659596_2
ConnectionError: request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916394_29605495_7153_2429124_623864_134_278299_1659596_2
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793665
    at Object.callback (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793285)
    at u (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:12111)
    at XMLHttpRequest.i.onreadystatechange (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:11541)
2022-04-27T13:41:27.306Z E request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916394_29605495_7153_2429124_623864_134_278299_1659596_2
ConnectionError: request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916394_29605495_7153_2429124_623864_134_278299_1659596_2
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793665
    at Object.callback (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793285)
    at u (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:12111)
    at XMLHttpRequest.i.onreadystatechange (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:11541)
2022-04-27T13:41:27.306Z I Number of consecutive failed sync requests: 1
2022-04-27T13:41:27.306Z I Starting keep-alive
2022-04-27T13:41:27.307Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T13:41:38.130Z I MatrixClient sync state => %s SYNCING
2022-04-27T13:45:06.682Z E /sync error %s request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916395_29605651_7153_2429133_623864_134_278299_1659601_2
ConnectionError: request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916395_29605651_7153_2429133_623864_134_278299_1659601_2
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793665
    at Object.callback (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793285)
    at u (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:12111)
    at XMLHttpRequest.i.onreadystatechange (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:11541)
2022-04-27T13:45:06.716Z E request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916395_29605651_7153_2429133_623864_134_278299_1659601_2
ConnectionError: request failed: CORS request rejected: https://matrix.darkcloud.ca/_matrix/client/r0/sync?filter=3&timeout=30000&since=s2916395_29605651_7153_2429133_623864_134_278299_1659601_2
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793665
    at Object.callback (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:793285)
    at u (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:12111)
    at XMLHttpRequest.i.onreadystatechange (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:11541)
2022-04-27T13:45:06.716Z I Number of consecutive failed sync requests: 1
2022-04-27T13:45:06.716Z I Starting keep-alive
2022-04-27T13:45:06.717Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T13:45:30.226Z I MatrixClient sync state => %s ERROR
2022-04-27T13:46:03.227Z I MatrixClient sync state => %s ERROR
2022-04-27T13:46:34.355Z I TURN creds are valid for another 8029461 ms: not fetching new ones.
2022-04-27T13:46:34.426Z I Updating homeserver-configured integration managers...
2022-04-27T13:46:34.426Z I Homeserver has no integration managers
2022-04-27T13:46:34.426Z I Attempting to get Jitsi conference information from homeserver
2022-04-27T13:46:34.426Z I Jitsi conference domain: meet.element.io
2022-04-27T13:46:34.645Z I MatrixClient sync state => %s CATCHUP
2022-04-27T13:46:35.124Z I MatrixClient sync state => %s SYNCING
2022-04-27T13:57:06.020Z E /sync error %s Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T13:57:06.078Z E Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T13:57:06.078Z I Number of consecutive failed sync requests: 1
2022-04-27T13:57:06.078Z I Starting keep-alive
2022-04-27T13:57:06.081Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T14:14:27.345Z I TURN creds are valid for another 6356471 ms: not fetching new ones.
2022-04-27T14:32:43.967Z I MatrixClient sync state => %s ERROR
2022-04-27T14:48:11.452Z I MatrixClient sync state => %s ERROR
2022-04-27T14:48:35.396Z I MatrixClient sync state => %s ERROR
2022-04-27T14:49:34.159Z I MatrixClient sync state => %s CATCHUP
2022-04-27T14:49:39.623Z I MatrixClient sync state => %s SYNCING
2022-04-27T15:16:34.255Z E /sync error %s Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T15:16:34.304Z E Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T15:16:34.304Z I Number of consecutive failed sync requests: 1
2022-04-27T15:16:34.304Z I Starting keep-alive
2022-04-27T15:16:34.306Z I MatrixClient sync state => %s RECONNECTING
2022-04-27T15:17:46.501Z I MatrixClient sync state => %s SYNCING
2022-04-27T15:33:17.038Z E /sync error %s Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T15:33:17.038Z E Locally timed out waiting for a response
ORG.MATRIX.JSSDK_TIMEOUT: Locally timed out waiting for a response
    at vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:792906
    at d (vector://vector/webapp/bundles/21ed71297f175e2d4e03/vendors~init.js:2:3093256)
2022-04-27T15:33:17.039Z I Number of consecutive failed sync requests: 1
2022-04-27T15:33:17.039Z I Starting keep-alive
2022-04-27T15:33:17.046Z I MatrixClient sync state => %s RECONNECTING

I have lots more, but considering it just repeats again and again I assume that's probably enough? (let me know if not)

EDIT: I should add that I'm able to ssh into my server without trouble while this is going on and the bandwidth and CPU usage is low (memory use is always fairly high, though I added 2 gigs to the swap today and it didn't use much more or change anything)

H-Shay commented 2 years ago

Alright, so it appears we are seeing some mysteriously long /sync requests in the logs, but don't have enough information to determine why the processing of those requests is taking so long. Two things might be helpful here: first, if you would be willing to provide logs for a longer timeframe (4-24 hours) within which you're sure there were a few timeouts (you can upload as a .txt file), that would be very useful. Second, do you have graphana or any other sort of metrics/monitoring enabled on your homeserver? If not, it might be something that you would want to consider and would possibly help in debugging this situation.

squahtx commented 2 years ago

Second, do you have graphana or any other sort of metrics/monitoring enabled on your homeserver? If not, it might be something that you would want to consider and would possibly help in debugging this situation.

To add onto what Shay said, Synapse reports timings for many processes, including GC durations, as part of its Prometheus metrics. It's a little suspicious that you've seen some an instance of connectivity drops without any GC log lines. Looking at the metrics would allow us to confirm or rule out GC as the source of the issue.

prurigro commented 2 years ago

Thanks for the quick responses, I really appreciate the help in tracking down the source of this issue! I agree that it's suspicious that there are drops without GC log lines- most of them have them, and all of them I'd checked prior to the ones I'd posted without had them so I'd assumed that was to blame, but now I'm not so sure.

I don't currently have any sort of metrics/monitoring running, but can look into setting that up soon. For now, here are the client and server logs for the 27th (which had lots of outages). I redacted usernames, channel names, emails and some server addresses using regex for the privacy of the people on my server, so let me know if you run into anything I inadvertently clobbered.

http://96.126.108.7:90/client-2022-04-27.log http://96.126.108.7:90/server-2022-04-27.log

Thanks again!

prurigro commented 2 years ago

Not sure if it's related, but the server was inaccessible for a chunk of the morning today, and it hung attempting to restart the service. Logs showed this after hanging:

Apr 29 11:47:02 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:02,624 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 29 11:47:02 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:02,631 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 29 11:47:02 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:02,634 - synapse.federation.transport.server.federation - 102 - INFO - PUT-3103 - Received txn 1647878842329 from zenon.wiki. (PDUs: 0, EDUs: 1)
Apr 29 11:47:02 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:02,660 - synapse.federation.transport.server.federation - 102 - INFO - PUT-3092 - Received txn 1650987688470 from totally.rip. (PDUs: 0, EDUs: 1)
Apr 29 11:47:02 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:02,675 - synapse.push.httppusher - 192 - INFO - httppush.process-8 - Processing 0 unprocessed push actions for @REDACTED:matrix.darkcloud.ca/im.vector.app.android/fkvWAJHGSRubjnTNWd40sn:APA91bFaTat0Laz3dIzy7KV7IqFs5Vu3cscTtSg1XShnX2wjzgXMf6CuRjfoY_ytGrCGUrV2uJaGUJ7OT7izjEKXmNprL80qsH_RntfQbxIk5bzQ8FzVCC-IQgeOCZ8h8OfdqLCNx38U starting at stream_ordering 2919432
Apr 29 11:47:02 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:02,681 - synapse.access.http.8008 - 427 - INFO - PUT-3101 - 185.194.93.131 - 8008 - {matrix.circl.lu} Processed request: 0.084sec/0.002sec (0.003sec, 0.001sec) (0.003sec/0.066sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650964369346 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 29 11:47:02 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:02,692 - synapse.access.http.8008 - 427 - INFO - PUT-3103 - 45.63.9.113 - 8008 - {zenon.wiki} Processed request: 0.058sec/0.002sec (0.005sec, 0.001sec) (0.003sec/0.048sec/5) 11B 200 "PUT /_matrix/federation/v1/send/1647878842329 HTTP/1.0" "Synapse/1.49.2" [0 dbevts]
Apr 29 11:47:02 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:02,778 - synapse.access.http.8008 - 427 - INFO - PUT-3092 - 135.181.244.180 - 8008 - {totally.rip} Processed request: 3.642sec/0.000sec (0.006sec, 0.001sec) (0.004sec/0.117sec/8) 11B 200 "PUT /_matrix/federation/v1/send/1650987688470 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 29 11:47:02 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:02,799 - synapse.access.http.8008 - 427 - INFO - GET-3094 - 89.35.163.160 - 8008 - {brixit.nl} Processed request: 3.661sec/0.001sec (0.003sec, 0.000sec) (0.001sec/0.144sec/2) 2783B 200 "GET /_matrix/federation/v1/user/devices/%40wantija%3Amatrix.darkcloud.ca HTTP/1.0" "Synapse/1.54.0" [0 dbevts]
Apr 29 11:47:03 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:03,227 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 29 11:47:03 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:03,229 - synapse.federation.transport.server.federation - 102 - INFO - PUT-3104 - Received txn 1650592624896 from halogen.city. (PDUs: 0, EDUs: 1)
Apr 29 11:47:03 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:03,253 - synapse.access.http.8008 - 427 - INFO - PUT-3104 - 23.227.135.186 - 8008 - {halogen.city} Processed request: 0.025sec/0.000sec (0.003sec, 0.000sec) (0.001sec/0.020sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650592624896 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 29 11:47:03 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:03,265 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 29 11:47:03 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:03,267 - synapse.federation.transport.server.federation - 102 - INFO - PUT-3105 - Received txn 1650592624917 from halogen.city. (PDUs: 0, EDUs: 1)
Apr 29 11:47:03 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:03,273 - synapse.access.http.8008 - 427 - INFO - PUT-3105 - 23.227.135.186 - 8008 - {halogen.city} Processed request: 0.006sec/0.000sec (0.003sec, 0.000sec) (0.001sec/0.003sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650592624917 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 29 11:47:06 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:06,651 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
Apr 29 11:47:06 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:06,653 - synapse.federation.transport.server.federation - 102 - INFO - PUT-3106 - Received txn 1650979525279 from netserve.live. (PDUs: 0, EDUs: 1)
Apr 29 11:47:06 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:06,687 - synapse.access.http.8008 - 427 - INFO - PUT-3106 - 94.23.162.228 - 8008 - {netserve.live} Processed request: 0.035sec/0.000sec (0.003sec, 0.001sec) (0.001sec/0.031sec/2) 11B 200 "PUT /_matrix/federation/v1/send/1650979525279 HTTP/1.0" "Synapse/1.57.0" [0 dbevts]
Apr 29 11:47:06 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:06,886 - synapse.handlers.federation_event - 788 - INFO - _process_incoming_pdus_in_room_inner-0-$RVPDmMDOH2AhY1x94bzEwod_GQEdFmfpN6q1RvfYd3A-$f99w5ZKHqGhKGqc7AMe-CkOANbOM2AF_RmMIptwGLj0 - Requesting state after missing prev_event $uedPn5LUAY3j0xC9MpYF1JmbNhcWXJLxBGUlKqSbhyI
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:07,572 - synapse.http.matrixfederationclient - 595 - INFO - _process_incoming_pdus_in_room_inner-0-$RVPDmMDOH2AhY1x94bzEwod_GQEdFmfpN6q1RvfYd3A-$f99w5ZKHqGhKGqc7AMe-CkOANbOM2AF_RmMIptwGLj0-$uedPn5LUAY3j0xC9MpYF1JmbNhcWXJLxBGUlKqSbhyI - {GET-O-5732} [trygve.me] Got response headers: 404 Not Found
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:07,573 - synapse.http.matrixfederationclient - 673 - WARNING - _process_incoming_pdus_in_room_inner-0-$RVPDmMDOH2AhY1x94bzEwod_GQEdFmfpN6q1RvfYd3A-$f99w5ZKHqGhKGqc7AMe-CkOANbOM2AF_RmMIptwGLj0-$uedPn5LUAY3j0xC9MpYF1JmbNhcWXJLxBGUlKqSbhyI - {GET-O-5732} [trygve.me] Request failed: GET matrix://trygve.me/_matrix/federation/v1/state_ids/%21yUHxXrvmurdnsPyhiH%3Asakura.ci?event_id=%24uedPn5LUAY3j0xC9MpYF1JmbNhcWXJLxBGUlKqSbhyI: HttpResponseException('404: Not Found')
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]: 2022-04-29 11:47:07,574 - synapse.handlers.federation_event - 829 - WARNING - _process_incoming_pdus_in_room_inner-0-$RVPDmMDOH2AhY1x94bzEwod_GQEdFmfpN6q1RvfYd3A-$f99w5ZKHqGhKGqc7AMe-CkOANbOM2AF_RmMIptwGLj0 - Error attempting to resolve state at missing prev_events
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]: Traceback (most recent call last):
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:   File "/usr/lib/python3.10/site-packages/synapse/handlers/federation_event.py", line 794, in _resolve_state_at_missing_prevs
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:     remote_state = await self._get_state_after_missing_prev_event(
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:   File "/usr/lib/python3.10/site-packages/synapse/handlers/federation_event.py", line 860, in _get_state_after_missing_prev_event
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:     ) = await self._federation_client.get_room_state_ids(
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:   File "/usr/lib/python3.10/site-packages/synapse/federation/federation_client.py", line 409, in get_room_state_ids
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:     result = await self.transport_layer.get_room_state_ids(
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:   File "/usr/lib/python3.10/site-packages/synapse/federation/transport/client.py", line 83, in get_room_state_ids
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:     return await self.client.get_json(
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:   File "/usr/lib/python3.10/site-packages/synapse/http/matrixfederationclient.py", line 1043, in get_json
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:     response = await self._send_request_with_optional_trailing_slash(
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:   File "/usr/lib/python3.10/site-packages/synapse/http/matrixfederationclient.py", line 382, in _send_request_with_optional_trailing_slash
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:     response = await self._send_request(request, **send_request_args)
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:   File "/usr/lib/python3.10/site-packages/synapse/http/matrixfederationclient.py", line 634, in _send_request
Apr 29 11:47:07 canode.darkcloud.ca synapse[904]:     raise exc
H-Shay commented 2 years ago

Right thanks for the logs. I am seeing lots of "No state group for unknown or outlier event" errors, which is related to some validation that was added recently. Can you run this query on your db and let me know the result? 

select * from event_forward_extremities efe left join events e using (event_id) where e.event_id is null;

Related: #12507, #12549

prurigro commented 2 years ago

Those issues do sound very similar! I ran that select query and nothing was returned on that note.

synapse=# select * from event_forward_extremities efe left join events e using (event_id) where e.event_id is null;
 event_id | room_id | topological_ordering | type | room_id | content | unrecognized_keys | processed | outlier | depth | origin_server_ts | received_ts | sender | contains_url | instance_name | stream_ordering | state_key | rejection_reason 
----------+---------+----------------------+------+---------+---------+-------------------+-----------+---------+-------+------------------+-------------+--------+--------------+---------------+-----------------+-----------+------------------
(0 rows)
H-Shay commented 2 years ago

I think this is essentially #12549. As is outlined in that issue, seeing many "No state group for unknown or outlier event" errors is the result of database corruption that may have happened long ago but is now being highlighted by some recently added validation logic. There are some suggestions on that issue on how to mitigate the situation, and in light of that I am going to close this issue in favor of #12549, but feel free to ask more questions on that issue if you can't resolve the problem.

prurigro commented 2 years ago

Hmm, I only migrated to postgresql two months ago, and it was good for the first month- it'd be weird to run into corruption so quickly wouldn't it? I'll take a look at the other issue though, thanks for pointing me there!

prurigro commented 2 years ago

@H-Shay Hmm, I don't think this is the issue since the check only appeared in 1.57.0? I was having this issue with 1.55.2 as well, though not as badly.

I'm testing a downgrade to 1.55.2 to see what happens- maybe I've hit one smaller separate issue as well as the one in #12549

prurigro commented 2 years ago

still getting disconnects with 1.55.2, but so far they're shorter and less frequent

DMRobertson commented 2 years ago

I think this is essentially #12549. As is outlined in that issue, seeing many "No state group for unknown or outlier event" errors is the result of database corruption that may have happened long ago but is now being highlighted by some recently added validation logic.

What's your thinking here Shay? I think(?) we'd expect borked data to result in an error response rather than a dropped connection. (Edit: there probably is DB corruption, but I'm not sure it explains the reported symptoms)

H-Shay commented 2 years ago

After re-examining the log in question, I discovered that I was looking at the wrong set of logs when I found the "No state group for unknown or outlier event" errors-so epic fail on my part there and I apologize! I've re-opened the issue in light of this. So what I know for sure thus far: the homeserver in question is occasionally taking a long time to process /sync requests-it appears that the long-processing requests usually take a little over 30s to process, but sometimes up to ~95-120 seconds. The client connection times out during these long-processing requests and drops. So the question really seems to be: why are /sync requests sometimes taking so long to process? This is totally grasping at straws but I did notice that a not-insignificant number of the overly-long /syncs contained a presence update. It is known that presence causes poor performance, it might be worth disabling presence for a day see if that solves the problem?

prurigro commented 2 years ago

Thanks for re-opening this!

I'll try disabling presence and see if that improves the situation. Would you recommend upgrading back to 1.57, or should I continue to ride 1.55 initially?

H-Shay commented 2 years ago

Good question-I think sticking with 1.57, since that is what the issue was opened with and what your provided logs for makes the most sense.

prurigro commented 2 years ago

It seems like the outages are slightly less frequent, though I've noticed that sending messages sometimes takes up to 30 seconds now so maybe it's just the client isn't noticing them as quickly?

EDIT: When I send a message and it's taking 30+ seconds I'll get the "connectivity to the server has been lost" message and then a loading spinner before the send goes through

prurigro commented 2 years ago

So it seems like synapse works well for an hour or two after restarting before sending messages starts to lag like crazy, and then a bit after that the drops start happening again too- reducing the load made the curve a bit more gradual and easier to chart, and it seems to imply that there's something going on in synapse that's making it less and less efficient?

In case it helps, a bit more background: A couple months ago I'd migrated from sqlite to postgres and things were suddenly lightning fast; previously messages would take 2-3 seconds to send, which makes sense considering it was interacting with a single file, but now everything was immediate and snappy. Things remained lightning fast for a month and a week or so until a week before I created this issue, and a few days after I'd upgraded synapse to 1.55. Since creating this issue I've done the recommended database maintenance (rebuilding the index, compress state, etc) and while it dropped the size down like crazy, things have slowly gotten worse.

Also in case it matters, I don't have an expiry set for old content (so I believe there are about 3 years of content in the database).

Would it be worth collecting more logs since switching presence off?

H-Shay commented 2 years ago

Hmm so two things might be helpful here: collecting another set of logs, this time with the logging level set to debug; and as was mentioned before, if it all possible it would be very helpful to add monitoring to your Synapse instance: https://matrix-org.github.io/synapse/latest/metrics-howto.html.

prurigro commented 2 years ago

Hey, I migrated to a new server with better specs on the chance that slow I/O or something was to blame and while I haven't set prometheus up yet (that's next on my list!), it does have some basic monitoring included. I'm still getting timeouts, but I can see now that they're associated with higher CPU usage, they're also a bit less frequent and the duration is shorter.

image

There were timeouts happening all through the higher CPU usage there, and they stopped (for the moment) once CPU usage dropped. I noticed that both synapse and postgres are using more CPU in these situations.

Once I get prometheus up I'll collect some logs along side so you have a complete picture.

prurigro commented 2 years ago

So I'm running a puppet bridge on the same server, and this is what the log shows when the connection drops:

May 06 15:30:26 tornode.darkcloud.ca python[20145]: [2022-05-06 15:30:26,543] [WARNING@mau.puppet.90404380] Syncer for @REDACTED:matrix.darkcloud.ca errored: 502: <html>
May 06 15:30:26 tornode.darkcloud.ca python[20145]: <head><title>502 Bad Gateway</title></head>
May 06 15:30:26 tornode.darkcloud.ca python[20145]: <body>
May 06 15:30:26 tornode.darkcloud.ca python[20145]: <center><h1>502 Bad Gateway</h1></center>
May 06 15:30:26 tornode.darkcloud.ca python[20145]: <hr><center>nginx/1.20.2</center>
May 06 15:30:26 tornode.darkcloud.ca python[20145]: </body>
May 06 15:30:26 tornode.darkcloud.ca python[20145]: </html>
May 06 15:30:26 tornode.darkcloud.ca python[20145]: . Waiting for 16 seconds...
prurigro commented 2 years ago

So I have debug level logging enabled and prometheus + grafana (with synapse.json) running- I'll be working tomorrow and can keep element running on a screen on the side to see what the connectivity is like. When things go bad should I be watching for something in grafana, or is there a particular thing that would be useful to export?

prurigro commented 2 years ago

Interesting, I refreshed grafana during an outage and got a broken pipe error in synapse:

2022-05-09 11:22:53,086 - synapse.state - 459 - INFO - _process_incoming_pdus_in_room_inner-3714-$L1Eh0pkgcHWuKQLY808y6PvVlNhlg37wuuLhiMFEbYc-$6ZFCzrxblgs8ua9JMtT2V95DcK3XLuYbKX7QoZs6x-Q - Resolving state for !yUHxXrvmurdnsPyhiH:sakura.ci with 66 groups
2022-05-09 11:22:59,843 - twisted - 286 - ERROR - sentinel - ----------------------------------------
2022-05-09 11:22:59,825 - twisted - 286 - ERROR - sentinel - ----------------------------------------
2022-05-09 11:22:59,989 - twisted - 286 - ERROR - sentinel - Exception occurred during processing of request from ('127.0.0.1', 58872)
2022-05-09 11:23:00,003 - twisted - 286 - ERROR - sentinel - Exception occurred during processing of request from ('127.0.0.1', 58870)
2022-05-09 11:23:00,111 - twisted - 286 - ERROR - sentinel - Traceback (most recent call last):
2022-05-09 11:23:00,122 - twisted - 286 - ERROR - sentinel - Traceback (most recent call last):
2022-05-09 11:23:00,130 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/socketserver.py", line 683, in process_request_thread
2022-05-09 11:23:00,136 - twisted - 286 - ERROR - sentinel -     self.finish_request(request, client_address)
2022-05-09 11:23:00,143 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/socketserver.py", line 360, in finish_request
2022-05-09 11:23:00,144 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/socketserver.py", line 683, in process_request_thread
2022-05-09 11:23:00,151 - twisted - 286 - ERROR - sentinel -     self.finish_request(request, client_address)
2022-05-09 11:23:00,151 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/socketserver.py", line 360, in finish_request
2022-05-09 11:23:00,150 - twisted - 286 - ERROR - sentinel -     self.RequestHandlerClass(request, client_address, self)
2022-05-09 11:23:00,158 - twisted - 286 - ERROR - sentinel -     self.RequestHandlerClass(request, client_address, self)
2022-05-09 11:23:00,178 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/socketserver.py", line 747, in __init__
2022-05-09 11:23:00,187 - twisted - 286 - ERROR - sentinel -     self.handle()
2022-05-09 11:23:00,195 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/http/server.py", line 425, in handle
2022-05-09 11:23:00,196 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/socketserver.py", line 747, in __init__
2022-05-09 11:23:00,215 - twisted - 286 - ERROR - sentinel -     self.handle_one_request()
2022-05-09 11:23:00,226 - twisted - 286 - ERROR - sentinel -     self.handle()
2022-05-09 11:23:00,228 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/http/server.py", line 425, in handle
2022-05-09 11:23:00,229 - twisted - 286 - ERROR - sentinel -     self.handle_one_request()
2022-05-09 11:23:00,229 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/http/server.py", line 413, in handle_one_request
2022-05-09 11:23:00,245 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/http/server.py", line 413, in handle_one_request
2022-05-09 11:23:00,264 - twisted - 286 - ERROR - sentinel -     method()
2022-05-09 11:23:00,271 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/site-packages/synapse/metrics/_exposition.py", line 206, in do_GET
2022-05-09 11:23:00,278 - twisted - 286 - ERROR - sentinel -     self.wfile.write(output)
2022-05-09 11:23:00,286 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/socketserver.py", line 826, in write
2022-05-09 11:23:00,294 - twisted - 286 - ERROR - sentinel -     method()
2022-05-09 11:23:00,295 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/site-packages/synapse/metrics/_exposition.py", line 206, in do_GET
2022-05-09 11:23:00,295 - twisted - 286 - ERROR - sentinel -     self.wfile.write(output)
2022-05-09 11:23:00,296 - twisted - 286 - ERROR - sentinel -   File "/usr/lib/python3.10/socketserver.py", line 826, in write
2022-05-09 11:23:00,296 - twisted - 286 - ERROR - sentinel -     self._sock.sendall(b)
2022-05-09 11:23:00,296 - twisted - 286 - ERROR - sentinel - BrokenPipeError: [Errno 32] Broken pipe
2022-05-09 11:23:00,297 - twisted - 286 - ERROR - sentinel -     self._sock.sendall(b)
2022-05-09 11:23:00,303 - twisted - 286 - ERROR - sentinel - ----------------------------------------
2022-05-09 11:23:00,303 - twisted - 286 - ERROR - sentinel - BrokenPipeError: [Errno 32] Broken pipe
2022-05-09 11:23:00,338 - twisted - 286 - ERROR - sentinel - ----------------------------------------
prurigro commented 2 years ago

Got this in the logs during an outage:

2022-05-09 11:55:52,150 - synapse.util.async_helpers - 466 - DEBUG - persist_events-38 - Releasing linearizer lock 'state_resolve_lock' for key frozenset({248832, 252674, 247172, 246661, 252809, 247818, 252303, 252176, 246678, 252823, 254102, 251930, 251802, 248860, 252826, 246942, 252830, 248830, 250023, 246697, 252204, 250030, 252207, 250031, 252080, 248500, 250043, 250048, 248131, 248902, 252742, 252102, 250057, 246727, 252104, 252108, 248398, 248144, 252114, 252798, 247381, 248917, 248150, 248152, 252121, 252119, 246619, 252123, 248029, 249438, 248153, 252125, 250081, 254051, 252778, 246894, 252142, 248944, 252785, 246641, 253811, 249718, 252662, 253434, 252668, 252670})
prurigro commented 2 years ago

This is just following an outage (and it's currently in and out)

stats

prurigro commented 2 years ago

Here's the log with debugging output of the latest outage -- seems like the log goes from outputting messages every so many milliseconds to nothing for over a minute:

2022-05-09 13:42:05,760 - synapse.event_auth - 229 - DEBUG - persist_events-100 - Allowing! <FrozenEventV3 event_id=$R4ey2ff7eWaWjYQ72bUBaoNmIu6f29nUiMmSavZGtRw, type=m.room.member, state_key=@REDACTED:REDACTED.TLD, outlier=False>
2022-05-09 13:42:05,761 - synapse.state.v2 - 183 - DEBUG - persist_events-100 - resolved
2022-05-09 13:42:05,763 - synapse.state.v2 - 188 - DEBUG - persist_events-100 - done
2022-05-09 13:42:07,922 - synapse.util.metrics - 165 - DEBUG - persist_events-100 - Exiting block state._resolve_events
2022-05-09 13:42:07,941 - synapse.util.metrics - 152 - DEBUG - persist_events-100 - Entering block state.create_group_ids
2022-05-09 13:42:12,251 - synapse.storage.txn - 717 - DEBUG - _process_incoming_pdus_in_room_inner-140-$i7d2oaSFgSVTS4htLl_eLWhLcPiK3GR7nUBx1wYNSdI - [TXN END] {get_auth_chain_difference_chains-727d} 9.518113 sec
2022-05-09 13:43:18,412 - synapse.util.metrics - 165 - DEBUG - persist_events-100 - Exiting block state.create_group_ids
2022-05-09 13:43:19,081 - synapse.util.async_helpers - 466 - DEBUG - persist_events-100 - Releasing linearizer lock 'state_resolve_lock' for key frozenset({248832, 252674, 247172, 246661, 252809, 247818, 252303, 252176, 246678, 252823, 251930, 251802, 254108, 248860, 246942, 252830, 252826, 254113, 248830, 250023, 246697, 252204, 250030, 252207, 250031, 254126, 252080, 248500, 250043, 250048, 248131, 248902, 252742, 252102, 250057, 246727, 252104, 252108, 248398, 248144, 252114, 252798, 247381, 248917, 248150, 248152, 252121, 252119, 246619, 252123, 248029, 249438, 248153, 252125, 250081, 254051, 252778, 246894, 252142, 248944, 252785, 246641, 253811, 249718, 252662, 253434, 252668, 252670})
squahtx commented 2 years ago

That's curious. It's interesting to see that there's a gap in the dashboard data during the outage as well? I'm not sure what to make of it yet.

prurigro commented 2 years ago

Here's the updated dashboard-- it's been dropping in and out. Is there a way to see a play-by-play in the dashboard data? The graph seems like it might just fill in the blanks?

Screenshot 2022-05-09 at 13-50-03 Synapse - Grafana

prurigro commented 2 years ago

Completely random thought, but I've been noticing that restarting synapse only helps a bit while restarting the server helps a lot, and it occurred to me that I've allocated swap space that appears to be getting used... That wouldn't impact performance enough to cause this type of drop would it?

Right after setting the new server up there were a bunch of outages without swap allocated, but then it was also catching up with the sync, and I allocated it right after that... Maybe I'll try without and see how it goes.

squahtx commented 2 years ago

The dashboard dropping in and out is very suspicious...

Completely random thought, but I've been noticing that restarting synapse only helps a bit while restarting the server helps a lot, and it occurred to me that I've allocated swap space that appears to be getting used... That wouldn't impact performance enough to cause this type of drop would it?

Running out of memory might explain a lot. Could you provide the first couple of lines of output from top? In particular, the Mem and Swap lines.

prurigro commented 2 years ago

Disabling swap didn't help- usually RAM is like 80% and swap is ~500 megs used - I've re-enabled swap and will report back once things start slowing down again.

prurigro commented 2 years ago

So after 8 hours and a number of outages, it seems like I have:

Also, sorry, I didn't mean the dashboard itself was dropping in and out, rather, the screenshot of the dashboard is showing what synapse looked like while dropping in and out.

prurigro commented 2 years ago

Caught some more debugging output during a shorter outage-- once again it seems like the log stops outputting for multiple seconds when it normally outputs every few milliseconds.

2022-05-11 15:41:05,518 - synapse.handlers.device - 987 - WARNING - _maybe_retry_device_resync-439 - Failed to handle device list update for REDACTED:REDACTED.REDACTED.REDACTED 400: Bad Request
2022-05-11 15:41:05,518 - synapse.handlers.device - 973 - DEBUG - _maybe_retry_device_resync-439 - Attempting to resync the device list for REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:05,519 - synapse.handlers.device - 973 - DEBUG - _maybe_retry_device_resync-439 - Attempting to resync the device list for REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:05,519 - synapse.handlers.device - 973 - DEBUG - _maybe_retry_device_resync-439 - Attempting to resync the device list for REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:05,519 - synapse.handlers.device - 973 - DEBUG - _maybe_retry_device_resync-439 - Attempting to resync the device list for REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:05,520 - synapse.handlers.device - 973 - DEBUG - _maybe_retry_device_resync-439 - Attempting to resync the device list for REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:05,520 - synapse.handlers.device - 973 - DEBUG - _maybe_retry_device_resync-439 - Attempting to resync the device list for REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:05,521 - synapse.handlers.device - 973 - DEBUG - _maybe_retry_device_resync-439 - Attempting to resync the device list for REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:05,522 - synapse.handlers.device - 973 - DEBUG - _maybe_retry_device_resync-439 - Attempting to resync the device list for REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:05,523 - synapse.handlers.device - 973 - DEBUG - _maybe_retry_device_resync-439 - Attempting to resync the device list for REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:05,523 - synapse.handlers.device - 973 - DEBUG - _maybe_retry_device_resync-439 - Attempting to resync the device list for REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:05,524 - synapse.handlers.device - 973 - DEBUG - _maybe_retry_device_resync-439 - Attempting to resync the device list for REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:06,235 - synapse.handlers.typing - 98 - DEBUG - typing._handle_timeouts-2313 - Checking for typing timeouts
2022-05-11 15:41:06,414 - synapse.storage.TIME - 532 - DEBUG - sentinel - Total database time: 35.667% {get_rooms_with_many_extremities(1): 3.477%, set_received_txn_response(10): 3.282%, get_received_txn_response(10): 3.150%}
2022-05-11 15:41:06,439 - synapse.metrics._gc - 118 - DEBUG - sentinel - Collecting gc 0
2022-05-11 15:41:07,446 - synapse.metrics._gc - 118 - DEBUG - sentinel - Collecting gc 0
2022-05-11 15:41:10,171 - synapse.storage.txn - 614 - DEBUG - prune_old_user_ips-2298 - [TXN START] {_prune_old_user_ips-12895}
2022-05-11 15:41:10,195 - synapse.storage.txn - 717 - DEBUG - prune_old_user_ips-2298 - [TXN END] {_prune_old_user_ips-12895} 0.023386 sec
2022-05-11 15:41:10,204 - synapse.http.site - 510 - WARNING - sentinel - forwarded request lacks an x-forwarded-proto header: assuming https
2022-05-11 15:41:10,205 - synapse.access.http.8008 - 382 - DEBUG - GET-12729 - 108.162.140.176 - 8008 - Received request: GET /_matrix/client/r0/sync?filter=0&set_presence=online&timeout=30000&since=s2938320_29901531_976_2488788_629888_134_279627_1717312_2
2022-05-11 15:41:10,206 - synapse.rest.client.sync - 130 - DEBUG - GET-12729 - /sync: user=REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:10,212 - synapse.util.metrics - 152 - DEBUG - GET-12729 - Entering block presence_update_states
2022-05-11 15:41:10,213 - synapse.util.metrics - 165 - DEBUG - GET-12729 - Exiting block presence_update_states
2022-05-11 15:41:10,215 - synapse.util.caches.response_cache - 230 - DEBUG - GET-12729 - [sync]: no cached result for [(REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:10,215 - synapse.handlers.sync - 348 - DEBUG - GET-12729 - Deleted 0 to-device messages up to 279627
2022-05-11 15:41:10,216 - synapse.handlers.sync - 1081 - DEBUG - GET-12729 - Calculating sync response for REDACTED:REDACTED.REDACTED.REDACTED
2022-05-11 15:41:10,218 - synapse.handlers.sync - 1106 - DEBUG - GET-12729 - Fetching account data
2022-05-11 15:41:10,220 - synapse.handlers.sync - 1112 - DEBUG - GET-12729 - Fetching room data
2022-05-11 15:41:10,220 - synapse.util.metrics - 152 - DEBUG - GET-12729 - Entering block ephemeral_by_room
2022-05-11 15:41:10,221 - synapse.util.metrics - 152 - DEBUG - GET-12729 - Entering block typing.get_new_events
2022-05-11 15:41:10,221 - synapse.util.metrics - 165 - DEBUG - GET-12729 - Exiting block typing.get_new_events
2022-05-11 15:41:10,223 - synapse.util.metrics - 165 - DEBUG - GET-12729 - Exiting block ephemeral_by_room
2022-05-11 15:41:10,225 - synapse.handlers.sync - 1584 - DEBUG - GET-12729 - no-oping sync
2022-05-11 15:41:10,225 - synapse.handlers.sync - 1131 - DEBUG - GET-12729 - Fetching to-device data
2022-05-11 15:41:10,225 - synapse.util.metrics - 152 - DEBUG - GET-12729 - Entering block _generate_sync_entry_for_device_list
2022-05-11 15:41:10,226 - synapse.util.metrics - 165 - DEBUG - GET-12729 - Exiting block _generate_sync_entry_for_device_list
2022-05-11 15:41:10,226 - synapse.handlers.sync - 1142 - DEBUG - GET-12729 - Fetching OTK data
2022-05-11 15:41:10,228 - synapse.handlers.sync - 1159 - DEBUG - GET-12729 - Fetching group data
2022-05-11 15:41:10,228 - synapse.util.metrics - 152 - DEBUG - GET-12729 - Entering block _generate_sync_entry_for_groups
2022-05-11 15:41:10,229 - synapse.storage.txn - 614 - DEBUG - GET-12729 - [TXN START] {get_groups_changes_for_user-12896}
2022-05-11 15:41:10,233 - synapse.storage.txn - 717 - DEBUG - GET-12729 - [TXN END] {get_groups_changes_for_user-12896} 0.003428 sec
2022-05-11 15:41:10,234 - synapse.util.metrics - 165 - DEBUG - GET-12729 - Exiting block _generate_sync_entry_for_groups
2022-05-11 15:41:10,235 - synapse.handlers.sync - 1175 - DEBUG - GET-12729 - Sync response calculation complete
2022-05-11 15:41:10,236 - synapse.storage.txn - 614 - DEBUG - Lock._renew-638 - [TXN START] {renew_lock-12897}
2022-05-11 15:41:10,239 - synapse.storage.txn - 717 - DEBUG - Lock._renew-638 - [TXN END] {renew_lock-12897} 0.003428 sec
2022-05-11 15:41:11,243 - synapse.handlers.typing - 98 - DEBUG - typing._handle_timeouts-2314 - Checking for typing timeouts

I've also increased the available swap space to 6 gigs (meaning there's a total of 8 gigs available to synapse) -- currently there's 4.7 gigs free

prurigro commented 2 years ago

Considering there seems to be available CPU and postgres doesn't seem to be getting stressed, would it make sense to add a worker to take a load off the main process?

EDIT: I'm now running two workers- one for client requests and one for federation requests. I'll report back on how it goes!

prurigro commented 2 years ago

Hmm, something seems to have caused the client worker to crash:

May 12 02:14:28 tornode.darkcloud.ca synapse[486]: synapse.http.server: [POST-726] Failed handle request via 'ReadMarkerRestServlet': <SynapseRequest at 0x7fc286c07ac0 method='POST' uri='/_matrix/client/r0/rooms/!dmZfaUmSFKHDUskykN%3Amatrix.darkcloud.ca/read_markers' clien>
                                                   Traceback (most recent call last):
                                                     File "/usr/lib/python3.10/site-packages/synapse/http/server.py", line 268, in _async_render_wrapper
                                                       callback_return = await self._async_render(request)
                                                     File "/usr/lib/python3.10/site-packages/synapse/http/server.py", line 470, in _async_render
                                                       callback_return = await raw_callback_return
                                                     File "/usr/lib/python3.10/site-packages/synapse/rest/client/read_marker.py", line 63, in on_POST
                                                       await self.receipts_handler.received_client_receipt(

EDIT: Trying workers again today- no crash so far, but definitely still getting drops and lag

EDIT 2: Hit the same crash again

prurigro commented 2 years ago

So here's a question... If I blow away the database and assets and start fresh, am I going to have any issues with federation moving forward? Considering other servers would think people from mine were already connected to their channels and whatnot.

If I'm the only one having these issues, the only common threads between the previous server and the new one is the database and the config.

prurigro commented 2 years ago

Hey, so I have an update- one of the people on my server wanted to make some backups before I reset the database but needed the server a bit more stable first, so I was going to whitelist his IP and block everyone else. I initially started with just the federation block to test though, and without federation enabled everything is running perfectly. No delays and no outages for the last 12 hours.

prurigro commented 2 years ago

@H-Shay Hey, figured I'd give you a mention since this should narrow down the surface of the bug pretty considerably ^^ -- Federation is still enabled, I've just blocked outgoing/incoming in the reverse proxy and I've had zero issues. I'm not sure if there's a bug in the federation logic, or possible a malicious/buggy server? It's possible my server isn't beefy enough to handle a bunch of federation stuff, too, but the resources are far from strained on the actual server.

I'm planning on wiping and replacing synapse with dendrite in a few days, so if you think my logs might be helpful in solving this (now that we see other people running into a similar situation?) I can help in the mean time. I have full monitoring setup at this point, so anything you need should be possible to get.

lnicola commented 2 years ago

@prurigro if you haven't seen it, I think I have the same issue in https://github.com/matrix-org/synapse/issues/12730.

prurigro commented 2 years ago

@lnicola yeah, that seems almost identical- does disabling federation resolve the issue for you? (not that disabling federation is a resolution)

prurigro commented 2 years ago

One more thing that changed when federation got disabled is the database doesn't seem to be growing by nearly a gig every day. I almost wonder if a bot account didn't connect to a malicious federated server and just dump tons of data in? Though there was typically very little actual traffic happening.

prurigro commented 2 years ago

So just to follow up- I reset with dendrite, noticed my subdomain had actually been banned on at least one server (likely due to malicious activity) and tons of federation activity was incoming from dozens of domains that didn't have valid certs, so I switched to my top level domain. Dendrite had too many little bugs so I switched back to synapse, and on the new domain with the same synapse config and a reset database (with no more of what I assume were malicious bot accounts), everything has been working swimmingly.

Based on everything I've seen and the conversation @ https://github.com/matrix-org/synapse/issues/12730 I think we can conclude that this "bug" is actually the result of malicious bots and can be solved by not having open registration (which is a bit unfortunate). I'm going to close my issue since I've reached a resolution, but if the synapse devs think it's worth treating the ability for malicious accounts to take out a server (or at least the inability to easily resolve that when it happens) a missing feature, it might be worth using https://github.com/matrix-org/synapse/issues/12730 to come up with a solution.

Either way, thanks to everyone who offered help here, and for all the hard works the devs on this project have put into making such a great tool