[MDEV-16368] server crash when query_cache_type is changed Created: 2018-06-01  Updated: 2023-11-28

Status: Confirmed
Project: MariaDB Server
Component/s: Query Cache
Affects Version/s: 5.5, 10.0, 10.1, 10.2, 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10, 10.11
Fix Version/s: 10.4, 10.5, 10.6

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Oleksandr Byelkin
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-10826 Assertion `thd->get_stmt_da()->is_eof... Confirmed
relates to MDEV-14526 MariaDB keeps crashing under load whe... Closed
relates to MDEV-16007 Buffer overflow when turning off quer... Closed

 Description   

testcase from MDEV-14526, run with --repeat=N 

CREATE TABLE t1 (
 
  `id` int(10) NOT NULL AUTO_INCREMENT,
 
  `k` int(10) NOT NULL default '0',
 
  PRIMARY KEY (`id`)) 
ENGINE=MyISAM;
 
 
INSERT IGNORE INTO t1 VALUES
 
  (NULL,1),(NULL,8),(NULL,NULL),(NULL,NULL),(NULL,4),(NULL,9),(NULL,7),
 
  (NULL,3),(NULL,NULL),(NULL,2),(NULL,3),(NULL,NULL),(NULL,2),(NULL,7), 
  (NULL,1),(NULL,2),(NULL,4),(NULL,NULL),(NULL,1),(NULL,1),(NULL,4);
 
 
SET GLOBAL query_cache_size= 1024*1024;
 
SET GLOBAL query_cache_type= 1;
 
 
--connect (con1,localhost,root,,test)
 
--send
 
	SELECT DISTINCT id FROM t1 WHERE id BETWEEN 5603 AND 16218 ORDER BY k;
 
 
--connection default
 
SET GLOBAL query_cache_type= 0;
 
 
--connection con1
 
--reap
 
 
# Cleanup
 
--disconnect con1
 
--connection default
 
DROP TABLE t1;
 
SEt GLOBAL query_cache_size= DEFAULT;
 
SEt GLOBAL query_cache_type= DEFAULT;


5.5 1ada4afb0a51f7283b6187a95019ec2cb80c8a0b
 
Thread 1 (Thread 0x7feb86778700 (LWP 21990)):
 
#0  __pthread_kill (threadid=<optimized out>, signo=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
 
#1  0x0000000000ce27b9 in my_write_core (sig=11) at /home/alice/git/5.5/mysys/stacktrace.c:457
 
#2  0x00000000007c7b14 in handle_fatal_signal (sig=11) at /home/alice/git/5.5/sql/signal_handler.cc:262
 
#3  <signal handler called>
 
#4  0x00000000005b9b0c in inline_mysql_rwlock_unlock (that=0x7fec6dfebcd0) at /home/alice/git/5.5/include/mysql/psi/mysql_thread.h:913
 
#5  0x00000000005c804b in Query_cache_query::unlock_writing (this=0x7fec6dfebcc8) at /home/alice/git/5.5/sql/sql_cache.cc:944
 
#6  0x00000000005bccd5 in Query_cache::store_query (this=0x15878e0 <query_cache>, thd=0x291a890, tables_used=0x7feb70004f90) at /home/alice/git/5.5/sql/sql_cache.cc:1566
 
#7  0x000000000060f41b in execute_sqlcom_select (thd=0x291a890, all_tables=0x7feb70004f90) at /home/alice/git/5.5/sql/sql_parse.cc:4677
 
#8  0x000000000060815c in mysql_execute_command (thd=0x291a890) at /home/alice/git/5.5/sql/sql_parse.cc:2224
 
#9  0x0000000000612268 in mysql_parse (thd=0x291a890, rawbuf=0x7feb70004d38 "SELECT DISTINCT id FROM t1 WHERE id BETWEEN 5603 AND 16218 ORDER BY k", length=69, parser_state=0x7feb867776b0) at /home/alice/git/5.5/sql/sql_parse.cc:5923
 
#10 0x00000000006055ff in dispatch_command (command=COM_QUERY, thd=0x291a890, packet=0x2920ce1 "SELECT DISTINCT id FROM t1 WHERE id BETWEEN 5603 AND 16218 ORDER BY k", packet_length=69) at /home/alice/git/5.5/sql/sql_parse.cc:1066
 
#11 0x00000000006047be in do_command (thd=0x291a890) at /home/alice/git/5.5/sql/sql_parse.cc:793
 
#12 0x0000000000713eee in do_handle_one_connection (thd_arg=0x291a890) at /home/alice/git/5.5/sql/sql_connect.cc:1268
 
#13 0x0000000000713c66 in handle_one_connection (arg=0x291a890) at /home/alice/git/5.5/sql/sql_connect.cc:1184
 
#14 0x0000000000c8f24e in pfs_spawn_thread (arg=0x28ddcd0) at /home/alice/git/5.5/storage/perfschema/pfs.cc:1015
 
#15 0x00007feb8a3096ba in start_thread (arg=0x7feb86778700) at pthread_create.c:333
 
#16 0x00007feb899b441d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109



 Comments   
Comment by Elena Stepanova [ 2018-07-17 ]

ASAN variation of it (also non-deterministic):

10.0 1fd84f9129

 
==12901==ERROR: AddressSanitizer: heap-use-after-free on address 0x7f10d93b5a80 at pc 0x610c20 bp 0x7f10d90a9000 sp 0x7f10d90a8ff8
 
READ of size 4 at 0x7f10d93b5a80 thread T7
 
    #0 0x610c1f in Query_cache_block::query() /data/src/10.0/sql/sql_cache.cc:855
 
    #1 0x61e49d in Query_cache::store_query(THD*, TABLE_LIST*) /data/src/10.0/sql/sql_cache.cc:1573
 
    #2 0x6b6584 in execute_sqlcom_select /data/src/10.0/sql/sql_parse.cc:5297
 
    #3 0x6ce43a in mysql_execute_command(THD*) /data/src/10.0/sql/sql_parse.cc:2554
 
    #4 0x6e4498 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.0/sql/sql_parse.cc:6634
 
    #5 0x6e80b7 in dispatch_command(enum_server_command, THD*, char*, unsigned int) /data/src/10.0/sql/sql_parse.cc:1297
 
    #6 0x6ec9b0 in do_command(THD*) /data/src/10.0/sql/sql_parse.cc:1000
 
    #7 0x97bbd9 in do_handle_one_connection(THD*) /data/src/10.0/sql/sql_connect.cc:1377
 
    #8 0x97be40 in handle_one_connection /data/src/10.0/sql/sql_connect.cc:1292
 
    #9 0x11b7e52 in pfs_spawn_thread /data/src/10.0/storage/perfschema/pfs.cc:1861
 
    #10 0x7f10e3f9c493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
    #11 0x7f10e235593e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
 
 
 
0x7f10d93b5a80 is located 640 bytes inside of 1031676-byte region [0x7f10d93b5800,0x7f10d94b15fc)
 
freed by thread T7 here:
 
    #0 0x7f10e4206527 in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x54527)
 
    #1 0x18f684d in free_memory /data/src/10.0/mysys/safemalloc.c:276
 
 
 
previously allocated by thread T6 here:
 
    #0 0x7f10e420673f in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x5473f)
 
    #1 0x18f691e in sf_malloc /data/src/10.0/mysys/safemalloc.c:115
 
    #2 0x19d9bca (/data/bld/10.0-asan/bin/mysqld+0x19d9bca)
 
 
 
Thread T7 created by T0 here:
 
    #0 0x7f10e41d5bba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
 
    #1 0x11c36a9 in spawn_thread_v1 /data/src/10.0/storage/perfschema/pfs.cc:1911
 
 
 
Thread T6 created by T0 here:
 
    #0 0x7f10e41d5bba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
 
    #1 0x11c36a9 in spawn_thread_v1 /data/src/10.0/storage/perfschema/pfs.cc:1911
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /data/src/10.0/sql/sql_cache.cc:855 Query_cache_block::query()
 
Shadow bytes around the buggy address:
 
  0x0fe29b26eb00: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0fe29b26eb10: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0fe29b26eb20: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0fe29b26eb30: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0fe29b26eb40: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
=>0x0fe29b26eb50:[fd]fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0fe29b26eb60: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0fe29b26eb70: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0fe29b26eb80: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0fe29b26eb90: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0fe29b26eba0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
Shadow byte legend (one shadow byte represents 8 application bytes):
 
  Addressable:           00
 
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
 
  Heap right redzone:      fb
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  Stack partial redzone:   f4
 
  Stack after return:      f5
 
  Stack use after scope:   f8
 
  Global redzone:          f9
 
  Global init order:       f6
 
  Poisoned by user:        f7
 
  Contiguous container OOB:fc
 
  ASan internal:           fe
 
==12901==ABORTING

Comment by Elena Stepanova [ 2019-12-04 ]

In a pile of mostly outdated comments to MDEV-10826 I found an apparently deterministic test case with a sync point which is still applicable at least to the current 10.1 (I checked on 10.1 05e72a33) and produces the same stack trace. I'll add it here so it's not lost, while MDEV-10826 will be about the assertion which it was initially filed for.

Sync point for 10.1

 
diff --git a/sql/sql_cache.cc b/sql/sql_cache.cc
 
index 91dd8ad..c677f8e 100644
 
--- a/sql/sql_cache.cc
 
+++ b/sql/sql_cache.cc
 
@@ -826,6 +826,7 @@ void Query_cache_block::init(ulong block_length)
 
   used = 0;
 
   type = Query_cache_block::FREE;
 
   n_tables = 0;
 
+  DEBUG_SYNC(current_thd,"in_qc_block_init");
 
   DBUG_VOID_RETURN;
 
 }

Test case using the sync point above

 
--source include/have_debug_sync.inc
 
--enable_connect_log
 
 
set @save_qc_type=@@global.query_cache_type;
 
set @save_qc_size=@@global.query_cache_size;
 
set global query_cache_type=1, query_cache_size=1024*1024;
 
 
CREATE TABLE t1 (id int(10) NOT NULL auto_increment PRIMARY KEY);
 
INSERT INTO t1 VALUES (NULL),(NULL);
 
 
--connect (con8,localhost,root,,test)
 
set debug_sync='in_qc_block_init SIGNAL set_free WAIT_FOR proceed';
 
--send
 
	SELECT * FROM t1;
 
 
--connection default
 
set debug_sync='now WAIT_FOR set_free';
 
SET GLOBAL query_cache_type = 0;
 
set debug_sync='now SIGNAL proceed';
 
 
--connection con8
 
--reap
 
--disconnect con8
 
 
--connection default
 
drop table t1;
 
set debug_sync='RESET';
 
set global query_cache_type=@save_qc_type, query_cache_size=@save_qc_size;

10.1 05e72a33

 
#3  <signal handler called>
 
#4  0x00007fe9ae770c43 in _xend () at pthread_rwlock_unlock.c:38
 
#5  __GI___pthread_rwlock_unlock (rwlock=0x7fe9a4680290) at pthread_rwlock_unlock.c:38
 
#6  0x0000564754622dc1 in inline_mysql_rwlock_unlock (that=0x7fe9a4680290) at /data/src/10.1-bug/include/mysql/psi/mysql_thread.h:1071
 
#7  0x0000564754630e4b in Query_cache_query::unlock_writing (this=0x7fe9a4680288) at /data/src/10.1-bug/sql/sql_cache.cc:952
 
#8  0x0000564754625ced in Query_cache::store_query (this=0x5647559be8c0 <query_cache>, thd=0x7fe9a63d4070, tables_used=0x7fe9a4821260) at /data/src/10.1-bug/sql/sql_cache.cc:1563
 
#9  0x0000564754681de7 in execute_sqlcom_select (thd=0x7fe9a63d4070, all_tables=0x7fe9a4821260) at /data/src/10.1-bug/sql/sql_parse.cc:5690
 
#10 0x0000564754678c21 in mysql_execute_command (thd=0x7fe9a63d4070) at /data/src/10.1-bug/sql/sql_parse.cc:3038
 
#11 0x0000564754685a81 in mysql_parse (thd=0x7fe9a63d4070, rawbuf=0x7fe9a4821088 "SELECT * FROM t1", length=16, parser_state=0x7fe9aeaa21e0) at /data/src/10.1-bug/sql/sql_parse.cc:7209
 
#12 0x0000564754674c33 in dispatch_command (command=COM_QUERY, thd=0x7fe9a63d4070, packet=0x7fe9a63da071 "SELECT * FROM t1", packet_length=16) at /data/src/10.1-bug/sql/sql_parse.cc:1499
 
#13 0x00005647546739f1 in do_command (thd=0x7fe9a63d4070) at /data/src/10.1-bug/sql/sql_parse.cc:1131
 
#14 0x00005647547b164b in do_handle_one_connection (thd_arg=0x7fe9a63d4070) at /data/src/10.1-bug/sql/sql_connect.cc:1331
 
#15 0x00005647547b137c in handle_one_connection (arg=0x7fe9a63d4070) at /data/src/10.1-bug/sql/sql_connect.cc:1242
 
#16 0x0000564754be6e3c in pfs_spawn_thread (arg=0x7fe9ac83a170) at /data/src/10.1-bug/storage/perfschema/pfs.cc:1861
 
#17 0x00007fe9ae76b4a4 in start_thread (arg=0x7fe9aeaa3700) at pthread_create.c:456
 
#18 0x00007fe9ad181d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Generated at Thu Feb 08 08:28:23 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.