[MDEV-18259] ASAN heap-use-after-free or server crash in get_foreign_key_info Created: 2019-01-15  Updated: 2020-09-07  Resolved: 2020-07-29

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2, 10.3, 10.4
Fix Version/s: 10.4.4, 10.1.45, 10.2.32, 10.3.23

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Duplicate Votes: 0
Labels: rr-profile-analyzed

Issue Links:
Duplicate
duplicates MDEV-13301 Optimize DROP INDEX, ADD INDEX into R... Closed
duplicates MDEV-22180 Planner opens unnecessary tables when... Closed
is duplicated by MDEV-19859 ASAN heap-use-after-free dict0mem.h:5... Open
Relates
relates to MDEV-22788 SUMMARY: AddressSanitizer: heap-use-a... Confirmed
relates to MDEV-23686 ASAN heap-use-after-free or server cr... Confirmed

 Description   

The test case in the description is highly non-deterministic, run with the high value of --repeat (hundreds).
Also, when it doesn't crash, it can produce other kinds of failures:

2019-03-21 22:23:20 20 [ERROR] InnoDB: Failed to load table '`test`.`t3`' which has a foreign key constraint with table '`test`.`t1`'.
 
^ Found warnings in /data/src/10.4-bug/mysql-test/var/log/mysqld.1.err


+#sql2-7566-13d.frm
 
+#sql2-7566-13d.ibd


2019-03-21 22:30:32 139973994747648 [ERROR] InnoDB: In ALTER TABLE `test`.`t3` has or is referenced in foreign key constraints which are not compatible with the new table definition.

It contains suppressions for some error codes and messages to be able to reach the ultimate failure (ASAN error or crash), but the errors themselves aren't necessarily expected, and possibly it can hit other ones.

--source include/have_innodb.inc
 
 
 
call mtr.add_suppression("which has a foreign key constraint with table");
 
 
 
CREATE TABLE tx (x INT, KEY(x)) ENGINE=InnoDB;
 
CREATE TABLE t1 (pk INT, a INT, b INT, PRIMARY KEY(pk), FOREIGN KEY (a) REFERENCES tx (x)) ENGINE=InnoDB;
 
CREATE TABLE t2 (pk INT, c INT, d INT, KEY(d), PRIMARY KEY(pk), FOREIGN KEY b (c) REFERENCES t2 (d)) ENGINE=InnoDB;
 
CREATE TABLE t3 (pk INT, e INT, f INT, KEY(e), PRIMARY KEY(pk), FOREIGN KEY (e) REFERENCES t1 (a)) ENGINE=InnoDB;
 
 
 
--send
 
  ALTER TABLE t3 ADD FOREIGN KEY (f) REFERENCES t3 (e);
 
 
 
--connect (con1,localhost,root,,test)
 
ALTER TABLE t1 FORCE;
 
SET SESSION FOREIGN_KEY_CHECKS = OFF;
 
--error ER_FK_FAIL_ADD_SYSTEM,ER_FK_NO_INDEX_PARENT
 
ALTER TABLE t1 ADD CONSTRAINT b FOREIGN KEY (b) REFERENCES txx (x), ADD FOREIGN KEY fk1 (a) REFERENCES t3 (f);
 
 
 
--error 13
 
LOAD DATA INFILE 'non_existing_file' INTO TABLE t1;
 
--disconnect con1
 
 
 
--connection default
 
--error 0,ER_ERROR_ON_RENAME
 
--reap
 
 
 
# Cleanup
 
SET FOREIGN_KEY_CHECKS= OFF;
 
DROP TABLE IF EXISTS t3, t2, t1, tx;

10.4 de51acd0

 
==13416==ERROR: AddressSanitizer: heap-use-after-free on address 0x618000090918 at pc 0x55bdc069a765 bp 0x7f7080cd81f0 sp 0x7f7080cd81e8
 
READ of size 8 at 0x618000090918 thread T28
 
    #0 0x55bdc069a764 in id_name_t::operator char const*() const /data/src/10.4/storage/innobase/include/dict0mem.h:526
 
    #1 0x55bdc067fd76 in get_foreign_key_info /data/src/10.4/storage/innobase/handler/ha_innodb.cc:14952
 
    #2 0x55bdc06807f2 in ha_innobase::get_parent_foreign_key_list(THD*, List<st_foreign_key_info>*) /data/src/10.4/storage/innobase/handler/ha_innodb.cc:15033
 
    #3 0x55bdbf560cc3 in DML_prelocking_strategy::handle_table(THD*, Query_tables_list*, TABLE_LIST*, bool*) /data/src/10.4/sql/sql_base.cc:4629
 
    #4 0x55bdbf55c3ef in open_and_process_table /data/src/10.4/sql/sql_base.cc:3810
 
    #5 0x55bdbf55eca9 in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /data/src/10.4/sql/sql_base.cc:4265
 
    #6 0x55bdbf5635ed in open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /data/src/10.4/sql/sql_base.cc:5147
 
    #7 0x55bdbf4cc53a in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) /data/src/10.4/sql/sql_base.h:502
 
    #8 0x55bdbf69f9c8 in mysql_load(THD*, sql_exchange const*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool, bool) /data/src/10.4/sql/sql_load.cc:388
 
    #9 0x55bdbf6cf359 in mysql_execute_command(THD*) /data/src/10.4/sql/sql_parse.cc:5233
 
    #10 0x55bdbf6e2830 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.4/sql/sql_parse.cc:8205
 
    #11 0x55bdbf6ba73b in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.4/sql/sql_parse.cc:1829
 
    #12 0x55bdbf6b758c in do_command(THD*) /data/src/10.4/sql/sql_parse.cc:1358
 
    #13 0x55bdbfa4b433 in do_handle_one_connection(CONNECT*) /data/src/10.4/sql/sql_connect.cc:1399
 
    #14 0x55bdbfa4ae2c in handle_one_connection /data/src/10.4/sql/sql_connect.cc:1302
 
    #15 0x55bdc0612efc in pfs_spawn_thread /data/src/10.4/storage/perfschema/pfs.cc:1862
 
    #16 0x7f709d403493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
    #17 0x7f709b5d193e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
 
 
 
0x618000090918 is located 152 bytes inside of 792-byte region [0x618000090880,0x618000090b98)
 
freed by thread T28 here:
 
    #0 0x7f709d66d527 in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x54527)
 
    #1 0x55bdc07e4aa1 in mem_heap_block_free(mem_block_info_t*, mem_block_info_t*) /data/src/10.4/storage/innobase/mem/mem0mem.cc:415
 
    #2 0x55bdc0bf0dbd in mem_heap_free /data/src/10.4/storage/innobase/include/mem0mem.ic:528
 
    #3 0x55bdc0bf87a3 in dict_mem_index_free(dict_index_t*) /data/src/10.4/storage/innobase/dict/dict0mem.cc:1083
 
    #4 0x55bdc0bbc128 in dict_index_remove_from_cache_low /data/src/10.4/storage/innobase/dict/dict0dict.cc:2523
 
    #5 0x55bdc0bbc152 in dict_index_remove_from_cache(dict_table_t*, dict_index_t*) /data/src/10.4/storage/innobase/dict/dict0dict.cc:2534
 
    #6 0x55bdc08f5d76 in row_merge_drop_indexes(trx_t*, dict_table_t*, unsigned long) /data/src/10.4/storage/innobase/row/row0merge.cc:4013
 
    #7 0x55bdc06ec610 in innobase_rollback_sec_index /data/src/10.4/storage/innobase/handler/handler0alter.cc:8553
 
    #8 0x55bdc06f7710 in ha_innobase::commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) /data/src/10.4/storage/innobase/handler/handler0alter.cc:11011
 
    #9 0x55bdbfe7e403 in handler::ha_commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) /data/src/10.4/sql/handler.cc:4712
 
    #10 0x55bdbf8f69e4 in mysql_inplace_alter_table /data/src/10.4/sql/sql_table.cc:7696
 
    #11 0x55bdbf90493d in mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /data/src/10.4/sql/sql_table.cc:9934
 
    #12 0x55bdbfa60e00 in Sql_cmd_alter_table::execute(THD*) /data/src/10.4/sql/sql_alter.cc:499
 
    #13 0x55bdbf6d7e7f in mysql_execute_command(THD*) /data/src/10.4/sql/sql_parse.cc:6394
 
    #14 0x55bdbf6e2830 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.4/sql/sql_parse.cc:8205
 
    #15 0x55bdbf6ba73b in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.4/sql/sql_parse.cc:1829
 
    #16 0x55bdbf6b758c in do_command(THD*) /data/src/10.4/sql/sql_parse.cc:1358
 
    #17 0x55bdbfa4b433 in do_handle_one_connection(CONNECT*) /data/src/10.4/sql/sql_connect.cc:1399
 
    #18 0x55bdbfa4ae2c in handle_one_connection /data/src/10.4/sql/sql_connect.cc:1302
 
    #19 0x55bdc0612efc in pfs_spawn_thread /data/src/10.4/storage/perfschema/pfs.cc:1862
 
    #20 0x7f709d403493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
 
 
previously allocated by thread T28 here:
 
    #0 0x7f709d66d73f in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x5473f)
 
    #1 0x55bdc07e4069 in mem_heap_create_block_func(mem_block_info_t*, unsigned long, char const*, unsigned int, unsigned long) /data/src/10.4/storage/innobase/mem/mem0mem.cc:269
 
    #2 0x55bdc07e47ca in mem_heap_add_block(mem_block_info_t*, unsigned long) /data/src/10.4/storage/innobase/mem/mem0mem.cc:375
 
    #3 0x55bdc0bf09db in mem_heap_alloc /data/src/10.4/storage/innobase/include/mem0mem.ic:201
 
    #4 0x55bdc0bf07ad in mem_heap_zalloc /data/src/10.4/storage/innobase/include/mem0mem.ic:170
 
    #5 0x55bdc0bf694f in dict_mem_index_create(dict_table_t*, char const*, unsigned long, unsigned long) /data/src/10.4/storage/innobase/dict/dict0mem.cc:743
 
    #6 0x55bdc0bbe6a0 in dict_index_build_internal_non_clust /data/src/10.4/storage/innobase/dict/dict0dict.cc:3020
 
    #7 0x55bdc0bbaf04 in dict_index_add_to_cache(dict_index_t*, unsigned long, bool, dberr_t*, dict_add_v_col_t const*) /data/src/10.4/storage/innobase/dict/dict0dict.cc:2354
 
    #8 0x55bdc0b9f3d7 in dict_create_index_step(que_thr_t*) /data/src/10.4/storage/innobase/dict/dict0crea.cc:1346
 
    #9 0x55bdc086683c in que_thr_step /data/src/10.4/storage/innobase/que/que0que.cc:1052
 
    #10 0x55bdc0866bdc in que_run_threads_low /data/src/10.4/storage/innobase/que/que0que.cc:1104
 
    #11 0x55bdc0866f33 in que_run_threads(que_thr_t*) /data/src/10.4/storage/innobase/que/que0que.cc:1144
 
    #12 0x55bdc06d7302 in create_index_dict /data/src/10.4/storage/innobase/handler/handler0alter.cc:5926
 
    #13 0x55bdc06dfd7f in prepare_inplace_alter_table_dict /data/src/10.4/storage/innobase/handler/handler0alter.cc:6737
 
    #14 0x55bdc06e92f5 in ha_innobase::prepare_inplace_alter_table(TABLE*, Alter_inplace_info*) /data/src/10.4/storage/innobase/handler/handler0alter.cc:8127
 
    #15 0x55bdbfe7e132 in handler::ha_prepare_inplace_alter_table(TABLE*, Alter_inplace_info*) /data/src/10.4/sql/handler.cc:4692
 
    #16 0x55bdbf8f6258 in mysql_inplace_alter_table /data/src/10.4/sql/sql_table.cc:7611
 
    #17 0x55bdbf90493d in mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /data/src/10.4/sql/sql_table.cc:9934
 
    #18 0x55bdbfa60e00 in Sql_cmd_alter_table::execute(THD*) /data/src/10.4/sql/sql_alter.cc:499
 
    #19 0x55bdbf6d7e7f in mysql_execute_command(THD*) /data/src/10.4/sql/sql_parse.cc:6394
 
    #20 0x55bdbf6e2830 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.4/sql/sql_parse.cc:8205
 
    #21 0x55bdbf6ba73b in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.4/sql/sql_parse.cc:1829
 
    #22 0x55bdbf6b758c in do_command(THD*) /data/src/10.4/sql/sql_parse.cc:1358
 
    #23 0x55bdbfa4b433 in do_handle_one_connection(CONNECT*) /data/src/10.4/sql/sql_connect.cc:1399
 
    #24 0x55bdbfa4ae2c in handle_one_connection /data/src/10.4/sql/sql_connect.cc:1302
 
    #25 0x55bdc0612efc in pfs_spawn_thread /data/src/10.4/storage/perfschema/pfs.cc:1862
 
    #26 0x7f709d403493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
 
 
Thread T28 created by T0 here:
 
    #0 0x7f709d63cbba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
 
    #1 0x55bdc06134c4 in spawn_thread_v1 /data/src/10.4/storage/perfschema/pfs.cc:1912
 
    #2 0x55bdbf402226 in inline_mysql_thread_create /data/src/10.4/include/mysql/psi/mysql_thread.h:1268
 
    #3 0x55bdbf417b18 in create_thread_to_handle_connection(CONNECT*) /data/src/10.4/sql/mysqld.cc:6218
 
    #4 0x55bdbf41821d in create_new_thread(CONNECT*) /data/src/10.4/sql/mysqld.cc:6288
 
    #5 0x55bdbf4185ad in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /data/src/10.4/sql/mysqld.cc:6386
 
    #6 0x55bdbf4191f9 in handle_connections_sockets() /data/src/10.4/sql/mysqld.cc:6544
 
    #7 0x55bdbf417353 in mysqld_main(int, char**) /data/src/10.4/sql/mysqld.cc:5876
 
    #8 0x55bdbf4000af in main /data/src/10.4/sql/main.cc:25
 
    #9 0x7f709b5092b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0)
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /data/src/10.4/storage/innobase/include/dict0mem.h:526 id_name_t::operator char const*() const
 
Shadow bytes around the buggy address:
 
  0x0c308000a0d0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c308000a0e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c308000a0f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c308000a100: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c308000a110: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
=>0x0c308000a120: fd fd fd[fd]fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c308000a130: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c308000a140: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c308000a150: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c308000a160: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c308000a170: fd fd fd fa fa fa fa fa fa fa fa fa fa fa fa fa
 
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
 
==13416==ABORTING

It seems to be failing somewhat faster on 10.4, less frequently on 10.2/10.3, but I've seen the ASAN failures on all off 10.4 de51acd0, 10.3 117291db, 10.2 a77e2668.
Also, earlier a similar non-ASAN crash was observed in concurrent tests on 10.2:

10.2 662217a592

 
#3  <signal handler called>
 
#4  0x00007f3d82064746 in strlen () from /lib/x86_64-linux-gnu/libc.so.6
 
#5  0x000055ddac69933b in get_foreign_key_info (thd=0x7f3d40008c20, foreign=0x7f3d3813dba8) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:15147
 
#6  0x000055ddac699698 in ha_innobase::get_parent_foreign_key_list (this=0x7f3d4003d558, thd=0x7f3d40008c20, f_key_list=0x7f3d6a7f49d0) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:15227
 
#7  0x000055ddac18ff88 in DML_prelocking_strategy::handle_table (this=0x7f3d6a7f4c60, thd=0x7f3d40008c20, prelocking_ctx=0x7f3d4009d4c0, table_list=0x7f3d400a2a98, need_prelocking=0x7f3d6a7f4ad0) at /home/travis/src/sql/sql_base.cc:4320
 
#8  0x000055ddac18e511 in open_and_process_table (thd=0x7f3d40008c20, lex=0x7f3d4009d4b8, tables=0x7f3d400a2a98, counter=0x7f3d6a7f4cb4, flags=512, prelocking_strategy=0x7f3d6a7f4c60, has_prelocking_list=false, ot_ctx=0x7f3d6a7f4be0) at /home/travis/src/sql/sql_base.cc:3566
 
#9  0x000055ddac18f4cc in open_tables (thd=0x7f3d40008c20, options=..., start=0x7f3d6a7f4ca0, counter=0x7f3d6a7f4cb4, flags=512, prelocking_strategy=0x7f3d6a7f4c60) at /home/travis/src/sql/sql_base.cc:4011
 
#10 0x000055ddac1d68d6 in open_tables (thd=0x7f3d40008c20, tables=0x7f3d6a7f4ca0, counter=0x7f3d6a7f4cb4, flags=512) at /home/travis/src/sql/sql_base.h:475
 
#11 0x000055ddac222d46 in select_like_stmt_test_with_open (stmt=0x7f3d4004a4a0, tables=0x7f3d4009ec58, specific_prepare=0x55ddac2239da <mysql_insert_select_prepare_tester(THD*)>, setup_tables_done_option=1073741824) at /home/travis/src/sql/sql_prepare.cc:1807
 
#12 0x000055ddac223b08 in mysql_test_insert_select (stmt=0x7f3d4004a4a0, tables=0x7f3d4009ec58) at /home/travis/src/sql/sql_prepare.cc:2236
 
#13 0x000055ddac2242ad in check_prepared_statement (stmt=0x7f3d4004a4a0) at /home/travis/src/sql/sql_prepare.cc:2482
 
#14 0x000055ddac227c8f in Prepared_statement::prepare (this=0x7f3d4004a4a0, packet=0x7f3d400200b1 "INSERT INTO `view_A` SELECT * FROM `view_A` /* QNO 606 CON_ID 18 */ ", packet_len=68) at /home/travis/src/sql/sql_prepare.cc:4021
 
#15 0x000055ddac22466a in mysqld_stmt_prepare (thd=0x7f3d40008c20, packet=0x7f3d400200b1 "INSERT INTO `view_A` SELECT * FROM `view_A` /* QNO 606 CON_ID 18 */ ", packet_length=68) at /home/travis/src/sql/sql_prepare.cc:2646
 
#16 0x000055ddac1f96f3 in dispatch_command (command=COM_STMT_PREPARE, thd=0x7f3d40008c20, packet=0x7f3d400200b1 "INSERT INTO `view_A` SELECT * FROM `view_A` /* QNO 606 CON_ID 18 */ ", packet_length=68, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1783
 
#17 0x000055ddac1f8358 in do_command (thd=0x7f3d40008c20) at /home/travis/src/sql/sql_parse.cc:1379
 
#18 0x000055ddac34a994 in do_handle_one_connection (connect=0x55ddaf4a40a0) at /home/travis/src/sql/sql_connect.cc:1335
 
#19 0x000055ddac34a714 in handle_one_connection (arg=0x55ddaf4a40a0) at /home/travis/src/sql/sql_connect.cc:1241
 
#20 0x00007f3d82c4b6ba in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
 
#21 0x00007f3d820e041d in clone () from /lib/x86_64-linux-gnu/libc.so.6

elenst-jira-refs f6970b243 Toolbox: c826c29aaa

 
perl ./runall-new.pl --basedir=/home/travis/server --vardir=/home/travis/logs/vardir --duration=350 --threads=6 --seed=1547523386 --reporters=Backtrace,ErrorLog,Deadlock --validators=TransformerNoComparator --views --redefine=conf/mariadb/alter_table.yy --redefine=conf/mariadb/sp.yy --redefine=conf/mariadb/bulk_insert.yy --redefine=conf/mariadb/modules/foreign_keys.yy --redefine=conf/mariadb/modules/admin.yy --redefine=conf/mariadb/modules/sql_mode.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=30 --mysqld=--lock-wait-timeout=10 --mysqld=--loose-innodb-lock-wait-timeout=5 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --grammar=conf/partitioning/partitions.yy --ps-protocol --transformers=ExecuteAsCTE,ExecuteAsExecuteImmediate,ExecuteAsDeleteReturning,ExecuteAsInsertSelect,ExecuteAsUnion,ExecuteAsUpdateDelete,ExecuteAsView

Not reproducible right away.

 Comments   
Comment by Elena Stepanova [ 2019-02-01 ]

On 10.4 with ASAN:
https://travis-ci.org/elenst/travis-tests/jobs/487435359 [2653 26 4]

10.4 923415f

 
==6562==ERROR: AddressSanitizer: heap-use-after-free on address 0x6180001ca118 at pc 0x560ac74ee419 bp 0x7fc235bc2840 sp 0x7fc235bc2830
 
READ of size 8 at 0x6180001ca118 thread T46
 
    #0 0x560ac74ee418 in id_name_t::operator char const*() const /home/travis/src/storage/innobase/include/dict0mem.h:526
 
    #1 0x560ac74d2965 in get_foreign_key_info /home/travis/src/storage/innobase/handler/ha_innodb.cc:14847
 
    #2 0x560ac74d333f in ha_innobase::get_parent_foreign_key_list(THD*, List<st_foreign_key_info>*) /home/travis/src/storage/innobase/handler/ha_innodb.cc:14928
 
    #3 0x560ac6704a3e in DML_prelocking_strategy::handle_table(THD*, Query_tables_list*, TABLE_LIST*, bool*) /home/travis/src/sql/sql_base.cc:4625
 
    #4 0x560ac67002cf in open_and_process_table /home/travis/src/sql/sql_base.cc:3806
 
    #5 0x560ac6702b99 in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /home/travis/src/sql/sql_base.cc:4261
 
    #6 0x560ac67072c3 in open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /home/travis/src/sql/sql_base.cc:5143
 
    #7 0x560ac667a706 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) /home/travis/src/sql/sql_base.h:509
 
    #8 0x560ac68339b5 in mysql_load(THD*, sql_exchange const*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool, bool) /home/travis/src/sql/sql_load.cc:387
 
    #9 0x560ac6860de4 in mysql_execute_command(THD*) /home/travis/src/sql/sql_parse.cc:5145
 
    #10 0x560ac6873f73 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /home/travis/src/sql/sql_parse.cc:8117
 
    #11 0x560ac684cc08 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /home/travis/src/sql/sql_parse.cc:1803
 
    #12 0x560ac6849de8 in do_command(THD*) /home/travis/src/sql/sql_parse.cc:1356
 
    #13 0x560ac6ba743c in do_handle_one_connection(CONNECT*) /home/travis/src/sql/sql_connect.cc:1398
 
    #14 0x560ac6ba6e06 in handle_one_connection /home/travis/src/sql/sql_connect.cc:1301
 
    #15 0x7fc24a1556b9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76b9)
 
    #16 0x7fc2493e641c in clone (/lib/x86_64-linux-gnu/libc.so.6+0x10741c)
 
ASAN:SIGSEGV
 
==6562==AddressSanitizer: while reporting a bug found another one. Ignoring.

Comment by Elena Stepanova [ 2019-02-07 ]

https://dev.azure.com/elenst/MariaDB%20tests/_build/results?buildId=708 [test009]

Comment by Elena Stepanova [ 2019-02-15 ]

https://travis-ci.org/elenst/travis-tests/jobs/492819901 [2747 10 1]

Comment by Marko Mäkelä [ 2020-07-29 ]

I suspect that this could share a root cause with MDEV-22788: ALTER TABLE is missing necessary MDL around the tables that are connected by FOREIGN KEY constraints.

I cannot confirm this, because I was unable to repeat the failure on an ASAN build of 10.2 8ec877f40a0e8e7432f1ef2cbd1d744c793eab2d.

The ‘best’ that I got was something that I would probably have avoided by using cmake -DWITH_SSL=bundled:

10.2 8ec877f40a0e8e7432f1ef2cbd1d744c793eab2d

 
2020-07-29 15:01:38 139942370125568 [Note] /dev/shm/10.2a/sql/mysqld: Shutdown complete
 
 
 
Direct leak of 596 byte(s) in 2 object(s) allocated from:
 
    #0 0x633cfd in malloc (/dev/shm/10.2a/sql/mysqld+0x633cfd)
 
    #1 0x7f46fbe68889 in CRYPTO_zalloc (/usr/lib/x86_64-linux-gnu/libcrypto.so.1.1+0x18f889)

Can I please get an rr replay trace of this?

Comment by Marko Mäkelä [ 2020-07-29 ]

I was able to obtain an rr replay trace on 10.4 de51acd03730311505677eb7212756e7126183b3 after disabling many features in ASAN_OPTIONS.

I think that already the ASAN diagnostics is suggesting that this shares a root cause with MDEV-22788. Unlike MDEV-22788, which involves a table rebuild, this one appears to involve a failed ADD INDEX (implied by {{ADD FOREIGN KEY):

10.4 de51acd03730311505677eb7212756e7126183b3

 
==158927==ERROR: AddressSanitizer: heap-use-after-free on address 0x61800005e118 at pc 0x55d4d1d805b4 bp 0x1fae60805650 sp 0x1fae60805648
 
READ of size 8 at 0x61800005e118 thread T27
 
    #0 0x55d4d1d805b3 in id_name_t::operator char const*() const /mariadb/10.4/storage/innobase/include/dict0mem.h:526:10
 
    #1 0x55d4d1d805b3 in get_foreign_key_info(THD*, dict_foreign_t*) /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:14952:9
 
    #2 0x55d4d1d808c2 in ha_innobase::get_parent_foreign_key_list(THD*, List<st_foreign_key_info>*) /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:15033:17
 
    #3 0x55d4d0d9f6ac in DML_prelocking_strategy::handle_table(THD*, Query_tables_list*, TABLE_LIST*, bool*) /mariadb/10.4/sql/sql_base.cc:4629:20
 
    #4 0x55d4d0d9b44d in open_and_process_table(THD*, LEX*, TABLE_LIST*, unsigned int*, unsigned int, Prelocking_strategy*, bool, Open_table_context*) /mariadb/10.4/sql/sql_base.cc:3809:33
 
    #5 0x55d4d0d9b44d in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /mariadb/10.4/sql/sql_base.cc:4263:14
 
    #6 0x55d4d0da4845 in open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /mariadb/10.4/sql/sql_base.cc:5147:7
 
    #7 0x55d4d0ef0089 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) /mariadb/10.4/sql/sql_base.h:500:10
 
    #8 0x55d4d0ef0089 in mysql_load(THD*, sql_exchange const*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool, bool) /mariadb/10.4/sql/sql_load.cc:388:7
 
    #9 0x55d4d0f3425b in mysql_execute_command(THD*) /mariadb/10.4/sql/sql_parse.cc:5231:10
 
    #10 0x55d4d0f16012 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /mariadb/10.4/sql/sql_parse.cc:8205:18
 
    #11 0x55d4d0f0e373 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /mariadb/10.4/sql/sql_parse.cc:1828:7
 
    #12 0x55d4d0f1779c in do_command(THD*) /mariadb/10.4/sql/sql_parse.cc:1357:17
 
    #13 0x55d4d12ddcd0 in do_handle_one_connection(CONNECT*) /mariadb/10.4/sql/sql_connect.cc:1399:11
 
    #14 0x55d4d12dd3e3 in handle_one_connection /mariadb/10.4/sql/sql_connect.cc:1302:3
 
    #15 0x55d4d29f4a85 in pfs_spawn_thread /mariadb/10.4/storage/perfschema/pfs.cc:1862:3
 
    #16 0x7f5350366ea6 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x8ea6)
 
    #17 0x31f428c5edae in clone (/lib/x86_64-linux-gnu/libc.so.6+0xfddae)
 
 
 
0x61800005e118 is located 152 bytes inside of 792-byte region [0x61800005e080,0x61800005e398)
 
freed by thread T27 here:
 
    #0 0x55d4d0be731d in free (/dev/shm/10.4/sql/mysqld+0xfa431d)
 
    #1 0x55d4d24af732 in mem_heap_free(mem_block_info_t*) /mariadb/10.4/storage/innobase/include/mem0mem.ic:528:3
 
    #2 0x55d4d24af732 in dict_mem_index_free(dict_index_t*) /mariadb/10.4/storage/innobase/dict/dict0mem.cc:1083:2
 
    #3 0x55d4d2068137 in row_merge_drop_indexes(trx_t*, dict_table_t*, unsigned long) /mariadb/10.4/storage/innobase/row/row0merge.cc:4013:4
 
    #4 0x55d4d1ded3de in innobase_rollback_sec_index(dict_table_t*, TABLE const*, unsigned long, trx_t*) /mariadb/10.4/storage/innobase/handler/handler0alter.cc:8553:2
 
    #5 0x55d4d1ded3de in ha_innobase::commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) /mariadb/10.4/storage/innobase/handler/handler0alter.cc:11010:5
 
    #6 0x55d4d11955f3 in mysql_inplace_alter_table(THD*, TABLE_LIST*, TABLE*, TABLE*, Alter_inplace_info*, enum_alter_inplace_result, MDL_request*, Alter_table_ctx*) /mariadb/10.4/sql/sql_table.cc:7696:22
 
    #7 0x55d4d11955f3 in mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /mariadb/10.4/sql/sql_table.cc:9932:16
 
    #8 0x55d4d12f2eb3 in Sql_cmd_alter_table::execute(THD*) /mariadb/10.4/sql/sql_alter.cc:493:11
 
    #9 0x55d4d0f26021 in mysql_execute_command(THD*) /mariadb/10.4/sql/sql_parse.cc:6394:26
 
    #10 0x55d4d0f16012 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /mariadb/10.4/sql/sql_parse.cc:8205:18
 
    #11 0x55d4d0f0e373 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /mariadb/10.4/sql/sql_parse.cc:1828:7
 
    #12 0x55d4d0f1779c in do_command(THD*) /mariadb/10.4/sql/sql_parse.cc:1357:17
 
    #13 0x55d4d12ddcd0 in do_handle_one_connection(CONNECT*) /mariadb/10.4/sql/sql_connect.cc:1399:11
 
    #14 0x55d4d12dd3e3 in handle_one_connection /mariadb/10.4/sql/sql_connect.cc:1302:3

Let us debug a bit further with rr replay:

(rr) continue
 
…
 
Thread 3 received signal SIGABRT, Aborted.
 
[Switching to Thread 158927.159558]
 
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
50	../sysdeps/unix/sysv/linux/raise.c: Tiedostoa tai hakemistoa ei ole.
 
(rr) when
 
Current event: 898538
 
(rr) awatch ((char*)0x7fff8000)[0x61800005e118 / 8]
 
Hardware access (read/write) watchpoint 1: ((char*)0x7fff8000)[0x61800005e118 / 8]
 
(rr) reverse-continue 
Continuing.
 
…
 
(rr) reverse-continue 
Continuing.
 
 
 
Thread 3 hit Hardware access (read/write) watchpoint 1: ((char*)0x7fff8000)[0x61800005e118 / 8]
 
 
 
Old value = -3 '\375'
 
New value = 0 '\000'
 
__memset_avx2_unaligned_erms ()
 
    at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:190
 
190	../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S: Tiedostoa tai hakemistoa ei ole.
 
(rr) when
 
Current event: 882899
 
(rr) bt
 
#0  __memset_avx2_unaligned_erms ()
 
    at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:190
 
#1  0x000055d4d0b749f2 in __asan::Allocator::QuarantineChunk(__asan::AsanChunk*, void*, __sanitizer::BufferedStackTrace*) ()
 
#2  0x000055d4d0be73a2 in free ()
 
#3  0x000055d4d24af733 in mem_heap_free (heap=0x6110000a1080)
 
    at /mariadb/10.4/storage/innobase/include/mem0mem.ic:528
 
#4  dict_mem_index_free (index=<optimized out>)
 
    at /mariadb/10.4/storage/innobase/dict/dict0mem.cc:1083
 
…

The most interesting takeaway is that the invalid access occurred in the same thread (Thread 3) that had freed the memory! Thus, this particular failure cannot share a cause with MDEV-22788.

In the wrong access, we are somehow using an invalid ha_innobase object, without checking that the table actually existed:

(rr) when
 
Current event: 891885
 
(rr) fra 2
 
#2  0x000055d4d1d808c3 in ha_innobase::get_parent_foreign_key_list (
 
    this=<optimized out>, thd=0x62b00009a208, f_key_list=<optimized out>)
 
    at /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:15033
 
15033			pf_key_info = get_foreign_key_info(thd, foreign);
 
(rr) p thd->query_string
 
$1 = {string = {
 
    str = 0x62b0000a1220 "LOAD DATA INFILE 'non_existing_file' INTO TABLE t1", 
    length = 50}, cs = 0x55d4d4327b60 <my_charset_latin1>}
 
(rr) p m_prebuilt->table->name
 
value has been optimized out
 
(rr) up
 
#3  0x000055d4d0d9f6ad in DML_prelocking_strategy::handle_table (
 
    this=<optimized out>, thd=<optimized out>, prelocking_ctx=<optimized out>, 
    table_list=<optimized out>, need_prelocking=<optimized out>)
 
    at /mariadb/10.4/sql/sql_base.cc:4629
 
4629	      table->file->get_parent_foreign_key_list(thd, &fk_list);
 
(rr) p ((ha_innobase*)table->file)->m_prebuilt->table->name
 
$2 = {m_name = 0x6030000859c0 "test/t1"}

In 10.4, this test case was magically fixed by MDEV-13301. I can repeat the failure with the parent of 10.4 3a3d5ba2356b85626d34d6a65e4d8e8e6205b60d but not with that commit any more.

In other versions, I suspect that this scenario may have been fixed by MDEV-22180, which claims to have removed unnecessary prelocking in Lock_tables_prelocking_strategy::handle_table().

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