MySQL Bugs: #58198: Read of freed memory when "USE db" and "SHOW PROCESSLIST"

Bug #58198	Read of freed memory when "USE db" and "SHOW PROCESSLIST"
Submitted:	15 Nov 2010 10:40	Modified:	22 Aug 2013 17:04
Reporter:	Guilhem Bichot	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: General	Severity:	S1 (Critical)
Version:	5.1.54,5.5.8,5.6	OS:	Linux
Assigned to:		CPU Architecture:	Any

Description:
I didn't check earlier versions. I am using next-mr-bugfixing
revision-id magne.mahre@oracle.com-20101110112645-e3gfx6kw5b0p3zkj .
If a connection changes its default database (with the "USE" command) and at the same moment another connection does "SHOW PROCESSLIST", that second connection, when it wants to read and display the first connection's default database, accesses invalid memory, which has been freed by the first connection (and potentially re-allocated to some completely different purpose than storing a database). It could crash. Valgrind points it out.

How to repeat:
Patch the server to introduce debug sync points, which make repeating easier:
=== modified file 'sql/sql_db.cc'
--- sql/sql_db.cc	2010-10-21 12:30:57 +0000
+++ sql/sql_db.cc	2010-11-15 10:20:25 +0000
@@ -1291,6 +1291,7 @@
       we just call THD::reset_db(). Since THD::reset_db() does not releases
       the previous database name, we should do it explicitly.
     */
+    DEBUG_SYNC(thd, "before_free_db");
     my_free(thd->db);
 
     thd->reset_db(new_db_name->str, new_db_name->length);

=== modified file 'sql/sql_show.cc'
--- sql/sql_show.cc	2010-11-03 14:31:27 +0000
+++ sql/sql_show.cc	2010-11-15 10:21:55 +0000
@@ -1818,7 +1818,11 @@
                                       tmp_sctx->host_or_ip : 
                                       tmp_sctx->host ? tmp_sctx->host : "");
         if ((thd_info->db=tmp->db))             // Safe test
+        {
+          if (thd_info->thread_id==3)
+            DEBUG_SYNC(thd, "after_read_db_ptr");
           thd_info->db=thd->strdup(thd_info->db);
+        }
         thd_info->command=(int) tmp->get_command();
         mysql_mutex_lock(&tmp->LOCK_thd_data);
         if ((mysys_var= tmp->mysys_var))

Then run this test:
./mtr --mem db --valgrind

db.test is:
connect (con1,localhost,root,,);
connect (con2,localhost,root,,);

connection con1;
create database test1;
use test1;
create database testlong;
set debug_sync= 'before_free_db SIGNAL db_is_readable WAIT_FOR db_is_read';
send use testlong;

  connection con2;
  set debug_sync= 'now WAIT_FOR db_is_readable';
  SET DEBUG_SYNC= 'after_read_db_ptr SIGNAL db_is_read WAIT_FOR freed_db';
  send SHOW PROCESSLIST;

connection con1;
reap;
set debug_sync="now SIGNAL freed_db";

connection con2;
reap;
drop database test1;
drop database testlong;

Suggested fix:
Analysis of the problem.
The second connection does SHOW PROCESSLIST which comes here in sql_show.cc:
        if ((thd_info->db=tmp->db))             // Safe test
        {
          thd_info->db=thd->strdup(thd_info->db);
        }
Between the evaluation of
thd_info->db=tmp->db
and of
thd_info->db=thd->strdup(thd_info->db);
there is a time window. Assume connection1 has set thd_info->db to tmp->db and there is a context switch (thread pauses). Then the first connection changes its default database, coming here in sql_db.cc:

  else
  {
    /*
      Here we already have a copy of database name to be used in THD. So,
      we just call THD::reset_db(). Since THD::reset_db() does not releases
      the previous database name, we should do it explicitly.
    */
    my_free(thd->db);

    thd->reset_db(new_db_name->str, new_db_name->length);
  }
This my_free() makes thd->db point to freed memory (which is thus illegal to access). Then the first connection resumes execution, and executes
thd_info->db=thd->strdup(thd_info->db);
which is reading freed data at the old address contained in thd_info->db. Valgrind complains:
==13778== Invalid read of size 1
==13778==    at 0x4C261D2: strlen (mc_replace_strmem.c:275)
==13778==    by 0xAFF491: strdup_root (my_alloc.c:414)
==13778==    by 0x5CE724: Query_arena::strdup(char const*) (sql_class.h:656)
==13778==    by 0x662F6E: mysqld_list_processes(THD*, char const*, bool) (sql_show.cc:1824)
==13778==    by 0x5F9257: mysql_execute_command(THD*) (sql_parse.cc:3036)
==13778==    by 0x5FFFB4: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5537)
==13778==    by 0x5F4175: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1056)
==13778==    by 0x5F3784: do_command(THD*) (sql_parse.cc:796)
==13778==    by 0x6DD054: do_handle_one_connection(THD*) (sql_connect.cc:745)
==13778==    by 0x6DCE8E: handle_one_connection (sql_connect.cc:684)
==13778==    by 0xAC9DEC: pfs_spawn_thread (pfs.cc:1078)
==13778==    by 0x4E30A03: start_thread (pthread_create.c:300)
==13778==    by 0x612CD4C: clone (clone.S:112)
==13778==  Address 0xefd2a70 is 0 bytes inside a block of size 6 free'd
==13778==    at 0x4C24D68: free (vg_replace_malloc.c:325)
==13778==    by 0xB0992E: my_free (my_malloc.c:128)
==13778==    by 0x5D47C3: mysql_change_db_impl(THD*, st_mysql_lex_string*, unsigned long, charset_info_st*) (sql_db.cc:1295)
==13778==    by 0x5D4E00: mysql_change_db(THD*, st_mysql_lex_string const*, bool) (sql_db.cc:1583)
==13778==    by 0x5F938A: mysql_execute_command(THD*) (sql_parse.cc:3064)
==13778==    by 0x5FFFB4: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5537)
==13778==    by 0x5F4175: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1056)
==13778==    by 0x5F3784: do_command(THD*) (sql_parse.cc:796)
==13778==    by 0x6DD054: do_handle_one_connection(THD*) (sql_connect.cc:745)
==13778==    by 0x6DCE8E: handle_one_connection (sql_connect.cc:684)
==13778==    by 0xAC9DEC: pfs_spawn_thread (pfs.cc:1078)
==13778==    by 0x4E30A03: start_thread (pthread_create.c:300)
==13778==    by 0x612CD4C: clone (clone.S:112)
(and other similar errors).
Worse: if the freed memory is already re-allocated to some other thread at this moment, we are doing strdup() on the other thread's data, data to which our user does not have access (table rows etc) which we'll see in SHOW PROCESSLIST; that data may not even be 0-terminated so strdup() can go wild.
Conclusion: this unprotected read of THD::db should be fixed. It looks like a classical mistake of threads programming :-(

related: bug 53822

full outputs from valgrind

Attachment: bug58198_5.5.8_valgrind_output.txt (text/plain), 7.40 KiB.

full outputs from valgrind

Attachment: bug58198_5.1.54_valgrind_output.txt (text/plain), 2.24 KiB.

Sorry Miguel; here is a working patch:
=== modified file 'sql/sql_db.cc'
--- sql/sql_db.cc	2010-10-21 12:30:57 +0000
+++ sql/sql_db.cc	2010-11-15 20:17:46 +0000
@@ -38,6 +38,7 @@
 #ifdef __WIN__
 #include <direct.h>
 #endif
+#include "debug_sync.h"
 
 #define MAX_DROP_TABLE_Q_LEN      1024
 
@@ -1291,6 +1292,7 @@
       we just call THD::reset_db(). Since THD::reset_db() does not releases
       the previous database name, we should do it explicitly.
     */
+    DEBUG_SYNC(thd, "before_free_db");
     my_free(thd->db);
 
     thd->reset_db(new_db_name->str, new_db_name->length);

=== modified file 'sql/sql_show.cc'
--- sql/sql_show.cc	2010-11-03 14:31:27 +0000
+++ sql/sql_show.cc	2010-11-15 10:21:55 +0000
@@ -1818,7 +1818,11 @@
                                       tmp_sctx->host_or_ip : 
                                       tmp_sctx->host ? tmp_sctx->host : "");
         if ((thd_info->db=tmp->db))             // Safe test
+        {
+          if (thd_info->thread_id==3)
+            DEBUG_SYNC(thd, "after_read_db_ptr");
           thd_info->db=thd->strdup(thd_info->db);
+        }
         thd_info->command=(int) tmp->get_command();
         mysql_mutex_lock(&tmp->LOCK_thd_data);
         if ((mysys_var= tmp->mysys_var))

Guilhem, Miguel, you need no patches to repeat the bug.
Just run in 10 threads:

use test
use information_schema
use mysql
show processlist

Thank you for the feedback.

I keep hitting this bug.  The way I call stored routines is like this:

CALL test.p1();

The current database is NULL. This means any connection running show processlist
while this sp is running might cause a read of freed memory!

calling a `database`.`stored_routine`() and show processlist yields this..

Attachment: bug58198_5.5.14_valgrind_stored_routine.txt (text/plain), 2.30 KiB.

Still affects mysql-trunk(5.7.1)

create database if not exists aaaaaaaaaaaaaaa;
drop procedure if exists aaaaaaaaaaaaaaa.p1;
create procedure aaaaaaaaaaaaaaa.p1() select now();

call aaaaaaaaaaaaaaa.p1(); #in a bunch of threads
show processlist;          #in one thread.

--------------
Invalid read of size 8
at: memcpy@@GLIBC_2.14 (mc_replace_strmem.c:881)
by: strmake_root (my_alloc.c:436)
by: mysqld_list_processes (sql_show.cc:2081)
by: mysql_execute_command (sql_parse.cc:3468)
by: mysql_parse (sql_parse.cc:6020)
by: dispatch_command (sql_parse.cc:1329)
by: do_handle_one_connection(THD*) (sql_connect.cc:977)
by: handle_one_connection (sql_connect.cc:893)
by: pfs_spawn_thread (pfs.cc:1922)
by: start_thread (pthread_create.c:309)
by: clone (clone.S:115)
 Address 0x1a07ed00 is 0 bytes inside a block of size 16 free'd
at: free (vg_replace_malloc.c:446)
by: mysql_change_db_impl (sql_db.cc:1314)
by: mysql_change_db (sql_db.cc:1605)
by: sp_head::execute (sp_head.cc:801)
by: sp_head::execute_procedure(THD*, List<Item>*) (sp_head.cc:1338)
by: mysql_execute_command (sql_parse.cc:4334)
by: mysql_parse (sql_parse.cc:6020)
by: dispatch_command (sql_parse.cc:1329)
by: do_handle_one_connection(THD*) (sql_connect.cc:977)
by: handle_one_connection (sql_connect.cc:893)
by: pfs_spawn_thread (pfs.cc:1922)
by: start_thread (pthread_create.c:309)
by: clone (clone.S:115)

I confirm 5.6.10 is affected.   Running mysqld in valgrind, and the following statements in 50 threads gets a problem quick:

use test;
use information_schema;
use mysql;
show processlist;

==26055== Invalid read of size 1
==26055==    at 0x4A0B639: __GI_memmove (mc_replace_strmem.c:1027)
==26055==    by 0x9161B8: strmake_root (my_alloc.c:436)
==26055==    by 0x74FAC9: mysqld_list_processes(THD*, char const*, bool) (sql_class.h:745)
==26055==    by 0x71263A: mysql_execute_command(THD*) (sql_parse.cc:3590)
==26055==    by 0x7188C7: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:6149)
==26055==    by 0x7191E6: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1334)
==26055==    by 0x71A486: do_command(THD*) (sql_parse.cc:1036)
==26055==    by 0x6E4C75: do_handle_one_connection(THD*) (sql_connect.cc:969)
==26055==    by 0x6E4D54: handle_one_connection (sql_connect.cc:885)
==26055==    by 0x3679C07D13: start_thread (pthread_create.c:309)
==26055==    by 0x36798F168C: clone (clone.S:115)
==26055==  Address 0x14fb74b2 is 2 bytes inside a block of size 6 free'd
==26055==    at 0x4A07786: free (vg_replace_malloc.c:446)
==26055==    by 0x6E7656: mysql_change_db_impl(THD*, st_mysql_lex_string*, unsigned long, charset_info_st const*) (sql_db.cc:1315)
==26055==    by 0x6E79CC: mysql_change_db(THD*, st_mysql_lex_string const*, bool) (sql_db.cc:1603)
==26055==    by 0x71429E: mysql_execute_command(THD*) (sql_parse.cc:3612)
==26055==    by 0x7188C7: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:6149)
==26055==    by 0x7191E6: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1334)
==26055==    by 0x71A486: do_command(THD*) (sql_parse.cc:1036)
==26055==    by 0x6E4C75: do_handle_one_connection(THD*) (sql_connect.cc:969)
==26055==    by 0x6E4D54: handle_one_connection (sql_connect.cc:885)
==26055==    by 0x3679C07D13: start_thread (pthread_create.c:309)
==26055==    by 0x36798F168C: clone (clone.S:115)

Noted in 5.1.72, 5.5.34, 5.6.14, 5.7.3 changelogs.

If one connection changed its default database and simultaneously
another connection executed SHOW PROCESSLIST, the second connection
could access invalid memory when attempting to display the first
connection's default database. memory.

5.1$ bzr log -r 4037
------------------------------------------------------------
revno: 4037
committer: Praveenkumar Hulakund <praveenkumar.hulakund@oracle.com>
branch nick: mysql_5_1
timestamp: Wed 2013-08-21 10:39:40 +0530
message:
  Bug#11765252 - READ OF FREED MEMORY WHEN "USE DB" AND
                 "SHOW PROCESSLIST"
  
  Analysis:
  ----------
  The problem here is, if one connection changes its
  default db and at the same time another connection executes
  "SHOW PROCESSLIST", when it wants to read db of the another
  connection then there is a chance of accessing the invalid
  memory. 
  
  The db name stored in THD is not guarded while changing user
  DB and while reading the user DB in "SHOW PROCESSLIST".
  So, if THD.db is freed by thd "owner" thread and if another
  thread executing "SHOW PROCESSLIST" statement tries to read
  and copy THD.db at the same time then we may endup in the issue
  reported here.
  
  Fix:
  ----------
  Used mutex "LOCK_thd_data" to guard THD.db while freeing it
  and while copying it to processlist.

5.5$ bzr log -r 4442 -n0
------------------------------------------------------------
revno: 4442 [merge]
committer: Praveenkumar Hulakund <praveenkumar.hulakund@oracle.com>
branch nick: mysql_5_5
timestamp: Wed 2013-08-21 10:44:22 +0530
message:
  Bug#11765252 - READ OF FREED MEMORY WHEN "USE DB" AND
                 "SHOW PROCESSLIST"
  
  Merging from 5.1 to 5.5
    ------------------------------------------------------------
    revno: 2661.844.61
    committer: Praveenkumar Hulakund <praveenkumar.hulakund@oracle.com>
    branch nick: mysql_5_1
    timestamp: Wed 2013-08-21 10:39:40 +0530
    message:
      Bug#11765252 - READ OF FREED MEMORY WHEN "USE DB" AND
                     "SHOW PROCESSLIST"
      
      Analysis:
      ----------
      The problem here is, if one connection changes its
      default db and at the same time another connection executes
      "SHOW PROCESSLIST", when it wants to read db of the another
      connection then there is a chance of accessing the invalid
      memory. 
      
      The db name stored in THD is not guarded while changing user
      DB and while reading the user DB in "SHOW PROCESSLIST".
      So, if THD.db is freed by thd "owner" thread and if another
      thread executing "SHOW PROCESSLIST" statement tries to read
      and copy THD.db at the same time then we may endup in the issue
      reported here.
      
      Fix:
      ----------
      Used mutex "LOCK_thd_data" to guard THD.db while freeing it
      and while copying it to processlist.

5.5$ bzr log -r 4455
------------------------------------------------------------
revno: 4455
committer: Praveenkumar Hulakund <praveenkumar.hulakund@oracle.com>
branch nick: mysql_5_5
timestamp: Fri 2013-08-23 18:56:31 +0530
message:
  Bug#11765252 - READ OF FREED MEMORY WHEN "USE DB" AND
                 "SHOW PROCESSLIST"
  
  Follow up path, addressing pb2 test failure.

It is not easy to crash the server even this bug is hit because the freed memory address is invalid.

I tested the following codes and concluded that the behaviour is depended on the implementation of malloc/free.

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <time.h>

int main(int argc, char *argv[])
{
  const char *str = "hello world!";
  int len = strlen(str)+1;

  srand((unsigned)time(NULL));

  for (;;)
  {
    char *dump = (char*)malloc(len);
    memset(dump, 0, len);
    strcpy(dump, str);
    
    printf("len: %d, ", len);
    printf("before free: %p, %s, %d, ", dump, dump, strlen(dump));
    free(dump);
    printf("after free: %p, %s, %d\n", dump, dump, strlen(dump));
    
    len += rand() % 16;                                                                                                               
  }
  return 0;
}

It is not easy to crash the server even this bug is hit because the freed memory address is invalid.

-->

It is not easy to crash the server even this bug is hit because the freed memory address is valid.