Bug #104121 PSI_THREAD_INFO not updated while executing PREPARED STATEMENTS.
Submitted: 26 Jun 2021 15:19 Modified: 24 May 2024 13:12
Reporter: Pranay Motupalli Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S3 (Non-critical)
Version:>=5.7.28 , >=8.0.18, 8.0.25, 5.7.34 OS:Any
Assigned to: Marc ALFF CPU Architecture:Any

[26 Jun 2021 15:19] Pranay Motupalli
Description:
PSI_THREAD_INFO doesn't' get updated while executing a PREPARED STATEMENT. This is a regression caused due to commit https://github.com/mysql/mysql-server/commit/afcaac4d6f8aecc70c418138f1d8dd4e4965e629

How to repeat:
Used tpcc-mysql tool to generate load. Source: https:/github.com/Percona-Lab/tpcc-mysql

Create MySQL server with version 5.7.28/8.0.18 or above.

cd tpcc-mysql
mysql -uroot -pxxxxx -h x.x.x.x -e "CREATE DATABASE tpcc10;"
mysql -uroot -pxxxxxx -h x.x.x.x tpcc10 < create_table.sql
mysql -uroot -pxxxxxx -h x.x.x.x tpcc10 < add_fkey_idx.sql
./tpcc_load -h xxxxx -uroot -pxxxxxxx -w 1 -d tpcc10
./tpcc_start -h xxxxx -uroot -pxxxxxxx -w 1 -d tpcc10 -c10 -r1 -l1200 &

When load is running, run the following query:

mysql> select a.processlist_info,b.info from performance_schema.threads a , information_schema.processlist b where a.processlist_id=b.id\G
*************************** 1. row ***************************
processlist_info: SELECT 1
            info: NULL
*************************** 2. row ***************************
processlist_info: select a.processlist_info,b.info from performance_schema.threads a , information_schema.processlist b where a.processlist_id=b.id
            info: select a.processlist_info,b.info from performance_schema.threads a , information_schema.processlist b where a.processlist_id=b.id
*************************** 3. row ***************************
processlist_info: commit
            info: NULL
*************************** 4. row ***************************
processlist_info: commit
            info: NULL
*************************** 5. row ***************************
processlist_info: commit
            info: SELECT i_price, i_name, i_data FROM item WHERE i_id = ?
*************************** 6. row ***************************
processlist_info: commit
            info: UPDATE warehouse SET w_ytd = w_ytd + 3584 WHERE w_id = 1
*************************** 7. row ***************************
processlist_info: commit
            info: commit
*************************** 8. row ***************************
processlist_info: commit
            info: SELECT d_next_o_id, d_tax FROM district WHERE d_id = ? AND d_w_id = ? FOR UPDATE
*************************** 9. row ***************************
processlist_info: commit
            info: UPDATE warehouse SET w_ytd = w_ytd + 4889 WHERE w_id = 1
*************************** 10. row ***************************
processlist_info: commit
            info: NULL
*************************** 11. row ***************************
processlist_info: commit
            info: NULL
*************************** 12. row ***************************
processlist_info: commit
            info: UPDATE warehouse SET w_ytd = w_ytd + 4366 WHERE w_id = 1
12 rows in set (0.00 sec)

As you can see, PROCESSLIST_INFO and PSI_THREAD_INFO is not matching for all the queries except the current executed query. The non matching ones are prepared statements. It works for normal query as we call set_query_for_display in mysql_parse function.

The reason why we are seeing commit in PROCESSLIST_INFO is that 'commit' here is the previously executed statement on the same thread. This is also a bug which I reported before https://bugs.mysql.com/bug.php?id=99039

#####################################

Analysis:
########

5.7.26:
#######

void THD::set_query(const LEX_CSTRING& query_arg)
{
  DBUG_ASSERT(this == current_thd);
  mysql_mutex_lock(&LOCK_thd_query);
  m_query_string= query_arg;
  mysql_mutex_unlock(&LOCK_thd_query);

#ifdef HAVE_PSI_THREAD_INTERFACE
  PSI_THREAD_CALL(set_thread_info)(query_arg.str, query_arg.length);    ----------------> This one was removed and placed in set_query_for_display() function in sql_class.h. In versions >= 5.7.28/8.0.18, this function is not being called.
#endif
}

void set_thd_to_ps(THD *thd, Prepared_statement *stmt)
{
  DBUG_ENTER("Statement_backup::set_thd_to_ps");

  mysql_mutex_lock(&thd->LOCK_thd_data);
  m_lex=    thd->lex;
  thd->lex= stmt->lex;
  mysql_mutex_unlock(&thd->LOCK_thd_data);

  m_query_string= thd->query();
  thd->set_query(stmt->m_query_string);     ---------> set_query is being called in all versions.

  DBUG_VOID_RETURN;
}

Stack Trace:
-----------

Breakpoint 1, THD::set_query (this=this@entry=0x2b5241c7a000, query_arg=...) at /sql/sql_class.cc:4357
4357	/sql/sql_class.cc: No such file or directory.
(gdb) bt
#0  THD::set_query (this=this@entry=0x2b5241c7a000, query_arg=...) at /sql/sql_class.cc:4357
#1  0x0000000000d26e31 in set_thd_to_ps (stmt=0x2b5241d91180, thd=0x2b5241c7a000, this=<synthetic pointer>) at /sql/sql_prepare.cc:299
#2  Prepared_statement::execute (this=this@entry=0x2b5241d91180, expanded_query=expanded_query@entry=0x2b4f245ef490, open_cursor=open_cursor@entry=false)
    at /sql/sql_prepare.cc:3878
#3  0x0000000000d29fc3 in Prepared_statement::execute_loop (this=0x2b5241d91180, expanded_query=0x2b4f245ef490, open_cursor=<optimized out>, packet=<optimized out>, packet_end=<optimized out>)
    at /sql/sql_prepare.cc:3585
#4  0x0000000000d2a2eb in mysqld_stmt_execute (thd=thd@entry=0x2b5241c7a000, stmt_id=<optimized out>, flags=0, params=0x2b5241cf98ea "", params_length=20)
    at /sql/sql_prepare.cc:2573
#5  0x0000000000cffee6 in dispatch_command (thd=thd@entry=0x2b5241c7a000, com_data=com_data@entry=0x2b4f245efd10, command=COM_STMT_EXECUTE)
    at /sql/sql_parse.cc:1421
#6  0x0000000000d00e13 in do_command (thd=thd@entry=0x2b5241c7a000) at /sql/sql_parse.cc:1028
#7  0x0000000000dbfc18 in handle_connection (arg=arg@entry=0x2b50af5ffa40) at /sql/conn_handler/connection_handler_per_thread.cc:306
#8  0x00000000012ead59 in pfs_spawn_thread (arg=0x2b521d3a8460) at /storage/perfschema/pfs.cc:2190
#9  0x00002b4f23c92dc5 in start_thread () from /lib64/libpthread.so.0
#10 0x00002b4f23f9dc9d in clone () from /lib64/libc.so.6
(gdb) p query_arg
$1 = (const LEX_CSTRING &) @0x2b5241d913d0: {str = 0x2b5245a90a50 "SELECT count(*) FROM stock WHERE s_w_id = ? AND s_i_id = ? AND s_quantity < ?", length = 77}

5.7.28:
#######

void THD::set_query(const LEX_CSTRING& query_arg)
{
  DBUG_ASSERT(this == current_thd);
  mysql_mutex_lock(&LOCK_thd_query);
  m_query_string= query_arg;
  mysql_mutex_unlock(&LOCK_thd_query);
}

Update function for PSI_THREAD_INFO was moved to set_query_for_display and mysql doesn't call it.

void set_query_for_display(const char *query_arg, size_t query_length_arg) {
    MYSQL_SET_STATEMENT_TEXT(m_statement_psi, query_arg, query_length_arg);
#ifdef HAVE_PSI_THREAD_INTERFACE
    PSI_THREAD_CALL(set_thread_info)(query_arg, query_length_arg);
#endif
  }

Stack Trace: 
-----------

It never touched the set_query_for_display function here but touches set_query as expected but doesn't set PSI_THREAD_INFO.

Breakpoint 9, THD::set_query (this=this@entry=0x2b9e9f21d000, query_arg=...) at /sql/sql_class.cc:4364
4364	/sql/sql_class.cc: No such file or directory.
(gdb) bt
#0  THD::set_query (this=this@entry=0x2b9e9f21d000, query_arg=...) at /sql/sql_class.cc:4364
#1  0x0000000000d26ef1 in set_thd_to_ps (stmt=0x2b9e9f2e2f80, thd=0x2b9e9f21d000, this=<synthetic pointer>) at /sql/sql_prepare.cc:306
#2  Prepared_statement::execute (this=this@entry=0x2b9e9f2e2f80, expanded_query=expanded_query@entry=0x2b9b85585490, open_cursor=open_cursor@entry=false)
    at /sql/sql_prepare.cc:3886
#3  0x0000000000d2a0a3 in Prepared_statement::execute_loop (this=0x2b9e9f2e2f80, expanded_query=0x2b9b85585490, open_cursor=<optimized out>, packet=<optimized out>, packet_end=<optimized out>)
    at /sql/sql_prepare.cc:3593
#4  0x0000000000d2a3cb in mysqld_stmt_execute (thd=thd@entry=0x2b9e9f21d000, stmt_id=<optimized out>, flags=0, params=0x2b9e9f27f6ea "", params_length=14)
    at /sql/sql_prepare.cc:2581
#5  0x0000000000cfffe5 in dispatch_command (thd=thd@entry=0x2b9e9f21d000, com_data=com_data@entry=0x2b9b85585d10, command=COM_STMT_EXECUTE)
    at /sql/sql_parse.cc:1428
#6  0x0000000000d00ea3 in do_command (thd=thd@entry=0x2b9e9f21d000) at /sql/sql_parse.cc:1035
#7  0x0000000000dc01a8 in handle_connection (arg=arg@entry=0x2b9cf6bfc0a0) at /sql/conn_handler/connection_handler_per_thread.cc:313
#8  0x00000000012eb849 in pfs_spawn_thread (arg=0x2b9e7e3a9260) at /storage/perfschema/pfs.cc:2197
#9  0x00002b9b84c28dc5 in start_thread () from /lib64/libpthread.so.0
#10 0x00002b9b84f33c9d in clone () from /lib64/libc.so.6

NON-PREPARED STATEMENT:
----------------------
(gdb) bt
#0  pfs_set_thread_info_v1 (info=info@entry=0x2b9ea5d4f030 "commit", info_len=info_len@entry=6) at /storage/perfschema/pfs.cc:2527
#1  0x0000000000cfe7f3 in set_query_for_display (query_length_arg=<optimized out>, query_arg=<optimized out>, this=0x2b9ea5d1a000) at /sql/sql_class.h:4398
#2  mysql_parse (thd=thd@entry=0x2b9ea5d1a000, parser_state=parser_state@entry=0x2b9b8f7036b0) at /sql/sql_parse.cc:5667
#3  0x0000000000cff302 in dispatch_command (thd=thd@entry=0x2b9ea5d1a000, com_data=com_data@entry=0x2b9b8f703d10, command=COM_QUERY)
    at /sql/sql_parse.cc:1497
#4  0x0000000000d00ea3 in do_command (thd=thd@entry=0x2b9ea5d1a000) at /sql/sql_parse.cc:1035
#5  0x0000000000dc01a8 in handle_connection (arg=arg@entry=0x2b9cf6bfcdc0) at /sql/conn_handler/connection_handler_per_thread.cc:313
#6  0x00000000012eb849 in pfs_spawn_thread (arg=0x2b9e7e3a8ee0) at /storage/perfschema/pfs.cc:2197
#7  0x00002b9b84c28dc5 in start_thread () from /lib64/libpth

Suggested fix:
Root Cause:
----------
Regression due to commit https://github.com/mysql/mysql-server/commit/afcaac4d6f8aecc70c418138f1d8dd4e4965e629

Proposed Solution:
------------------
Call set_query_for_display in THD::set_query function.
[28 Jun 2021 14:46] Pranay Motupalli
root@ip-172-31-50-102:~/mysql-server# git diff @{upstream}
diff --git a/sql/sql_class.cc b/sql/sql_class.cc
index b8f43573b21..5c0dc2ffb01 100644
--- a/sql/sql_class.cc
+++ b/sql/sql_class.cc
@@ -4369,6 +4369,7 @@ void THD::set_query(const LEX_CSTRING& query_arg)
   mysql_mutex_lock(&LOCK_thd_query);
   m_query_string= query_arg;
   mysql_mutex_unlock(&LOCK_thd_query);
+  current_thd->set_query_for_display(query_arg.str, query_arg.length);
 }
[29 Jun 2021 5:30] MySQL Verification Team
Hello Pranay,

Thank you for the report and feedback.
Verified as described.

regards,
Umesh
[29 Jun 2021 6:21] MySQL Verification Team
MySQL Server 8.0.25, 5.7.34 test results

Attachment: 104121.results (application/octet-stream, text), 16.37 KiB.

[29 Jun 2021 6:27] MySQL Verification Team
Hi Pranay,

Please note that in order to submit contributions you must first sign the Oracle Contribution Agreement (OCA). More details are described in "Contributions" tab. Also, once you sign OCA ensure to re-send the patch via "Contributions" tab.
Otherwise we would not be able to accept it.

regards,
Umesh
[30 Jun 2021 1:04] Pranay Motupalli
I hereby submit the above one-lined under public domain for anybody to use freely. I will not sign the OCA.
[17 Aug 2021 17:29] Pranay Motupalli
Hi Team,

Can you please provide the status of this bug fix.

Thanks
[2 May 2023 22:28] Daniel Lenski
> This is a regression caused due to commit https://github.com/mysql/mysql-server/commit/afcaac4d6f8aecc70c418138f1d8dd4e4965e629

We can be *more precise* about what caused this regression.

It was, very specifically, the removal of the following 3 lines from sql/sql_class.cc
https://github.com/mysql/mysql-server/commit/afcaac4d6f8aecc70c418138f1d8dd4e4965e629#diff...

    diff --git a/sql/sql_class.cc b/sql/sql_class.cc
    index 49ac2015b3ba..91cfb7ca73fc 100644
    --- a/sql/sql_class.cc
    +++ b/sql/sql_class.cc
    @@ -4354,10 +4354,6 @@ void THD::set_query(const LEX_CSTRING& query_arg)
       mysql_mutex_lock(&LOCK_thd_query);
       m_query_string= query_arg;
       mysql_mutex_unlock(&LOCK_thd_query);
    -
    -#ifdef HAVE_PSI_THREAD_INTERFACE
    -  PSI_THREAD_CALL(set_thread_info)(query_arg.str, query_arg.length);
    -#endif
     }

The one-line patch provided in https://bugs.mysql.com/bug.php?id=104121#c513825 has the unwanted side effect of overwriting `performance_schema.events_statements_history.SQL_TEXT` and causing it to appear as `NULL`.

The safest fix is simply to re-add the removed lines (above), since those caused the regression.
[4 May 2023 18:27] Daniel Lenski
My colleague has now submitted a pull request to resolve this bug.

(The PR description includes manual demonstrating that the PR does not reintroduce unobfuscated passwords into the query text in PERFORMANCE_SCHEMA.THREADS table.)

https://github.com/mysql/mysql-server/pull/462
[27 Jun 2023 18:30] Daniel Lenski
Adding a new comment here to try to debug why Oracle team cannot see my account.
[14 Feb 2024 14:11] OCA Admin
Contribution submitted via Github - Bug#104121: Ensure that PREPAREd statements are shown correctly in PERFORMANCE_S 
(*) Contribution by Daniel Lenski (Github dlenski, mysql-server/pull/519#issuecomment-1942861612): This contribution is under the OCA signed by Amazon and covering submissions to the MySQL project.

Contribution: git_patch_1724489440.txt (text/plain), 3.91 KiB.

[20 Mar 2024 14:34] Marc ALFF
Thanks for submitting this contribution on Feb 14, 2014,
under the terms of the OCA.

Our technical analysis of the contribution is as follows.

1)

The fix for:
  Bug#20712046: SHOW PROCESSLIST AND PERFORMANCE_SCHEMA TABLES DO NOT MASK PASSWORD FROM QUERY

indeed caused the regression reported in:
  Bug#104121 PSI_THREAD_INFO not updated while executing PREPARED STATEMENTS

The analysis is correct here.

2)

The proposed contribution:
  From 9b03ce5519273efdcecc2ef0a484f59e6997be7d Mon Sep 17 00:00:00 2001
  From: Daniel Lenski <dlenski@amazon.com>
  Date: Tue, 13 Feb 2024 11:17:52 -0800
  Subject: [PATCH] Bug#104121: Ensure that PREPAREd statements are shown
   correctly in PERFORMANCE_SCHEMA.THREADS table

claims that:
  We verified that this change *does not* undo the intended effect of the
  original commit. Passwords (still) do not leak into the
  `PERFORMANCE_SCHEMA.THREADS` table with this change:

Our assessment of the patch is different.

Applying the proposed patch on top of the current MySQL code,
and applying the extra following change:

--- begin diff
malff@malff-desktop GIT_BUG33057164_AMAZON]$ git diff storage/perfschema/pfs.cc
diff --git a/storage/perfschema/pfs.cc b/storage/perfschema/pfs.cc
index 5a0bde3cd54..d0f834f19dc 100644
--- a/storage/perfschema/pfs.cc
+++ b/storage/perfschema/pfs.cc
@@ -3389,6 +3389,10 @@ void pfs_set_thread_info_vc(const char *info, uint info_len) {
   pfs_dirty_state dirty_state;
   PFS_thread *pfs = my_thread_get_THR_PFS();
 
+  if (info != nullptr) {
+    fprintf(stderr, "THREAD.PROCESSLIST_INFO = %.*s\n", info_len, info);
+  }
+
   if (likely(pfs != nullptr)) {
     if (info_len > sizeof(pfs->m_processlist_info)) {
       info_len = sizeof(pfs->m_processlist_info);
--- end diff

shows that, after issuing the following query:
  CREATE USER alice IDENTIFIED BY 'thisisapassword';

the stderr log contains:
  THREAD.PROCESSLIST_INFO = CREATE USER alice IDENTIFIED BY 'thisisapassword'
  THREAD.PROCESSLIST_INFO = CREATE USER 'alice'@'%' IDENTIFIED BY <secret>

In other words, the full query, including sensitive data like
the password in cleartext, is printed in table performance_schema.threads
when this patch is applied.

Actually observing the sensitive data might be difficult in practice,
because the PROCESSLIST_INFO column is soon overwritten with the
sanitized version (as seen in the second line),
but the fact remains that sensitive data is leaked.

The proposed patch contains a security vulnerability,
and can not be accepted as is.

This issue:
  Bug#104121 PSI_THREAD_INFO not updated while executing PREPARED STATEMENTS
is still unresolved at this point.
[20 Mar 2024 14:37] Marc ALFF
Correction:
  Thanks for submitting this contribution on Feb 14, 2024.
[24 May 2024 13:12] Edward Gilmore
Posted by developer:
 
Added the following note to the MySQL Server 8.0.38, 8.4.1, and 9.0.0 release notes:
	
    The PROCESSLIST_INFO column of THREADS was not updated when executing a prepared statement.

Thank you for the bug report.