search

matrix-org / synapse

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

Log values at DEBUG level with execute_values #16281

Closed DMRobertson closed 1 year ago

DMRobertson commented 1 year ago

In #16271 I asked to see debug SQL logs to understand what exactly the user directory rebuild was doing. Unfortunately the logs didn't include the list of values given to the SQL statement:

2023-09-08 06:55:35,291 - synapse.storage.SQL - 449 - DEBUG - background_updates-1 - [SQL] {populate_user_directory_temp-1aa} INSERT INTO user_directory_search(user_id, vector) VALUES ? ON CONFLICT (user_id) DO UPDATE SET vector=EXCLUDED.vector
2023-09-08 06:55:35,292 - synapse.storage.SQL - 475 - DEBUG - background_updates-1 - [SQL time] {populate_user_directory_temp-1aa} 0.000619 sec

With my change, I ran the same(ish) logic using SYNAPSE_POSTGRES=1 SYNAPSE_TEST_LOG_LEVEL=DEBUG trial tests.storage.test_user_directory and observed e.g.

* 2023-09-08 13:52:47+0100 [-] synapse.storage.SQL - 465 - DEBUG - sentinel - [SQL] {update_profiles_in_user_dir-62} INSERT INTO user_directory_search(user_id, vector) VALUES ? ON CONFLICT (user_id) DO UPDATE SET vector=EXCLUDED.vector
  2023-09-08 13:52:47+0100 [-] synapse.storage.SQL - 470 - DEBUG - sentinel - [SQL values] {update_profiles_in_user_dir-62} [('@alice:a', 'alice', 'a', 'gáo')]
  2023-09-08 13:52:47+0100 [-] synapse.storage.SQL - 491 - DEBUG - sentinel - [SQL time] {update_profiles_in_user_dir-62} 0.000417 sec
DMRobertson commented 1 year ago

Failed due to a known flake. I also re-ran the test with SYNAPSE_TEST_LOG_LEVEL=INFO and sanity-checked that we didn't log any sql values by grepping the test logs for values.