[MDEV-24982] heap-use-after-free in rec_get_offsets_func Created: 2021-02-25  Updated: 2021-04-13  Resolved: 2021-04-13

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.6.0
Fix Version/s: 10.6.0

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Duplicate Votes: 0
Labels: rr-profile

Attachments: File TBR-905.yy     File TBR-90n.cfg    
Issue Links:
Duplicate
duplicates MDEV-24863 InnoDB: Failing assertion: index == c... Closed

 Description   

10.6 7953bae22a8f1054acce9a74e089401f7e93e579 2021-02-24T09:30:17+02:00
RQG test where several concurrent sessions run a DDL/DML mix including
frequent buffer pool resizing.
[rr 2412117 469420]==2412117==ERROR: AddressSanitizer: heap-use-after-free on address 0x616002c84e38 at pc 0x55ed4b5da536 bp 0x7fa9a9f745d0 sp 0x7fa9a9f745c0
[rr 2412117 469425]READ of size 8 at 0x616002c84e38 thread T20
[rr 2412117 477021]    #0 0x55ed4b5da535 in rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned short*, bool, unsigned long, char const*, unsigned int, mem_block_info_t**) /Server/10.6D/storage/innobase/rem/rem0rec.cc:830
[rr 2412117 477042]    #1 0x55ed4b8bed24 in btr_search_drop_page_hash_index(buf_block_t*) /Server/10.6D/storage/innobase/btr/btr0sea.cc:1319
[rr 2412117 477071]    #2 0x55ed4b5215b3 in mtr_defer_drop_ahi /Server/10.6D/storage/innobase/mtr/mtr0mtr.cc:986
[rr 2412117 477089]    #3 0x55ed4b521d6c in mtr_t::page_lock(buf_block_t*, unsigned long) /Server/10.6D/storage/innobase/mtr/mtr0mtr.cc:1082
[rr 2412117 477135]    #4 0x55ed4b8e3df2 in buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool) /Server/10.6D/storage/innobase/buf/buf0buf.cc:3278
[rr 2412117 477137]    #5 0x55ed4b8e4396 in buf_page_get_gen(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool) /Server/10.6D/storage/innobase/buf/buf0buf.cc:3341
[rr 2412117 477158]    #6 0x55ed4b9c8dd1 in dict_stats_analyze_index_below_cur /Server/10.6D/storage/innobase/dict/dict0stats.cc:1517
[rr 2412117 477168]    #7 0x55ed4b9c9c73 in dict_stats_analyze_index_for_n_prefix /Server/10.6D/storage/innobase/dict/dict0stats.cc:1790
[rr 2412117 477170]    #8 0x55ed4b9cbe87 in dict_stats_analyze_index /Server/10.6D/storage/innobase/dict/dict0stats.cc:2192
[rr 2412117 477172]    #9 0x55ed4b9cc3b5 in dict_stats_update_persistent /Server/10.6D/storage/innobase/dict/dict0stats.cc:2250
[rr 2412117 477174]    #10 0x55ed4b9d1ce5 in dict_stats_update(dict_table_t*, dict_stats_upd_option_t) /Server/10.6D/storage/innobase/dict/dict0stats.cc:3223
[rr 2412117 477176]    #11 0x55ed4b9d243c in dict_stats_update(dict_table_t*, dict_stats_upd_option_t) /Server/10.6D/storage/innobase/dict/dict0stats.cc:3344
[rr 2412117 477261]    #12 0x55ed4b2f71f2 in dict_stats_init /Server/10.6D/storage/innobase/include/dict0stats.ic:165
[rr 2412117 477263]    #13 0x55ed4b35e9c8 in ha_innobase::reload_statistics() (/data/Server_bin/10.6D_asan/bin/mariadbd+0x2c279c8)
[rr 2412117 477265]    #14 0x55ed4b2f8f04 in innodb_notify_tabledef_changed /Server/10.6D/storage/innobase/handler/ha_innodb.cc:1394
[rr 2412117 477299]    #15 0x55ed4a3868b2 in mysql_inplace_alter_table /Server/10.6D/sql/sql_table.cc:8161
[rr 2412117 477313]    #16 0x55ed4a397b32 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, bool) /Server/10.6D/sql/sql_table.cc:10677
[rr 2412117 477330]    #17 0x55ed4a512793 in Sql_cmd_alter_table::execute(THD*) /Server/10.6D/sql/sql_alter.cc:539
[rr 2412117 477380]    #18 0x55ed4a129693 in mysql_execute_command(THD*) /Server/10.6D/sql/sql_parse.cc:5946
[rr 2412117 477412]2021-02-25  4:14:20 25 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
[rr 2412117 477422]    #19 0x55ed4a135fd6 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /Server/10.6D/sql/sql_parse.cc:7972
[rr 2412117 477424]    #20 0x55ed4a10e62d in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /Server/10.6D/sql/sql_parse.cc:1886
[rr 2412117 477426]    #21 0x55ed4a10b8ff in do_command(THD*, bool) /Server/10.6D/sql/sql_parse.cc:1397
[rr 2412117 477472]    #22 0x55ed4a4f9a71 in do_handle_one_connection(CONNECT*, bool) /Server/10.6D/sql/sql_connect.cc:1410
[rr 2412117 477474]    #23 0x55ed4a4f93d5 in handle_one_connection /Server/10.6D/sql/sql_connect.cc:1312
[rr 2412117 477532]    #24 0x55ed4b125aec in pfs_spawn_thread /Server/10.6D/storage/perfschema/pfs.cc:2201
[rr 2412117 477538]    #25 0x7fa9d9ad5608 in start_thread /build/glibc-eX1tMB/glibc-2.31/nptl/pthread_create.c:477
[rr 2412117 477562]    #26 0x7fa9d96a9292 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x122292)
 
(rr) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00007fa9d95ac859 in __GI_abort () at abort.c:79
#2  0x00007fa9d9f216a2 in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
#3  0x00007fa9d9f2c24c in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
#4  0x00007fa9d9f0d8ec in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
#5  0x00007fa9d9f0d363 in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
#6  0x00007fa9d9f0e1ab in __asan_report_load8 () from /lib/x86_64-linux-gnu/libasan.so.5
#7  0x000055ed4b5da536 in rec_get_offsets_func (rec=0x7fa9bfb396cb "\200", index=0x616002c84e20, offsets=0x61500001fca0, leaf=true, n_fields=1, file=0x55ed4ce432e0 "/Server/10.6D/storage/innobase/btr/btr0sea.cc", line=1319, heap=0x7fa9a9f747f0)
    at /Server/10.6D/storage/innobase/rem/rem0rec.cc:830
#8  0x000055ed4b8bed25 in btr_search_drop_page_hash_index (block=0x7fa9bc64d0c0) at /Server/10.6D/storage/innobase/btr/btr0sea.cc:1319
#9  0x000055ed4b5215b4 in mtr_defer_drop_ahi (block=0x7fa9bc64d0c0, fix_type=MTR_MEMO_PAGE_S_FIX) at /Server/10.6D/storage/innobase/mtr/mtr0mtr.cc:986
#10 0x000055ed4b521d6d in mtr_t::page_lock (this=0x7fa9a9f74de0, block=0x7fa9bc64d0c0, rw_latch=1) at /Server/10.6D/storage/innobase/mtr/mtr0mtr.cc:1082
#11 0x000055ed4b8e3df3 in buf_page_get_low (page_id=..., zip_size=0, rw_latch=1, guess=0x0, mode=10, mtr=0x7fa9a9f74de0, err=0x7fa9a9f74d70, allow_ibuf_merge=false) at /Server/10.6D/storage/innobase/buf/buf0buf.cc:3278
#12 0x000055ed4b8e4397 in buf_page_get_gen (page_id=..., zip_size=0, rw_latch=1, guess=0x0, mode=10, mtr=0x7fa9a9f74de0, err=0x7fa9a9f74d70, allow_ibuf_merge=false) at /Server/10.6D/storage/innobase/buf/buf0buf.cc:3341
#13 0x000055ed4b9c8dd2 in dict_stats_analyze_index_below_cur (cur=0x7fa9a9f75470, n_prefix=1, n_diff=0x7fa9a9f75430, n_external_pages=0x7fa9a9f75450) at /Server/10.6D/storage/innobase/dict/dict0stats.cc:1517
#14 0x000055ed4b9c9c74 in dict_stats_analyze_index_for_n_prefix (index=0x616003cf6a20, n_prefix=1, boundaries=0x6060000697b8, n_diff_data=0x6070000e3288, mtr=0x7fa9a9f75750) at /Server/10.6D/storage/innobase/dict/dict0stats.cc:1790
#15 0x000055ed4b9cbe88 in dict_stats_analyze_index (index=0x616003cf6a20) at /Server/10.6D/storage/innobase/dict/dict0stats.cc:2192
#16 0x000055ed4b9cc3b6 in dict_stats_update_persistent (table=0x618000071520) at /Server/10.6D/storage/innobase/dict/dict0stats.cc:2250
#17 0x000055ed4b9d1ce6 in dict_stats_update (table=0x618000071520, stats_upd_option=DICT_STATS_RECALC_PERSISTENT) at /Server/10.6D/storage/innobase/dict/dict0stats.cc:3223
#18 0x000055ed4b9d243d in dict_stats_update (table=0x618000071520, stats_upd_option=DICT_STATS_FETCH_ONLY_IF_NOT_IN_MEMORY) at /Server/10.6D/storage/innobase/dict/dict0stats.cc:3344
#19 0x000055ed4b2f71f3 in dict_stats_init (table=0x618000071520) at /Server/10.6D/storage/innobase/include/dict0stats.ic:165
#20 0x000055ed4b35e9c9 in ha_innobase::reload_statistics (this=0x61d0014992b8) at /Server/10.6D/storage/innobase/handler/ha_innodb.cc:1380
#21 0x000055ed4b2f8f05 in innodb_notify_tabledef_changed (handler=0x61d0014992b8) at /Server/10.6D/storage/innobase/handler/ha_innodb.cc:1394
#22 0x000055ed4a3868b3 in mysql_inplace_alter_table (thd=0x62b00011f218, table_list=0x62b0001263e8, table=0x61900049c098, altered_table=0x7fa9a9f78430, ha_alter_info=0x7fa9a9f77f50, target_mdl_request=0x7fa9a9f78030, alter_ctx=0x7fa9a9f78e90)
    at /Server/10.6D/sql/sql_table.cc:8161
#23 0x000055ed4a397b33 in mysql_alter_table (thd=0x62b00011f218, new_db=0x62b000123c90, new_name=0x62b000124090, create_info=0x7fa9a9f7a210, table_list=0x62b0001263e8, alter_info=0x7fa9a9f7a100, order_num=0, order=0x0, ignore=false, 
    if_exists=false) at /Server/10.6D/sql/sql_table.cc:10677
#24 0x000055ed4a512794 in Sql_cmd_alter_table::execute (this=0x62b000126b50, thd=0x62b00011f218) at /Server/10.6D/sql/sql_alter.cc:539
#25 0x000055ed4a129694 in mysql_execute_command (thd=0x62b00011f218) at /Server/10.6D/sql/sql_parse.cc:5946
#26 0x000055ed4a135fd7 in mysql_parse (thd=0x62b00011f218, rawbuf=0x62b000126238 "ALTER TABLE t4 DROP INDEX `idx1`, LOCK = EXCLUSIVE, ALGORITHM = NOCOPY /* E_R Thread8 QNO 2375 CON_ID 24 */", length=107, parser_state=0x7fa9a9f7b870)
    at /Server/10.6D/sql/sql_parse.cc:7972
#27 0x000055ed4a10e62e in dispatch_command (command=COM_QUERY, thd=0x62b00011f218, packet=0x62900073f219 "ALTER TABLE t4 DROP INDEX `idx1`, LOCK = EXCLUSIVE, ALGORITHM = NOCOPY /* E_R Thread8 QNO 2375 CON_ID 24 */ ", packet_length=108, 
    blocking=true) at /Server/10.6D/sql/sql_parse.cc:1886
#28 0x000055ed4a10b900 in do_command (thd=0x62b00011f218, blocking=true) at /Server/10.6D/sql/sql_parse.cc:1397
#29 0x000055ed4a4f9a72 in do_handle_one_connection (connect=0x6080000037b8, put_in_cache=true) at /Server/10.6D/sql/sql_connect.cc:1410
#30 0x000055ed4a4f93d6 in handle_one_connection (arg=0x6080000037b8) at /Server/10.6D/sql/sql_connect.cc:1312
#31 0x000055ed4b125aed in pfs_spawn_thread (arg=0x61500000be98) at /Server/10.6D/storage/perfschema/pfs.cc:2201
#32 0x00007fa9d9ad5609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#33 0x00007fa9d96a9293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(rr)
 
Query: ALTER TABLE t4 DROP INDEX `idx1`, LOCK = EXCLUSIVE, ALGORITHM = NOCOPY
Status: KILL_TIMEOUT
 
sdp:/home/mleich/RQG_O/storage/1614254107/TBR-905/dev/shm/vardir/1614254107/107/1/rr
_RR_TRACE_DIR="." rr replay --mark-stdio
 
RQG
====
git clone https://github.com/mleich1/rqg --branch experimental RQG
 
perl rqg.pl \               
--duration=300 \
--queries=10000000 \
--no_mask \
--seed=random \
--gendata_sql=conf/mariadb/table_stress.sql \
--gendata=conf/mariadb/table_stress.zz \
--engine=InnoDB \
--rpl_mode=none \
--mysqld=--loose-max-statement-time=30 \
--mysqld=--innodb_adaptive_hash_index=on \
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
--mysqld=--innodb_stats_persistent=on \
--mysqld=--innodb_page_size=64K \
--mysqld=--net_read_timeout=30 \
--mysqld=--log-bin \
--mysqld=--loose-idle_transaction_timeout=0 \
--mysqld=--innodb-lock-wait-timeout=50 \
--mysqld=--loose-table_lock_wait_timeout=50 \
--mysqld=--file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
--mysqld=--lock-wait-timeout=86400 \
--mysqld=--log_bin_trust_function_creators=1 \
--mysqld=--loose-idle_write_transaction_timeout=0 \
--mysqld=--log-output=none \
--mysqld=--wait_timeout=28800 \
--mysqld=--innodb-buffer-pool-size=256M \
--mysqld=--interactive_timeout=28800 \
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
--mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
--mysqld=--plugin-load-add=file_key_management.so \
--mysqld=--net_write_timeout=60 \
--mysqld=--slave_net_timeout=60 \
--mysqld=--connect_timeout=60 \
--reporters=Deadlock1,ErrorLog,ServerDead \
--validators=None \
--grammar=TBR-905.yy \
--threads=10 \
--workdir=<local settings> \
--vardir=<local settings> \
--mtr-build-thread=<local settings> \
--basedir1=<local settings> \
--script_debug=_nix_ \
--rr=Server
 



 Comments   
Comment by Matthias Leich [ 2021-02-25 ]

I get the following ASAN failures with the test from above
    # SUMMARY: AddressSanitizer: heap-use-after-free /Server/10.6D/storage/innobase/include/dict0mem.h:1799 in dict_table_t::not_redundant() const
    # SUMMARY: AddressSanitizer: heap-use-after-free /Server/10.6D/storage/innobase/include/dict0mem.h:600 in dict_col_t::is_nullable() const
    # SUMMARY: AddressSanitizer: heap-use-after-free /Server/10.6D/storage/innobase/include/dict0mem.h:1174 in dict_index_t::is_ibuf() const
    # SUMMARY: AddressSanitizer: heap-use-after-free /Server/10.6D/storage/innobase/rem/rem0rec.cc:608 in rec_init_offsets
    # SUMMARY: AddressSanitizer: heap-use-after-free /Server/10.6D/storage/innobase/rem/rem0rec.cc:830 in rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned short*, bool, unsigned long, char const*, unsigned int, mem_block_info_t**)
    # mysqld: /Server/10.6D/storage/innobase/row/row0row.cc:274: dtuple_t* row_build_index_entry_low(const dtuple_t*, const row_ext_t*, const dict_index_t*, mem_heap_t*, ulint): Assertion `flag == 1' failed.
 
The RQG grammar is already simplified (only automatic simplification).  Nevertheless its runtime properties are quite problematic.
Without rr the likelihood to replay one of the ASAN failures is low, with rr lower and with rr+option chaos roughly zero. 

Comment by Marko Mäkelä [ 2021-04-12 ]

mleich, is this bug still repeatable? I see that the memory was freed here:

10.6 7953bae22a8f1054acce9a74e089401f7e93e579

#6  0x000055ed4b9b4e2a in dict_mem_index_free (index=0x616002c84e20) at /Server/10.6D/storage/innobase/dict/dict0mem.cc:1108
#7  0x000055ed4b8b8da2 in btr_search_lazy_free (index=0x616002c84e20) at /Server/10.6D/storage/innobase/btr/btr0sea.cc:211
#8  0x000055ed4b8c781b in buf_pool_t::clear_hash_index (this=0x55ed4dfdf880 <buf_pool>) at /Server/10.6D/storage/innobase/btr/btr0sea.cc:950
#9  0x000055ed4b8b905b in btr_search_disable () at /Server/10.6D/storage/innobase/btr/btr0sea.cc:255
#10 0x000055ed4b8faaa3 in buf_pool_t::resize (this=0x55ed4dfdf880 <buf_pool>) at /Server/10.6D/storage/innobase/buf/buf0buf.cc:1986
#11 0x000055ed4b8dee2d in buf_resize_callback () at /Server/10.6D/storage/innobase/buf/buf0buf.cc:2316

Given that this last occurred on 7953bae22a8f1054acce9a74e089401f7e93e579 2021-02-24T09:30:17+02:00 (just before the merge of MDEV-24863 two days later, in b47304eb02fd203ab9ecd29261e6915e0059af0a), I think that we can conclude that this report is a duplicate of MDEV-24863.

Generated at Thu Feb 08 09:34:11 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.