erikjohnston
commented
1 year ago @dbkr Can you enable debug logging and try to reproduce again?
Closed dbkr closed 11 months ago
erikjohnston
commented
1 year ago @dbkr Can you enable debug logging and try to reproduce again?
dbkr
commented
1 year ago Ah, yes. Quite surprised I didn't have debug logging on already.
2023-02-17 13:45:24,242 - synapse.access.http.8008 - 415 - DEBUG - OPTIONS-11 - ::1 - 8008 - Received request: OPTIONS /_matrix/client/r0/voip/turnServer
2023-02-17 13:45:24,243 - synapse.access.http.8008 - 460 - DEBUG - OPTIONS-11 - ::1 - 8008 - {None} Processed request: 0.001sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 0B 204 "OPTIONS /_matrix/client/r0/voip/turnServer HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:45:24,246 - synapse.access.http.8008 - 415 - DEBUG - GET-12 - ::1 - 8008 - Received request: GET /_matrix/client/r0/voip/turnServer
2023-02-17 13:45:24,247 - synapse.access.http.8008 - 460 - INFO - GET-12 - ::1 - 8008 - {@alan:localhost} Processed request: 0.001sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "GET /_matrix/client/r0/voip/turnServer HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:45:24,312 - synapse.metrics._gc - 118 - DEBUG - sentinel - Collecting gc 0
2023-02-17 13:45:26,984 - synapse.storage.txn - 692 - DEBUG - prune_old_user_ips-15 - [TXN START] {_prune_old_user_ips-47}
2023-02-17 13:45:26,985 - synapse.storage.txn - 796 - DEBUG - prune_old_user_ips-15 - [TXN END] {_prune_old_user_ips-47} 0.001065 sec
2023-02-17 13:45:27,012 - synapse.handlers.typing - 100 - DEBUG - typing._handle_timeouts-15 - Checking for typing timeouts
2023-02-17 13:45:27,012 - synapse.handlers.presence - 909 - DEBUG - handle_presence_timeouts-9 - Handling presence timeouts
2023-02-17 13:45:27,013 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-9 - Entering block presence_update_states
2023-02-17 13:45:27,013 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-9 - Exiting block presence_update_states
2023-02-17 13:45:27,027 - synapse.storage.TIME - 606 - DEBUG - sentinel - Total database time: 0.021% {_prune_old_user_ips(2): 0.021%, update_cached_last_access_time(0): 0.000%, stats_incremental_position(0): 0.000%}
2023-02-17 13:45:31,985 - synapse.storage.txn - 692 - DEBUG - prune_old_user_ips-16 - [TXN START] {_prune_old_user_ips-48}
2023-02-17 13:45:31,986 - synapse.storage.txn - 796 - DEBUG - prune_old_user_ips-16 - [TXN END] {_prune_old_user_ips-48} 0.000476 sec
2023-02-17 13:45:32,011 - synapse.handlers.typing - 100 - DEBUG - typing._handle_timeouts-16 - Checking for typing timeouts
2023-02-17 13:45:32,012 - synapse.handlers.presence - 909 - DEBUG - handle_presence_timeouts-10 - Handling presence timeouts
2023-02-17 13:45:32,012 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-10 - Entering block presence_update_states
2023-02-17 13:45:32,012 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-10 - Exiting block presence_update_states
2023-02-17 13:45:36,982 - synapse.storage.txn - 692 - DEBUG - _get_stats_for_federation_staging-2 - [TXN START] {_get_stats_for_federation_staging-49}
2023-02-17 13:45:36,982 - synapse.storage.txn - 796 - DEBUG - _get_stats_for_federation_staging-2 - [TXN END] {_get_stats_for_federation_staging-49} 0.000471 sec
2023-02-17 13:45:36,982 - synapse.storage.txn - 692 - DEBUG - prune_old_user_ips-17 - [TXN START] {_prune_old_user_ips-4a}
2023-02-17 13:45:36,983 - synapse.storage.txn - 796 - DEBUG - prune_old_user_ips-17 - [TXN END] {_prune_old_user_ips-4a} 0.000270 sec
2023-02-17 13:45:37,004 - synapse.storage.databases.main.event_push_actions - 1441 - DEBUG - rotate_notifs-2 - Handling new receipts
2023-02-17 13:45:37,005 - synapse.storage.txn - 692 - DEBUG - rotate_notifs-2 - [TXN START] {_handle_new_receipts_for_notifs_txn-4b}
2023-02-17 13:45:37,006 - synapse.storage.txn - 796 - DEBUG - rotate_notifs-2 - [TXN END] {_handle_new_receipts_for_notifs_txn-4b} 0.001349 sec
2023-02-17 13:45:37,006 - synapse.storage.databases.main.event_push_actions - 1452 - INFO - rotate_notifs-2 - Rotating notifications
2023-02-17 13:45:37,007 - synapse.handlers.typing - 100 - DEBUG - typing._handle_timeouts-17 - Checking for typing timeouts
2023-02-17 13:45:37,007 - synapse.handlers.presence - 909 - DEBUG - handle_presence_timeouts-11 - Handling presence timeouts
2023-02-17 13:45:37,007 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-11 - Entering block presence_update_states
2023-02-17 13:45:37,007 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-11 - Exiting block presence_update_states
2023-02-17 13:45:37,008 - synapse.storage.txn - 692 - DEBUG - rotate_notifs-2 - [TXN START] {_rotate_notifs-4c}
2023-02-17 13:45:37,008 - synapse.storage.databases.main.event_push_actions - 1675 - INFO - rotate_notifs-2 - Rotating notifications up to: 3632
2023-02-17 13:45:37,008 - synapse.storage.databases.main.event_push_actions - 1774 - INFO - rotate_notifs-2 - Rotating notifications, handling 0 rows
2023-02-17 13:45:37,008 - synapse.util.caches.lrucache - 134 - DEBUG - LruCache._expire_old_entries-2 - Searching for stale caches
2023-02-17 13:45:37,009 - synapse.util.caches.lrucache - 212 - INFO - LruCache._expire_old_entries-2 - Dropped 0 items from caches
2023-02-17 13:45:37,008 - synapse.storage.txn - 796 - DEBUG - rotate_notifs-2 - [TXN END] {_rotate_notifs-4c} 0.000826 sec
2023-02-17 13:45:37,009 - synapse.storage.txn - 692 - DEBUG - _maybe_retry_device_resync-2 - [TXN START] {get_user_ids_requiring_device_list_resync-4d}
2023-02-17 13:45:37,009 - synapse.storage.txn - 796 - DEBUG - _maybe_retry_device_resync-2 - [TXN END] {get_user_ids_requiring_device_list_resync-4d} 0.000124 sec
2023-02-17 13:45:37,009 - synapse.storage.txn - 692 - DEBUG - rotate_notifs-2 - [TXN START] {simple_select_one_onecol-4e}
2023-02-17 13:45:37,010 - synapse.storage.txn - 796 - DEBUG - rotate_notifs-2 - [TXN END] {simple_select_one_onecol-4e} 0.000099 sec
2023-02-17 13:45:37,010 - synapse.storage.txn - 692 - DEBUG - rotate_notifs-2 - [TXN START] {_remove_old_push_actions_that_have_rotated-4f}
2023-02-17 13:45:37,010 - synapse.storage.databases.main.event_push_actions - 1867 - INFO - rotate_notifs-2 - Rotating notifications, deleted 0 push actions
2023-02-17 13:45:37,010 - synapse.storage.txn - 796 - DEBUG - rotate_notifs-2 - [TXN END] {_remove_old_push_actions_that_have_rotated-4f} 0.000107 sec
2023-02-17 13:45:37,029 - synapse.storage.TIME - 606 - DEBUG - sentinel - Total database time: 0.037% {_handle_new_receipts_for_notifs_txn(1): 0.013%, _rotate_notifs(1): 0.008%, _prune_old_user_ips(2): 0.007%}
2023-02-17 13:45:38,216 - synapse.handlers.sync - 1440 - DEBUG - GET-10 - Calculating sync response for @alan:localhost between StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176883, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1) and StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176883, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1)
2023-02-17 13:45:38,217 - synapse.handlers.sync - 1458 - DEBUG - GET-10 - Fetching account data
2023-02-17 13:45:38,218 - synapse.storage.txn - 692 - DEBUG - GET-10 - [TXN START] {get_updated_global_account_data_for_user-50}
2023-02-17 13:45:38,218 - synapse.storage.txn - 796 - DEBUG - GET-10 - [TXN END] {get_updated_global_account_data_for_user-50} 0.000540 sec
2023-02-17 13:45:38,220 - synapse.storage.txn - 692 - DEBUG - GET-10 - [TXN START] {have_push_rules_changed-51}
2023-02-17 13:45:38,220 - synapse.storage.txn - 796 - DEBUG - GET-10 - [TXN END] {have_push_rules_changed-51} 0.000284 sec
2023-02-17 13:45:38,220 - synapse.handlers.sync - 1481 - DEBUG - GET-10 - Fetching room data
2023-02-17 13:45:38,220 - synapse.storage.txn - 692 - DEBUG - GET-10 - [TXN START] {get_updated_room_account_data_for_user-52}
2023-02-17 13:45:38,221 - synapse.storage.txn - 796 - DEBUG - GET-10 - [TXN END] {get_updated_room_account_data_for_user-52} 0.000156 sec
2023-02-17 13:45:38,221 - synapse.util.metrics - 163 - DEBUG - GET-10 - Entering block ephemeral_by_room
2023-02-17 13:45:38,221 - synapse.util.metrics - 163 - DEBUG - GET-10 - Entering block typing.get_new_events
2023-02-17 13:45:38,221 - synapse.util.metrics - 176 - DEBUG - GET-10 - Exiting block typing.get_new_events
2023-02-17 13:45:38,221 - synapse.util.metrics - 176 - DEBUG - GET-10 - Exiting block ephemeral_by_room
2023-02-17 13:45:38,221 - synapse.storage.txn - 692 - DEBUG - GET-10 - [TXN START] {get_updated_tags-53}
2023-02-17 13:45:38,222 - synapse.storage.txn - 796 - DEBUG - GET-10 - [TXN END] {get_updated_tags-53} 0.000134 sec
2023-02-17 13:45:38,222 - synapse.handlers.sync - 1915 - DEBUG - GET-10 - no-oping sync
2023-02-17 13:45:38,222 - synapse.handlers.sync - 1504 - DEBUG - GET-10 - Fetching presence data
2023-02-17 13:45:38,222 - synapse.util.metrics - 163 - DEBUG - GET-10 - Entering block presence.get_new_events
2023-02-17 13:45:38,222 - synapse.util.metrics - 176 - DEBUG - GET-10 - Exiting block presence.get_new_events
2023-02-17 13:45:38,222 - synapse.util.metrics - 163 - DEBUG - GET-10 - Entering block _generate_sync_entry_for_device_list
2023-02-17 13:45:38,222 - synapse.util.metrics - 176 - DEBUG - GET-10 - Exiting block _generate_sync_entry_for_device_list
2023-02-17 13:45:38,222 - synapse.handlers.sync - 1520 - DEBUG - GET-10 - Fetching to-device data
2023-02-17 13:45:38,222 - synapse.handlers.sync - 1523 - DEBUG - GET-10 - Fetching OTK data
2023-02-17 13:45:38,223 - synapse.handlers.sync - 1552 - DEBUG - GET-10 - Sync response calculation complete
2023-02-17 13:45:38,223 - synapse.handlers.sync - 324 - DEBUG - GET-10 - Returning sync response for @alan:localhost
2023-02-17 13:45:38,223 - synapse.util.metrics - 163 - DEBUG - GET-10 - Entering block presence_update_states
2023-02-17 13:45:38,223 - synapse.util.metrics - 176 - DEBUG - GET-10 - Exiting block presence_update_states
2023-02-17 13:45:38,223 - synapse.rest.client.sync - 222 - DEBUG - GET-10 - Formatting events in sync response
2023-02-17 13:45:38,223 - synapse.rest.client.sync - 257 - DEBUG - GET-10 - building sync response dict
2023-02-17 13:45:38,223 - synapse.rest.client.sync - 211 - DEBUG - GET-10 - Event formatting complete
2023-02-17 13:45:38,224 - synapse.access.http.8008 - 460 - INFO - GET-10 - ::1 - 8008 - {@alan:localhost} Processed request: 30.013sec/0.000sec (0.000sec, 0.000sec) (0.001sec/0.001sec/4) 371B 200 "GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176883_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:45:38,244 - synapse.access.http.8008 - 415 - DEBUG - OPTIONS-13 - ::1 - 8008 - Received request: OPTIONS /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176883_0_724_1855_1_1174_293_0_1
2023-02-17 13:45:38,244 - synapse.access.http.8008 - 460 - DEBUG - OPTIONS-13 - ::1 - 8008 - {None} Processed request: 0.001sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 0B 204 "OPTIONS /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176883_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:45:38,247 - synapse.access.http.8008 - 415 - DEBUG - GET-14 - ::1 - 8008 - Received request: GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176883_0_724_1855_1_1174_293_0_1
2023-02-17 13:45:38,247 - synapse.rest.client.sync - 131 - DEBUG - GET-14 - /sync: user=@alan:localhost, timeout=30000, since='s3632_176883_0_724_1855_1_1174_293_0_1', set_presence='online', filter_id='1', device_id='FUJBEAPBLK'
2023-02-17 13:45:38,248 - synapse.util.metrics - 163 - DEBUG - GET-14 - Entering block presence_update_states
2023-02-17 13:45:38,248 - synapse.util.metrics - 176 - DEBUG - GET-14 - Exiting block presence_update_states
2023-02-17 13:45:38,248 - synapse.util.metrics - 163 - DEBUG - GET-14 - Entering block presence_update_states
2023-02-17 13:45:38,248 - synapse.util.metrics - 176 - DEBUG - GET-14 - Exiting block presence_update_states
2023-02-17 13:45:38,248 - synapse.util.caches.response_cache - 236 - DEBUG - GET-14 - [sync]: no cached result for [(@alan:localhost, 30000, 's3632_176883_0_724_1855_1_1174_293_0_1', '1', False, 'FUJBEAPBLK')], calculating new one
2023-02-17 13:45:38,248 - synapse.handlers.sync - 366 - DEBUG - GET-14 - Deleted 0 to-device messages up to 1174
2023-02-17 13:45:38,312 - synapse.metrics._gc - 118 - DEBUG - sentinel - Collecting gc 0
2023-02-17 13:45:41,983 - synapse.storage.txn - 692 - DEBUG - prune_old_user_ips-18 - [TXN START] {_prune_old_user_ips-54}
2023-02-17 13:45:41,983 - synapse.storage.txn - 796 - DEBUG - prune_old_user_ips-18 - [TXN END] {_prune_old_user_ips-54} 0.000498 sec
2023-02-17 13:45:42,011 - synapse.handlers.typing - 100 - DEBUG - typing._handle_timeouts-18 - Checking for typing timeouts
2023-02-17 13:45:42,011 - synapse.handlers.presence - 909 - DEBUG - handle_presence_timeouts-12 - Handling presence timeouts
2023-02-17 13:45:42,012 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-12 - Entering block presence_update_states
2023-02-17 13:45:42,012 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-12 - Exiting block presence_update_states
2023-02-17 13:45:46,986 - synapse.storage.txn - 692 - DEBUG - prune_old_user_ips-19 - [TXN START] {_prune_old_user_ips-55}
2023-02-17 13:45:46,986 - synapse.storage.txn - 796 - DEBUG - prune_old_user_ips-19 - [TXN END] {_prune_old_user_ips-55} 0.000638 sec
2023-02-17 13:45:47,007 - synapse.handlers.typing - 100 - DEBUG - typing._handle_timeouts-19 - Checking for typing timeouts
2023-02-17 13:45:47,007 - synapse.handlers.presence - 909 - DEBUG - handle_presence_timeouts-13 - Handling presence timeouts
2023-02-17 13:45:47,007 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-13 - Entering block presence_update_states
2023-02-17 13:45:47,007 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-13 - Exiting block presence_update_states
2023-02-17 13:45:47,028 - synapse.storage.TIME - 606 - DEBUG - sentinel - Total database time: 0.023% {_prune_old_user_ips(2): 0.011%, get_updated_global_account_data_for_user(1): 0.005%, have_push_rules_changed(1): 0.003%}
2023-02-17 13:45:51,986 - synapse.storage.txn - 692 - DEBUG - prune_old_user_ips-20 - [TXN START] {_prune_old_user_ips-56}
2023-02-17 13:45:51,986 - synapse.storage.txn - 796 - DEBUG - prune_old_user_ips-20 - [TXN END] {_prune_old_user_ips-56} 0.000675 sec
2023-02-17 13:45:52,011 - synapse.handlers.typing - 100 - DEBUG - typing._handle_timeouts-20 - Checking for typing timeouts
2023-02-17 13:45:52,011 - synapse.handlers.presence - 909 - DEBUG - handle_presence_timeouts-14 - Handling presence timeouts
2023-02-17 13:45:52,011 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-14 - Entering block presence_update_states
2023-02-17 13:45:52,011 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-14 - Exiting block presence_update_states
2023-02-17 13:45:56,989 - synapse.storage.txn - 692 - DEBUG - prune_old_user_ips-21 - [TXN START] {_prune_old_user_ips-57}
2023-02-17 13:45:56,990 - synapse.storage.txn - 796 - DEBUG - prune_old_user_ips-21 - [TXN END] {_prune_old_user_ips-57} 0.001014 sec
2023-02-17 13:45:57,010 - synapse.handlers.typing - 100 - DEBUG - typing._handle_timeouts-21 - Checking for typing timeouts
2023-02-17 13:45:57,011 - synapse.handlers.presence - 909 - DEBUG - handle_presence_timeouts-15 - Handling presence timeouts
2023-02-17 13:45:57,011 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-15 - Entering block presence_update_states
2023-02-17 13:45:57,011 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-15 - Exiting block presence_update_states
2023-02-17 13:45:57,028 - synapse.storage.TIME - 606 - DEBUG - sentinel - Total database time: 0.017% {_prune_old_user_ips(2): 0.017%, update_cached_last_access_time(0): 0.000%, stats_incremental_position(0): 0.000%}
2023-02-17 13:46:01,988 - synapse.storage.txn - 692 - DEBUG - prune_old_user_ips-22 - [TXN START] {_prune_old_user_ips-58}
2023-02-17 13:46:01,989 - synapse.storage.txn - 796 - DEBUG - prune_old_user_ips-22 - [TXN END] {_prune_old_user_ips-58} 0.000537 sec
2023-02-17 13:46:02,011 - synapse.handlers.typing - 100 - DEBUG - typing._handle_timeouts-22 - Checking for typing timeouts
2023-02-17 13:46:02,012 - synapse.handlers.presence - 909 - DEBUG - handle_presence_timeouts-16 - Handling presence timeouts
2023-02-17 13:46:02,012 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-16 - Entering block presence_update_states
2023-02-17 13:46:02,012 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-16 - Exiting block presence_update_states
2023-02-17 13:46:06,984 - synapse.storage.txn - 692 - DEBUG - _get_stats_for_federation_staging-3 - [TXN START] {_get_stats_for_federation_staging-59}
2023-02-17 13:46:06,985 - synapse.storage.txn - 796 - DEBUG - _get_stats_for_federation_staging-3 - [TXN END] {_get_stats_for_federation_staging-59} 0.001030 sec
2023-02-17 13:46:06,985 - synapse.storage.txn - 692 - DEBUG - prune_old_user_ips-23 - [TXN START] {_prune_old_user_ips-5a}
2023-02-17 13:46:06,986 - synapse.storage.txn - 796 - DEBUG - prune_old_user_ips-23 - [TXN END] {_prune_old_user_ips-5a} 0.000901 sec
2023-02-17 13:46:07,003 - synapse.storage.databases.main.event_push_actions - 1441 - DEBUG - rotate_notifs-3 - Handling new receipts
2023-02-17 13:46:07,006 - synapse.storage.txn - 692 - DEBUG - rotate_notifs-3 - [TXN START] {_handle_new_receipts_for_notifs_txn-5b}
2023-02-17 13:46:07,007 - synapse.util.caches.expiringcache - 189 - DEBUG - prune_cache_get_pdu_cache-1 - [get_pdu_cache] _prune_cache before: 0, after len: 0
2023-02-17 13:46:07,007 - synapse.handlers.typing - 100 - DEBUG - typing._handle_timeouts-23 - Checking for typing timeouts
2023-02-17 13:46:07,007 - synapse.storage.txn - 796 - DEBUG - rotate_notifs-3 - [TXN END] {_handle_new_receipts_for_notifs_txn-5b} 0.001569 sec
2023-02-17 13:46:07,008 - synapse.handlers.presence - 909 - DEBUG - handle_presence_timeouts-17 - Handling presence timeouts
2023-02-17 13:46:07,008 - synapse.storage.txn - 692 - DEBUG - _maybe_retry_device_resync-3 - [TXN START] {get_user_ids_requiring_device_list_resync-5c}
2023-02-17 13:46:07,008 - synapse.storage.txn - 796 - DEBUG - _maybe_retry_device_resync-3 - [TXN END] {get_user_ids_requiring_device_list_resync-5c} 0.000301 sec
2023-02-17 13:46:07,008 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-17 - Entering block presence_update_states
2023-02-17 13:46:07,008 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-17 - Exiting block presence_update_states
2023-02-17 13:46:07,009 - synapse.metrics._gc - 118 - DEBUG - sentinel - Collecting gc 0
2023-02-17 13:46:07,010 - synapse.handlers.presence - 797 - INFO - persist_presence_changes-0 - Persisting 1 unpersisted presence updates
2023-02-17 13:46:07,010 - synapse.storage.txn - 692 - DEBUG - persist_presence_changes-0 - [TXN START] {update_presence-5d}
2023-02-17 13:46:07,011 - synapse.storage.databases.main.event_push_actions - 1452 - INFO - rotate_notifs-3 - Rotating notifications
2023-02-17 13:46:07,011 - synapse.util.caches.lrucache - 134 - DEBUG - LruCache._expire_old_entries-3 - Searching for stale caches
2023-02-17 13:46:07,012 - synapse.util.caches.lrucache - 212 - INFO - LruCache._expire_old_entries-3 - Dropped 0 items from caches
2023-02-17 13:46:07,016 - synapse.storage.txn - 796 - DEBUG - persist_presence_changes-0 - [TXN END] {update_presence-5d} 0.005334 sec
2023-02-17 13:46:07,016 - synapse.storage.txn - 692 - DEBUG - rotate_notifs-3 - [TXN START] {_rotate_notifs-5e}
2023-02-17 13:46:07,016 - synapse.util.metrics - 163 - DEBUG - user_directory.notify_new_event-1 - Entering block user_dir_delta
2023-02-17 13:46:07,016 - synapse.util.metrics - 176 - DEBUG - user_directory.notify_new_event-1 - Exiting block user_dir_delta
2023-02-17 13:46:07,017 - synapse.util.metrics - 163 - DEBUG - presence.notify_new_event-0 - Entering block presence_delta
2023-02-17 13:46:07,017 - synapse.util.metrics - 176 - DEBUG - presence.notify_new_event-0 - Exiting block presence_delta
2023-02-17 13:46:07,017 - synapse.storage.databases.main.event_push_actions - 1675 - INFO - rotate_notifs-3 - Rotating notifications up to: 3632
2023-02-17 13:46:07,017 - synapse.storage.databases.main.event_push_actions - 1774 - INFO - rotate_notifs-3 - Rotating notifications, handling 0 rows
2023-02-17 13:46:07,017 - synapse.storage.txn - 796 - DEBUG - rotate_notifs-3 - [TXN END] {_rotate_notifs-5e} 0.001510 sec
2023-02-17 13:46:07,018 - synapse.storage.txn - 692 - DEBUG - update_recently_accessed_media-1 - [TXN START] {update_cached_last_access_time-5f}
2023-02-17 13:46:07,018 - synapse.storage.txn - 796 - DEBUG - update_recently_accessed_media-1 - [TXN END] {update_cached_last_access_time-5f} 0.000273 sec
2023-02-17 13:46:07,018 - synapse.storage.txn - 692 - DEBUG - rotate_notifs-3 - [TXN START] {simple_select_one_onecol-60}
2023-02-17 13:46:07,018 - synapse.storage.txn - 796 - DEBUG - rotate_notifs-3 - [TXN END] {simple_select_one_onecol-60} 0.000226 sec
2023-02-17 13:46:07,018 - synapse.storage.txn - 692 - DEBUG - rotate_notifs-3 - [TXN START] {_remove_old_push_actions_that_have_rotated-61}
2023-02-17 13:46:07,019 - synapse.storage.databases.main.event_push_actions - 1867 - INFO - rotate_notifs-3 - Rotating notifications, deleted 0 push actions
2023-02-17 13:46:07,019 - synapse.storage.txn - 796 - DEBUG - rotate_notifs-3 - [TXN END] {_remove_old_push_actions_that_have_rotated-61} 0.000160 sec
2023-02-17 13:46:07,027 - synapse.storage.TIME - 606 - DEBUG - sentinel - Total database time: 0.118% {update_presence(1): 0.053%, _handle_new_receipts_for_notifs_txn(1): 0.016%, _rotate_notifs(1): 0.015%}
2023-02-17 13:46:08,254 - synapse.handlers.sync - 1440 - DEBUG - GET-14 - Calculating sync response for @alan:localhost between StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176883, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1) and StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176884, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1)
2023-02-17 13:46:08,255 - synapse.handlers.sync - 1458 - DEBUG - GET-14 - Fetching account data
2023-02-17 13:46:08,256 - synapse.storage.txn - 692 - DEBUG - GET-14 - [TXN START] {get_updated_global_account_data_for_user-62}
2023-02-17 13:46:08,256 - synapse.storage.txn - 796 - DEBUG - GET-14 - [TXN END] {get_updated_global_account_data_for_user-62} 0.000518 sec
2023-02-17 13:46:08,257 - synapse.storage.txn - 692 - DEBUG - GET-14 - [TXN START] {have_push_rules_changed-63}
2023-02-17 13:46:08,257 - synapse.storage.txn - 796 - DEBUG - GET-14 - [TXN END] {have_push_rules_changed-63} 0.000149 sec
2023-02-17 13:46:08,257 - synapse.handlers.sync - 1481 - DEBUG - GET-14 - Fetching room data
2023-02-17 13:46:08,258 - synapse.storage.txn - 692 - DEBUG - GET-14 - [TXN START] {get_updated_room_account_data_for_user-64}
2023-02-17 13:46:08,258 - synapse.storage.txn - 796 - DEBUG - GET-14 - [TXN END] {get_updated_room_account_data_for_user-64} 0.000192 sec
2023-02-17 13:46:08,258 - synapse.util.metrics - 163 - DEBUG - GET-14 - Entering block ephemeral_by_room
2023-02-17 13:46:08,258 - synapse.util.metrics - 163 - DEBUG - GET-14 - Entering block typing.get_new_events
2023-02-17 13:46:08,258 - synapse.util.metrics - 176 - DEBUG - GET-14 - Exiting block typing.get_new_events
2023-02-17 13:46:08,259 - synapse.util.metrics - 176 - DEBUG - GET-14 - Exiting block ephemeral_by_room
2023-02-17 13:46:08,259 - synapse.storage.txn - 692 - DEBUG - GET-14 - [TXN START] {get_updated_tags-65}
2023-02-17 13:46:08,259 - synapse.storage.txn - 796 - DEBUG - GET-14 - [TXN END] {get_updated_tags-65} 0.000104 sec
2023-02-17 13:46:08,259 - synapse.handlers.sync - 1915 - DEBUG - GET-14 - no-oping sync
2023-02-17 13:46:08,259 - synapse.handlers.sync - 1504 - DEBUG - GET-14 - Fetching presence data
2023-02-17 13:46:08,259 - synapse.util.metrics - 163 - DEBUG - GET-14 - Entering block presence.get_new_events
2023-02-17 13:46:08,260 - synapse.util.metrics - 176 - DEBUG - GET-14 - Exiting block presence.get_new_events
2023-02-17 13:46:08,260 - synapse.util.metrics - 163 - DEBUG - GET-14 - Entering block _generate_sync_entry_for_device_list
2023-02-17 13:46:08,260 - synapse.util.metrics - 176 - DEBUG - GET-14 - Exiting block _generate_sync_entry_for_device_list
2023-02-17 13:46:08,260 - synapse.handlers.sync - 1520 - DEBUG - GET-14 - Fetching to-device data
2023-02-17 13:46:08,260 - synapse.handlers.sync - 1523 - DEBUG - GET-14 - Fetching OTK data
2023-02-17 13:46:08,260 - synapse.handlers.sync - 1552 - DEBUG - GET-14 - Sync response calculation complete
2023-02-17 13:46:08,260 - synapse.handlers.sync - 324 - DEBUG - GET-14 - Returning sync response for @alan:localhost
2023-02-17 13:46:08,260 - synapse.util.metrics - 163 - DEBUG - GET-14 - Entering block presence_update_states
2023-02-17 13:46:08,260 - synapse.util.metrics - 176 - DEBUG - GET-14 - Exiting block presence_update_states
2023-02-17 13:46:08,261 - synapse.rest.client.sync - 222 - DEBUG - GET-14 - Formatting events in sync response
2023-02-17 13:46:08,261 - synapse.rest.client.sync - 257 - DEBUG - GET-14 - building sync response dict
2023-02-17 13:46:08,261 - synapse.rest.client.sync - 211 - DEBUG - GET-14 - Event formatting complete
2023-02-17 13:46:08,261 - synapse.access.http.8008 - 460 - INFO - GET-14 - ::1 - 8008 - {@alan:localhost} Processed request: 30.014sec/0.000sec (0.000sec, 0.000sec) (0.001sec/0.001sec/4) 524B 200 "GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176883_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:46:08,278 - synapse.access.http.8008 - 415 - DEBUG - OPTIONS-15 - ::1 - 8008 - Received request: OPTIONS /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1
2023-02-17 13:46:08,279 - synapse.access.http.8008 - 460 - DEBUG - OPTIONS-15 - ::1 - 8008 - {None} Processed request: 0.001sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 0B 204 "OPTIONS /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:46:08,281 - synapse.access.http.8008 - 415 - DEBUG - GET-16 - ::1 - 8008 - Received request: GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1
2023-02-17 13:46:08,282 - synapse.rest.client.sync - 131 - DEBUG - GET-16 - /sync: user=@alan:localhost, timeout=30000, since='s3632_176884_0_724_1855_1_1174_293_0_1', set_presence='online', filter_id='1', device_id='FUJBEAPBLK'
2023-02-17 13:46:08,282 - synapse.util.metrics - 163 - DEBUG - GET-16 - Entering block presence_update_states
2023-02-17 13:46:08,282 - synapse.util.metrics - 176 - DEBUG - GET-16 - Exiting block presence_update_states
2023-02-17 13:46:08,282 - synapse.util.metrics - 163 - DEBUG - GET-16 - Entering block presence_update_states
2023-02-17 13:46:08,283 - synapse.util.metrics - 176 - DEBUG - GET-16 - Exiting block presence_update_states
2023-02-17 13:46:08,283 - synapse.util.caches.response_cache - 236 - DEBUG - GET-16 - [sync]: no cached result for [(@alan:localhost, 30000, 's3632_176884_0_724_1855_1_1174_293_0_1', '1', False, 'FUJBEAPBLK')], calculating new one
2023-02-17 13:46:08,283 - synapse.handlers.sync - 366 - DEBUG - GET-16 - Deleted 0 to-device messages up to 1174
2023-02-17 13:46:08,283 - synapse.handlers.sync - 1440 - DEBUG - GET-16 - Calculating sync response for @alan:localhost between StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176884, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1) and StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176884, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1)
2023-02-17 13:46:08,284 - synapse.handlers.sync - 1458 - DEBUG - GET-16 - Fetching account data
2023-02-17 13:46:08,284 - synapse.storage.txn - 692 - DEBUG - GET-16 - [TXN START] {get_updated_global_account_data_for_user-66}
2023-02-17 13:46:08,284 - synapse.storage.txn - 796 - DEBUG - GET-16 - [TXN END] {get_updated_global_account_data_for_user-66} 0.000219 sec
2023-02-17 13:46:08,285 - synapse.storage.txn - 692 - DEBUG - GET-16 - [TXN START] {have_push_rules_changed-67}
2023-02-17 13:46:08,285 - synapse.storage.txn - 796 - DEBUG - GET-16 - [TXN END] {have_push_rules_changed-67} 0.000135 sec
2023-02-17 13:46:08,285 - synapse.handlers.sync - 1481 - DEBUG - GET-16 - Fetching room data
2023-02-17 13:46:08,285 - synapse.storage.txn - 692 - DEBUG - GET-16 - [TXN START] {get_updated_room_account_data_for_user-68}
2023-02-17 13:46:08,286 - synapse.storage.txn - 796 - DEBUG - GET-16 - [TXN END] {get_updated_room_account_data_for_user-68} 0.000157 sec
2023-02-17 13:46:08,286 - synapse.util.metrics - 163 - DEBUG - GET-16 - Entering block ephemeral_by_room
2023-02-17 13:46:08,286 - synapse.util.metrics - 163 - DEBUG - GET-16 - Entering block typing.get_new_events
2023-02-17 13:46:08,286 - synapse.util.metrics - 176 - DEBUG - GET-16 - Exiting block typing.get_new_events
2023-02-17 13:46:08,286 - synapse.util.metrics - 176 - DEBUG - GET-16 - Exiting block ephemeral_by_room
2023-02-17 13:46:08,286 - synapse.storage.txn - 692 - DEBUG - GET-16 - [TXN START] {get_updated_tags-69}
2023-02-17 13:46:08,287 - synapse.storage.txn - 796 - DEBUG - GET-16 - [TXN END] {get_updated_tags-69} 0.000126 sec
2023-02-17 13:46:08,287 - synapse.handlers.sync - 1915 - DEBUG - GET-16 - no-oping sync
2023-02-17 13:46:08,287 - synapse.handlers.sync - 1504 - DEBUG - GET-16 - Fetching presence data
2023-02-17 13:46:08,287 - synapse.util.metrics - 163 - DEBUG - GET-16 - Entering block presence.get_new_events
2023-02-17 13:46:08,287 - synapse.util.metrics - 176 - DEBUG - GET-16 - Exiting block presence.get_new_events
2023-02-17 13:46:08,287 - synapse.util.metrics - 163 - DEBUG - GET-16 - Entering block _generate_sync_entry_for_device_list
2023-02-17 13:46:08,287 - synapse.util.metrics - 176 - DEBUG - GET-16 - Exiting block _generate_sync_entry_for_device_list
2023-02-17 13:46:08,287 - synapse.handlers.sync - 1520 - DEBUG - GET-16 - Fetching to-device data
2023-02-17 13:46:08,287 - synapse.handlers.sync - 1523 - DEBUG - GET-16 - Fetching OTK data
2023-02-17 13:46:08,287 - synapse.handlers.sync - 1552 - DEBUG - GET-16 - Sync response calculation complete
2023-02-17 13:46:08,287 - synapse.handlers.sync - 324 - DEBUG - GET-16 - Returning sync response for @alan:localhost
2023-02-17 13:46:08,287 - synapse.util.metrics - 163 - DEBUG - GET-16 - Entering block presence_update_states
2023-02-17 13:46:08,287 - synapse.util.metrics - 176 - DEBUG - GET-16 - Exiting block presence_update_states
2023-02-17 13:46:08,287 - synapse.rest.client.sync - 222 - DEBUG - GET-16 - Formatting events in sync response
2023-02-17 13:46:08,287 - synapse.rest.client.sync - 257 - DEBUG - GET-16 - building sync response dict
2023-02-17 13:46:08,288 - synapse.rest.client.sync - 211 - DEBUG - GET-16 - Event formatting complete
2023-02-17 13:46:08,288 - synapse.access.http.8008 - 460 - INFO - GET-16 - ::1 - 8008 - {@alan:localhost} Processed request: 0.007sec/0.000sec (0.000sec, 0.000sec) (0.001sec/0.001sec/4) 371B 200 "GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:46:08,299 - synapse.access.http.8008 - 415 - DEBUG - OPTIONS-17 - ::1 - 8008 - Received request: OPTIONS /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1
2023-02-17 13:46:08,299 - synapse.access.http.8008 - 460 - DEBUG - OPTIONS-17 - ::1 - 8008 - {None} Processed request: 0.000sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 0B 204 "OPTIONS /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:46:08,300 - synapse.access.http.8008 - 415 - DEBUG - GET-18 - ::1 - 8008 - Received request: GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1
2023-02-17 13:46:08,301 - synapse.rest.client.sync - 131 - DEBUG - GET-18 - /sync: user=@alan:localhost, timeout=30000, since='s3632_176884_0_724_1855_1_1174_293_0_1', set_presence='online', filter_id='1', device_id='FUJBEAPBLK'
2023-02-17 13:46:08,301 - synapse.util.metrics - 163 - DEBUG - GET-18 - Entering block presence_update_states
2023-02-17 13:46:08,301 - synapse.util.metrics - 176 - DEBUG - GET-18 - Exiting block presence_update_states
2023-02-17 13:46:08,301 - synapse.util.metrics - 163 - DEBUG - GET-18 - Entering block presence_update_states
2023-02-17 13:46:08,301 - synapse.util.metrics - 176 - DEBUG - GET-18 - Exiting block presence_update_states
2023-02-17 13:46:08,301 - synapse.util.caches.response_cache - 236 - DEBUG - GET-18 - [sync]: no cached result for [(@alan:localhost, 30000, 's3632_176884_0_724_1855_1_1174_293_0_1', '1', False, 'FUJBEAPBLK')], calculating new one
2023-02-17 13:46:08,301 - synapse.handlers.sync - 366 - DEBUG - GET-18 - Deleted 0 to-device messages up to 1174
2023-02-17 13:46:08,301 - synapse.handlers.sync - 1440 - DEBUG - GET-18 - Calculating sync response for @alan:localhost between StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176884, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1) and StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176884, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1)
2023-02-17 13:46:08,301 - synapse.handlers.sync - 1458 - DEBUG - GET-18 - Fetching account data
2023-02-17 13:46:08,301 - synapse.storage.txn - 692 - DEBUG - GET-18 - [TXN START] {get_updated_global_account_data_for_user-6a}
2023-02-17 13:46:08,302 - synapse.storage.txn - 796 - DEBUG - GET-18 - [TXN END] {get_updated_global_account_data_for_user-6a} 0.000093 sec
2023-02-17 13:46:08,302 - synapse.storage.txn - 692 - DEBUG - GET-18 - [TXN START] {have_push_rules_changed-6b}
2023-02-17 13:46:08,302 - synapse.storage.txn - 796 - DEBUG - GET-18 - [TXN END] {have_push_rules_changed-6b} 0.000073 sec
2023-02-17 13:46:08,302 - synapse.handlers.sync - 1481 - DEBUG - GET-18 - Fetching room data
2023-02-17 13:46:08,302 - synapse.storage.txn - 692 - DEBUG - GET-18 - [TXN START] {get_updated_room_account_data_for_user-6c}
2023-02-17 13:46:08,302 - synapse.storage.txn - 796 - DEBUG - GET-18 - [TXN END] {get_updated_room_account_data_for_user-6c} 0.000064 sec
2023-02-17 13:46:08,302 - synapse.util.metrics - 163 - DEBUG - GET-18 - Entering block ephemeral_by_room
2023-02-17 13:46:08,302 - synapse.util.metrics - 163 - DEBUG - GET-18 - Entering block typing.get_new_events
2023-02-17 13:46:08,302 - synapse.util.metrics - 176 - DEBUG - GET-18 - Exiting block typing.get_new_events
2023-02-17 13:46:08,302 - synapse.util.metrics - 176 - DEBUG - GET-18 - Exiting block ephemeral_by_room
2023-02-17 13:46:08,302 - synapse.storage.txn - 692 - DEBUG - GET-18 - [TXN START] {get_updated_tags-6d}
2023-02-17 13:46:08,303 - synapse.storage.txn - 796 - DEBUG - GET-18 - [TXN END] {get_updated_tags-6d} 0.000049 sec
2023-02-17 13:46:08,303 - synapse.handlers.sync - 1915 - DEBUG - GET-18 - no-oping sync
2023-02-17 13:46:08,303 - synapse.handlers.sync - 1504 - DEBUG - GET-18 - Fetching presence data
2023-02-17 13:46:08,303 - synapse.util.metrics - 163 - DEBUG - GET-18 - Entering block presence.get_new_events
2023-02-17 13:46:08,303 - synapse.util.metrics - 176 - DEBUG - GET-18 - Exiting block presence.get_new_events
2023-02-17 13:46:08,303 - synapse.util.metrics - 163 - DEBUG - GET-18 - Entering block _generate_sync_entry_for_device_list
2023-02-17 13:46:08,303 - synapse.util.metrics - 176 - DEBUG - GET-18 - Exiting block _generate_sync_entry_for_device_list
2023-02-17 13:46:08,303 - synapse.handlers.sync - 1520 - DEBUG - GET-18 - Fetching to-device data
2023-02-17 13:46:08,303 - synapse.handlers.sync - 1523 - DEBUG - GET-18 - Fetching OTK data
2023-02-17 13:46:08,303 - synapse.handlers.sync - 1552 - DEBUG - GET-18 - Sync response calculation complete
2023-02-17 13:46:08,303 - synapse.handlers.sync - 324 - DEBUG - GET-18 - Returning sync response for @alan:localhost
2023-02-17 13:46:08,303 - synapse.util.metrics - 163 - DEBUG - GET-18 - Entering block presence_update_states
2023-02-17 13:46:08,303 - synapse.util.metrics - 176 - DEBUG - GET-18 - Exiting block presence_update_states
2023-02-17 13:46:08,303 - synapse.rest.client.sync - 222 - DEBUG - GET-18 - Formatting events in sync response
2023-02-17 13:46:08,303 - synapse.rest.client.sync - 257 - DEBUG - GET-18 - building sync response dict
2023-02-17 13:46:08,303 - synapse.rest.client.sync - 211 - DEBUG - GET-18 - Event formatting complete
2023-02-17 13:46:08,303 - synapse.access.http.8008 - 460 - INFO - GET-18 - ::1 - 8008 - {@alan:localhost} Processed request: 0.003sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/4) 371B 200 "GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:46:08,308 - synapse.metrics._gc - 118 - DEBUG - sentinel - Collecting gc 0
2023-02-17 13:46:08,310 - synapse.access.http.8008 - 415 - DEBUG - OPTIONS-19 - ::1 - 8008 - Received request: OPTIONS /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1
2023-02-17 13:46:08,310 - synapse.access.http.8008 - 460 - DEBUG - OPTIONS-19 - ::1 - 8008 - {None} Processed request: 0.000sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 0B 204 "OPTIONS /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:46:08,311 - synapse.access.http.8008 - 415 - DEBUG - GET-20 - ::1 - 8008 - Received request: GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1
2023-02-17 13:46:08,311 - synapse.rest.client.sync - 131 - DEBUG - GET-20 - /sync: user=@alan:localhost, timeout=30000, since='s3632_176884_0_724_1855_1_1174_293_0_1', set_presence='online', filter_id='1', device_id='FUJBEAPBLK'
2023-02-17 13:46:08,311 - synapse.util.metrics - 163 - DEBUG - GET-20 - Entering block presence_update_states
2023-02-17 13:46:08,311 - synapse.util.metrics - 176 - DEBUG - GET-20 - Exiting block presence_update_states
2023-02-17 13:46:08,311 - synapse.util.metrics - 163 - DEBUG - GET-20 - Entering block presence_update_states
2023-02-17 13:46:08,311 - synapse.util.metrics - 176 - DEBUG - GET-20 - Exiting block presence_update_states
2023-02-17 13:46:08,311 - synapse.util.caches.response_cache - 236 - DEBUG - GET-20 - [sync]: no cached result for [(@alan:localhost, 30000, 's3632_176884_0_724_1855_1_1174_293_0_1', '1', False, 'FUJBEAPBLK')], calculating new one
2023-02-17 13:46:08,311 - synapse.handlers.sync - 366 - DEBUG - GET-20 - Deleted 0 to-device messages up to 1174
2023-02-17 13:46:08,311 - synapse.handlers.sync - 1440 - DEBUG - GET-20 - Calculating sync response for @alan:localhost between StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176884, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1) and StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176884, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1)
2023-02-17 13:46:08,311 - synapse.handlers.sync - 1458 - DEBUG - GET-20 - Fetching account data
2023-02-17 13:46:08,311 - synapse.storage.txn - 692 - DEBUG - GET-20 - [TXN START] {get_updated_global_account_data_for_user-6e}
2023-02-17 13:46:08,312 - synapse.storage.txn - 796 - DEBUG - GET-20 - [TXN END] {get_updated_global_account_data_for_user-6e} 0.000110 sec
2023-02-17 13:46:08,312 - synapse.storage.txn - 692 - DEBUG - GET-20 - [TXN START] {have_push_rules_changed-6f}
2023-02-17 13:46:08,312 - synapse.storage.txn - 796 - DEBUG - GET-20 - [TXN END] {have_push_rules_changed-6f} 0.000055 sec
2023-02-17 13:46:08,312 - synapse.handlers.sync - 1481 - DEBUG - GET-20 - Fetching room data
2023-02-17 13:46:08,312 - synapse.storage.txn - 692 - DEBUG - GET-20 - [TXN START] {get_updated_room_account_data_for_user-70}
2023-02-17 13:46:08,312 - synapse.storage.txn - 796 - DEBUG - GET-20 - [TXN END] {get_updated_room_account_data_for_user-70} 0.000057 sec
2023-02-17 13:46:08,312 - synapse.util.metrics - 163 - DEBUG - GET-20 - Entering block ephemeral_by_room
2023-02-17 13:46:08,312 - synapse.util.metrics - 163 - DEBUG - GET-20 - Entering block typing.get_new_events
2023-02-17 13:46:08,312 - synapse.util.metrics - 176 - DEBUG - GET-20 - Exiting block typing.get_new_events
2023-02-17 13:46:08,312 - synapse.util.metrics - 176 - DEBUG - GET-20 - Exiting block ephemeral_by_room
2023-02-17 13:46:08,312 - synapse.storage.txn - 692 - DEBUG - GET-20 - [TXN START] {get_updated_tags-71}
2023-02-17 13:46:08,312 - synapse.storage.txn - 796 - DEBUG - GET-20 - [TXN END] {get_updated_tags-71} 0.000045 sec
2023-02-17 13:46:08,312 - synapse.handlers.sync - 1915 - DEBUG - GET-20 - no-oping sync
2023-02-17 13:46:08,313 - synapse.handlers.sync - 1504 - DEBUG - GET-20 - Fetching presence data
2023-02-17 13:46:08,313 - synapse.util.metrics - 163 - DEBUG - GET-20 - Entering block presence.get_new_events
2023-02-17 13:46:08,313 - synapse.util.metrics - 176 - DEBUG - GET-20 - Exiting block presence.get_new_events
2023-02-17 13:46:08,313 - synapse.util.metrics - 163 - DEBUG - GET-20 - Entering block _generate_sync_entry_for_device_list
2023-02-17 13:46:08,313 - synapse.util.metrics - 176 - DEBUG - GET-20 - Exiting block _generate_sync_entry_for_device_list
2023-02-17 13:46:08,313 - synapse.handlers.sync - 1520 - DEBUG - GET-20 - Fetching to-device data
2023-02-17 13:46:08,313 - synapse.handlers.sync - 1523 - DEBUG - GET-20 - Fetching OTK data
2023-02-17 13:46:08,313 - synapse.handlers.sync - 1552 - DEBUG - GET-20 - Sync response calculation complete
2023-02-17 13:46:08,313 - synapse.handlers.sync - 324 - DEBUG - GET-20 - Returning sync response for @alan:localhost
2023-02-17 13:46:08,313 - synapse.util.metrics - 163 - DEBUG - GET-20 - Entering block presence_update_states
2023-02-17 13:46:08,313 - synapse.util.metrics - 176 - DEBUG - GET-20 - Exiting block presence_update_states
2023-02-17 13:46:08,313 - synapse.rest.client.sync - 222 - DEBUG - GET-20 - Formatting events in sync response
2023-02-17 13:46:08,313 - synapse.rest.client.sync - 257 - DEBUG - GET-20 - building sync response dict
2023-02-17 13:46:08,313 - synapse.rest.client.sync - 211 - DEBUG - GET-20 - Event formatting complete
2023-02-17 13:46:08,313 - synapse.access.http.8008 - 460 - INFO - GET-20 - ::1 - 8008 - {@alan:localhost} Processed request: 0.003sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/4) 371B 200 "GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:46:08,320 - synapse.access.http.8008 - 415 - DEBUG - OPTIONS-21 - ::1 - 8008 - Received request: OPTIONS /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1
2023-02-17 13:46:08,320 - synapse.access.http.8008 - 460 - DEBUG - OPTIONS-21 - ::1 - 8008 - {None} Processed request: 0.000sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 0B 204 "OPTIONS /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:46:08,321 - synapse.access.http.8008 - 415 - DEBUG - GET-22 - ::1 - 8008 - Received request: GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1
2023-02-17 13:46:08,321 - synapse.rest.client.sync - 131 - DEBUG - GET-22 - /sync: user=@alan:localhost, timeout=30000, since='s3632_176884_0_724_1855_1_1174_293_0_1', set_presence='online', filter_id='1', device_id='FUJBEAPBLK'
2023-02-17 13:46:08,321 - synapse.util.metrics - 163 - DEBUG - GET-22 - Entering block presence_update_states
2023-02-17 13:46:08,321 - synapse.util.metrics - 176 - DEBUG - GET-22 - Exiting block presence_update_states
2023-02-17 13:46:08,321 - synapse.util.metrics - 163 - DEBUG - GET-22 - Entering block presence_update_states
2023-02-17 13:46:08,321 - synapse.util.metrics - 176 - DEBUG - GET-22 - Exiting block presence_update_states
2023-02-17 13:46:08,321 - synapse.util.caches.response_cache - 236 - DEBUG - GET-22 - [sync]: no cached result for [(@alan:localhost, 30000, 's3632_176884_0_724_1855_1_1174_293_0_1', '1', False, 'FUJBEAPBLK')], calculating new one
2023-02-17 13:46:08,321 - synapse.handlers.sync - 366 - DEBUG - GET-22 - Deleted 0 to-device messages up to 1174
2023-02-17 13:46:08,321 - synapse.handlers.sync - 1440 - DEBUG - GET-22 - Calculating sync response for @alan:localhost between StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176884, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1) and StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176884, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1)
2023-02-17 13:46:08,321 - synapse.handlers.sync - 1458 - DEBUG - GET-22 - Fetching account data
2023-02-17 13:46:08,321 - synapse.storage.txn - 692 - DEBUG - GET-22 - [TXN START] {get_updated_global_account_data_for_user-72}
2023-02-17 13:46:08,321 - synapse.storage.txn - 796 - DEBUG - GET-22 - [TXN END] {get_updated_global_account_data_for_user-72} 0.000122 sec
2023-02-17 13:46:08,322 - synapse.storage.txn - 692 - DEBUG - GET-22 - [TXN START] {have_push_rules_changed-73}
2023-02-17 13:46:08,322 - synapse.storage.txn - 796 - DEBUG - GET-22 - [TXN END] {have_push_rules_changed-73} 0.000059 sec
2023-02-17 13:46:08,322 - synapse.handlers.sync - 1481 - DEBUG - GET-22 - Fetching room data
2023-02-17 13:46:08,322 - synapse.storage.txn - 692 - DEBUG - GET-22 - [TXN START] {get_updated_room_account_data_for_user-74}
2023-02-17 13:46:08,322 - synapse.storage.txn - 796 - DEBUG - GET-22 - [TXN END] {get_updated_room_account_data_for_user-74} 0.000054 sec
2023-02-17 13:46:08,322 - synapse.util.metrics - 163 - DEBUG - GET-22 - Entering block ephemeral_by_room
2023-02-17 13:46:08,322 - synapse.util.metrics - 163 - DEBUG - GET-22 - Entering block typing.get_new_events
2023-02-17 13:46:08,322 - synapse.util.metrics - 176 - DEBUG - GET-22 - Exiting block typing.get_new_events
2023-02-17 13:46:08,322 - synapse.util.metrics - 176 - DEBUG - GET-22 - Exiting block ephemeral_by_room
2023-02-17 13:46:08,322 - synapse.storage.txn - 692 - DEBUG - GET-22 - [TXN START] {get_updated_tags-75}
2023-02-17 13:46:08,322 - synapse.storage.txn - 796 - DEBUG - GET-22 - [TXN END] {get_updated_tags-75} 0.000040 sec
2023-02-17 13:46:08,322 - synapse.handlers.sync - 1915 - DEBUG - GET-22 - no-oping sync
2023-02-17 13:46:08,322 - synapse.handlers.sync - 1504 - DEBUG - GET-22 - Fetching presence data
2023-02-17 13:46:08,322 - synapse.util.metrics - 163 - DEBUG - GET-22 - Entering block presence.get_new_events
2023-02-17 13:46:08,322 - synapse.util.metrics - 176 - DEBUG - GET-22 - Exiting block presence.get_new_events
2023-02-17 13:46:08,323 - synapse.util.metrics - 163 - DEBUG - GET-22 - Entering block _generate_sync_entry_for_device_list
2023-02-17 13:46:08,323 - synapse.util.metrics - 176 - DEBUG - GET-22 - Exiting block _generate_sync_entry_for_device_list
2023-02-17 13:46:08,323 - synapse.handlers.sync - 1520 - DEBUG - GET-22 - Fetching to-device data
2023-02-17 13:46:08,323 - synapse.handlers.sync - 1523 - DEBUG - GET-22 - Fetching OTK data
2023-02-17 13:46:08,323 - synapse.handlers.sync - 1552 - DEBUG - GET-22 - Sync response calculation complete
2023-02-17 13:46:08,323 - synapse.handlers.sync - 324 - DEBUG - GET-22 - Returning sync response for @alan:localhost
2023-02-17 13:46:08,323 - synapse.util.metrics - 163 - DEBUG - GET-22 - Entering block presence_update_states
2023-02-17 13:46:08,323 - synapse.util.metrics - 176 - DEBUG - GET-22 - Exiting block presence_update_states
2023-02-17 13:46:08,323 - synapse.rest.client.sync - 222 - DEBUG - GET-22 - Formatting events in sync response
2023-02-17 13:46:08,323 - synapse.rest.client.sync - 257 - DEBUG - GET-22 - building sync response dict
2023-02-17 13:46:08,323 - synapse.rest.client.sync - 211 - DEBUG - GET-22 - Event formatting complete
2023-02-17 13:46:08,323 - synapse.access.http.8008 - 460 - INFO - GET-22 - ::1 - 8008 - {@alan:localhost} Processed request: 0.002sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/4) 371B 200 "GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:46:08,328 - synapse.access.http.8008 - 415 - DEBUG - OPTIONS-23 - ::1 - 8008 - Received request: OPTIONS /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1
2023-02-17 13:46:08,329 - synapse.access.http.8008 - 460 - DEBUG - OPTIONS-23 - ::1 - 8008 - {None} Processed request: 0.000sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 0B 204 "OPTIONS /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
2023-02-17 13:46:08,329 - synapse.access.http.8008 - 415 - DEBUG - GET-24 - ::1 - 8008 - Received request: GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1
2023-02-17 13:46:08,329 - synapse.rest.client.sync - 131 - DEBUG - GET-24 - /sync: user=@alan:localhost, timeout=30000, since='s3632_176884_0_724_1855_1_1174_293_0_1', set_presence='online', filter_id='1', device_id='FUJBEAPBLK'
2023-02-17 13:46:08,330 - synapse.util.metrics - 163 - DEBUG - GET-24 - Entering block presence_update_states
2023-02-17 13:46:08,330 - synapse.util.metrics - 176 - DEBUG - GET-24 - Exiting block presence_update_states
2023-02-17 13:46:08,330 - synapse.util.metrics - 163 - DEBUG - GET-24 - Entering block presence_update_states
2023-02-17 13:46:08,330 - synapse.util.metrics - 176 - DEBUG - GET-24 - Exiting block presence_update_states
2023-02-17 13:46:08,330 - synapse.util.caches.response_cache - 236 - DEBUG - GET-24 - [sync]: no cached result for [(@alan:localhost, 30000, 's3632_176884_0_724_1855_1_1174_293_0_1', '1', False, 'FUJBEAPBLK')], calculating new one
2023-02-17 13:46:08,330 - synapse.handlers.sync - 366 - DEBUG - GET-24 - Deleted 0 to-device messages up to 1174
2023-02-17 13:46:08,330 - synapse.handlers.sync - 1440 - DEBUG - GET-24 - Calculating sync response for @alan:localhost between StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176884, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1) and StreamToken(room_key=RoomStreamToken(topological=None, stream=3632, instance_map=frozendict.frozendict({})), presence_key=176884, typing_key=0, receipt_key=724, account_data_key=1855, push_rules_key=1, to_device_key=1174, device_list_key=293, groups_key=0, un_partial_stated_rooms_key=1)
2023-02-17 13:46:08,330 - synapse.handlers.sync - 1458 - DEBUG - GET-24 - Fetching account data
2023-02-17 13:46:08,330 - synapse.storage.txn - 692 - DEBUG - GET-24 - [TXN START] {get_updated_global_account_data_for_user-76}
2023-02-17 13:46:08,330 - synapse.storage.txn - 796 - DEBUG - GET-24 - [TXN END] {get_updated_global_account_data_for_user-76} 0.000086 sec
2023-02-17 13:46:08,330 - synapse.storage.txn - 692 - DEBUG - GET-24 - [TXN START] {have_push_rules_changed-77}
2023-02-17 13:46:08,330 - synapse.storage.txn - 796 - DEBUG - GET-24 - [TXN END] {have_push_rules_changed-77} 0.000050 sec
2023-02-17 13:46:08,331 - synapse.handlers.sync - 1481 - DEBUG - GET-24 - Fetching room data
2023-02-17 13:46:08,331 - synapse.storage.txn - 692 - DEBUG - GET-24 - [TXN START] {get_updated_room_account_data_for_user-78}
2023-02-17 13:46:08,331 - synapse.storage.txn - 796 - DEBUG - GET-24 - [TXN END] {get_updated_room_account_data_for_user-78} 0.000040 sec
2023-02-17 13:46:08,331 - synapse.util.metrics - 163 - DEBUG - GET-24 - Entering block ephemeral_by_room
2023-02-17 13:46:08,331 - synapse.util.metrics - 163 - DEBUG - GET-24 - Entering block typing.get_new_events
2023-02-17 13:46:08,331 - synapse.util.metrics - 176 - DEBUG - GET-24 - Exiting block typing.get_new_events
2023-02-17 13:46:08,331 - synapse.util.metrics - 176 - DEBUG - GET-24 - Exiting block ephemeral_by_room
2023-02-17 13:46:08,331 - synapse.storage.txn - 692 - DEBUG - GET-24 - [TXN START] {get_updated_tags-79}
2023-02-17 13:46:08,331 - synapse.storage.txn - 796 - DEBUG - GET-24 - [TXN END] {get_updated_tags-79} 0.000051 sec
2023-02-17 13:46:08,331 - synapse.handlers.sync - 1915 - DEBUG - GET-24 - no-oping sync
2023-02-17 13:46:08,331 - synapse.handlers.sync - 1504 - DEBUG - GET-24 - Fetching presence data
2023-02-17 13:46:08,331 - synapse.util.metrics - 163 - DEBUG - GET-24 - Entering block presence.get_new_events
2023-02-17 13:46:08,331 - synapse.util.metrics - 176 - DEBUG - GET-24 - Exiting block presence.get_new_events
2023-02-17 13:46:08,331 - synapse.util.metrics - 163 - DEBUG - GET-24 - Entering block _generate_sync_entry_for_device_list
2023-02-17 13:46:08,331 - synapse.util.metrics - 176 - DEBUG - GET-24 - Exiting block _generate_sync_entry_for_device_list
2023-02-17 13:46:08,331 - synapse.handlers.sync - 1520 - DEBUG - GET-24 - Fetching to-device data
2023-02-17 13:46:08,331 - synapse.handlers.sync - 1523 - DEBUG - GET-24 - Fetching OTK data
2023-02-17 13:46:08,331 - synapse.handlers.sync - 1552 - DEBUG - GET-24 - Sync response calculation complete
2023-02-17 13:46:08,331 - synapse.handlers.sync - 324 - DEBUG - GET-24 - Returning sync response for @alan:localhost
2023-02-17 13:46:08,332 - synapse.util.metrics - 163 - DEBUG - GET-24 - Entering block presence_update_states
2023-02-17 13:46:08,332 - synapse.util.metrics - 176 - DEBUG - GET-24 - Exiting block presence_update_states
2023-02-17 13:46:08,332 - synapse.rest.client.sync - 222 - DEBUG - GET-24 - Formatting events in sync response
2023-02-17 13:46:08,332 - synapse.rest.client.sync - 257 - DEBUG - GET-24 - building sync response dict
2023-02-17 13:46:08,332 - synapse.rest.client.sync - 211 - DEBUG - GET-24 - Event formatting complete
2023-02-17 13:46:08,332 - synapse.access.http.8008 - 460 - INFO - GET-24 - ::1 - 8008 - {@alan:localhost} Processed request: 0.002sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/4) 371B 200 "GET /_matrix/client/r0/sync?filter=1&timeout=30000&since=s3632_176884_0_724_1855_1_1174_293_0_1 HTTP/1.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36" [0 dbevts]
clokep
commented
1 year ago From where that's returning it sounds like it might be due to #14973 😢
Are you using any filters?
dbkr
commented
1 year ago This is a fairly boring element sync request, so the filter is {"room":{"state":{"lazy_load_members":true},"timeline":{"unread_thread_notifications":true}}}
reivilibre
commented
1 year ago Is this consistently reproducible on your dev setup?
dbkr
commented
1 year ago Just tried again but I can't repro it now. I'm not sure what changed.
reivilibre
commented
1 year ago Shame, I'm struggling to make sense of the logs but was hoping we might have a reproducible case available in a test environment that could be passed around, guess not though
ThomasHalwax
commented
1 year ago I'm facing the same problem. Dockerized Synapse v1.78.0 on my dev machine, completely idle. My sync code went crazy so I tried to reproduce the issue using curl: same problem:
## first request
2023-03-07 13:27:58,319 - synapse.access.http.8008 - 415 - DEBUG - GET-27 - ::ffff:172.17.0.1 - 8008 - Received request: GET /_matrix/client/v3/sync?timeout=30000&since=s20535_72983_0_62_800_1_10_553_0_1
2023-03-07 13:27:58,319 - synapse.rest.client.sync - 131 - DEBUG - GET-27 - /sync: user=@sylvester:thomass-macbook-pro.local, timeout=30000, since='s20535_72983_0_62_800_1_10_553_0_1', set_presence='online', filter_id=None, device_id='LAPTOP'
2023-03-07 13:27:58,319 - synapse.util.metrics - 163 - DEBUG - GET-27 - Entering block presence_update_states
2023-03-07 13:27:58,319 - synapse.util.metrics - 176 - DEBUG - GET-27 - Exiting block presence_update_states
2023-03-07 13:27:58,320 - synapse.util.metrics - 163 - DEBUG - GET-27 - Entering block presence_update_states
2023-03-07 13:27:58,320 - synapse.util.metrics - 176 - DEBUG - GET-27 - Exiting block presence_update_states
2023-03-07 13:27:58,320 - synapse.util.caches.response_cache - 236 - DEBUG - GET-27 - [sync]: no cached result for [(@sylvester:thomass-macbook-pro.local, 30000, 's20535_72983_0_62_800_1_10_553_0_1', None, False, 'LAPTOP')], calculating new one
2023-03-07 13:27:58,320 - synapse.storage.txn - 692 - DEBUG - GET-27 - [TXN START] {delete_messages_for_device-ea}
2023-03-07 13:27:58,321 - synapse.storage.txn - 796 - DEBUG - GET-27 - [TXN END] {delete_messages_for_device-ea} 0.000186 sec
2023-03-07 13:27:58,321 - synapse.handlers.sync - 366 - DEBUG - GET-27 - Deleted 0 to-device messages up to 10
2023-03-07 13:27:58,322 - synapse.handlers.sync - 1440 - DEBUG - GET-27 - Calculating sync response for @sylvester:thomass-macbook-pro.local between StreamToken(room_key=RoomStreamToken(topological=None, stream=20535, instance_map=frozendict.frozendict({})), presence_key=72983, typing_key=0, receipt_key=62, account_data_key=800, push_rules_key=1, to_device_key=10, device_list_key=553, groups_key=0, un_partial_stated_rooms_key=1) and StreamToken(room_key=RoomStreamToken(topological=None, stream=20535, instance_map=frozendict.frozendict({})), presence_key=72983, typing_key=0, receipt_key=62, account_data_key=800, push_rules_key=1, to_device_key=10, device_list_key=553, groups_key=0, un_partial_stated_rooms_key=1)
2023-03-07 13:27:58,322 - synapse.handlers.sync - 1458 - DEBUG - GET-27 - Fetching account data
2023-03-07 13:27:58,322 - synapse.storage.txn - 692 - DEBUG - GET-27 - [TXN START] {get_updated_global_account_data_for_user-eb}
2023-03-07 13:27:58,322 - synapse.storage.txn - 796 - DEBUG - GET-27 - [TXN END] {get_updated_global_account_data_for_user-eb} 0.000255 sec
2023-03-07 13:27:58,323 - synapse.storage.txn - 692 - DEBUG - GET-27 - [TXN START] {have_push_rules_changed-ec}
2023-03-07 13:27:58,323 - synapse.storage.txn - 796 - DEBUG - GET-27 - [TXN END] {have_push_rules_changed-ec} 0.000171 sec
2023-03-07 13:27:58,323 - synapse.handlers.sync - 1481 - DEBUG - GET-27 - Fetching room data
2023-03-07 13:27:58,324 - synapse.storage.txn - 692 - DEBUG - GET-27 - [TXN START] {get_updated_room_account_data_for_user-ed}
2023-03-07 13:27:58,324 - synapse.storage.txn - 796 - DEBUG - GET-27 - [TXN END] {get_updated_room_account_data_for_user-ed} 0.000161 sec
2023-03-07 13:27:58,324 - synapse.util.metrics - 163 - DEBUG - GET-27 - Entering block ephemeral_by_room
2023-03-07 13:27:58,324 - synapse.util.metrics - 163 - DEBUG - GET-27 - Entering block typing.get_new_events
2023-03-07 13:27:58,324 - synapse.util.metrics - 176 - DEBUG - GET-27 - Exiting block typing.get_new_events
2023-03-07 13:27:58,324 - synapse.util.metrics - 176 - DEBUG - GET-27 - Exiting block ephemeral_by_room
2023-03-07 13:27:58,325 - synapse.storage.txn - 692 - DEBUG - GET-27 - [TXN START] {get_updated_tags-ee}
2023-03-07 13:27:58,325 - synapse.storage.txn - 796 - DEBUG - GET-27 - [TXN END] {get_updated_tags-ee} 0.000200 sec
2023-03-07 13:27:58,325 - synapse.handlers.sync - 1915 - DEBUG - GET-27 - no-oping sync
2023-03-07 13:27:58,325 - synapse.handlers.sync - 1504 - DEBUG - GET-27 - Fetching presence data
2023-03-07 13:27:58,325 - synapse.util.metrics - 163 - DEBUG - GET-27 - Entering block presence.get_new_events
2023-03-07 13:27:58,326 - synapse.util.metrics - 176 - DEBUG - GET-27 - Exiting block presence.get_new_events
2023-03-07 13:27:58,326 - synapse.util.metrics - 163 - DEBUG - GET-27 - Entering block _generate_sync_entry_for_device_list
2023-03-07 13:27:58,326 - synapse.util.metrics - 176 - DEBUG - GET-27 - Exiting block _generate_sync_entry_for_device_list
2023-03-07 13:27:58,326 - synapse.handlers.sync - 1520 - DEBUG - GET-27 - Fetching to-device data
2023-03-07 13:27:58,326 - synapse.handlers.sync - 1523 - DEBUG - GET-27 - Fetching OTK data
2023-03-07 13:27:58,326 - synapse.handlers.sync - 1552 - DEBUG - GET-27 - Sync response calculation complete
2023-03-07 13:27:58,326 - synapse.handlers.sync - 324 - DEBUG - GET-27 - Returning sync response for @sylvester:thomass-macbook-pro.local
2023-03-07 13:27:58,326 - synapse.util.metrics - 163 - DEBUG - GET-27 - Entering block presence_update_states
2023-03-07 13:27:58,327 - synapse.util.metrics - 176 - DEBUG - GET-27 - Exiting block presence_update_states
2023-03-07 13:27:58,327 - synapse.rest.client.sync - 222 - DEBUG - GET-27 - Formatting events in sync response
2023-03-07 13:27:58,327 - synapse.rest.client.sync - 257 - DEBUG - GET-27 - building sync response dict
2023-03-07 13:27:58,327 - synapse.rest.client.sync - 211 - DEBUG - GET-27 - Event formatting complete
2023-03-07 13:27:58,328 - synapse.access.http.8008 - 460 - INFO - GET-27 - ::ffff:172.17.0.1 - 8008 - {@sylvester:thomass-macbook-pro.local} Processed request: 0.008sec/0.000sec (0.002sec, 0.002sec) (0.001sec/0.001sec/5) 1170B 200 "GET /_matrix/client/v3/sync?timeout=30000&since=s20535_72983_0_62_800_1_10_553_0_1 HTTP/1.1" "curl/7.86.0" [0 dbevts]
2023-03-07 13:27:58,404 - synapse.metrics._gc - 118 - DEBUG - sentinel - Collecting gc 0
2023-03-07 13:28:02,901 - synapse.storage.txn - 692 - DEBUG - prune_old_user_ips-58 - [TXN START] {_prune_old_user_ips-ef}
2023-03-07 13:28:02,901 - synapse.storage.txn - 796 - DEBUG - prune_old_user_ips-58 - [TXN END] {_prune_old_user_ips-ef} 0.000396 sec
2023-03-07 13:28:03,097 - synapse.handlers.typing - 100 - DEBUG - typing._handle_timeouts-58 - Checking for typing timeouts
2023-03-07 13:28:03,098 - synapse.handlers.presence - 909 - DEBUG - handle_presence_timeouts-52 - Handling presence timeouts
2023-03-07 13:28:03,098 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-52 - Entering block presence_update_states
2023-03-07 13:28:03,098 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-52 - Exiting block presence_update_states
2023-03-07 13:28:07,625 - synapse.access.http.8008 - 415 - DEBUG - GET-28 - ::ffff:127.0.0.1 - 8008 - Received request: GET /health
2023-03-07 13:28:07,625 - synapse.access.http.8008 - 460 - DEBUG - GET-28 - ::ffff:127.0.0.1 - 8008 - {None} Processed request: 0.000sec/-0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 2B 200 "GET /health HTTP/1.1" "curl/7.74.0" [0 dbevts]
2023-03-07 13:28:07,897 - synapse.storage.txn - 692 - DEBUG - _cleanup_old_transaction_ids-0 - [TXN START] {_cleanup_old_transaction_ids-f0}
2023-03-07 13:28:07,898 - synapse.storage.txn - 796 - DEBUG - _cleanup_old_transaction_ids-0 - [TXN END] {_cleanup_old_transaction_ids-f0} 0.000929 sec
2023-03-07 13:28:07,899 - synapse.storage.txn - 692 - DEBUG - _get_stats_for_federation_staging-9 - [TXN START] {_get_stats_for_federation_staging-f1}
2023-03-07 13:28:07,899 - synapse.storage.txn - 796 - DEBUG - _get_stats_for_federation_staging-9 - [TXN END] {_get_stats_for_federation_staging-f1} 0.000373 sec
2023-03-07 13:28:07,899 - synapse.storage.txn - 692 - DEBUG - _censor_redactions-0 - [TXN START] {_censor_redactions_fetch-f2}
2023-03-07 13:28:07,900 - synapse.storage.txn - 796 - DEBUG - _censor_redactions-0 - [TXN END] {_censor_redactions_fetch-f2} 0.001172 sec
2023-03-07 13:28:07,901 - synapse.storage.txn - 692 - DEBUG - prune_old_user_ips-59 - [TXN START] {_prune_old_user_ips-f3}
2023-03-07 13:28:07,901 - synapse.storage.txn - 796 - DEBUG - prune_old_user_ips-59 - [TXN END] {_prune_old_user_ips-f3} 0.000696 sec
2023-03-07 13:28:07,902 - synapse.storage.txn - 692 - DEBUG - _censor_redactions-0 - [TXN START] {_update_censor_txn-f4}
2023-03-07 13:28:07,902 - synapse.storage.txn - 796 - DEBUG - _censor_redactions-0 - [TXN END] {_update_censor_txn-f4} 0.000555 sec
2023-03-07 13:28:08,031 - synapse.storage.txn - 692 - DEBUG - rotate_notifs-9 - [TXN START] {_handle_new_receipts_for_notifs_txn-f5}
2023-03-07 13:28:08,031 - synapse.storage.txn - 796 - DEBUG - rotate_notifs-9 - [TXN END] {_handle_new_receipts_for_notifs_txn-f5} 0.000446 sec
2023-03-07 13:28:08,032 - synapse.storage.txn - 692 - DEBUG - rotate_notifs-9 - [TXN START] {_rotate_notifs-f6}
2023-03-07 13:28:08,032 - synapse.storage.txn - 796 - DEBUG - rotate_notifs-9 - [TXN END] {_rotate_notifs-f6} 0.000333 sec
2023-03-07 13:28:08,033 - synapse.storage.txn - 692 - DEBUG - rotate_notifs-9 - [TXN START] {simple_select_one_onecol-f7}
2023-03-07 13:28:08,033 - synapse.storage.txn - 796 - DEBUG - rotate_notifs-9 - [TXN END] {simple_select_one_onecol-f7} 0.000191 sec
2023-03-07 13:28:08,034 - synapse.storage.txn - 692 - DEBUG - rotate_notifs-9 - [TXN START] {_remove_old_push_actions_that_have_rotated-f8}
2023-03-07 13:28:08,034 - synapse.storage.txn - 796 - DEBUG - rotate_notifs-9 - [TXN END] {_remove_old_push_actions_that_have_rotated-f8} 0.000205 sec
2023-03-07 13:28:08,071 - synapse.storage.txn - 692 - DEBUG - expire_old_sessions-0 - [TXN START] {delete_old_ui_auth_sessions-f9}
2023-03-07 13:28:08,071 - synapse.storage.txn - 796 - DEBUG - expire_old_sessions-0 - [TXN END] {delete_old_ui_auth_sessions-f9} 0.000425 sec
2023-03-07 13:28:08,096 - synapse.util.caches.expiringcache - 189 - DEBUG - prune_cache_get_pdu_cache-4 - [get_pdu_cache] _prune_cache before: 0, after len: 0
2023-03-07 13:28:08,096 - synapse.util.caches.expiringcache - 189 - DEBUG - prune_cache_get_room_hierarchy_cache-1 - [get_room_hierarchy_cache] _prune_cache before: 0, after len: 0
2023-03-07 13:28:08,097 - synapse.handlers.typing - 100 - DEBUG - typing._handle_timeouts-59 - Checking for typing timeouts
2023-03-07 13:28:08,097 - synapse.storage.txn - 692 - DEBUG - _maybe_retry_device_resync-9 - [TXN START] {get_user_ids_requiring_device_list_resync-fa}
2023-03-07 13:28:08,097 - synapse.handlers.presence - 797 - INFO - persist_presence_changes-3 - Persisting 1 unpersisted presence updates
2023-03-07 13:28:08,097 - synapse.storage.txn - 796 - DEBUG - _maybe_retry_device_resync-9 - [TXN END] {get_user_ids_requiring_device_list_resync-fa} 0.000476 sec
2023-03-07 13:28:08,098 - synapse.handlers.presence - 909 - DEBUG - handle_presence_timeouts-53 - Handling presence timeouts
2023-03-07 13:28:08,098 - synapse.storage.txn - 692 - DEBUG - send_dummy_events_to_fill_extremities-0 - [TXN START] {get_rooms_with_many_extremities-fb}
2023-03-07 13:28:08,099 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-53 - Entering block presence_update_states
2023-03-07 13:28:08,099 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-53 - Exiting block presence_update_states
2023-03-07 13:28:08,102 - synapse.storage.txn - 796 - DEBUG - send_dummy_events_to_fill_extremities-0 - [TXN END] {get_rooms_with_many_extremities-fb} 0.003897 sec
2023-03-07 13:28:08,102 - synapse.storage.txn - 692 - DEBUG - persist_presence_changes-3 - [TXN START] {update_presence-fc}
2023-03-07 13:28:08,104 - synapse.metrics._gc - 118 - DEBUG - sentinel - Collecting gc 0
2023-03-07 13:28:08,106 - synapse.storage.txn - 796 - DEBUG - persist_presence_changes-3 - [TXN END] {update_presence-fc} 0.003619 sec
2023-03-07 13:28:08,107 - synapse.util.metrics - 163 - DEBUG - user_directory.notify_new_event-12 - Entering block user_dir_delta
2023-03-07 13:28:08,107 - synapse.util.metrics - 176 - DEBUG - user_directory.notify_new_event-12 - Exiting block user_dir_delta
2023-03-07 13:28:08,107 - synapse.util.metrics - 163 - DEBUG - presence.notify_new_event-11 - Entering block presence_delta
2023-03-07 13:28:08,107 - synapse.util.metrics - 176 - DEBUG - presence.notify_new_event-11 - Exiting block presence_delta
2023-03-07 13:28:08,108 - synapse.util.caches.lrucache - 134 - DEBUG - LruCache._expire_old_entries-9 - Searching for stale caches
2023-03-07 13:28:08,109 - synapse.util.caches.lrucache - 212 - INFO - LruCache._expire_old_entries-9 - Dropped 0 items from caches
2023-03-07 13:28:08,121 - synapse.storage.txn - 692 - DEBUG - update_recently_accessed_media-4 - [TXN START] {update_cached_last_access_time-fd}
2023-03-07 13:28:08,121 - synapse.storage.txn - 796 - DEBUG - update_recently_accessed_media-4 - [TXN END] {update_cached_last_access_time-fd} 0.000204 sec
2023-03-07 13:28:08,152 - synapse.storage.TIME - 606 - DEBUG - sentinel - Total database time: 0.149% {get_rooms_with_many_extremities(1): 0.039%, update_presence(1): 0.036%, _censor_redactions_fetch(1): 0.012%}
2023-03-07 13:28:08,154 - synapse.storage.txn - 692 - DEBUG - common_usage_metrics_update_gauges-1 - [TXN START] {count_daily_users-fe}
2023-03-07 13:28:08,154 - synapse.storage.txn - 796 - DEBUG - common_usage_metrics_update_gauges-1 - [TXN END] {count_daily_users-fe} 0.000187 sec
2023-03-07 13:28:08,154 - synapse.storage.txn - 692 - DEBUG - generate_user_daily_visits-0 - [TXN START] {generate_user_daily_visits-ff}
2023-03-07 13:28:08,156 - synapse.storage.txn - 796 - DEBUG - generate_user_daily_visits-0 - [TXN END] {generate_user_daily_visits-ff} 0.001374 sec
## call returns immediately
## making second request with the same streamToken
2023-03-07 13:28:10,196 - synapse.access.http.8008 - 415 - DEBUG - GET-29 - ::ffff:172.17.0.1 - 8008 - Received request: GET /_matrix/client/v3/sync?timeout=30000&since=s20535_72983_0_62_800_1_10_553_0_1
2023-03-07 13:28:10,196 - synapse.rest.client.sync - 131 - DEBUG - GET-29 - /sync: user=@sylvester:thomass-macbook-pro.local, timeout=30000, since='s20535_72983_0_62_800_1_10_553_0_1', set_presence='online', filter_id=None, device_id='LAPTOP'
2023-03-07 13:28:10,196 - synapse.util.metrics - 163 - DEBUG - GET-29 - Entering block presence_update_states
2023-03-07 13:28:10,196 - synapse.util.metrics - 176 - DEBUG - GET-29 - Exiting block presence_update_states
2023-03-07 13:28:10,196 - synapse.util.metrics - 163 - DEBUG - GET-29 - Entering block presence_update_states
2023-03-07 13:28:10,197 - synapse.util.metrics - 176 - DEBUG - GET-29 - Exiting block presence_update_states
2023-03-07 13:28:10,197 - synapse.util.caches.response_cache - 236 - DEBUG - GET-29 - [sync]: no cached result for [(@sylvester:thomass-macbook-pro.local, 30000, 's20535_72983_0_62_800_1_10_553_0_1', None, False, 'LAPTOP')], calculating new one
2023-03-07 13:28:10,197 - synapse.storage.txn - 692 - DEBUG - GET-29 - [TXN START] {delete_messages_for_device-100}
2023-03-07 13:28:10,198 - synapse.storage.txn - 796 - DEBUG - GET-29 - [TXN END] {delete_messages_for_device-100} 0.000213 sec
2023-03-07 13:28:10,198 - synapse.handlers.sync - 366 - DEBUG - GET-29 - Deleted 0 to-device messages up to 10
2023-03-07 13:28:10,199 - synapse.handlers.sync - 1440 - DEBUG - GET-29 - Calculating sync response for @sylvester:thomass-macbook-pro.local between StreamToken(room_key=RoomStreamToken(topological=None, stream=20535, instance_map=frozendict.frozendict({})), presence_key=72983, typing_key=0, receipt_key=62, account_data_key=800, push_rules_key=1, to_device_key=10, device_list_key=553, groups_key=0, un_partial_stated_rooms_key=1) and StreamToken(room_key=RoomStreamToken(topological=None, stream=20535, instance_map=frozendict.frozendict({})), presence_key=72984, typing_key=0, receipt_key=62, account_data_key=800, push_rules_key=1, to_device_key=10, device_list_key=553, groups_key=0, un_partial_stated_rooms_key=1)
2023-03-07 13:28:10,199 - synapse.handlers.sync - 1458 - DEBUG - GET-29 - Fetching account data
2023-03-07 13:28:10,199 - synapse.storage.txn - 692 - DEBUG - GET-29 - [TXN START] {get_updated_global_account_data_for_user-101}
2023-03-07 13:28:10,199 - synapse.storage.txn - 796 - DEBUG - GET-29 - [TXN END] {get_updated_global_account_data_for_user-101} 0.000255 sec
2023-03-07 13:28:10,200 - synapse.storage.txn - 692 - DEBUG - GET-29 - [TXN START] {have_push_rules_changed-102}
2023-03-07 13:28:10,200 - synapse.storage.txn - 796 - DEBUG - GET-29 - [TXN END] {have_push_rules_changed-102} 0.000336 sec
2023-03-07 13:28:10,201 - synapse.handlers.sync - 1481 - DEBUG - GET-29 - Fetching room data
2023-03-07 13:28:10,201 - synapse.storage.txn - 692 - DEBUG - GET-29 - [TXN START] {get_updated_room_account_data_for_user-103}
2023-03-07 13:28:10,201 - synapse.storage.txn - 796 - DEBUG - GET-29 - [TXN END] {get_updated_room_account_data_for_user-103} 0.000160 sec
2023-03-07 13:28:10,201 - synapse.util.metrics - 163 - DEBUG - GET-29 - Entering block ephemeral_by_room
2023-03-07 13:28:10,202 - synapse.util.metrics - 163 - DEBUG - GET-29 - Entering block typing.get_new_events
2023-03-07 13:28:10,202 - synapse.util.metrics - 176 - DEBUG - GET-29 - Exiting block typing.get_new_events
2023-03-07 13:28:10,202 - synapse.util.metrics - 176 - DEBUG - GET-29 - Exiting block ephemeral_by_room
2023-03-07 13:28:10,202 - synapse.storage.txn - 692 - DEBUG - GET-29 - [TXN START] {get_updated_tags-104}
2023-03-07 13:28:10,202 - synapse.storage.txn - 796 - DEBUG - GET-29 - [TXN END] {get_updated_tags-104} 0.000169 sec
2023-03-07 13:28:10,203 - synapse.handlers.sync - 1915 - DEBUG - GET-29 - no-oping sync
2023-03-07 13:28:10,203 - synapse.handlers.sync - 1504 - DEBUG - GET-29 - Fetching presence data
2023-03-07 13:28:10,203 - synapse.util.metrics - 163 - DEBUG - GET-29 - Entering block presence.get_new_events
2023-03-07 13:28:10,203 - synapse.util.metrics - 176 - DEBUG - GET-29 - Exiting block presence.get_new_events
2023-03-07 13:28:10,203 - synapse.util.metrics - 163 - DEBUG - GET-29 - Entering block _generate_sync_entry_for_device_list
2023-03-07 13:28:10,204 - synapse.util.metrics - 176 - DEBUG - GET-29 - Exiting block _generate_sync_entry_for_device_list
2023-03-07 13:28:10,204 - synapse.handlers.sync - 1520 - DEBUG - GET-29 - Fetching to-device data
2023-03-07 13:28:10,204 - synapse.handlers.sync - 1523 - DEBUG - GET-29 - Fetching OTK data
2023-03-07 13:28:10,204 - synapse.handlers.sync - 1552 - DEBUG - GET-29 - Sync response calculation complete
2023-03-07 13:28:10,204 - synapse.handlers.sync - 324 - DEBUG - GET-29 - Returning sync response for @sylvester:thomass-macbook-pro.local
2023-03-07 13:28:10,204 - synapse.util.metrics - 163 - DEBUG - GET-29 - Entering block presence_update_states
2023-03-07 13:28:10,204 - synapse.util.metrics - 176 - DEBUG - GET-29 - Exiting block presence_update_states
2023-03-07 13:28:10,205 - synapse.rest.client.sync - 222 - DEBUG - GET-29 - Formatting events in sync response
2023-03-07 13:28:10,205 - synapse.rest.client.sync - 257 - DEBUG - GET-29 - building sync response dict
2023-03-07 13:28:10,205 - synapse.rest.client.sync - 211 - DEBUG - GET-29 - Event formatting complete
2023-03-07 13:28:10,206 - synapse.access.http.8008 - 460 - INFO - GET-29 - ::ffff:172.17.0.1 - 8008 - {@sylvester:thomass-macbook-pro.local} Processed request: 0.010sec/0.001sec (0.004sec, 0.002sec) (0.001sec/0.001sec/5) 1340B 200 "GET /_matrix/client/v3/sync?timeout=30000&since=s20535_72983_0_62_800_1_10_553_0_1 HTTP/1.1" "curl/7.86.0" [0 dbevts]This gets even more strange. I witness the following on our production server (v1.78.0 started with docker compose using PostgreSQL):
1) start a simple http client that calls /_matrix/client/v3/sync?timeout=30000&since=$streamToken$ with a filter definition of
const EVENT_TYPES = {
STATE: ['m.room.name', 'm.room.member', 'm.space.child', 'm.room.create']
}
const filter = {
room: {
timeline: { limit: 1000, types: EVENT_TYPES.STATE },
ephemeral: {
not_types: [ '*' ]
}
}
}2) sync seems to be OK, long polling returns after approximately 30 secs 3) open Element@iOS (same user as the http client) 4) sync goes crazy, simple http client long polling returns immediately 5) close Element@iOS 6) sync gets back on track ???
clokep
commented
1 year ago According to @richvdh:
the symptoms of that are /sync returning with next_batch=since
Unclear what the root cause of this is, however.
kegsay
commented
11 months ago This is a dupe of https://github.com/matrix-org/synapse/issues/15824
clokep
commented
11 months ago Seems like it. 👍
Description
https://github.com/matrix-org/synapse/issues/8518 seems to be reocurring on my dev setup. Symptoms appear to be the same and since this my dev homeserver, there's nothing else happening on the server, so the sync response is indeed empty. I start the synapse server, the client connects and completes 4 sync requests normally, each taking 30 seconds. The 5th and subsequent requests return straight away and start tightlooping. Also notable is the fact that the last sync response that takes 30 seconds contains a presence update for the user's own user.
Steps to reproduce
Probably:
...although I've not changed anything about my dev setup and I haven't seen this previously, so this would suggest something else has changed.
Homeserver
local dev
Synapse Version
d1efc479252f71f196e5a339af999d2c632bc294
Installation Method
Other (please mention below)
Database
sqlite
Workers
Single process
Platform
Running from source with poetry, macos.
Configuration
No response
Relevant log output
Anything else that would be useful to know?
No response