synapse icon indicating copy to clipboard operation
synapse copied to clipboard
verified publisher icon element-hq

sso login cannot update avatar

Open ShareTheWorld opened this issue 1 year ago • 0 comments

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

  • sso login with a third party, (user must have an avatar)
  • Changing user avatars in third parties
  • The third party is again used for sso login
  • See if the user's avatar has changed in the matrix

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', '[email protected]', '@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

ShareTheWorld avatar Aug 08 '24 09:08 ShareTheWorld