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

Initial and incremental syncs with presence enabled eat up RAM until an OOM hits #13901

Open
fsa opened this issue Sep 26, 2022 · 21 comments
Open
Labels
A-Memory-Usage A-Presence O-Uncommon Most users are unlikely to come across this or unexpected workflow S-Major Major functionality / product severely impaired, no satisfactory workaround. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.

Comments

@fsa
Copy link

fsa commented Sep 26, 2022

Description

Synapse eat all ram (8GB) and swap until OOM hits.

Steps to reproduce

There are 3 accounts on the server. This happens when one of the users connects (my account is an administrator). Did not connect to other rooms with a large number of connections before the problem occurred.

Homeserver

tavda.org

Synapse Version

{"server_version":"1.67.0","python_version":"3.10.6"}

Installation Method

Debian packages from packages.matrix.org

Platform

Ubuntu 22.04 LTS

Relevant log output

Sep 26 14:27:29 nether2.network systemd[1]: matrix-synapse.service: A process of this unit has been killed by the OOM killer.
Sep 26 14:27:30 nether2.network systemd[1]: matrix-synapse.service: Main process exited, code=killed, status=9/KILL
Sep 26 14:27:30 nether2.network systemd[1]: matrix-synapse.service: Failed with result 'oom-kill'.
Sep 26 14:27:30 nether2.network systemd[1]: matrix-synapse.service: Consumed 29.476s CPU time.
Sep 26 14:27:33 nether2.network systemd[1]: matrix-synapse.service: Scheduled restart job, restart counter is at 15.
Sep 26 14:27:33 nether2.network systemd[1]: Stopped Synapse Matrix homeserver.
Sep 26 14:27:33 nether2.network systemd[1]: matrix-synapse.service: Consumed 29.476s CPU time.
Sep 26 14:27:33 nether2.network systemd[1]: Starting Synapse Matrix homeserver...
Sep 26 14:27:39 nether2.network synapse[8680]: root: [main] ***** STARTING SERVER *****
Sep 26 14:27:39 nether2.network synapse[8680]: root: [main] Server /opt/venvs/matrix-synapse/lib/python3.10/site-packages/synapse/app/homeserver.py version 1.67.0
Sep 26 14:27:39 nether2.network synapse[8680]: root: [main] Server hostname: tavda.org
Sep 26 14:27:39 nether2.network synapse[8680]: root: [main] Instance name: master
Sep 26 14:27:39 nether2.network synapse[8680]: synapse.app.homeserver: [main] Setting up server
Sep 26 14:27:39 nether2.network synapse[8680]: synapse.server: [main] Setting up.
Sep 26 14:27:39 nether2.network synapse[8680]: synapse.storage.databases: [main] [database config 'master']: Checking database server
Sep 26 14:27:39 nether2.network synapse[8680]: synapse.storage.databases: [main] [database config 'master']: Preparing for databases ['main', 'state']
Sep 26 14:27:39 nether2.network synapse[8680]: synapse.storage.prepare_database: [main] ['main', 'state']: Checking existing schema version
Sep 26 14:27:39 nether2.network synapse[8680]: synapse.storage.prepare_database: [main] ['main', 'state']: Existing schema is 72 (+8 deltas)
Sep 26 14:27:39 nether2.network synapse[8680]: synapse.storage.databases.main: [main] Checking database for consistency with configuration...
Sep 26 14:27:39 nether2.network synapse[8680]: synapse.storage.prepare_database: [main] Applying schema deltas for v72
Sep 26 14:27:39 nether2.network synapse[8680]: synapse.storage.prepare_database: [main] Schema now up to date
Sep 26 14:27:39 nether2.network synapse[8680]: synapse.storage.databases: [main] [database config 'master']: Starting 'main' database

Anything else that would be useful to know?

During normal server operation, the top shows 7.5GB of free memory. The other two users can communicate with each other.

@DMRobertson DMRobertson added S-Major Major functionality / product severely impaired, no satisfactory workaround. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues. O-Uncommon Most users are unlikely to come across this or unexpected workflow A-Memory-Usage X-Needs-Info This issue is blocked awaiting information from the reporter labels Sep 26, 2022
@DMRobertson
Copy link
Contributor

What is Synapse doing before it is killed? Can you share the last five minutes of logs prior to it getting OOMed?

To best advise you we'd need to see metrics to understand where Synapse is allocating RAM and what Synapse is doing. Are you able to setup Prometheus and Grafana? See https://matrix-org.github.io/synapse/latest/metrics-howto.html

@fsa
Copy link
Author

fsa commented Sep 26, 2022

Here is the log from when everything is fine and when the client connected.

Sep 26 22:40:32 nether2.network synapse[13189]: synapse.access.http.8008: [GET-402] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {None} Processed request: 0.000sec/0.001sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 606B 200 "GET /_matrix/client/versions HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 22:40:34 nether2.network synapse[13189]: synapse.access.http.8008: [GET-403] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {@fsa:tavda.org} Processed request: 0.008sec/0.000sec (0.005sec, 0.000sec) (0.001sec/0.004sec/2) 2B 200 "GET /_matrix/client/r0/thirdparty/protocols HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 22:40:34 nether2.network synapse[13189]: synapse.access.http.8008: [GET-404] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {@fsa:tavda.org} Processed request: 0.019sec/0.001sec (0.003sec, 0.001sec) (0.001sec/0.017sec/2) 673B 200 "GET /_matrix/client/unstable/room_keys/version HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 22:40:34 nether2.network synapse[13189]: synapse.access.http.8008: [GET-405] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {@fsa:tavda.org} Processed request: 0.002sec/0.002sec (0.000sec, 0.003sec) (0.000sec/0.000sec/0) 174B 200 "GET /_matrix/client/r0/voip/turnServer HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 22:40:34 nether2.network synapse[13189]: synapse.access.http.8008: [GET-406] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {None} Processed request: 0.000sec/0.002sec (0.001sec, 0.000sec) (0.000sec/0.000sec/0) 606B 200 "GET /_matrix/client/versions HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 22:40:34 nether2.network synapse[13189]: synapse.handlers.e2e_keys: [POST-407] Updating device_keys for device 'DWPBDDKNLO' for user @fsa:tavda.org at 1664206834427
Sep 26 22:40:34 nether2.network synapse[13189]: synapse.access.http.8008: [POST-407] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {@fsa:tavda.org} Processed request: 0.010sec/0.000sec (0.004sec, 0.000sec) (0.001sec/0.006sec/4) 48B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 22:40:34 nether2.network synapse[13189]: synapse.access.http.8008: [GET-408] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {@fsa:tavda.org} Processed request: 0.001sec/0.001sec (0.003sec, 0.000sec) (0.000sec/0.000sec/0) 3596B 200 "GET /_matrix/client/r0/pushrules/ HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 22:40:34 nether2.network synapse[13189]: synapse.access.http.8008: [GET-409] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {@fsa:tavda.org} Processed request: 0.004sec/0.000sec (0.004sec, 0.000sec) (0.000sec/0.001sec/1) 45B 200 "GET /_matrix/client/r0/user/%40fsa%3Atavda.org/filter/1 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 22:41:02 nether2.network systemd[1]: matrix-synapse.service: A process of this unit has been killed by the OOM killer.
Sep 26 22:41:03 nether2.network systemd[1]: matrix-synapse.service: Main process exited, code=killed, status=9/KILL
Sep 26 22:41:03 nether2.network systemd[1]: matrix-synapse.service: Failed with result 'oom-kill'.

@fsa
Copy link
Author

fsa commented Sep 26, 2022

@DMRobertson
Copy link
Contributor

DMRobertson commented Sep 26, 2022

Are you able to change the logging config to output DEBUG logs at the root level and include those? See
https://matrix-org.github.io/synapse/latest/usage/configuration/logging_sample_config.html?highlight=DEBUG for example.
(Beware: they may contain sensitive information---check carefully before pasting them publicly.)

@fsa
Copy link
Author

fsa commented Sep 26, 2022

Sep 26 23:32:57 nether2.network synapse[14610]: synapse.access.http.8008: [PUT-1] 67.58.53.218 - 8008 - Received request: PUT /_matrix/federation/v1/send/1661824
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.crypto.keyring: [keyring_server-1] Starting fetch for [_FetchKeyRequest(server_name='matrix.nrp-nautilus.io', minimum_valid_until_ts=1694, key_ids=['ed25519:a'])]
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.crypto.keyring: [keyring_server-1] Deduplicated key requests to [_FetchKeyRequest(server_name='matrix.nrp-nautilus.io', minimum_valid_until_ts=1664209977894, key_ids=['ed25519:a'])]
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.crypto.keyring: [keyring_server-1] Starting fetch for _FetchKeyRequest(server_name='matrix.nrp-nautilus.io', minimum_valid_until_ts=166494, key_ids=['ed25519:a'])
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.crypto.keyring: [keyring_server-1] Getting keys from <synapse.crypto.keyring.StoreKeyFetcher object at 0x7f93ab670> for _FetchKeyRequest(server_name='matrix.nrp-nautilus.io', minimum_valid_until_ts=166894, key_ids=['ed25519:a'])
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [StoreKeyFetcher-1] [TXN START] {get_server_verify_keys-1a}
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [StoreKeyFetcher-1] [SQL] {get_server_verify_keys-1a} SELECT server_name, key_id, verify_key, ts_valid_until_ms FROM server_signature_keys WHERE 1=0 OR (server_name=? AND key_id=?)
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [StoreKeyFetcher-1] [SQL values] {get_server_verify_keys-1a} ('matrix.nrp-nautilus.io', 'ed25519:a')
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [StoreKeyFetcher-1] [SQL time] {get_server_verify_keys-1a} 0.001413 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [StoreKeyFetcher-1] [TXN END] {get_server_verify_keys-1a} 0.003032 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.federation.transport.server._base: [PUT-1] Request from matrix.nrp-nautilus.io
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN START] {get_destination_retry_timings-1b}
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL] {get_destination_retry_timings-1b} SELECT failure_ts, retry_last_ts, retry_interval FROM destinations WHERE destination = ?
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL values] {get_destination_retry_timings-1b} ['matrix.nrp-nautilus.io']
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL time] {get_destination_retry_timings-1b} 0.000735 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN END] {get_destination_retry_timings-1b} 0.002212 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.federation.transport.server.federation: [PUT-1] Decoded 16624: {'edus': [{'content': {'push': [{'last_active_ago': 70232, 'presence': 'offline', 'user_id': '@dimm:matrix.nrp-nautilus.io'}]}, 'edu_type': 'm.presence'}], 'origin': 'matrix.nrp-nautilus.io', 'origin_server_ts': 1664209977474, 'pdus': []}
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.federation.transport.server.federation: [PUT-1] Received txn 1624 from matrix.nrp-nautilus.io. (PDUs: 0, EDUs: 1)
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.federation.federation_server: [PUT-1] [1624] Got transaction
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.util.caches.response_cache: [PUT-1] [fed_txn_handler]: no cached result for [('matrix.nrp-nautilus.io', '1624')], calculating new one
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN START] {get_received_txn_response-1c}
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL] {get_received_txn_response-1c} SELECT transaction_id, origin, ts, response_code, response_json, has_been_referenced FROM received_transactions WHERE transaction_id = ? AND origin = ?
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL values] {get_received_txn_response-1c} ['1624', 'matrix.nrp-nautilus.io']
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL time] {get_received_txn_response-1c} 0.000850 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN END] {get_received_txn_response-1c} 0.001459 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.federation.federation_server: [PUT-1] [1624] Transaction is new
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.util.metrics: [PUT-1] Entering block presence_update_states
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.metrics._gc: [sentinel] Collecting gc 0
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN START] {_load_next_mult_id-1d}
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL] {_load_next_mult_id-1d} SELECT nextval(?) FROM generate_series(1, ?)
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL values] {_load_next_mult_id-1d} ('presence_stream_sequence', 1)
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL time] {_load_next_mult_id-1d} 0.000586 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN END] {_load_next_mult_id-1d} 0.001142 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN START] {update_presence-1e}
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL] {update_presence-1e} DELETE FROM presence_stream WHERE stream_id < ? AND user_id = ANY(?)
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL values] {update_presence-1e} [1154261, ['@dimm:matrix.nrp-nautilus.io']]
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL time] {update_presence-1e} 0.001648 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL] {update_presence-1e} INSERT INTO presence_stream (stream_id, user_id, state, last_active_ts, last_federation_update_ts, last_user_sync_ts, status_msg, currently_active, instance_name) VALUES ?
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL time] {update_presence-1e} 0.000388 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN END] {update_presence-1e} 0.006243 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN START] {MultiWriterIdGenerator._update_table-1f}
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL] {MultiWriterIdGenerator._update_table-1f} INSERT INTO stream_positions (stream_name, instance_name, stream_id) VALUES (?, ?, ?) ON CONFLICT (stream_name, instance_name) DO UPDATE SET stream_id = GREATEST(stream_positions.stream_id, EXCLUDED.stream_id)
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL values] {MultiWriterIdGenerator._update_table-1f} ('presence_stream', 'master', (1154261,))
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL time] {MultiWriterIdGenerator._update_table-1f} 0.002091 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN END] {MultiWriterIdGenerator._update_table-1f} 0.003373 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN START] {get_rooms_for_user_with_stream_ordering-20}
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL] {get_rooms_for_user_with_stream_ordering-20} SELECT room_id, e.instance_name, e.stream_ordering FROM current_state_events AS c INNER JOIN events AS e USING (room_id, event_id) WHERE c.type = 'm.room.member' AND c.state_key = ? AND c.membership = ?
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL values] {get_rooms_for_user_with_stream_ordering-20} ('@dimm:matrix.nrp-nautilus.io', 'join')
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL time] {get_rooms_for_user_with_stream_ordering-20} 0.002135 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN END] {get_rooms_for_user_with_stream_ordering-20} 0.005408 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.util.metrics: [PUT-1] Entering block on_new_event
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.util.metrics: [user_directory.notify_new_event-4] Entering block user_dir_delta
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.util.metrics: [user_directory.notify_new_event-4] Exiting block user_dir_delta
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.util.metrics: [presence.notify_new_event-3] Entering block presence_delta
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.util.metrics: [presence.notify_new_event-3] Exiting block presence_delta
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.util.metrics: [PUT-1] Exiting block on_new_event
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.util.metrics: [PUT-1] Exiting block presence_update_states
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.federation.federation_server: [PUT-1] Returning: {'pdus': {}}
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN START] {set_received_txn_response-21}
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL] {set_received_txn_response-21} INSERT INTO received_transactions (transaction_id, origin, response_code, response_json, ts) VALUES (?, ?, ?, ?, ?) ON CONFLICT (transaction_id, origin) DO NOTHING
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL values] {set_received_txn_response-21} ['1624', 'matrix.nrp-nautilus.io', 200, <memory at 0x7f580>, 16636]
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-1] [SQL time] {set_received_txn_response-21} 0.007338 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.storage.txn: [PUT-1] [TXN END] {set_received_txn_response-21} 0.008709 sec
Sep 26 23:32:57 nether2.network synapse[14610]: synapse.access.http.8008: [PUT-1] 67.58.53.218 - 8008 - {matrix.nrp-nautilus.io} Processed request: 0.055sec/0.001sec (0.014sec, 0.001sec) (0.003sec/0.029sec/7) 11B 200 "PUT /_matrix/federation/v1/send/16624 HTTP/1.0" "Synapse/1.65.0" [0 dbevts]
Sep 26 23:32:58 nether2.network synapse[14610]: synapse.storage.txn: [prune_old_user_ips-2] [TXN START] {_prune_old_user_ips-22}
Sep 26 23:32:58 nether2.network synapse[14610]: synapse.storage.SQL: [prune_old_user_ips-2] [SQL] {_prune_old_user_ips-22} DELETE FROM user_ips WHERE last_seen <= ( SELECT COALESCE(MAX(last_seen), -1) FROM ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) AS u )
Sep 26 23:32:58 nether2.network synapse[14610]: synapse.storage.SQL: [prune_old_user_ips-2] [SQL values] {_prune_old_user_ips-22} (1661790778758,)
Sep 26 23:32:58 nether2.network synapse[14610]: synapse.storage.SQL: [prune_old_user_ips-2] [SQL time] {_prune_old_user_ips-22} 0.001308 sec
Sep 26 23:32:58 nether2.network synapse[14610]: synapse.storage.txn: [prune_old_user_ips-2] [TXN END] {_prune_old_user_ips-22} 0.003813 sec
Sep 26 23:32:59 nether2.network synapse[14610]: synapse.storage.txn: [wake_destinations_needing_catchup-0] [TXN START] {get_catch_up_outstanding_destinations-23}
Sep 26 23:32:59 nether2.network synapse[14610]: synapse.storage.SQL: [wake_destinations_needing_catchup-0] [SQL] {get_catch_up_outstanding_destinations-23} SELECT DISTINCT destination FROM destinations INNER JOIN destination_rooms USING (destination) WHERE stream_ordering > last_successful_stream_ordering AND destination > ? AND ( retry_last_ts IS NULL OR retry_last_ts + retry_interval < ? ) ORDER BY destination LIMIT 25
Sep 26 23:32:59 nether2.network synapse[14610]: synapse.storage.SQL: [wake_destinations_needing_catchup-0] [SQL values] {get_catch_up_outstanding_destinations-23} ('', 1664209978999)
Sep 26 23:32:59 nether2.network synapse[14610]: synapse.storage.SQL: [wake_destinations_needing_catchup-0] [SQL time] {get_catch_up_outstanding_destinations-23} 0.001749 sec
Sep 26 23:32:59 nether2.network synapse[14610]: synapse.storage.txn: [wake_destinations_needing_catchup-0] [TXN END] {get_catch_up_outstanding_destinations-23} 0.004027 sec
Sep 26 23:32:59 nether2.network synapse[14610]: synapse.handlers.typing: [typing._handle_timeouts-2] Checking for typing timeouts
Sep 26 23:33:03 nether2.network synapse[14610]: synapse.storage.txn: [prune_old_user_ips-3] [TXN START] {_prune_old_user_ips-24}
Sep 26 23:33:03 nether2.network synapse[14610]: synapse.storage.SQL: [prune_old_user_ips-3] [SQL] {_prune_old_user_ips-24} DELETE FROM user_ips WHERE last_seen <= ( SELECT COALESCE(MAX(last_seen), -1) FROM ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) AS u )
Sep 26 23:33:03 nether2.network synapse[14610]: synapse.storage.SQL: [prune_old_user_ips-3] [SQL values] {_prune_old_user_ips-24} (1658,)
Sep 26 23:33:03 nether2.network synapse[14610]: synapse.storage.SQL: [prune_old_user_ips-3] [SQL time] {_prune_old_user_ips-24} 0.001440 sec
Sep 26 23:33:03 nether2.network synapse[14610]: synapse.storage.txn: [prune_old_user_ips-3] [TXN END] {_prune_old_user_ips-24} 0.003828 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.handlers.typing: [typing._handle_timeouts-3] Checking for typing timeouts
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.TIME: [sentinel] Total database time: 0.432% {set_received_txn_response(1): 0.087%, _prune_old_user_ips(2): 0.076%, update_presence(1): 0.062%}
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.access.http.8008: [PUT-2] 188.19.200.51 - 8008 - Received request: PUT /_matrix/federation/v1/send/1646
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.crypto.keyring: [keyring_server-2] Starting fetch for [_FetchKeyRequest(server_name='oma.su', minimum_valid_until_ts=162, key_ids=['ed25519:a'])]
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.crypto.keyring: [keyring_server-2] Deduplicated key requests to [_FetchKeyRequest(server_name='oma.su', minimum_valid_until_ts=162, key_ids=['ed25519:a'])]
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.crypto.keyring: [keyring_server-2] Starting fetch for _FetchKeyRequest(server_name='oma.su', minimum_valid_until_ts=162, key_ids=['ed25519:a'])
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.crypto.keyring: [keyring_server-2] Getting keys from <synapse.crypto.keyring.StoreKeyFetcher object at 0x7f9670> for _FetchKeyRequest(server_name='oma.su', minimum_valid_until_ts=1672, key_ids=['ed25519:a'])
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [StoreKeyFetcher-2] [TXN START] {get_server_verify_keys-25}
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [StoreKeyFetcher-2] [SQL] {get_server_verify_keys-25} SELECT server_name, key_id, verify_key, ts_valid_until_ms FROM server_signature_keys WHERE 1=0 OR (server_name=? AND key_id=?)
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [StoreKeyFetcher-2] [SQL values] {get_server_verify_keys-25} ('oma.su', 'ed25519:a')
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [StoreKeyFetcher-2] [SQL time] {get_server_verify_keys-25} 0.000926 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [StoreKeyFetcher-2] [TXN END] {get_server_verify_keys-25} 0.002160 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.federation.transport.server._base: [PUT-2] Request from oma.su
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN START] {get_destination_retry_timings-26}
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {get_destination_retry_timings-26} SELECT failure_ts, retry_last_ts, retry_interval FROM destinations WHERE destination = ?
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {get_destination_retry_timings-26} ['oma.su']
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {get_destination_retry_timings-26} 0.000532 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN END] {get_destination_retry_timings-26} 0.001684 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.federation.transport.server.federation: [PUT-2] Decoded 1663066557446: {'edus': [{'content': {'room_id': '!OICmmhekyXTAKxBVQz:matrix.org', 'typing': True, 'user_id': '@d:oma.su'}, 'edu_type': 'm.typing'}, {'content': {'!OICmmhekyXTAKxBVQz:matrix.org': {'m.read': {'@d:oma.su': {'data': {'ts': 167}, 'event_ids': ['$-cB9I2Dm9aF9WN_NLOh5wTt4uQJvrfYNfrwd3ud7GeQ']}}}}, 'edu_type': 'm.receipt'}], 'origin': 'oma.su', 'origin_server_ts': 1690, 'pdus': []}
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.federation.transport.server.federation: [PUT-2] Received txn 1663066557446 from oma.su. (PDUs: 0, EDUs: 2)
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.federation.federation_server: [PUT-2] [16646] Got transaction
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.util.caches.response_cache: [PUT-2] [fed_txn_handler]: no cached result for [('oma.su', '1646')], calculating new one
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN START] {get_received_txn_response-27}
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {get_received_txn_response-27} SELECT transaction_id, origin, ts, response_code, response_json, has_been_referenced FROM received_transactions WHERE transaction_id = ? AND origin = ?
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {get_received_txn_response-27} ['1646', 'oma.su']
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {get_received_txn_response-27} 0.000461 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN END] {get_received_txn_response-27} 0.001666 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.federation.federation_server: [PUT-2] [1646] Transaction is new
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.util.metrics: [PUT-2] Entering block check_host_in_room
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.util.metrics: [PUT-2] Entering block check_host_in_room
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN START] {is_host_joined-28}
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {is_host_joined-28} SELECT state_key FROM current_state_events AS c INNER JOIN room_memberships AS m USING (event_id) WHERE m.membership = ? AND type = 'm.room.member' AND c.room_id = ? AND state_key LIKE ? LIMIT 1
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {is_host_joined-28} ('join', '!OICmmhekyXTAKxBVQz:matrix.org', '%:tavda.org')
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {is_host_joined-28} 0.002721 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN END] {is_host_joined-28} 0.004058 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.util.metrics: [PUT-2] Exiting block check_host_in_room
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.util.metrics: [PUT-2] Exiting block check_host_in_room
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN START] {is_partial_state_room-29}
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {is_partial_state_room-29} SELECT room_id FROM partial_state_rooms WHERE room_id = ?
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {is_partial_state_room-29} ['!OICmmhekyXTAKxBVQz:matrix.org']
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN START] {_load_next_mult_id-2a}
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {_load_next_mult_id-2a} SELECT nextval(?) FROM generate_series(1, ?)
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {_load_next_mult_id-2a} ('receipts_sequence', 1)
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {_load_next_mult_id-2a} 0.000493 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN END] {_load_next_mult_id-2a} 0.001583 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {is_partial_state_room-29} 0.002569 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN END] {is_partial_state_room-29} 0.003671 sec
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN START] {insert_linearized_receipt-2b}
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {insert_linearized_receipt-2b} SELECT stream_ordering, received_ts FROM events WHERE event_id = ?
Sep 26 23:33:04 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {insert_linearized_receipt-2b} ['$-cB9I2Dm9aF9WN_NLOud7GeQ']
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN START] {get_current_hosts_in_room-2c}
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {get_current_hosts_in_room-2c} SELECT /* Match the domain part of the MXID */ substring(c.state_key FROM '@[^:]*:(.*)$') as server_domain FROM current_state_events c /* Get the depth of the event from the events table */ INNER JOIN events AS e USING (event_id) WHERE /* Find any join state events in the room */ c.type = 'm.room.member' AND c.membership = 'join' AND c.room_id = ? /* Group all state events from the same domain into their own buckets (groups) */ GROUP BY server_domain /* Sorted by lowest depth first */ ORDER BY min(e.depth) ASC;
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {get_current_hosts_in_room-2c} ('!OICmmhekQz:matrix.org',)
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {insert_linearized_receipt-2b} 0.007123 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {insert_linearized_receipt-2b} SELECT stream_ordering, event_id FROM events INNER JOIN receipts_linearized AS r USING (event_id, room_id) WHERE r.room_id = ? AND r.receipt_type = ? AND r.user_id = ?
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {insert_linearized_receipt-2b} ('!OICmxBVQz:matrix.org', 'm.read', '@d:oma.su')
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {insert_linearized_receipt-2b} 0.001137 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {insert_linearized_receipt-2b} INSERT INTO receipts_linearized (room_id, receipt_type, user_id, stream_id, event_id, data) VALUES (?, ?, ?, ?, ?, ?) ON CONFLICT (room_id, receipt_type, user_id) DO UPDATE SET stream_id=EXCLUDED.stream_id, event_id=EXCLUDED.event_id, data=EXCLUDED.data
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {insert_linearized_receipt-2b} ['!OICmBVQz:matrix.org', 'm.read', '@d:oma.su', 162821, '$-cB9I2Dm93ud7GeQ', '{"ts":1667}']
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {get_current_hosts_in_room-2c} 0.011802 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN END] {get_current_hosts_in_room-2c} 0.013228 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.handlers.typing: [PUT-2] Got typing update from @d:oma.su: {'room_id': '!OICmz:matrix.org', 'typing': True, 'user_id': '@d:oma.su'}
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.util.metrics: [PUT-2] Entering block on_new_event
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.util.metrics: [user_directory.notify_new_event-5] Entering block user_dir_delta
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.util.metrics: [user_directory.notify_new_event-5] Exiting block user_dir_delta
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.util.metrics: [presence.notify_new_event-4] Entering block presence_delta
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.util.metrics: [presence.notify_new_event-4] Exiting block presence_delta
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.util.metrics: [PUT-2] Exiting block on_new_event
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.metrics._gc: [sentinel] Collecting gc 0
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {insert_linearized_receipt-2b} 0.008530 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN END] {insert_linearized_receipt-2b} 0.021510 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN START] {MultiWriterIdGenerator._update_table-2d}
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {MultiWriterIdGenerator._update_table-2d} INSERT INTO stream_positions (stream_name, instance_name, stream_id) VALUES (?, ?, ?) ON CONFLICT (stream_name, instance_name) DO UPDATE SET stream_id = GREATEST(stream_positions.stream_id, EXCLUDED.stream_id)
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {MultiWriterIdGenerator._update_table-2d} ('receipts', 'master', (162821,))
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {MultiWriterIdGenerator._update_table-2d} 0.001003 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN END] {MultiWriterIdGenerator._update_table-2d} 0.002282 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.databases.main.receipts: [PUT-2] RR for event $-cB9I2Dm9aF9WN_3ud7GeQ in !OICmmhxBVQz:matrix.org (28424 ms old)
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN START] {insert_graph_receipt-2e}
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {insert_graph_receipt-2e} DELETE FROM receipts_graph WHERE room_id = ? AND receipt_type = ? AND user_id = ?
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {insert_graph_receipt-2e} ['!OICmmhVQz:matrix.org', 'm.read', '@d:oma.su']
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {insert_graph_receipt-2e} 0.000719 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {insert_graph_receipt-2e} INSERT INTO receipts_graph (room_id, receipt_type, user_id, event_ids, data) VALUES(?, ?, ?, ?, ?)
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {insert_graph_receipt-2e} ('!OICmxBVQz:matrix.org', 'm.read', '@d:oma.su', '["$-cB9I2rwd3ud7GeQ"]', '{"ts":1667}')
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {insert_graph_receipt-2e} 0.000326 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN END] {insert_graph_receipt-2e} 0.003451 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.util.metrics: [PUT-2] Entering block on_new_event
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.util.metrics: [user_directory.notify_new_event-6] Entering block user_dir_delta
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.util.metrics: [user_directory.notify_new_event-6] Exiting block user_dir_delta
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.util.metrics: [presence.notify_new_event-5] Entering block presence_delta
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.util.metrics: [presence.notify_new_event-5] Exiting block presence_delta
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.util.metrics: [PUT-2] Exiting block on_new_event
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN START] {get_users_sent_receipts_between-2f}
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {get_users_sent_receipts_between-2f} SELECT DISTINCT user_id FROM receipts_linearized WHERE ? < stream_id AND stream_id <= ?
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {get_users_sent_receipts_between-2f} (162820, 162821)
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {get_users_sent_receipts_between-2f} 0.000896 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN END] {get_users_sent_receipts_between-2f} 0.001576 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.federation.federation_server: [PUT-2] Returning: {'pdus': {}}
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN START] {set_received_txn_response-30}
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL] {set_received_txn_response-30} INSERT INTO received_transactions (transaction_id, origin, response_code, response_json, ts) VALUES (?, ?, ?, ?, ?) ON CONFLICT (transaction_id, origin) DO NOTHING
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL values] {set_received_txn_response-30} ['1646', 'oma.su', 200, <memory at 0x7f94c0>, 1634]
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.SQL: [PUT-2] [SQL time] {set_received_txn_response-30} 0.001735 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.storage.txn: [PUT-2] [TXN END] {set_received_txn_response-30} 0.002455 sec
Sep 26 23:33:05 nether2.network synapse[14610]: synapse.access.http.8008: [PUT-2] 188.19.200.51 - 8008 - {oma.su} Processed request: 0.066sec/0.000sec (0.020sec, 0.002sec) (0.008sec/0.057sec/11) 11B 200 "PUT /_matrix/federation/v1/send/1663066557446 HTTP/1.0" "Synapse/1.66.0" [0 dbevts]
Sep 26 23:33:06 nether2.network synapse[14610]: synapse.access.http.8008: [GET-3] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - Received request: GET /_matrix/client/versions
Sep 26 23:33:06 nether2.network synapse[14610]: synapse.access.http.8008: [GET-3] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {None} Processed request: 0.002sec/0.001sec (0.003sec, 0.000sec) (0.000sec/0.000sec/0) 606B 200 "GET /_matrix/client/versions HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.access.http.8008: [GET-4] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - Received request: GET /_matrix/client/r0/thirdparty/protocols
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.txn: [GET-4] [TXN START] {get_user_by_access_token-31}
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-4] [SQL] {get_user_by_access_token-31} SELECT users.name as user_id, users.is_guest, users.shadow_banned, access_tokens.id as token_id, access_tokens.device_id, access_tokens.valid_until_ms, access_tokens.user_id as token_owner, access_tokens.used as token_used FROM users INNER JOIN access_tokens on users.name = COALESCE(puppets_user_id, access_tokens.user_id) WHERE token = ?
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-4] [SQL values] {get_user_by_access_token-31} ('syt_ZnNh_dDGPYZa_1aX2eh',)
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-4] [SQL time] {get_user_by_access_token-31} 0.001093 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.txn: [GET-4] [TXN END] {get_user_by_access_token-31} 0.002651 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.txn: [GET-4] [TXN START] {mark_access_token_as_used-32}
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-4] [SQL] {mark_access_token_as_used-32} UPDATE access_tokens SET used = ? WHERE id = ?
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-4] [SQL values] {mark_access_token_as_used-32} [True, 2]
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-4] [SQL time] {mark_access_token_as_used-32} 0.001850 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.txn: [GET-4] [TXN END] {mark_access_token_as_used-32} 0.002739 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.access.http.8008: [GET-4] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {@fsa:tavda.org} Processed request: 0.010sec/0.000sec (0.005sec, 0.001sec) (0.001sec/0.005sec/2) 2B 200 "GET /_matrix/client/r0/thirdparty/protocols HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.txn: [prune_old_user_ips-4] [TXN START] {_prune_old_user_ips-33}
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [prune_old_user_ips-4] [SQL] {_prune_old_user_ips-33} DELETE FROM user_ips WHERE last_seen <= ( SELECT COALESCE(MAX(last_seen), -1) FROM ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) AS u )
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [prune_old_user_ips-4] [SQL values] {_prune_old_user_ips-33} (1658,)
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.txn: [update_client_ips-4] [TXN START] {_update_client_ips_batch-34}
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [update_client_ips-4] [SQL] {_update_client_ips_batch-34} INSERT INTO user_ips (user_id, access_token, ip, user_agent, device_id, last_seen) VALUES ? ON CONFLICT (user_id, access_token, ip) DO UPDATE SET user_agent=EXCLUDED.user_agent, device_id=EXCLUDED.device_id, last_seen=EXCLUDED.last_seen
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [update_client_ips-4] [SQL time] {_update_client_ips_batch-34} 0.000669 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [update_client_ips-4] [SQL] {_update_client_ips_batch-34} UPDATE devices SET user_agent = ?, last_seen = ?, ip = ? WHERE user_id = ? AND device_id = ?
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [update_client_ips-4] [SQL time] {_update_client_ips_batch-34} 0.000659 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [prune_old_user_ips-4] [SQL time] {_prune_old_user_ips-33} 0.003830 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.txn: [prune_old_user_ips-4] [TXN END] {_prune_old_user_ips-33} 0.006343 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.txn: [update_client_ips-4] [TXN END] {_update_client_ips_batch-34} 0.005119 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.metrics._gc: [sentinel] Collecting gc 0
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.access.http.8008: [GET-5] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - Received request: GET /_matrix/client/unstable/room_keys/version
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.util.async_helpers: [GET-5] Acquired uncontended linearizer lock 'upload_room_keys_lock' for key '@fsa:tavda.org'
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.txn: [GET-5] [TXN START] {get_e2e_room_keys_version_info-35}
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-5] [SQL] {get_e2e_room_keys_version_info-35} SELECT MAX(version) FROM e2e_room_keys_versions WHERE user_id=? AND deleted=0
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-5] [SQL values] {get_e2e_room_keys_version_info-35} ('@fsa:tavda.org',)
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-5] [SQL time] {get_e2e_room_keys_version_info-35} 0.001103 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-5] [SQL] {get_e2e_room_keys_version_info-35} SELECT version, algorithm, auth_data, etag FROM e2e_room_keys_versions WHERE user_id = ? AND version = ? AND deleted = ?
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-5] [SQL values] {get_e2e_room_keys_version_info-35} ['@fsa:tavda.org', 1, 0]
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-5] [SQL time] {get_e2e_room_keys_version_info-35} 0.000353 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.txn: [GET-5] [TXN END] {get_e2e_room_keys_version_info-35} 0.003913 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.txn: [GET-5] [TXN START] {count_e2e_room_keys-36}
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-5] [SQL] {count_e2e_room_keys-36} SELECT COUNT(*) FROM e2e_room_keys WHERE user_id = ? AND version = ?
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-5] [SQL values] {count_e2e_room_keys-36} ['@fsa:tavda.org', 1]
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.SQL: [GET-5] [SQL time] {count_e2e_room_keys-36} 0.000830 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.storage.txn: [GET-5] [TXN END] {count_e2e_room_keys-36} 0.001981 sec
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.util.async_helpers: [GET-5] Releasing linearizer lock 'upload_room_keys_lock' for key '@fsa:tavda.org'
Sep 26 23:33:08 nether2.network synapse[14610]: synapse.access.http.8008: [GET-5] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {@fsa:tavda.org} Processed request: 0.010sec/0.000sec (0.005sec, 0.001sec) (0.001sec/0.006sec/2) 673B 200 "GET /_matrix/client/unstable/room_keys/version HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.handlers.typing: [typing._handle_timeouts-4] Checking for typing timeouts
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.access.http.8008: [GET-6] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - Received request: GET /_matrix/client/r0/voip/turnServer
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.access.http.8008: [GET-6] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {@fsa:tavda.org} Processed request: 0.002sec/0.001sec (0.003sec, 0.000sec) (0.000sec/0.000sec/0) 174B 200 "GET /_matrix/client/r0/voip/turnServer HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.access.http.8008: [GET-7] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - Received request: GET /_matrix/client/versions
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.access.http.8008: [GET-7] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {None} Processed request: 0.001sec/0.001sec (0.002sec, 0.000sec) (0.000sec/0.000sec/0) 606B 200 "GET /_matrix/client/versions HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.access.http.8008: [POST-8] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - Received request: POST /_matrix/client/r0/keys/upload
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.handlers.e2e_keys: [POST-8] Updating device_keys for device 'DO' for user @fsa:tavda.org at 1689
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [POST-8] [TXN START] {set_e2e_device_keys-37}
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [POST-8] [SQL] {set_e2e_device_keys-37} SELECT key_json FROM e2e_device_keys_json WHERE user_id = ? AND device_id = ?
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [POST-8] [SQL values] {set_e2e_device_keys-37} ['@fsa:tavda.org', 'DWO']
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [POST-8] [SQL time] {set_e2e_device_keys-37} 0.001267 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [POST-8] [TXN END] {set_e2e_device_keys-37} 0.003051 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [POST-8] [TXN START] {store_device-38}
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [POST-8] [SQL] {store_device-38} INSERT INTO devices (user_id, device_id, display_name, hidden) VALUES (?, ?, ?, ?) ON CONFLICT (user_id, device_id) DO NOTHING
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [POST-8] [SQL values] {store_device-38} ['@fsa:tavda.org', 'DWO', None, False]
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [POST-8] [SQL time] {store_device-38} 0.000486 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [POST-8] [TXN END] {store_device-38} 0.002237 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [POST-8] [TXN START] {simple_select_one_onecol-39}
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [POST-8] [SQL] {simple_select_one_onecol-39} SELECT hidden FROM devices WHERE user_id = ? AND device_id = ?
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [POST-8] [SQL values] {simple_select_one_onecol-39} ['@fsa:tavda.org', 'DWPBDDKNLO']
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [POST-8] [SQL time] {simple_select_one_onecol-39} 0.000352 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [POST-8] [TXN END] {simple_select_one_onecol-39} 0.001440 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [POST-8] [TXN START] {count_e2e_one_time_keys-3a}
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [POST-8] [SQL] {count_e2e_one_time_keys-3a} SELECT algorithm, COUNT(key_id) FROM e2e_one_time_keys_json WHERE user_id = ? AND device_id = ? GROUP BY algorithm
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [POST-8] [SQL values] {count_e2e_one_time_keys-3a} ('@fsa:tavda.org', 'DO')
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [POST-8] [SQL time] {count_e2e_one_time_keys-3a} 0.001010 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [POST-8] [TXN END] {count_e2e_one_time_keys-3a} 0.002183 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.access.http.8008: [POST-8] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {@fsa:tavda.org} Processed request: 0.016sec/0.000sec (0.009sec, 0.001sec) (0.001sec/0.009sec/4) 48B 200 "POST /_matrix/client/r0/keys/upload HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.access.http.8008: [GET-9] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - Received request: GET /_matrix/client/r0/pushrules/
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [GET-9] [TXN START] {get_push_rules_for_user-3b}
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-9] [SQL] {get_push_rules_for_user-3b} SELECT user_name, rule_id, priority_class, priority, conditions, actions FROM push_rules WHERE user_name = ?
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-9] [SQL values] {get_push_rules_for_user-3b} ['@fsa:tavda.org']
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-9] [SQL time] {get_push_rules_for_user-3b} 0.001184 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [GET-9] [TXN END] {get_push_rules_for_user-3b} 0.003078 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [GET-9] [TXN START] {get_push_rules_enabled_for_user-3c}
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-9] [SQL] {get_push_rules_enabled_for_user-3c} SELECT rule_id, enabled FROM push_rules_enable WHERE user_name = ?
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-9] [SQL values] {get_push_rules_enabled_for_user-3c} ['@fsa:tavda.org']
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-9] [SQL time] {get_push_rules_enabled_for_user-3c} 0.000642 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [GET-9] [TXN END] {get_push_rules_enabled_for_user-3c} 0.001870 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.access.http.8008: [GET-9] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {@fsa:tavda.org} Processed request: 0.010sec/0.001sec (0.007sec, 0.000sec) (0.001sec/0.005sec/2) 3596B 200 "GET /_matrix/client/r0/pushrules/ HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.access.http.8008: [GET-10] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - Received request: GET /_matrix/client/r0/user/%40fsa%3Atavda.org/filter/1
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [GET-10] [TXN START] {get_user_filter-3d}
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-10] [SQL] {get_user_filter-3d} SELECT filter_json FROM user_filters WHERE user_id = ? AND filter_id = ?
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-10] [SQL values] {get_user_filter-3d} ['fsa', 1]
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-10] [SQL time] {get_user_filter-3d} 0.001018 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [GET-10] [TXN END] {get_user_filter-3d} 0.002941 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.access.http.8008: [GET-10] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - {@fsa:tavda.org} Processed request: 0.009sec/0.001sec (0.006sec, 0.000sec) (0.000sec/0.003sec/1) 45B 200 "GET /_matrix/client/r0/user/%40fsa%3Atavda.org/filter/1 HTTP/1.0" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" [0 dbevts]
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.access.http.8008: [GET-11] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - Received request: GET /_matrix/client/r0/sync?filter=%7B%22room%22%3A%7B%22state%22%3A%7B%22lazy_load_members%22%3Atrue%7D%2C%22timeline%22%3A%7B%22limit%22%3A20%7D%7D%7D&timeout=0&_cacheBuster=1664209989420
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.rest.client.sync: [GET-11] /sync: user=@fsa:tavda.org, timeout=0, since=None, set_presence='online', filter_id='{"room":{"state":{"lazy_load_members":true},"timeline":{"limit":20}}}', device_id='DO'
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [GET-11] [TXN START] {get_presence_for_users-3e}
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-11] [SQL] {get_presence_for_users-3e} SELECT user_id, state, last_active_ts, last_federation_update_ts, last_user_sync_ts, status_msg, currently_active FROM presence_stream WHERE user_id = ANY(?)
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-11] [SQL values] {get_presence_for_users-3e} [['@fsa:tavda.org']]
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-11] [SQL time] {get_presence_for_users-3e} 0.001182 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [GET-11] [TXN END] {get_presence_for_users-3e} 0.003202 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.util.metrics: [GET-11] Entering block presence_update_states
Sep 26 23:33:45 nether2.network systemd[1]: matrix-synapse.service: A process of this unit has been killed by the OOM killer.
Sep 26 23:33:45 nether2.network systemd[1]: matrix-synapse.service: Main process exited, code=killed, status=9/KILL
Sep 26 23:33:45 nether2.network systemd[1]: matrix-synapse.service: Failed with result 'oom-kill'.
Sep 26 23:33:45 nether2.network systemd[1]: matrix-synapse.service: Consumed 29.596s CPU time.

@DMRobertson
Copy link
Contributor

The only request which is received but not completed (Processed request:) is GET-11.

Sep 26 23:33:09 nether2.network synapse[14610]: synapse.access.http.8008: [GET-11] 2a01:620:c12e:df00:65f:19dc:12d0:3f9f - 8008 - Received request: GET /_matrix/client/r0/sync?filter=%7B%22room%22%3A%7B%22state%22%3A%7B%22lazy_load_members%22%3Atrue%7D%2C%22timeline%22%3A%7B%22limit%22%3A20%7D%7D%7D&timeout=0&_cacheBuster=1664209989420
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.rest.client.sync: [GET-11] /sync: user=@fsa:tavda.org, timeout=0, since=None, set_presence='online', filter_id='{"room":{"state":{"lazy_load_members":true},"timeline":{"limit":20}}}', device_id='DO'
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [GET-11] [TXN START] {get_presence_for_users-3e}
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-11] [SQL] {get_presence_for_users-3e} SELECT user_id, state, last_active_ts, last_federation_update_ts, last_user_sync_ts, status_msg, currently_active FROM presence_stream WHERE user_id = ANY(?)
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-11] [SQL values] {get_presence_for_users-3e} [['@fsa:tavda.org']]
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.SQL: [GET-11] [SQL time] {get_presence_for_users-3e} 0.001182 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.storage.txn: [GET-11] [TXN END] {get_presence_for_users-3e} 0.003202 sec
Sep 26 23:33:09 nether2.network synapse[14610]: synapse.util.metrics: [GET-11] Entering block presence_update_states

This looks like an initial sync (since=None). If that user is in a lot of rooms then Synapse has to fetch a lot of data and this can be expensive.

How many rooms is that user in?

You could try turning down cache factors in config. This would make Synapse slower and use more database IO, but would decrease its memory usage.

Other issues: #12158, #12971, #3720

I would also maybe try turning presence off to see if that helps---it's not well-used and known to be a bit buggy.

@DMRobertson
Copy link
Contributor

DMRobertson commented Sep 26, 2022

( matrix-org/matrix-spec-proposals#3575 is the long-term answer to "sync is slow")

@fsa
Copy link
Author

fsa commented Sep 26, 2022

How many rooms is that user in?

8 rooms where communication is rare. 550, 300 and 200 people maximum in the biggest ones.

The log is for the Element web client. Unfortunately, after the problem appeared, I cleared the browser cache. However, similar issues are seen on the Element mobile client. But some fresh messages manage to reach it before the server crashes for the same reason. It doesn't matter what device you're connecting from. The fall is still very fast, about a minute.

You could try turning down cache factors

The value was set by me to 10K. Reducing the value to 1K does not solve the problem.

@fsa
Copy link
Author

fsa commented Sep 26, 2022

is the long-term answer to "sync is slow"

The problem is not slow synchronization, but the fact that one connected user can completely paralyze the server! While a user is connected, other users cannot communicate normally.

@fsa
Copy link
Author

fsa commented Sep 28, 2022

1.68 :(

@tomsisk
Copy link

tomsisk commented Sep 28, 2022

@fsa I'm curious if this is related to issues we've been seeing since 1.64.0 (more in #12160 near the bottom of the thread). Have you tried turning presence off?

@fsa
Copy link
Author

fsa commented Sep 29, 2022

In my case, the memory leak occurs very quickly, within a minute after connecting one particular user. As long as this user has the client open, the server keeps crashing. You can see the speed of the fall in the video on YouTube.

@tomsisk
Copy link

tomsisk commented Sep 29, 2022

@fsa We've experienced similar although we have many more rooms, they're essentially all DMs. This makes it more difficult to track but this was one of my theories that it could be specific users.

If you can't turn presence off for whatever reason, can you at least give your version history? Did it start after recently upgrading? Did it just happen randomly? I've been banging my head against a wall for close to two months on this, we can't have presence on without it causing the service to fail within minutes, and this (seems to be) closest to what we've been seeing that I've seen on here.

@fsa
Copy link
Author

fsa commented Sep 29, 2022

It happened suddenly. There is a slight chance that there was an update before this, but I don't remember that. I discovered that something was wrong with the server during the day, on Monday, September 26, when I was walking with a child on the street. I could not write to another contact from my server. The day before, I had freely communicated with others. You need to look at when there were releases in the Ubuntu repository. When I came home, I found that something was happening with the server. After that, I moved the server and its configuration to another similar server in order to secure all the other services that I had there. After the transfer, the picture was preserved. As long as I don't connect to the server, others can communicate through it.

@DMRobertson
Copy link
Contributor

is the long-term answer to "sync is slow"

The problem is not slow synchronization, but the fact that one connected user can completely paralyze the server!

Agreed. But initial syncs are slow because they are expensive, and that expensiveness may explain why the you see OOMs.

1.68 :(

I'm not sure what this means. Are you saying that you still see the problem after upgrading to 1.68?

I would also maybe try turning presence off to see if that helps---it's not well-used and known to be a bit buggy.

To reiterate: can you turn off presence and let us know if it allows you to join without OOMkilling your server?

@fsa
Copy link
Author

fsa commented Sep 29, 2022

presence:
    enabled: false

Memory consumption stopped. I was able to log in with my account and the server is working fine.

@DMRobertson DMRobertson changed the title Synapse eat all ram until OOM Initial sync with presence enabled eats up RAM until an OOM hits Sep 29, 2022
@fsa
Copy link
Author

fsa commented Sep 29, 2022

The title has been incorrectly corrected. Even after the initial synchronization of the client, the above option cannot be disabled. Any user connection causes memory consumption when the option is disabled.

@DMRobertson
Copy link
Contributor

When you say

Any user connection causes memory consumption when the option is disabled

do you mean that reverting to

presence:
     enabled: true

and restarting synapse causes the same OOM problem as before once a client connects?

@fsa
Copy link
Author

fsa commented Sep 29, 2022

Right. The memory consumption was even when connected from a mobile client that I had synced. There, even, it was possible to have time to receive some of the messages before the server was killed.
Now, as soon as I disable the option, the problem returns again for this account.

@DMRobertson
Copy link
Contributor

I suggest you permanently leave

presence:
    enabled: false

until we can find a proper fix for this issue.

@DMRobertson DMRobertson changed the title Initial sync with presence enabled eats up RAM until an OOM hits Initial and incremental syncs with presence enabled eat up RAM until an OOM hits Sep 29, 2022
@fsa
Copy link
Author

fsa commented Sep 29, 2022

Yes. I'll have to use this crutch. Otherwise my server will not work properly.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
A-Memory-Usage A-Presence O-Uncommon Most users are unlikely to come across this or unexpected workflow S-Major Major functionality / product severely impaired, no satisfactory workaround. T-Defect Bugs, crashes, hangs, security vulnerabilities, or other reported issues.
Projects
None yet
Development

No branches or pull requests

3 participants