[MDEV-16063] [Draft] ASAN use-after-poison in row_sel / row_sel_step / que_thr_step Created: 2018-04-30  Updated: 2018-08-16  Resolved: 2018-08-16

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3
Fix Version/s: 10.2.18, 10.3.10

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Elena Stepanova
Resolution: Duplicate Votes: 0
Labels: None

Issue Links:
Blocks
blocks MDEV-16136 Various ASAN failures when testing 10... Closed
Relates
relates to MDEV-16119 InnoDB lock->index refers to a freed ... Closed
relates to MDEV-16781 InnoDB: AddressSanitizer: use-after-p... Closed

 Description   

10.3 ASAN cb16bc95ff9a7b

 
=================================================================
 
==5740==ERROR: AddressSanitizer: use-after-poison on address 0x7f151454e9c8 at pc 0x562f4e8d8194 bp 0x7f14f45c5fc0 sp 0x7f14f45c5fb8
 
READ of size 8 at 0x7f151454e9c8 thread T34
 
    #0 0x562f4e8d8193 in row_sel /data/src/10.3/storage/innobase/row/row0sel.cc:1798
 
    #1 0x562f4e8da065 in row_sel_step(que_thr_t*) /data/src/10.3/storage/innobase/row/row0sel.cc:2328
 
    #2 0x562f4e7cf78f in que_thr_step /data/src/10.3/storage/innobase/que/que0que.cc:1022
 
    #3 0x562f4e7cfe2a in que_run_threads_low /data/src/10.3/storage/innobase/que/que0que.cc:1108
 
    #4 0x562f4e7d0181 in que_run_threads(que_thr_t*) /data/src/10.3/storage/innobase/que/que0que.cc:1148
 
    #5 0x562f4e7d074c in que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) /data/src/10.3/storage/innobase/que/que0que.cc:1225
 
    #6 0x562f4eb91734 in dict_stats_exec_sql /data/src/10.3/storage/innobase/dict/dict0stats.cc:312
 
    #7 0x562f4eb9e67a in dict_stats_delete_from_table_stats /data/src/10.3/storage/innobase/dict/dict0stats.cc:3493
 
    #8 0x562f4eb9ead9 in dict_stats_drop_table(char const*, char*, unsigned long) /data/src/10.3/storage/innobase/dict/dict0stats.cc:3571
 
    #9 0x562f4e87cdae in row_drop_table_for_mysql(char const*, trx_t*, bool, unsigned long, bool) /data/src/10.3/storage/innobase/row/row0mysql.cc:3563
 
    #10 0x562f4e85b40d in row_merge_drop_table(trx_t*, dict_table_t*) /data/src/10.3/storage/innobase/row/row0merge.cc:4519
 
    #11 0x562f4eb38f71 in dict_table_close_and_drop(trx_t*, dict_table_t*) /data/src/10.3/storage/innobase/dict/dict0dict.cc:566
 
    #12 0x562f4e681f47 in rollback_inplace_alter_table(Alter_inplace_info*, TABLE const*, row_prebuilt_t*) (/data/bld/10.3-asan/bin/mysqld+0x1d8cf47)
 
    #13 0x562f4e67600c in ha_innobase::commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) /data/src/10.3/storage/innobase/handler/handler0alter.cc:9107
 
    #14 0x562f4de3b5a5 in handler::ha_commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) /data/src/10.3/sql/handler.cc:4406
 
    #15 0x562f4d9533fc in mysql_inplace_alter_table /data/src/10.3/sql/sql_table.cc:7626
 
    #16 0x562f4d95fe7f 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.3/sql/sql_table.cc:9670
 
    #17 0x562f4daa4e4f in Sql_cmd_alter_table::execute(THD*) /data/src/10.3/sql/sql_alter.cc:334
 
    #18 0x562f4d74b957 in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:6282
 
    #19 0x562f4d755ec6 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:8001
 
    #20 0x562f4d73076c in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1846
 
    #21 0x562f4d72d803 in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1391
 
    #22 0x562f4da96590 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1402
 
    #23 0x562f4da95fa5 in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
 
    #24 0x7f152a766493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
    #25 0x7f1528b4c93e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
 
 
 
0x7f151454e9c8 is located 531042696 bytes to the rightASAN:SIGSEGV
 
==5740==AddressSanitizer: while reporting a bug found another one.Ignoring.

Unfortunately this is the end of the report.

Similar problem on one of previous builds:

==26413==ERROR: AddressSanitizer: use-after-poison on address 0x7fbb7597bdd0 at pc 0x5559f417c27c bp 0x7fbb5588fc80 sp 0x7fbb5588fc78
 
READ of size 4 at 0x7fbb7597bdd0 thread T37
 
    #0 0x5559f417c27b in que_thr_step /data/src/10.3/storage/innobase/que/que0que.cc:1070
 
    #1 0x5559f417c516 in que_run_threads_low /data/src/10.3/storage/innobase/que/que0que.cc:1108
 
    #2 0x5559f417c86d in que_run_threads(que_thr_t*) /data/src/10.3/storage/innobase/que/que0que.cc:1148
 
    #3 0x5559f417ce38 in que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) /data/src/10.3/storage/innobase/que/que0que.cc:1225
 
    #4 0x5559f4541233 in dict_stats_exec_sql /data/src/10.3/storage/innobase/dict/dict0stats.cc:312
 
    #5 0x5559f454e20e in dict_stats_delete_from_table_stats /data/src/10.3/storage/innobase/dict/dict0stats.cc:3494
 
    #6 0x5559f454e66d in dict_stats_drop_table(char const*, char*, unsigned long) /data/src/10.3/storage/innobase/dict/dict0stats.cc:3572
 
    #7 0x5559f42299ed in row_drop_table_for_mysql(char const*, trx_t*, bool, unsigned long, bool) /data/src/10.3/storage/innobase/row/row0mysql.cc:3563
 
    #8 0x5559f3fa98d1 in ha_innobase::delete_table(char const*) /data/src/10.3/storage/innobase/handler/ha_innodb.cc:12952
 
    #9 0x5559f37e5c70 in handler::ha_delete_table(char const*) /data/src/10.3/sql/handler.cc:4510
 
    #10 0x5559f37d5d67 in ha_delete_table(THD*, handlerton*, char const*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, bool) /data/src/10.3/sql/handler.cc:2528
 
    #11 0x5559f32dbf3d in mysql_rm_table_no_locks(THD*, TABLE_LIST*, bool, bool, bool, bool, bool, bool) /data/src/10.3/sql/sql_table.cc:2513
 
    #12 0x5559f32da296 in mysql_rm_table(THD*, TABLE_LIST*, bool, bool, bool) /data/src/10.3/sql/sql_table.cc:2127
 
    #13 0x5559f30ebe32 in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:5050
 
    #14 0x5559f30fe702 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:8001
 
    #15 0x5559f30d8fa8 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1846
 
    #16 0x5559f30d603f in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1391
 
    #17 0x5559f343f10c in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1402
 
    #18 0x5559f343eb21 in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
 
    #19 0x7fbb8bb93493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
    #20 0x7fbb89f7993e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)

Both tests were run as

experimental 745dc5101b2c4e98

 
ASAN_OPTIONS=abort_on_error=1 perl ./runall-trials.pl --trials=10 --duration=350 --threads=6 --seed=1524795148  --validators=TransformerNoComparator --transformers=ConvertSubqueriesToViews,ConvertTablesToDerived,Count,DisableOptimizations,Distinct,EnableOptimizations,ExecuteAsCTE,ExecuteAsDeleteReturning,ExecuteAsDerived,ExecuteAsExcept,ExecuteAsExecuteImmediate,ExecuteAsInsertSelect,ExecuteAsIntersect,ExecuteAsSelectItem,ExecuteAsUnion,ExecuteAsUpdateDelete,ExecuteAsView,ExecuteAsWhereSubquery,Having,InlineSubqueries,LimitRowsExamined,OrderBy,StraightJoin,ExecuteAsPreparedTwice,ExecuteAsTrigger,ExecuteAsSPTwice,ExecuteAsFunctionTwice  --mysqld=--log_output=FILE  --mysqld=--max-statement-time=2 --mysqld=--lock-wait-timeout=5 --mysqld=--innodb-lock-wait-timeout=3 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --views  --basedir=/data/bld/10.3-asan --grammar=conf/runtime/alter_online.yy --gendata=conf/runtime/alter_online.zz --engine=InnoDB --vardir=/dev/shm/vardir2

It takes multiple trials to reproduce.

 Comments   
Comment by Marko Mäkelä [ 2018-05-07 ]

For me, the MDEV-15791 test occasionally triggers either use-after-poison or heap-use-after-free on DROP TABLE.
This is the test that I used (I had to add some alternative error codes at the end):

--source include/have_innodb.inc
 
CREATE TABLE t1 (col1 INT, col2 INT) ENGINE = InnoDB;
 
INSERT INTO t1 VALUES (1,1);
 
 
 
--connect(con1,localhost,root,,test)
 
XA BEGIN 'xid';
 
INSERT INTO t1 VALUES (1,0);
 
 
 
--connection default
 
--send
 
DELETE FROM t1;
 
 
 
--connection con1
 
--send
 
DELETE FROM t1;
 
 
 
--connect(con2,localhost,root,,test)
 
SET innodb_lock_wait_timeout= 1;
 
--send
 
ALTER TABLE t1 ADD UNIQUE KEY uidx(col1);
 
 
 
--connection con1
 
--error 0,ER_LOCK_DEADLOCK
 
--reap
 
--error 0,ER_DUP_ENTRY
 
INSERT INTO t1 VALUES (2,2),(2,2);
 
--error ER_XAER_RMFAIL
 
ALTER TABLE t1 FORCE;
 
UPDATE t1 SET col2 = 2;
 
 
 
# Cleanup
 
--disconnect con1
 
--connection con2
 
--error 0,ER_LOCK_WAIT_TIMEOUT,ER_DUP_ENTRY,ER_DUP_UNKNOWN_IN_INDEX,ER_LOCK_WAIT_TIMEOUT
 
--reap
 
--disconnect con2
 
--connection default
 
--error 0,ER_LOCK_DEADLOCK,ER_LOCK_WAIT_TIMEOUT
 
--reap
 
DROP TABLE t1;

With the ASAN heap or user poisoning disabled, it no longer crashes for me.

Comment by Marko Mäkelä [ 2018-05-07 ]

There is some indication that the problem may be related to failed or failing table-rebuilding ALTER TABLE.
Here is a stack trace from an ASAN core dump from mleich. Note that an error may have occurred earlier, before the crash at the start of this table-rebuilding ALTER TABLE:

# 2018-05-07T12:55:09 [26694] #9  0x00007f62dc6e770a in __asan_report_store4 () from /usr/lib/x86_64-linux-gnu/libasan.so.4
 
# 2018-05-07T12:55:09 [26694] #10 0x000056341e3ca1e0 in dict_create_table_step (thr=0x61b000459398) at /work/Server/10.3/storage/innobase/dict/dict0crea.cc:1256
 
# 2018-05-07T12:55:09 [26694] #11 0x000056341df89214 in que_thr_step (thr=0x61b000459398) at /work/Server/10.3/storage/innobase/que/que0que.cc:1054
 
# 2018-05-07T12:55:09 [26694] #12 0x000056341df895b4 in que_run_threads_low (thr=0x61b000459398) at /work/Server/10.3/storage/innobase/que/que0que.cc:1108
 
# 2018-05-07T12:55:09 [26694] #13 0x000056341df8999d in que_run_threads (thr=0x61b000459398) at /work/Server/10.3/storage/innobase/que/que0que.cc:1148
 
# 2018-05-07T12:55:09 [26694] #14 0x000056341e05c999 in row_create_table_for_mysql (table=0x617000b24588, trx=0x7f62c6784108, mode=FIL_ENCRYPTION_DEFAULT, key_id=1) at /work/Server/10.3/storage/innobase/row/row0mysql.cc:2413
 
# 2018-05-07T12:55:09 [26694] #15 0x000056341ddc2c9b in prepare_inplace_alter_table_dict (ha_alter_info=0x7f62afd5d5a0, altered_table=0x61f000872288, old_table=0x61f00083f688, table_name=0x61a000d83bdf "t3_1", flags=33, flags2=80, fts_doc_id_col=18446744073709551615, add_fts_doc_id=false, add_fts_doc_id_idx=false) at /work/Server/10.3/storage/innobase/handler/handler0alter.cc:5488
 
# 2018-05-07T12:55:09 [26694] #16 0x000056341ddcf8f3 in ha_innobase::prepare_inplace_alter_table (this=0x61d000585ca0, altered_table=0x61f000872288, ha_alter_info=0x7f62afd5d5a0) at /work/Server/10.3/storage/innobase/handler/handler0alter.cc:6962
 
# 2018-05-07T12:55:09 [26694] #17 0x000056341d7b3125 in handler::ha_prepare_inplace_alter_table (this=0x61d000585ca0, altered_table=0x61f000872288, ha_alter_info=0x7f62afd5d5a0) at /work/Server/10.3/sql/handler.cc:4387

Comment by Alice Sherepa [ 2018-07-03 ]

got something similar on 10.3 commit 358ae4b46dd52b329154c

==30481==ERROR: AddressSanitizer: use-after-poison on address 0x7f6992bfa468 at pc 0x55c9014c45a6 bp 0x7f697fcaf4d0 sp 0x7f697fcaf4c0
 
READ of size 8 at 0x7f6992bfa468 thread T17
 
    #0 0x55c9014c45a5 in row_sel /home/alice/git/10.3/storage/innobase/row/row0sel.cc:1798
 
    #1 0x55c9014c644f in row_sel_step(que_thr_t*) /home/alice/git/10.3/storage/innobase/row/row0sel.cc:2328
 
    #2 0x55c9013bd929 in que_thr_step /home/alice/git/10.3/storage/innobase/que/que0que.cc:1022
 
    #3 0x55c9013bdf90 in que_run_threads_low /home/alice/git/10.3/storage/innobase/que/que0que.cc:1108
 
    #4 0x55c9013be2d7 in que_run_threads(que_thr_t*) /home/alice/git/10.3/storage/innobase/que/que0que.cc:1148
 
    #5 0x55c9013be88b in que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) /home/alice/git/10.3/storage/innobase/que/que0que.cc:1225
 
    #6 0x55c90177c97c in dict_stats_exec_sql /home/alice/git/10.3/storage/innobase/dict/dict0stats.cc:311
 
    #7 0x55c9017855ba in dict_stats_save /home/alice/git/10.3/storage/innobase/dict/dict0stats.cc:2492
 
    #8 0x55c9017886a9 in dict_stats_update(dict_table_t*, dict_stats_upd_option_t) /home/alice/git/10.3/storage/innobase/dict/dict0stats.cc:3205
 
    #9 0x55c90178f362 in dict_stats_process_entry_from_recalc_pool /home/alice/git/10.3/storage/innobase/dict/dict0stats_bg.cc:387
 
    #10 0x55c90178f6df in dict_stats_thread /home/alice/git/10.3/storage/innobase/dict/dict0stats_bg.cc:466
 
    #11 0x7f699eb076b9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76b9)
 
    #12 0x7f699df9c41c in clone (/lib/x86_64-linux-gnu/libc.so.6+0x10741c)

Comment by Alice Sherepa [ 2018-07-04 ] 

Version: '10.3.9-MariaDB-debug-log'  socket: '/home/alice/aliska/3/current1_1/mysql.sock'  port: 13000  Source distribution
 
=================================================================
 
==32667==ERROR: AddressSanitizer: use-after-poison on address 0x7f01d3bfa4f8 at pc 0x55b4998febd3 bp 0x7f01c0cec0e0 sp 0x7f01c0cec0d0
 
WRITE of size 8 at 0x7f01d3bfa4f8 thread T17
 
    #0 0x55b4998febd2 in que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) /home/alice/git/10.3/storage/innobase/que/que0que.cc:1219
 
    #1 0x55b499cbd2aa in dict_stats_exec_sql /home/alice/git/10.3/storage/innobase/dict/dict0stats.cc:311
 
    #2 0x55b499cc5ee8 in dict_stats_save /home/alice/git/10.3/storage/innobase/dict/dict0stats.cc:2492
 
    #3 0x55b499cc8fd7 in dict_stats_update(dict_table_t*, dict_stats_upd_option_t) /home/alice/git/10.3/storage/innobase/dict/dict0stats.cc:3205
 
    #4 0x55b499ccfc90 in dict_stats_process_entry_from_recalc_pool /home/alice/git/10.3/storage/innobase/dict/dict0stats_bg.cc:387
 
    #5 0x55b499cd000d in dict_stats_thread /home/alice/git/10.3/storage/innobase/dict/dict0stats_bg.cc:466
 
    #6 0x7f01dfb446b9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76b9)
 
    #7 0x7f01defd941c in clone (/lib/x86_64-linux-gnu/libc.so.6+0x10741c)

Comment by Marko Mäkelä [ 2018-08-16 ]

I believe that this is a duplicate of MDEV-16136, caused by a race condition between the MDEV-15030 Pool memory poisoning and unpoisoning.

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