[MDEV-22903] heap-use-after-free while accessing fts cache deleted doc ids Created: 2020-06-15  Updated: 2020-07-23  Resolved: 2020-07-23

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.1, 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.1.46, 10.2.33, 10.3.24, 10.4.14, 10.5.5

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: rr-profile-analyzed

Attachments: File 001987.log    

 Description   

ASAN failure hit during RQG testing
==60090==ERROR: AddressSanitizer: heap-use-after-free on address 0x61a000120730 at pc 0x561a4926e8ef bp 0x683e3e275840 sp 0x683e3e275830
READ of size 8 at 0x61a000120730 thread T69
    #0 0x561a4926e8ee in ib_vector_size storage/innobase/include/ut0vec.ic:118
    #1 0x561a4928f11e in fts_cache_append_deleted_doc_ids(fts_cache_t const*, ib_vector_t*) storage/innobase/fts/fts0fts.cc:5188
    #2 0x561a492c7b94 in fts_query(trx_t*, dict_index_t*, unsigned int, unsigned char const*, unsigned long, fts_result_t**) storage/innobase/fts/fts0que.cc:4007
    #3 0x561a48ab1579 in ha_innobase::ft_init_ext(unsigned int, unsigned int, String*) storage/innobase/handler/ha_innodb.cc:9597
    #4 0x561a4812b2b8 in Item_func_match::init_search(THD*, bool) sql/item_func.cc:6068
    #5 0x561a4766d157 in init_ftfuncs(THD*, st_select_lex*, bool) sql/sql_base.cc:8909
    #6 0x561a47897823 in JOIN::optimize_stage2() sql/sql_select.cc:2778
    #7 0x561a47891e14 in JOIN::optimize_inner() sql/sql_select.cc:2262
    #8 0x561a4788b046 in JOIN::optimize() sql/sql_select.cc:1612
    #9 0x561a478ab46c in mysql_select(THD*, TABLE_LIST*, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) sql/sql_select.cc:4635
    #10 0x561a4787d812 in handle_select(THD*, LEX*, select_result*, unsigned long) sql/sql_select.cc:417
    #11 0x561a477edfe4 in execute_sqlcom_select sql/sql_parse.cc:6208
    #12 0x561a477dd313 in mysql_execute_command(THD*) sql/sql_parse.cc:3939
    #13 0x561a477f9138 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) sql/sql_parse.cc:7992
    #14 0x561a477cfc8c in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) sql/sql_parse.cc:1874
    #15 0x561a477cc50a in do_command(THD*) sql/sql_parse.cc:1355
    #16 0x561a47bf9a47 in do_handle_one_connection(CONNECT*, bool) sql/sql_connect.cc:1411
    #17 0x561a47bf93a5 in handle_one_connection sql/sql_connect.cc:1313
    #18 0x561a488b3096 in pfs_spawn_thread storage/perfschema/pfs.cc:2201
    #19 0x3d597f56b6da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)
    #20 0x7f49706bd88e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x12188e)
...
Query (0x62b0000f5238): SELECT `c12`,MATCH (`c3`) AGAINST ('one-third' IN NATURAL LANGUAGE MODE ) AS SCORE FROM `table400_innodb_int_autoinc` WHERE MATCH (`c2`) AGAINST ('personality' IN NATURAL LANGUAGE MODE ) != 1
 
origin/10.5 574ef3800567a24a57812d46118579fb08aaf243 2020-06-13T11:59:34+03:00
 
RQG
git clone https://github.com/mleich1/rqg --branch experimental RQG
origin/experimental 611a31e38a3bc157392c0748c95991b6a248bb3b 2020-06-09T15:31:46+02:00
 
perl rqg.pl \
--gendata=conf/engines/innodb/full_text_search.zz \
--short_column_names \
--grammar=conf/engines/innodb/full_text_search.yy \
--redefine=conf/mariadb/alter_table.yy \
--redefine=conf/mariadb/instant_add.yy \
--redefine=conf/mariadb/modules/alter_table_columns.yy \
--redefine=conf/mariadb/sp.yy \
--redefine=conf/mariadb/bulk_insert.yy \
--redefine=conf/mariadb/modules/foreign_keys.yy \
--redefine=conf/mariadb/modules/locks.yy \
--redefine=conf/mariadb/modules/sql_mode.yy \
--redefine=conf/mariadb/redefine_temporary_tables.yy \
--redefine=conf/mariadb/versioning.yy \
--redefine=conf/mariadb/sequences.yy \
--mysqld=--innodb_use_native_aio=1 \
--mysqld=--innodb_stats_persistent=off \
--mysqld=--innodb_lock_schedule_algorithm=fcfs \
--mysqld=--loose-idle_write_transaction_timeout=0 \
--mysqld=--loose-idle_transaction_timeout=0 \
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
--mysqld=--connect_timeout=60 \
--mysqld=--interactive_timeout=28800 \
--mysqld=--slave_net_timeout=60 \
--mysqld=--net_read_timeout=30 \
--mysqld=--net_write_timeout=60 \
--mysqld=--loose-table_lock_wait_timeout=50 \
--mysqld=--wait_timeout=28800 \
--mysqld=--lock-wait-timeout=86400 \
--mysqld=--innodb-lock-wait-timeout=50 \
--no-mask \
--queries=10000000 \
--seed=random \
--reporters=Backtrace \
--reporters=ErrorLog \
--reporters=Deadlock1 \
--validators=None \
--mysqld=--log_output=none \
--mysqld=--log-bin \
--mysqld=--log_bin_trust_function_creators=1 \
--mysqld=--loose-max-statement-time=30 \
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
--engine=InnoDB \
--restart_timeout=120 \
--duration=300 \
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
--mysqld=--loose-innodb-sync-debug \
--threads=33 \
--mysqld=--innodb_page_size=64K \
--mysqld=--innodb-buffer-pool-size=256M \
--duration=300 \
--no_mask \
... certain local settings ...



 Comments   
Comment by Thirunarayanan Balathandayuthapani [ 2020-06-16 ]

DDL does fts_sync_table() in ha_innobase::inplace_alter_table(). It does fts_cache_clear() and it frees sync_heap.
In the meantime, concurrent read tries to access deleted_doc_ids (which is basically sync_heap).
Need to read when to use cache->lock & cache->init_lock.

This problem could exist in 10.2+ too

Comment by Thirunarayanan Balathandayuthapani [ 2020-06-16 ]

#17 0x0000561a48afb1ba in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter
    (this=0x61b0000596f0, n_spins=30, n_delay=4, 
---Type <return> to continue, or q <return> to quit---
    name=0x561a4a718420 "/home/mleich/10.5_new/storage/innobase/fts/fts0fts.cc", line=1094)
    at /home/mleich/10.5_new/storage/innobase/include/ib0mutex.h:590
#18 0x0000561a49278fa6 in fts_cache_clear (cache=0x61b000059520)
    at /home/mleich/10.5_new/storage/innobase/fts/fts0fts.cc:1094
#19 0x0000561a49288f4a in fts_sync_commit (sync=0x61b0000598f0)
    at /home/mleich/10.5_new/storage/innobase/fts/fts0fts.cc:4148
#20 0x0000561a4928a3c8 in fts_sync (sync=0x61b0000598f0, unlock_cache=false, 
    wait=true) at /home/mleich/10.5_new/storage/innobase/fts/fts0fts.cc:4325
#21 0x0000561a4928a800 in fts_sync_table (table=0x619000856720, wait=true)
    at /home/mleich/10.5_new/storage/innobase/fts/fts0fts.cc:4364
#22 0x0000561a48e07cf0 in row_merge_read_clustered_index (
    trx=0x366c14a69688, table=0x551f754b2890, old_table=0x619000856720, 
    new_table=0x619000856720, online=false, index=0x61e0000a01b8, 
    fts_sort_idx=0x618000274120, psort_info=0x618000274498, 
    files=0x606000812b58, key_numbers=0x61e0000a01c8, n_index=1, 
    defaults=0x0, add_v=0x0, col_map=0x0, add_autoinc=18446744073709551615, 
    sequence=..., block=0x7f495bf94000 "", skip_pk_sort=false, 
    tmpfd=0x551f754af790, stage=0x6080000f2ab8, pct_cost=50, 
    crypt_block=0x0, eval_table=0x551f754b2890, allow_not_null=false)
    at /home/mleich/10.5_new/storage/innobase/row/row0merge.cc:2826
#23 0x0000561a48e13b2f in row_merge_build_indexes (trx=0x366c14a69688, 
    old_table=0x619000856720, new_table=0x619000856720, online=false, 
    indexes=0x61e0000a01b8, key_numbers=0x61e0000a01c8, n_indexes=1, 
    table=0x551f754b2890, defaults=0x0, col_map=0x0, 
    add_autoinc=18446744073709551615, sequence=..., skip_pk_sort=false, 
    stage=0x6080000f2ab8, add_v=0x0, eval_table=0x551f754b2890, 
    allow_not_null=false)
    at /home/mleich/10.5_new/storage/innobase/row/row0merge.cc:4533
#24 0x0000561a48b595b5 in ha_innobase::inplace_alter_table (
    this=0x61d000df48b8, altered_table=0x551f754b2890, 
    ha_alter_info=0x551f754b13b0)

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

This looks OK, but should we not fix this in 10.1 (InnoDB and XtraDB)?

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