sso login cannot update avatar #17541
Labels
Comments
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
{{ message }}
Description
I found that the sso login did not change the avatar. Because the picture data is of length 0, we compute the hash and then construct the upload_name, which will be the same each time, so the logic to update the avatar will not run
As you can see in the log, print(picture.read()) always prints b ", which should be why there are so many upload_names like this in the database
synapse/handlers/sso.py
async def set_avatar(self, user_id: str, picture_https_url: str) -> bool:
Steps to reproduce
Homeserver
matrix.org
Synapse Version
call synapse/handlers/sso.py set_avatar
Installation Method
Docker (matrixdotorg/synapse)
Database
postgresql
Workers
Single process
Platform
docker
Configuration
No response
Relevant log output
2024-08-08 15:45:06,724 - synapse.storage.SQL - 466 - DEBUG - _reap_stale_read_write_locks-6 - [SQL values] {_reap_stale_read_write_locks-5e} (1723102986724,) 2024-08-08 15:45:06,803 - synapse.storage.SQL - 487 - DEBUG - _reap_stale_read_write_locks-6 - [SQL time] {_reap_stale_read_write_locks-5e} 0.079324 sec 2024-08-08 15:45:06,804 - synapse.storage.txn - 857 - DEBUG - _reap_stale_read_write_locks-6 - [TXN END] {_reap_stale_read_write_locks-5e} 0.079967 sec 2024-08-08 15:45:06,814 - synapse.storage.SQL - 487 - DEBUG - prune_old_user_ips-14 - [SQL time] {_prune_old_user_ips-5d} 0.161490 sec 2024-08-08 15:45:06,897 - synapse.storage.txn - 857 - DEBUG - prune_old_user_ips-14 - [TXN END] {_prune_old_user_ips-5d} 0.244756 sec 2024-08-08 15:45:07,655 - synapse.handlers.typing - 119 - DEBUG - typing._handle_timeouts-13 - Checking for typing timeouts 2024-08-08 15:45:07,655 - synapse.handlers.presence - 1023 - DEBUG - handle_presence_timeouts-6 - Handling presence timeouts 2024-08-08 15:45:07,656 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-6 - Entering block presence_update_states 2024-08-08 15:45:07,656 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-6 - Exiting block presence_update_states 2024-08-08 15:45:07,691 - synapse.storage.TIME - 659 - DEBUG - sentinel - Total database time: 18.694% {get_scheduled_tasks(3): 8.002%, _prune_old_user_ips(2): 4.966%, get_catch_up_outstanding_destinations(1): 2.855%} 2024-08-08 15:45:11,471 - synapse.access.http.8008 - 420 - DEBUG - POST-0 - ::1 - 8008 - Received request: POST /_matrix/client/v3/login 2024-08-08 15:45:11,498 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {get_user_account-5f} 2024-08-08 15:45:11,499 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {get_user_account-5f} SELECT id, user_id, device_id, account_data, fingerprint FROM md_user_account WHERE user_id = ? AND fingerprint = ? 2024-08-08 15:45:11,499 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {get_user_account-5f} ['@guest_0003:matrix-dev.defed.network', '-1307776955'] 2024-08-08 15:45:11,559 - synapse.metrics._gc - 118 - DEBUG - sentinel - Collecting gc 0 2024-08-08 15:45:11,576 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {get_user_account-5f} 0.077193 sec 2024-08-08 15:45:11,576 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {get_user_account-5f} 0.078038 sec 2024-08-08 15:45:11,648 - synapse.storage.txn - 753 - DEBUG - prune_old_user_ips-15 - [TXN START] {_prune_old_user_ips-60} 2024-08-08 15:45:11,648 - synapse.storage.SQL - 461 - DEBUG - prune_old_user_ips-15 - [SQL] {_prune_old_user_ips-60} DELETE FROM user_ips WHERE last_seen IN ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) 2024-08-08 15:45:11,648 - synapse.storage.SQL - 466 - DEBUG - prune_old_user_ips-15 - [SQL values] {_prune_old_user_ips-60} (1720683911647,) 2024-08-08 15:45:11,653 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {get_refresh_token-61} 2024-08-08 15:45:11,653 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {get_refresh_token-61} SELECT token FROM refresh_tokens WHERE user_id = ? and device_id = ? order by expiry_ts desc limit 1 2024-08-08 15:45:11,653 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {get_refresh_token-61} ('@guest_0003:matrix-dev.defed.network', 'UHDDFEECVY') 2024-08-08 15:45:11,802 - synapse.storage.SQL - 487 - DEBUG - prune_old_user_ips-15 - [SQL time] {_prune_old_user_ips-60} 0.154052 sec 2024-08-08 15:45:11,805 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {get_refresh_token-61} 0.151512 sec 2024-08-08 15:45:11,881 - synapse.storage.txn - 857 - DEBUG - prune_old_user_ips-15 - [TXN END] {_prune_old_user_ips-60} 0.233200 sec 2024-08-08 15:45:11,883 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {get_refresh_token-61} 0.230490 sec 2024-08-08 15:45:11,884 - twisted - 275 - INFO - POST-0 - {'id': 116, 'user_id': '@guest_0003:matrix-dev.defed.network', 'device_id': 'UHDDFEECVY', 'account_data': '', 'fingerprint': '-1307776955', 'refresh_token': 'syr_Z3Vlc3RfMDAwMw_awKWZoIQVjFtmqHhSMFG_0mZgNq'} 2024-08-08 15:45:11,884 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {get_users_by_id_case_insensitive-62} 2024-08-08 15:45:11,884 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {get_users_by_id_case_insensitive-62} SELECT name, password_hash FROM users WHERE lower(name) = lower(?) 2024-08-08 15:45:11,884 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {get_users_by_id_case_insensitive-62} ('@guest_0003:matrix-dev.defed.network',) 2024-08-08 15:45:12,039 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {get_users_by_id_case_insensitive-62} 0.154230 sec 2024-08-08 15:45:12,115 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {get_users_by_id_case_insensitive-62} 0.230370 sec 2024-08-08 15:45:12,115 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {get_user_deactivated_status-63} 2024-08-08 15:45:12,115 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {get_user_deactivated_status-63} SELECT deactivated FROM users WHERE name = ? 2024-08-08 15:45:12,116 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {get_user_deactivated_status-63} ['@guest_0003:matrix-dev.defed.network'] 2024-08-08 15:45:12,192 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {get_user_deactivated_status-63} 0.076090 sec 2024-08-08 15:45:12,192 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {get_user_deactivated_status-63} 0.076559 sec 2024-08-08 15:45:12,269 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {store_device-64} 2024-08-08 15:45:12,269 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {store_device-64} INSERT INTO devices (user_id, device_id, display_name, hidden) VALUES (?, ?, ?, ?) ON CONFLICT (user_id, device_id) DO NOTHING 2024-08-08 15:45:12,269 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {store_device-64} ['@guest_0003:matrix-dev.defed.network', 'BAHOPLPGMD', None, False] 2024-08-08 15:45:12,346 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {store_device-64} 0.076943 sec 2024-08-08 15:45:12,346 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {store_device-64} 0.077420 sec 2024-08-08 15:45:12,422 - synapse.util.metrics - 163 - DEBUG - POST-0 - Entering block notify_device_update 2024-08-08 15:45:12,423 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {get_rooms_for_user-65} 2024-08-08 15:45:12,423 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {get_rooms_for_user-65} SELECT room_id FROM current_state_events WHERE type = ? AND membership = ? AND state_key = ? 2024-08-08 15:45:12,423 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {get_rooms_for_user-65} ['m.room.member', 'join', '@guest_0003:matrix-dev.defed.network'] 2024-08-08 15:45:12,500 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {get_rooms_for_user-65} 0.076745 sec 2024-08-08 15:45:12,500 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {get_rooms_for_user-65} 0.077124 sec 2024-08-08 15:45:12,581 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {add_device_change_to_stream-66} 2024-08-08 15:45:12,582 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {add_device_change_to_stream-66} DELETE FROM device_lists_stream WHERE user_id = ? AND stream_id < ? AND device_id = ANY(?) 2024-08-08 15:45:12,582 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {add_device_change_to_stream-66} ['@guest_0003:matrix-dev.defed.network', 1724, ['BAHOPLPGMD']] 2024-08-08 15:45:12,659 - synapse.handlers.typing - 119 - DEBUG - typing._handle_timeouts-14 - Checking for typing timeouts 2024-08-08 15:45:12,659 - synapse.handlers.presence - 1023 - DEBUG - handle_presence_timeouts-7 - Handling presence timeouts 2024-08-08 15:45:12,659 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-7 - Entering block presence_update_states 2024-08-08 15:45:12,659 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-7 - Exiting block presence_update_states 2024-08-08 15:45:12,740 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {add_device_change_to_stream-66} 0.158173 sec 2024-08-08 15:45:12,740 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {add_device_change_to_stream-66} INSERT INTO device_lists_stream (stream_id, user_id, device_id) VALUES ? 2024-08-08 15:45:12,740 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {add_device_change_to_stream-66} [(1724, '@guest_0003:matrix-dev.defed.network', 'BAHOPLPGMD')] 2024-08-08 15:45:12,817 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {add_device_change_to_stream-66} 0.076565 sec 2024-08-08 15:45:12,894 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {add_device_change_to_stream-66} 0.312194 sec 2024-08-08 15:45:12,894 - synapse.util.metrics - 163 - DEBUG - user_directory.notify_new_event-7 - Entering block user_dir_delta 2024-08-08 15:45:12,894 - synapse.util.metrics - 176 - DEBUG - user_directory.notify_new_event-7 - Exiting block user_dir_delta 2024-08-08 15:45:12,894 - synapse.util.metrics - 163 - DEBUG - presence.notify_new_event-6 - Entering block presence_delta 2024-08-08 15:45:12,895 - synapse.util.metrics - 176 - DEBUG - presence.notify_new_event-6 - Exiting block presence_delta 2024-08-08 15:45:12,895 - synapse.handlers.device - 672 - DEBUG - POST-0 - Notifying about update '@guest_0003:matrix-dev.defed.network'/'BAHOPLPGMD', ID: 1724 2024-08-08 15:45:12,895 - synapse.util.metrics - 163 - DEBUG - POST-0 - Entering block on_new_event 2024-08-08 15:45:12,895 - synapse.util.metrics - 163 - DEBUG - user_directory.notify_new_event-8 - Entering block user_dir_delta 2024-08-08 15:45:12,895 - synapse.util.metrics - 176 - DEBUG - user_directory.notify_new_event-8 - Exiting block user_dir_delta 2024-08-08 15:45:12,895 - synapse.util.metrics - 163 - DEBUG - presence.notify_new_event-7 - Entering block presence_delta 2024-08-08 15:45:12,895 - synapse.util.metrics - 176 - DEBUG - presence.notify_new_event-7 - Exiting block presence_delta 2024-08-08 15:45:12,896 - synapse.util.metrics - 176 - DEBUG - POST-0 - Exiting block on_new_event 2024-08-08 15:45:12,896 - synapse.util.metrics - 176 - DEBUG - POST-0 - Exiting block notify_device_update 2024-08-08 15:45:12,896 - synapse.storage.txn - 753 - DEBUG - _handle_new_device_update_async-1 - [TXN START] {get_device_change_last_converted_pos-67} 2024-08-08 15:45:12,896 - synapse.storage.SQL - 461 - DEBUG - _handle_new_device_update_async-1 - [SQL] {get_device_change_last_converted_pos-67} SELECT stream_id, room_id FROM device_lists_changes_converted_stream_position 2024-08-08 15:45:12,897 - synapse.storage.SQL - 466 - DEBUG - _handle_new_device_update_async-1 - [SQL values] {get_device_change_last_converted_pos-67} () 2024-08-08 15:45:12,897 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {add_refresh_token_to_user-68} 2024-08-08 15:45:12,897 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {add_refresh_token_to_user-68} INSERT INTO refresh_tokens (id, user_id, device_id, token, next_token_id, expiry_ts, ultimate_session_expiry_ts) VALUES(?, ?, ?, ?, ?, ?, ?) 2024-08-08 15:45:12,898 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {add_refresh_token_to_user-68} (1224, '@guest_0003:matrix-dev.defed.network', 'BAHOPLPGMD', 'syr_Z3Vlc3RfMDAwMw_vpIoOLUkSKJVsVxWYiJa_3jgf0U', None, None, None) 2024-08-08 15:45:12,959 - synapse.metrics._gc - 118 - DEBUG - sentinel - Collecting gc 0 2024-08-08 15:45:12,973 - synapse.storage.SQL - 487 - DEBUG - _handle_new_device_update_async-1 - [SQL time] {get_device_change_last_converted_pos-67} 0.076201 sec 2024-08-08 15:45:12,973 - synapse.storage.txn - 857 - DEBUG - _handle_new_device_update_async-1 - [TXN END] {get_device_change_last_converted_pos-67} 0.076615 sec 2024-08-08 15:45:13,050 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {add_refresh_token_to_user-68} 0.151959 sec 2024-08-08 15:45:13,050 - synapse.storage.txn - 753 - DEBUG - _handle_new_device_update_async-1 - [TXN START] {get_uncoverted_outbound_room_pokes-69} 2024-08-08 15:45:13,050 - synapse.storage.SQL - 461 - DEBUG - _handle_new_device_update_async-1 - [SQL] {get_uncoverted_outbound_room_pokes-69} SELECT user_id, device_id, room_id, stream_id, opentracing_context FROM device_lists_changes_in_room WHERE (stream_id, room_id) > (?, ?) AND stream_id <= ? AND NOT converted_to_destinations ORDER BY stream_id ASC, room_id ASC LIMIT ? 2024-08-08 15:45:13,050 - synapse.storage.SQL - 466 - DEBUG - _handle_new_device_update_async-1 - [SQL values] {get_uncoverted_outbound_room_pokes-69} (1723, '', 1724, 10) 2024-08-08 15:45:13,126 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {add_refresh_token_to_user-68} 0.229113 sec 2024-08-08 15:45:13,127 - synapse.handlers.auth - 999 - INFO - POST-0 - Logging in user @guest_0003:matrix-dev.defed.network on device BAHOPLPGMD until 2024-08-08 15:50:12 2024-08-08 15:45:13,127 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {is_support_user-6a} 2024-08-08 15:45:13,128 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {is_support_user-6a} SELECT user_type FROM users WHERE name = ? 2024-08-08 15:45:13,128 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {is_support_user-6a} ['@guest_0003:matrix-dev.defed.network'] 2024-08-08 15:45:13,203 - synapse.storage.SQL - 487 - DEBUG - _handle_new_device_update_async-1 - [SQL time] {get_uncoverted_outbound_room_pokes-69} 0.153155 sec 2024-08-08 15:45:13,281 - synapse.storage.txn - 857 - DEBUG - _handle_new_device_update_async-1 - [TXN END] {get_uncoverted_outbound_room_pokes-69} 0.231035 sec 2024-08-08 15:45:13,281 - synapse.storage.txn - 753 - DEBUG - _handle_new_device_update_async-1 - [TXN START] {set_device_change_last_converted_pos-6b} 2024-08-08 15:45:13,281 - synapse.storage.SQL - 461 - DEBUG - _handle_new_device_update_async-1 - [SQL] {set_device_change_last_converted_pos-6b} UPDATE device_lists_changes_converted_stream_position SET stream_id = ?, room_id = ? 2024-08-08 15:45:13,281 - synapse.storage.SQL - 466 - DEBUG - _handle_new_device_update_async-1 - [SQL values] {set_device_change_last_converted_pos-6b} [1724, ''] 2024-08-08 15:45:13,288 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {is_support_user-6a} 0.160056 sec 2024-08-08 15:45:13,368 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {is_support_user-6a} 0.241027 sec 2024-08-08 15:45:13,369 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {add_access_token_to_user-6c} 2024-08-08 15:45:13,369 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {add_access_token_to_user-6c} INSERT INTO access_tokens (id, user_id, token, device_id, valid_until_ms, puppets_user_id, last_validated, refresh_token_id, used) VALUES(?, ?, ?, ?, ?, ?, ?, ?, ?) 2024-08-08 15:45:13,369 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {add_access_token_to_user-6c} (1518, '@guest_0003:matrix-dev.defed.network', 'syt_Z3Vlc3RfMDAwMw_EGkUjsJemyssJMkNELds_0fseYA', 'BAHOPLPGMD', 1723103412268, None, 1723103113369, 1224, False) 2024-08-08 15:45:13,399 - synapse.storage.txn - 753 - DEBUG - room_forgetter.notify_new_event-2 - [TXN START] {room_forgetter_stream_pos-6d} 2024-08-08 15:45:13,399 - synapse.storage.SQL - 461 - DEBUG - room_forgetter.notify_new_event-2 - [SQL] {room_forgetter_stream_pos-6d} UPDATE room_forgetter_stream_pos SET stream_id = ? 2024-08-08 15:45:13,399 - synapse.storage.SQL - 466 - DEBUG - room_forgetter.notify_new_event-2 - [SQL values] {room_forgetter_stream_pos-6d} [6673] 2024-08-08 15:45:13,482 - synapse.storage.SQL - 487 - DEBUG - room_forgetter.notify_new_event-2 - [SQL time] {room_forgetter_stream_pos-6d} 0.082154 sec 2024-08-08 15:45:13,482 - synapse.storage.txn - 857 - DEBUG - room_forgetter.notify_new_event-2 - [TXN END] {room_forgetter_stream_pos-6d} 0.082595 sec 2024-08-08 15:45:13,526 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {add_access_token_to_user-6c} 0.156997 sec 2024-08-08 15:45:13,610 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {add_access_token_to_user-6c} 0.240417 sec 2024-08-08 15:45:13,610 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {get_device-6e} 2024-08-08 15:45:13,610 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {get_device-6e} SELECT user_id, device_id, display_name FROM devices WHERE user_id = ? AND device_id = ? AND hidden = ? 2024-08-08 15:45:13,611 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {get_device-6e} ['@guest_0003:matrix-dev.defed.network', 'BAHOPLPGMD', False] 2024-08-08 15:45:13,665 - synapse.storage.SQL - 487 - DEBUG - _handle_new_device_update_async-1 - [SQL time] {set_device_change_last_converted_pos-6b} 0.383049 sec 2024-08-08 15:45:13,665 - synapse.storage.txn - 857 - DEBUG - _handle_new_device_update_async-1 - [TXN END] {set_device_change_last_converted_pos-6b} 0.383428 sec 2024-08-08 15:45:13,691 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {get_device-6e} 0.080835 sec 2024-08-08 15:45:13,692 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {get_device-6e} 0.081228 sec 2024-08-08 15:45:13,774 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {set_profile_displayname-6f} 2024-08-08 15:45:13,774 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {set_profile_displayname-6f} INSERT INTO profiles (user_id, displayname, full_user_id) VALUES (?, ?, ?) ON CONFLICT (user_id) DO UPDATE SET displayname=EXCLUDED.displayname, full_user_id=EXCLUDED.full_user_id 2024-08-08 15:45:13,774 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {set_profile_displayname-6f} ['guest_0003', 'GUEST_0003', '@guest_0003:matrix-dev.defed.network'] 2024-08-08 15:45:13,851 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {set_profile_displayname-6f} 0.076653 sec 2024-08-08 15:45:13,851 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {set_profile_displayname-6f} 0.077037 sec 2024-08-08 15:45:13,928 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {get_profileinfo-70} 2024-08-08 15:45:13,928 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {get_profileinfo-70} SELECT displayname, avatar_url FROM profiles WHERE full_user_id = ? 2024-08-08 15:45:13,928 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {get_profileinfo-70} ['@guest_0003:matrix-dev.defed.network'] 2024-08-08 15:45:14,009 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {get_profileinfo-70} 0.081359 sec 2024-08-08 15:45:14,010 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {get_profileinfo-70} 0.081984 sec 2024-08-08 15:45:14,086 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {update_profiles_in_user_dir-71} 2024-08-08 15:45:14,086 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {update_profiles_in_user_dir-71} INSERT INTO user_directory (user_id, display_name, avatar_url) VALUES ? ON CONFLICT (user_id) DO UPDATE SET display_name=EXCLUDED.display_name, avatar_url=EXCLUDED.avatar_url 2024-08-08 15:45:14,086 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {update_profiles_in_user_dir-71} [('@guest_0003:matrix-dev.defed.network', 'GUEST_0003', 'mxc://matrix-dev.defed.network/LMmWPVUWSMowexNUkHUtxwAu')] 2024-08-08 15:45:14,238 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {update_profiles_in_user_dir-71} 0.152303 sec 2024-08-08 15:45:14,239 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {update_profiles_in_user_dir-71} INSERT INTO user_directory_search(user_id, vector) VALUES ? ON CONFLICT (user_id) DO UPDATE SET vector=EXCLUDED.vector 2024-08-08 15:45:14,239 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {update_profiles_in_user_dir-71} [('@guest_0003:matrix-dev.defed.network', 'guest_0003', 'matrix-dev.defed.network', 'guest_0003')] 2024-08-08 15:45:14,317 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {update_profiles_in_user_dir-71} 0.078059 sec 2024-08-08 15:45:14,394 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {update_profiles_in_user_dir-71} 0.308188 sec 2024-08-08 15:45:14,395 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {get_ratelimit_for_user-72} 2024-08-08 15:45:14,395 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {get_ratelimit_for_user-72} SELECT messages_per_second, burst_count FROM ratelimit_override WHERE user_id = ? 2024-08-08 15:45:14,395 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {get_ratelimit_for_user-72} ['@guest_0003:matrix-dev.defed.network'] 2024-08-08 15:45:14,476 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {get_ratelimit_for_user-72} 0.081349 sec 2024-08-08 15:45:14,477 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {get_ratelimit_for_user-72} 0.081805 sec 2024-08-08 15:45:14,563 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {simple_upsert-73} 2024-08-08 15:45:14,563 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {simple_upsert-73} INSERT INTO user_threepids (medium, address, user_id, validated_at, added_at) VALUES (?, ?, ?, ?, ?) ON CONFLICT (medium, address) DO UPDATE SET user_id=EXCLUDED.user_id, validated_at=EXCLUDED.validated_at, added_at=EXCLUDED.added_at 2024-08-08 15:45:14,564 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {simple_upsert-73} ['email', 'ht_test1@qq.com', '@guest_0003:matrix-dev.defed.network', 1723103114563, 1723103114563] 2024-08-08 15:45:14,644 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {simple_upsert-73} 0.080039 sec 2024-08-08 15:45:14,644 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {simple_upsert-73} 0.080486 sec 2024-08-08 15:45:14,725 - synapse.http.client - 368 - DEBUG - POST-0 - Sending request GET http://gips2.baidu.com/it/u=3093819921,829322739&fm=3028&app=3028&f=JPEG&fmt=auto?w=1024&h=1024 2024-08-08 15:45:14,732 - synapse.http.proxyagent - 313 - DEBUG - POST-0 - Requesting http://gips2.baidu.com/it/u=3093819921,829322739&fm=3028&app=3028&f=JPEG&fmt=auto?w=1024&h=1024 via <HostnameEndpoint gips2.baidu.com:80> 2024-08-08 15:45:14,759 - synapse.metrics._gc - 118 - DEBUG - sentinel - Collecting gc 0 2024-08-08 15:45:14,824 - synapse.http.client - 413 - INFO - POST-0 - Received response to GET http://gips2.baidu.com/it/u=3093819921,829322739&fm=3028&app=3028&f=JPEG&fmt=auto?w=1024&h=1024: 200 2024-08-08 15:45:14,882 - twisted - 275 - INFO - POST-0 - ******************** 2024-08-08 15:45:14,882 - twisted - 275 - INFO - POST-0 - 10485760 2024-08-08 15:45:14,882 - twisted - 275 - INFO - POST-0 - b'' 2024-08-08 15:45:14,882 - twisted - 275 - INFO - POST-0 - 141272 2024-08-08 15:45:14,882 - twisted - 275 - INFO - POST-0 - http://gips2.baidu.com/it/u=3093819921,829322739&fm=3028&app=3028&f=JPEG&fmt=auto?w=1024&h=1024 2024-08-08 15:45:14,883 - twisted - 275 - INFO - POST-0 - 200 2024-08-08 15:45:14,883 - twisted - 275 - INFO - POST-0 - {b'Server': [b'JSP3/2.0.14'], b'Date': [b'Thu, 08 Aug 2024 07:45:14 GMT'], b'Content-Type': [b'image/jpeg'], b'Expires': [b'Fri, 09 Aug 2024 23:17:08 GMT'], b'Last-Modified': [b'Tue, 06 Jan 1970 00:00:00 GMT'], b'ETag': [b'6a8e5fe3fbf22f666805044b64c1f4fc'], b'Age': [b'3092'], b'Accept-Ranges': [b'bytes'], b'Access-Control-Allow-Origin': [b'*'], b'Ohc-Global-Saved-Time': [b'Wed, 10 Jul 2024 23:17:08 GMT'], b'Ohc-Cache-Hit': [b'lz6ct64 [2], czix124 [3]'], b'Ohc-File-Size': [b'141272'], b'X-Cache-Status': [b'HIT'], b'Timing-Allow-Origin': [b'*'], b'Content-Encoding': [b'']} 2024-08-08 15:45:14,883 - twisted - 275 - INFO - POST-0 - sso_avatar_e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 2024-08-08 15:45:14,883 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {get_profileinfo-74} 2024-08-08 15:45:14,883 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {get_profileinfo-74} SELECT displayname, avatar_url FROM profiles WHERE full_user_id = ? 2024-08-08 15:45:14,883 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {get_profileinfo-74} ['@guest_0003:matrix-dev.defed.network'] 2024-08-08 15:45:14,960 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {get_profileinfo-74} 0.076451 sec 2024-08-08 15:45:14,960 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {get_profileinfo-74} 0.076872 sec 2024-08-08 15:45:15,047 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {get_local_media-75} 2024-08-08 15:45:15,047 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {get_local_media-75} SELECT media_type, media_length, upload_name, created_ts, quarantined_by, url_cache, last_access_ts, safe_from_quarantine, user_id FROM local_media_repository WHERE media_id = ? 2024-08-08 15:45:15,047 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {get_local_media-75} ['LMmWPVUWSMowexNUkHUtxwAu'] 2024-08-08 15:45:15,125 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {get_local_media-75} 0.078449 sec 2024-08-08 15:45:15,125 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {get_local_media-75} 0.078884 sec 2024-08-08 15:45:15,145 - synapse.storage.txn - 753 - DEBUG - _get_stats_for_federation_staging-2 - [TXN START] {_get_stats_for_federation_staging-76} 2024-08-08 15:45:15,145 - synapse.storage.SQL - 461 - DEBUG - _get_stats_for_federation_staging-2 - [SQL] {_get_stats_for_federation_staging-76} SELECT count(*) FROM federation_inbound_events_staging 2024-08-08 15:45:15,145 - synapse.storage.SQL - 466 - DEBUG - _get_stats_for_federation_staging-2 - [SQL values] {_get_stats_for_federation_staging-76} () **2024-08-08 15:45:15,205 - synapse.handlers.sso - 818 - INFO - POST-0 - skipping saving the user avatar** 2024-08-08 15:45:15,206 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {check_existing_user_account-77} 2024-08-08 15:45:15,206 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {check_existing_user_account-77} SELECT id FROM md_user_account WHERE user_id = ? AND fingerprint = ? 2024-08-08 15:45:15,206 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {check_existing_user_account-77} ['@guest_0003:matrix-dev.defed.network', '-1307776955'] 2024-08-08 15:45:15,286 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {check_existing_user_account-77} 0.080703 sec 2024-08-08 15:45:15,287 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {check_existing_user_account-77} 0.081041 sec 2024-08-08 15:45:15,306 - synapse.storage.SQL - 487 - DEBUG - _get_stats_for_federation_staging-2 - [SQL time] {_get_stats_for_federation_staging-76} 0.160472 sec 2024-08-08 15:45:15,306 - synapse.storage.SQL - 461 - DEBUG - _get_stats_for_federation_staging-2 - [SQL] {_get_stats_for_federation_staging-76} SELECT min(received_ts) FROM federation_inbound_events_staging 2024-08-08 15:45:15,306 - synapse.storage.SQL - 466 - DEBUG - _get_stats_for_federation_staging-2 - [SQL values] {_get_stats_for_federation_staging-76} () 2024-08-08 15:45:15,369 - synapse.storage.txn - 753 - DEBUG - POST-0 - [TXN START] {update_user_account-78} 2024-08-08 15:45:15,369 - synapse.storage.SQL - 461 - DEBUG - POST-0 - [SQL] {update_user_account-78} UPDATE md_user_account SET device_id = ?, account_data = ? WHERE id = ? 2024-08-08 15:45:15,369 - synapse.storage.SQL - 466 - DEBUG - POST-0 - [SQL values] {update_user_account-78} ['BAHOPLPGMD', '', 116] 2024-08-08 15:45:15,387 - synapse.storage.SQL - 487 - DEBUG - _get_stats_for_federation_staging-2 - [SQL time] {_get_stats_for_federation_staging-76} 0.081470 sec 2024-08-08 15:45:15,451 - synapse.storage.SQL - 487 - DEBUG - POST-0 - [SQL time] {update_user_account-78} 0.081933 sec 2024-08-08 15:45:15,451 - synapse.storage.txn - 857 - DEBUG - POST-0 - [TXN END] {update_user_account-78} 0.082446 sec 2024-08-08 15:45:15,468 - synapse.storage.txn - 857 - DEBUG - _get_stats_for_federation_staging-2 - [TXN END] {_get_stats_for_federation_staging-76} 0.322969 sec 2024-08-08 15:45:15,532 - synapse.access.http.8008 - 465 - INFO - POST-0 - ::1 - 8008 - {None} Processed request: 4.061sec/0.000sec (0.000sec, 0.000sec) (0.003sec/2.823sec/20) 268B 200 "POST /_matrix/client/v3/login HTTP/1.1" "Mozilla/5.0 (iPhone; CPU iPhone OS 16_6 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.6 Mobile/15E148 Safari/604.1" [0 dbevts] 2024-08-08 15:45:16,648 - synapse.storage.txn - 753 - DEBUG - prune_old_user_ips-16 - [TXN START] {_prune_old_user_ips-79} 2024-08-08 15:45:16,648 - synapse.storage.SQL - 461 - DEBUG - prune_old_user_ips-16 - [SQL] {_prune_old_user_ips-79} DELETE FROM user_ips WHERE last_seen IN ( SELECT last_seen FROM user_ips WHERE last_seen <= ? ORDER BY last_seen ASC LIMIT 5000 ) 2024-08-08 15:45:16,648 - synapse.storage.SQL - 466 - DEBUG - prune_old_user_ips-16 - [SQL values] {_prune_old_user_ips-79} (1720683916648,) 2024-08-08 15:45:16,811 - synapse.storage.SQL - 487 - DEBUG - prune_old_user_ips-16 - [SQL time] {_prune_old_user_ips-79} 0.162350 sec 2024-08-08 15:45:16,890 - synapse.storage.txn - 857 - DEBUG - prune_old_user_ips-16 - [TXN END] {_prune_old_user_ips-79} 0.241589 sec 2024-08-08 15:45:17,658 - synapse.handlers.typing - 119 - DEBUG - typing._handle_timeouts-15 - Checking for typing timeouts 2024-08-08 15:45:17,658 - synapse.handlers.presence - 1023 - DEBUG - handle_presence_timeouts-8 - Handling presence timeouts 2024-08-08 15:45:17,658 - synapse.util.metrics - 163 - DEBUG - handle_presence_timeouts-8 - Entering block presence_update_states 2024-08-08 15:45:17,658 - synapse.util.metrics - 176 - DEBUG - handle_presence_timeouts-8 - Exiting block presence_update_states 2024-08-08 15:45:17,693 - synapse.storage.TIME - 659 - DEBUG - sentinel - Total database time: 43.933% {_prune_old_user_ips(2): 4.747%, set_device_change_last_converted_pos(1): 3.834%, _get_stats_for_federation_staging(1): 3.229%} 2024-08-08 15:45:18,723 - synapse.storage.txn - 753 - DEBUG - _reap_stale_read_write_locks-7 - [TXN START] {_reap_stale_read_write_locks-7a} 2024-08-08 15:45:18,723 - synapse.storage.SQL - 461 - DEBUG - _reap_stale_read_write_locks-7 - [SQL] {_reap_stale_read_write_locks-7a} DELETE FROM worker_read_write_locks WHERE last_renewed_ts < ? 2024-08-08 15:45:18,723 - synapse.storage.SQL - 466 - DEBUG - _reap_stale_read_write_locks-7 - [SQL values] {_reap_stale_read_write_locks-7a} (1723102998723,) 2024-08-08 15:45:18,801 - synapse.storage.SQL - 487 - DEBUG - _reap_stale_read_write_locks-7 - [SQL time] {_reap_stale_read_write_locks-7a} 0.077539 sec 2024-08-08 15:45:18,801 - synapse.storage.txn - 857 - DEBUG - _reap_stale_read_write_locks-7 - [TXN END] {_reap_stale_read_write_locks-7a} 0.077946 sec ^C2024-08-08 15:45:18,916 - twisted - 275 - INFO - sentinel - Received SIGINT, shutting down. 2024-08-08 15:45:18,917 - synapse.storage.databases.main.lock - 106 - INFO - LockStore._on_shutdown-0 - Dropping held locks due to shutdown 2024-08-08 15:45:18,917 - synapse.storage.databases.main.lock - 117 - INFO - LockStore._on_shutdown-0 - Dropped locks due to shutdown 2024-08-08 15:45:18,917 - synapse.handlers.presence - 883 - INFO - presence.on_shutdown-0 - Performing _on_shutdown. Persisting 2 unpersisted changes 2024-08-08 15:45:18,917 - synapse.handlers.presence - 895 - INFO - presence.on_shutdown-0 - Finished _on_shutdown 2024-08-08 15:45:18,917 - synapse.app._base - 498 - INFO - sentinel - Shutting down... 2024-08-08 15:45:18,917 - twisted - 275 - INFO - sentinel - (TCP Port 8008 Closed) 2024-08-08 15:45:18,917 - twisted - 275 - INFO - sentinel - (TCP Port 8008 Closed) 2024-08-08 15:45:18,920 - twisted - 275 - INFO - sentinel - Main loop terminated.Anything else that would be useful to know?
No response
The text was updated successfully, but these errors were encountered: