Bug#33057164 PSI_THREAD_INFO not updated while executing PREPARED STATEMENTS

Bug 104121 PSI_THREAD_INFO not updated while executing PREPARED STATEMENTS

Problem:

When executing a PREPARED statement,
table performance_schema.threads does not populate the PROCESSLIST_INFO
column.

This prevents to properly observe the execution of prepared statements.

This is also a regression, introduced in:
- MySQL 5.6.46
- MySQL 5.7.28
- MySQL 8.0.18

Root cause:

The fix for:
  Bug 20712046 SHOW PROCESSLIST AND PERFORMANCE_SCHEMA TABLES DO NOT MASK PASSWORD FROM QUERY
removed a call to PSI_THREAD_CALL(set_thread_info) located in THD::set_query()

PSI_THREAD_CALL(set_thread_info) was called from different places in the
same fix, to make sure a properly sanitized query text is displayed if
needed, but the code path for prepared statements was overlooked.

Fix:

The fix is to call PSI_THREAD_CALL(set_thread_info) in the missing code
path, when executing a prepared statement.

The call uses either the executed query, or a sanitized version of it
if it contains sensitive data.

Additional fix:

The logic around rewrite_query_if_needed() was revised.

Trying to anticipate if a query will be displayed or not,
to possibly save a rewrite, is too fragile, and too dangerous.

Queries that contain sensitive data are always rewritten,
regardless of whether the query will actually be printed somewhere or not.

Change-Id: Ief9c80a24f539f0889371766843d2f7b05812ad8

Author: marcalff

include/mysql/psi/mysql_thread.h

@@ -187,6 +187,18 @@ static inline void mysql_thread_set_secondary_engine(bool secondary
 #endif
 }
 
+/**
+  Set the INFO attribute in the thread instrumentation.
+  @param str query string
+  @param len query length
+*/
+static inline void mysql_thread_set_info(const char *str [[maybe_unused]],
+                                         int len [[maybe_unused]]) {
+#ifdef HAVE_PSI_THREAD_INTERFACE
+  PSI_THREAD_CALL(set_thread_info)(str, len);
+#endif
+}
+
 /** @} (end of group psi_api_thread) */
 
 #endif

mysql-test/suite/perfschema/include/rewritten_queries.inc

@@ -0,0 +1,36 @@
+
+#
+# Checks to perform after each query.
+#
+# Parameters:
+# - $con1_thread_id
+# - $con1_connection_id
+#
+
+--disable_query_log
+eval SELECT "thread" as mark, PROCESSLIST_INFO
+  FROM performance_schema.threads
+  WHERE THREAD_ID = $con1_thread_id;
+
+eval SELECT "processlist" as mark, INFO
+  FROM performance_schema.processlist
+  WHERE ID = $con1_connection_id;
+
+eval SELECT "I_S.PROCESSLIST" as mark, INFO
+  FROM INFORMATION_SCHEMA.PROCESSLIST
+  WHERE ID = $con1_connection_id;
+
+eval SELECT "current" as mark, EVENT_NAME, SQL_TEXT, DIGEST_TEXT
+  FROM performance_schema.events_statements_current
+  WHERE THREAD_ID = $con1_thread_id;
+
+eval SELECT "history" as mark, EVENT_NAME, SQL_TEXT, DIGEST_TEXT
+  FROM performance_schema.events_statements_history
+  WHERE THREAD_ID = $con1_thread_id
+  ORDER BY EVENT_ID;
+
+eval SELECT "history_long" as mark, EVENT_NAME, SQL_TEXT, DIGEST_TEXT
+  FROM performance_schema.events_statements_history_long
+  WHERE THREAD_ID = $con1_thread_id
+  ORDER BY EVENT_ID;
+--enable_query_log

mysql-test/suite/perfschema/r/rewritten_queries.result

@@ -0,0 +1,140 @@
+
+# Test requires: sp-protocol/ps-protocol/view-protocol/cursor-protocol disabled
+--source include/no_protocol.inc
+
+
+--echo
+--echo # Connection 1
+--echo
+connect(con1, localhost, root,,);
+--disable_query_log
+let $con1_thread_id= `SELECT ps_current_thread_id()`;
+let $con1_connection_id= `SELECT connection_id()`;
+--enable_query_log
+
+--connection default
+CREATE TABLE test.t1(a int, b varchar(80));
+INSERT INTO test.t1 VALUES (1, "a"), (2, "b"), (3, "c");
+SELECT * FROM test.t1;
+
+BEGIN;
+SELECT * FROM test.t1 FOR UPDATE;
+
+--echo
+--echo # Regular query
+--echo
+--connection con1
+SELECT "This is not secret" as normal_query;
+--connection default
+--source ../include/rewritten_queries.inc
+
+--echo
+--echo # Regular query (in flight)
+--echo
+--connection con1
+--send INSERT INTO test.t1 VALUES (4, "This is not secret");
+--connection default
+--source ../include/rewritten_queries.inc
+
+COMMIT;
+--connection con1
+--reap
+--connection default
+--source ../include/rewritten_queries.inc
+
+--echo
+--echo # Sensitive query
+--echo
+--connection con1
+CREATE USER alice IDENTIFIED BY 'thisisapassword';
+--connection default
+--source ../include/rewritten_queries.inc
+
+
+--echo
+--echo # Regular prepared statement (prepare)
+--echo
+--connection con1
+PREPARE stmt FROM "SELECT 'This is not a secret either' as prepared_query";
+--connection default
+--source ../include/rewritten_queries.inc
+
+--echo
+--echo # Regular prepared statement (execute)
+--echo
+--connection con1
+EXECUTE stmt;
+--connection default
+--source ../include/rewritten_queries.inc
+
+--echo
+--echo # Regular prepared statement (deallocate)
+--echo
+--connection con1
+DEALLOCATE PREPARE stmt;
+--connection default
+--source ../include/rewritten_queries.inc
+
+BEGIN;
+SELECT * FROM test.t1 FOR UPDATE;
+
+--echo
+--echo # Regular prepared statement (prepare)
+--echo
+--connection con1
+PREPARE stmt FROM "INSERT INTO test.t1 VALUES (5, 'This is not secret either')";
+--connection default
+--source ../include/rewritten_queries.inc
+
+--echo
+--echo # Regular prepared statement (execute, in flight)
+--echo
+--connection con1
+--send EXECUTE stmt;
+--connection default
+--source ../include/rewritten_queries.inc
+
+COMMIT;
+--connection con1
+--reap
+--connection default
+--source ../include/rewritten_queries.inc
+
+--echo
+--echo # Regular prepared statement (deallocate)
+--echo
+--connection con1
+DEALLOCATE PREPARE stmt;
+--connection default
+--source ../include/rewritten_queries.inc
+
+--echo
+--echo # Sensitive prepared statement (prepare)
+--echo
+--connection con1
+PREPARE stmt FROM "CREATE USER bob IDENTIFIED BY 'thisisapassword'";
+--connection default
+--source ../include/rewritten_queries.inc
+
+--echo
+--echo # Sensitive prepared statement (execute)
+--echo
+--connection con1
+EXECUTE stmt;
+--connection default
+--source ../include/rewritten_queries.inc
+
+--echo
+--echo # Sensitive prepared statement (deallocate)
+--echo
+--connection con1
+DEALLOCATE PREPARE stmt;
+--connection default
+--source ../include/rewritten_queries.inc
+
+--connection default
+--disconnect con1
+
+DROP USER alice;
+DROP USER bob;
+DROP TABLE test.t1;

mysql-test/suite/perfschema/t/rewritten_queries.test

@@ -324,33 +324,26 @@ class Protocol_local final : public Protocol {
 ******************************************************************************/
 
 /**
-  Rewrite the current query (to obfuscate passwords etc.) if needed
-  (i.e. only if we'll be writing the query to any of our logs).
+  Rewrite the current query (to obfuscate passwords etc.).
 
   Side-effect: thd->rewritten_query() may be populated with a rewritten
                query.  If the query is not of a rewritable type,
                thd->rewritten_query() will be empty.
 
   @param thd                thread handle
 */
-static inline void rewrite_query_if_needed(THD *thd) {
-  bool general =
-      (opt_general_log && !(opt_general_log_raw || thd->slave_thread));
-
-  if ((thd->sp_runtime_ctx == nullptr) &&
-      (general || opt_slow_log || opt_bin_log)) {
-    /*
-      thd->m_rewritten_query may already contain "PREPARE stmt FROM ..."
-      at this point, so we reset it here so mysql_rewrite_query()
-      won't complain.
-    */
-    thd->reset_rewritten_query();
-    /*
-      Now replace the "PREPARE ..." with the obfuscated version of the
-      actual query were prepare.
-    */
-    mysql_rewrite_query(thd);
-  }
+static inline void rewrite_query(THD *thd) {
+  /*
+    thd->m_rewritten_query may already contain "PREPARE stmt FROM ..."
+    at this point, so we reset it here so mysql_rewrite_query()
+    won't complain.
+  */
+  thd->reset_rewritten_query();
+  /*
+    Now replace the "PREPARE ..." with the obfuscated version of the
+    actual query were prepare.
+  */
+  mysql_rewrite_query(thd);
 }
 
 /**
@@ -2273,11 +2266,11 @@ bool Execute_sql_statement::execute_server_code(THD *thd) {
   thd->m_statement_psi = nullptr;
 
   /*
-    Rewrite first (if needed); execution might replace passwords
+    Rewrite first, execution might replace passwords
     with hashes in situ without flagging it, and then we'd make
     a hash of that hash.
   */
-  rewrite_query_if_needed(thd);
+  rewrite_query(thd);
   log_execute_line(thd);
 
   error = mysql_execute_command(thd);
@@ -2635,18 +2628,23 @@ bool Prepared_statement::prepare(THD *thd, const char *query_str,
 
   lex_end(m_lex);
 
-  rewrite_query_if_needed(thd);
+  rewrite_query(thd);
+
+  const char *display_query_string;
+  int display_query_length;
 
   if (thd->rewritten_query().length()) {
-    thd->set_query_for_display(thd->rewritten_query().ptr(),
-                               thd->rewritten_query().length());
-    MYSQL_SET_PS_TEXT(m_prepared_stmt, thd->rewritten_query().ptr(),
-                      thd->rewritten_query().length());
+    display_query_string = thd->rewritten_query().ptr();
+    display_query_length = thd->rewritten_query().length();
   } else {
-    thd->set_query_for_display(thd->query().str, thd->query().length);
-    MYSQL_SET_PS_TEXT(m_prepared_stmt, thd->query().str, thd->query().length);
+    display_query_string = thd->query().str;
+    display_query_length = thd->query().length;
   }
 
+  thd->set_query_for_display(display_query_string, display_query_length);
+  MYSQL_SET_PS_TEXT(m_prepared_stmt, display_query_string,
+                    display_query_length);
+
   cleanup_stmt(thd);
   stmt_backup.restore_thd(thd, this);
   thd->stmt_arena = old_stmt_arena;
@@ -3636,13 +3634,26 @@ bool Prepared_statement::execute(THD *thd, String *expanded_query,
     - Any passwords in the "Execute" line should be substituted with
       their hashes, or a notice.
 
-    Rewrite first (if needed); execution might replace passwords
+    Rewrite first, execution might replace passwords
     with hashes in situ without flagging it, and then we'd make
     a hash of that hash.
   */
-  rewrite_query_if_needed(thd);
+  rewrite_query(thd);
   log_execute_line(thd);
 
+  const char *display_query_string;
+  int display_query_length;
+
+  if (thd->rewritten_query().length()) {
+    display_query_string = thd->rewritten_query().ptr();
+    display_query_length = thd->rewritten_query().length();
+  } else {
+    display_query_string = thd->query().str;
+    display_query_length = thd->query().length;
+  }
+
+  mysql_thread_set_info(display_query_string, display_query_length);
+
   thd->binlog_need_explicit_defaults_ts =
       m_lex->binlog_need_explicit_defaults_ts;
   resource_group_switched = mgr_ptr->switch_resource_group_if_needed(

sql/sql_prepare.cc

@@ -325,7 +325,7 @@ bool rewrite_query(THD *thd, Consumer_type type, const Rewrite_params *params,
 
   The query aimed to be rewritten in the usual log files
   (i.e. General, slow query and audit log) uses default value of
-  type which is Consumer_type::LOG
+  type which is Consumer_type::TEXTLOG
 
    Side-effects:
 
@@ -339,18 +339,18 @@ bool rewrite_query(THD *thd, Consumer_type type, const Rewrite_params *params,
 
   @param thd        The THD to rewrite for.
   @param type       Purpose of rewriting the query
-                     Consumer_type::LOG
+                     Consumer_type::TEXTLOG
                       To rewrite the query either for general, slow query
                       and audit log.
                      Consumer_type::BINLOG
                       To rewrite the query for binlogs.
-                     Consumer_type::CONSOLE
+                     Consumer_type::STDOUT
                       To rewrite the query for standard output.
   @param params     Wrapper object of parameters in case needed by a SQL
                       rewriter.
 */
-void mysql_rewrite_query(THD *thd, Consumer_type type /*= Consumer_type::LOG */,
-                         const Rewrite_params *params /*= nullptr*/) {
+void mysql_rewrite_query(THD *thd, Consumer_type type,
+                         const Rewrite_params *params) {
   String rlb;
 
   DBUG_TRACE;
@@ -373,12 +373,12 @@ void mysql_rewrite_query(THD *thd, Consumer_type type /*= Consumer_type::LOG */,
   @param rlb        Buffer to return rewritten query in (if any) if
                     do_ps_instrument is false.
   @param type       Purpose of rewriting the query
-                     Consumer_type::LOG
+                     Consumer_type::TEXTLOG
                       To rewrite the query either for general, slow query
                       and audit log.
                      Consumer_type::BINLOG
                       To rewrite the query for binlogs.
-                     Consumer_type::CONSOLE
+                     Consumer_type::STDOUT
                       To rewrite the query for standard output.
   @param params     Wrapper object of parameters in case needed by a SQL
                       rewriter.
@@ -392,8 +392,18 @@ void mysql_rewrite_acl_query(THD *thd, String &rlb, Consumer_type type,
   if (rewrite_query(thd, type, params, rlb) && (rlb.length() > 0) &&
       do_ps_instrument) {
     thd->swap_rewritten_query(rlb);
-    thd->set_query_for_display(thd->rewritten_query().ptr(),
-                               thd->rewritten_query().length());
+
+    /*
+      Queries rewritten for Consumer_type::BINLOG may contain
+      sensitive informations, encoded in the binlog event.
+      Do not print these.
+      A subsequent call, using Consumer_type::TEXTLOG,
+      will display a proper sanitized query.
+    */
+    if (type != Consumer_type::BINLOG) {
+      thd->set_query_for_display(thd->rewritten_query().ptr(),
+                                 thd->rewritten_query().length());
+    }
     /*
       rlb now contains the previous rewritten query.
       We clear it here both to save memory and to prevent possible confusion.