[MDEV-17005] ASAN heap-use-after-free in innobase_get_computed_value Created: 2018-08-16  Updated: 2019-10-11  Resolved: 2019-07-22

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Locking, Storage Engine - InnoDB, Virtual Columns
Affects Version/s: 10.2, 10.3, 10.4
Fix Version/s: 10.2.26, 10.3.17, 10.4.7

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Nikita Malyavin
Resolution: Fixed Votes: 0
Labels: affects-tests

Attachments: File mdev-17005.tgz    
Issue Links:
Relates
relates to MDEV-5800 indexes on virtual (not materialized)... Closed
relates to MDEV-19486 Server crashes in row_upd or row_upd_... Closed
relates to MDEV-20143 innodb.innodb-virtual-columns-debug f... Closed
relates to MDEV-16856 Crash Closed
relates to MDEV-18546 ASAN heap-use-after-free in innobase_... Closed
relates to MDEV-18891 ASAN heap-use-after-free in innobase_... Closed
Sub-Tasks:
Key
 Summary
 Type
 Status
 Assignee
MDEV-19619 Variety of test cases and stack trace... Technical task Closed  

 Description   

10.2 05153a670de6ee

 
==10706==ERROR: AddressSanitizer: heap-use-after-free on address 0x6230001712ec at pc 0x5568429cf673 bp 0x7f55d3e2fc30 sp 0x7f55d3e2fc28
 
READ of size 5 at 0x6230001712ec thread T33
 
    #0 0x5568429cf672 in innobase_get_computed_value(dtuple_t const*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**, mem_block_info_t*, dict_field_t const*, THD*, TABLE*, unsigned char*, dict_table_t const*, upd_t*, dict_foreign_t*) /data/src/10.2/storage/innobase/handler/ha_innodb.cc:22078
 
    #1 0x556842c946ad in row_upd_store_v_row /data/src/10.2/storage/innobase/row/row0upd.cc:2188
 
    #2 0x556842c94c84 in row_upd_store_row(upd_node_t*, THD*, TABLE*) /data/src/10.2/storage/innobase/row/row0upd.cc:2252
 
    #3 0x556842c98727 in row_upd_del_mark_clust_rec /data/src/10.2/storage/innobase/row/row0upd.cc:2975
 
    #4 0x556842c99574 in row_upd_clust_step /data/src/10.2/storage/innobase/row/row0upd.cc:3158
 
    #5 0x556842c9a015 in row_upd /data/src/10.2/storage/innobase/row/row0upd.cc:3279
 
    #6 0x556842c9ad2e in row_upd_step(que_thr_t*) /data/src/10.2/storage/innobase/row/row0upd.cc:3425
 
    #7 0x556842bf493d in row_update_for_mysql(row_prebuilt_t*) /data/src/10.2/storage/innobase/row/row0mysql.cc:1829
 
    #8 0x55684299ba67 in ha_innobase::delete_row(unsigned char const*) /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9228
 
    #9 0x5568422110e4 in handler::ha_delete_row(unsigned char const*) /data/src/10.2/sql/handler.cc:6019
 
    #10 0x556841bb0f2e in write_record(THD*, TABLE*, st_copy_info*) /data/src/10.2/sql/sql_insert.cc:1893
 
    #11 0x5568425f5664 in read_sep_field /data/src/10.2/sql/sql_load.cc:1256
 
    #12 0x5568425f1458 in mysql_load(THD*, sql_exchange*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool, bool) /data/src/10.2/sql/sql_load.cc:649
 
    #13 0x556841c1113f in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:4833
 
    #14 0x556841c25139 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:8009
 
    #15 0x556841bffd20 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1824
 
    #16 0x556841bfcdc4 in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1378
 
    #17 0x556841f3f825 in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
 
    #18 0x556841f3f23a in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
 
    #19 0x7f55f4bc9493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
    #20 0x7f55f2faf93e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
 
 
 
ASAN:SIGSEGV
 
==10706==AddressSanitizer: while reporting a bug found another one.Ignoring.

To reproduce:

git clone https://github.com/elenst/rqg --branch mdev17005 rqg-mdev17005
 
cd rqg-mdev17005
 
perl ./runall-new.pl --basedir=/data/bld/10.2-asan --vardir=/dev/shm/vardir --duration=350 --threads=4  --grammar=mdev17005.yy --skip-gendata --gendata-advanced --vcols

Notes:

  • Don't forget to change the basedir value.
  • The grammar is quite big and could definitely use some automatic simplification, but I'm not sure it's necessary, possibly the problem will be obvious right away.
  • Reproducible on 10.2 and 10.3. On 10.0 and 10.1 I hit MDEV-17004 instead.
  • The test reproduces the problem for me almost every time, but sometimes it misses the mark. Just run it again. You can also use this command line to run the same test a desired number of times: 

    perl ./runall-trials.pl --trials=10 --basedir=/data/bld/10.2-asan --vardir=/dev/shm/vardir --duration=350 --threads=4  --grammar=mdev17005.yy --skip-gendata --gendata-advanced --vcols

    runall-new.pl is replaced by runall-trials.pl --trials=N, all other options are the same. It will stop when the test fails for the first time.

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

Possibly related:

181006 11:55:56 [ERROR] mysqld got exception 0xc0000005 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.2.19-MariaDB-log
 
key_buffer_size=134217728
 
read_buffer_size=131072
 
max_used_connections=8
 
max_threads=65537
 
thread_count=14
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 136064 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x3abedc0f38
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
mysqld.exe!MoveSmall()[memcpy.asm:207]
 
mysqld.exe!innobase_get_computed_value()[ha_innodb.cc:21739]
 
mysqld.exe!row_upd_store_v_row()[row0upd.cc:2108]
 
mysqld.exe!row_upd_store_row()[row0upd.cc:2227]
 
mysqld.exe!row_upd_del_mark_clust_rec()[row0upd.cc:2954]
 
mysqld.exe!row_upd_clust_step()[row0upd.cc:3137]
 
mysqld.exe!row_upd()[row0upd.cc:3251]
 
mysqld.exe!row_upd_step()[row0upd.cc:3400]
 
mysqld.exe!row_update_for_mysql()[row0mysql.cc:1832]
 
mysqld.exe!ha_innobase::delete_row()[ha_innodb.cc:9086]
 
mysqld.exe!handler::ha_delete_row()[handler.cc:6021]
 
mysqld.exe!write_record()[sql_insert.cc:1893]
 
mysqld.exe!read_sep_field()[sql_load.cc:1256]
 
mysqld.exe!mysql_load()[sql_load.cc:647]
 
mysqld.exe!mysql_execute_command()[sql_parse.cc:4831]
 
mysqld.exe!mysql_parse()[sql_parse.cc:8016]
 
mysqld.exe!dispatch_command()[sql_parse.cc:1826]
 
mysqld.exe!do_command()[sql_parse.cc:1377]
 
mysqld.exe!threadpool_process_request()[threadpool_common.cc:366]
 
mysqld.exe!tp_callback()[threadpool_common.cc:192]
 
ntdll.dll!RtlFreeUnicodeString()
 
ntdll.dll!RtlFreeUnicodeString()
 
KERNEL32.DLL!BaseThreadInitThunk()
 
ntdll.dll!RtlUserThreadStart()
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x3abedc9800): LOAD DATA INFILE 'load_t5' REPLACE INTO TABLE t5 /* QNO 1132 CON_ID 16 */
 
Connection ID (thread ID): 16
 
Status: NOT_KILLED

Comment by Elena Stepanova [ 2018-10-31 ]

New occurrence of the failure from the previous comment on 10.2: http://buildbot.askmonty.org/buildbot/builders/qa-win-rel/builds/5462/steps/result_summary/logs/stdio

Comment by Marko Mäkelä [ 2018-11-01 ]

I can repeat easily:

10.2 abcd09c95a49d02bf136a21d62d38a2d03672f26

 
Version: '10.2.19-MariaDB-debug-log'  socket: '/dev/shm/vardir/mysql.sock'  port: 19300  Source distribution
 
=================================================================
 
==5345==ERROR: AddressSanitizer: heap-use-after-free on address 0x6200001991c3 at pc 0x00000067c71a bp 0x7fc2105da590 sp 0x7fc2105d9d40
 
READ of size 3 at 0x6200001991c3 thread T34
 
    #0 0x67c719 in __asan_memcpy (/dev/shm/10.2/sql/mysqld+0x67c719)
 
    #1 0x1570a93 in innobase_get_computed_value(dtuple_t const*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**, mem_block_info_t*, dict_field_t const*, THD*, TABLE*, unsigned char*, dict_table_t const*, upd_t*, dict_foreign_t*) /mariadb/10.2/storage/innobase/handler/ha_innodb.cc:21772:25
 
    #2 0x1910b4f in row_upd_store_row(upd_node_t*, THD*, TABLE*) /mariadb/10.2/storage/innobase/row/row0upd.cc:2186:6
 
    #3 0x19141a4 in row_upd_del_mark_clust_rec(upd_node_t*, dict_index_t*, unsigned long*, que_thr_t*, unsigned long, bool, mtr_t*) /mariadb/10.2/storage/innobase/row/row0upd.cc:2975:2
 
    #4 0x19141a4 in row_upd_clust_step(upd_node_t*, que_thr_t*) /mariadb/10.2/storage/innobase/row/row0upd.cc:3155
 
    #5 0x19141a4 in row_upd(upd_node_t*, que_thr_t*) /mariadb/10.2/storage/innobase/row/row0upd.cc:3281
 
    #6 0x191244f in row_upd_step(que_thr_t*) /mariadb/10.2/storage/innobase/row/row0upd.cc:3427:8
 
    #7 0x1838545 in row_update_for_mysql(row_prebuilt_t*) /mariadb/10.2/storage/innobase/row/row0mysql.cc:1832:3
 
    #8 0x153ca6f in ha_innobase::delete_row(unsigned char const*) /mariadb/10.2/storage/innobase/handler/ha_innodb.cc:9084:10
 
    #9 0xee77a4 in handler::ha_delete_row(unsigned char const*) /mariadb/10.2/sql/handler.cc:6021:3
 
    #10 0x876dd9 in write_record(THD*, TABLE*, st_copy_info*) /mariadb/10.2/sql/sql_insert.cc:1893:35
 
    #11 0x13e8871 in mysql_load(THD*, sql_exchange*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool, bool) /mariadb/10.2/sql/sql_load.cc:1256:10
 
    #12 0x8dbd69 in mysql_execute_command(THD*) /mariadb/10.2/sql/sql_parse.cc:4831:10
 
    #13 0x8c6f20 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /mariadb/10.2/sql/sql_parse.cc:8011:18
 
    #14 0x8be67e in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /mariadb/10.2/sql/sql_parse.cc:1823:7
 
    #15 0x8c384c in do_command(THD*) /mariadb/10.2/sql/sql_parse.cc:1377:17
 
    #16 0xc1dc4e in do_handle_one_connection(CONNECT*) /mariadb/10.2/sql/sql_connect.cc:1335:11
 
    #17 0xc1d605 in handle_one_connection /mariadb/10.2/sql/sql_connect.cc:1241:3
 
    #18 0x7fc22847af29 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7f29)
 
    #19 0x7fc227302ede in clone (/lib/x86_64-linux-gnu/libc.so.6+0xf7ede)
 
 
 
0x6200001991c3 is located 323 bytes inside of 3888-byte region [0x620000199080,0x620000199fb0)
 
freed by thread T33 here:
 
    #0 0x67d818 in __interceptor_free (/dev/shm/10.2/sql/mysqld+0x67d818)
 
    #1 0x21c4442 in my_free /mariadb/10.2/mysys/my_malloc.c:217:5
 
    #2 0x21a975e in free_root /mariadb/10.2/mysys/my_alloc.c:393:7
 
    #3 0xb6690c in TABLE_SHARE::destroy() /mariadb/10.2/sql/table.cc:474:3
 
    #4 0xb66c75 in free_table_share(TABLE_SHARE*) /mariadb/10.2/sql/table.cc:490:10
 
    #5 0xd92509 in THD::free_tmp_table_share(TMP_TABLE_SHARE*, bool) /mariadb/10.2/sql/temporary_tables.cc:1445:3
 
    #6 0xd99302 in THD::drop_temporary_table(TABLE*, bool*, bool) /mariadb/10.2/sql/temporary_tables.cc:637:3
 
    #7 0xb01abd in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /mariadb/10.2/sql/sql_table.cc:9631:8
 
    #8 0xc2c0d2 in Sql_cmd_alter_table::execute(THD*) /mariadb/10.2/sql/sql_alter.cc:323:11
 
    #9 0x8cfff6 in mysql_execute_command(THD*) /mariadb/10.2/sql/sql_parse.cc:6225:26
 
    #10 0x8c6f20 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /mariadb/10.2/sql/sql_parse.cc:8011:18
 
    #11 0x8be67e in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /mariadb/10.2/sql/sql_parse.cc:1823:7
 
    #12 0x8c384c in do_command(THD*) /mariadb/10.2/sql/sql_parse.cc:1377:17
 
    #13 0xc1dc4e in do_handle_one_connection(CONNECT*) /mariadb/10.2/sql/sql_connect.cc:1335:11
 
    #14 0xc1d605 in handle_one_connection /mariadb/10.2/sql/sql_connect.cc:1241:3
 
 
 
previously allocated by thread T33 here:
 
    #0 0x67dbf7 in __interceptor_malloc (/dev/shm/10.2/sql/mysqld+0x67dbf7)
 
    #1 0x21c3f76 in my_malloc /mariadb/10.2/mysys/my_malloc.c:101:10
 
    #2 0x21a8a96 in alloc_root /mariadb/10.2/mysys/my_alloc.c:242:30
 
    #3 0xb68f46 in TABLE_SHARE::init_from_binary_frm_image(THD*, bool, unsigned char const*, unsigned long) /mariadb/10.2/sql/table.cc:1592:27
 
    #4 0xd918da in THD::create_temporary_table(handlerton*, st_mysql_const_unsigned_lex_string*, char const*, char const*, char const*) /mariadb/10.2/sql/temporary_tables.cc:953:14
 
    #5 0xd91243 in THD::create_and_open_tmp_table(handlerton*, st_mysql_const_unsigned_lex_string*, char const*, char const*, char const*, bool) /mariadb/10.2/sql/temporary_tables.cc:74:15
 
    #6 0xafe841 in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /mariadb/10.2/sql/sql_table.cc:9492:12
 
    #7 0xc2c0d2 in Sql_cmd_alter_table::execute(THD*) /mariadb/10.2/sql/sql_alter.cc:323:11
 
    #8 0x8cfff6 in mysql_execute_command(THD*) /mariadb/10.2/sql/sql_parse.cc:6225:26
 
    #9 0x8c6f20 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /mariadb/10.2/sql/sql_parse.cc:8011:18
 
    #10 0x8be67e in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /mariadb/10.2/sql/sql_parse.cc:1823:7
 
    #11 0x8c384c in do_command(THD*) /mariadb/10.2/sql/sql_parse.cc:1377:17
 
    #12 0xc1dc4e in do_handle_one_connection(CONNECT*) /mariadb/10.2/sql/sql_connect.cc:1335:11
 
    #13 0xc1d605 in handle_one_connection /mariadb/10.2/sql/sql_connect.cc:1241:3
 
 
 
Thread T34 created by T0 here:
 
    #0 0x5d4dc0 in pthread_create (/dev/shm/10.2/sql/mysqld+0x5d4dc0)
 
    #1 0x6cec00 in create_thread_to_handle_connection(CONNECT*) /mariadb/10.2/sql/mysqld.cc:6454:15
 
    #2 0x6ce199 in create_new_thread(CONNECT*) /mariadb/10.2/sql/mysqld.cc:6524:3
 
    #3 0x6ce199 in handle_connections_sockets() /mariadb/10.2/sql/mysqld.cc:6799
 
    #4 0x6c6572 in mysqld_main(int, char**) /mariadb/10.2/sql/mysqld.cc:6073:3
 
    #5 0x7fc22722db16 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x22b16)
 
 
 
Thread T33 created by T0 here:
 
    #0 0x5d4dc0 in pthread_create (/dev/shm/10.2/sql/mysqld+0x5d4dc0)
 
    #1 0x6cec00 in create_thread_to_handle_connection(CONNECT*) /mariadb/10.2/sql/mysqld.cc:6454:15
 
    #2 0x6ce199 in create_new_thread(CONNECT*) /mariadb/10.2/sql/mysqld.cc:6524:3
 
    #3 0x6ce199 in handle_connections_sockets() /mariadb/10.2/sql/mysqld.cc:6799
 
    #4 0x6c6572 in mysqld_main(int, char**) /mariadb/10.2/sql/mysqld.cc:6073:3
 
    #5 0x7fc22722db16 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x22b16)
 
…
 
Query (0x62b0000d9220): LOAD DATA INFILE 'load_t4' REPLACE INTO TABLE t4 /* QNO 440 CON_ID 15 */

It seems to me that LOAD DATA INFILE is accessing a freed TABLE_SHARE object. Could we be missing a metadata lock (MDL) that wrongly allowed the LOAD DATA INFILE to execute concurrently with the ALTER TABLE that took place in Thread 33?

If the SQL layer is always providing the values for indexed virtual columns before invoking handler::ha_delete_row(), then InnoDB should use those values and not evaluate any virtual columns during DML processing (well, except if FOREIGN KEY constraints are involved).

Comment by Marko Mäkelä [ 2018-11-01 ]

svoj, could you check if there is a problem with the MDL that could cause a race condition between LOAD DATA and ALTER TABLE?

Comment by Matthias Leich [ 2018-11-02 ] 

Result of RQG grammar simplification:
 
Replaying the problem does not require more than one connection.
 
I was able to shrink it down to MTR based testcases but I usually need several MTR runs for one replay.
 
The archive mdev-17005.tgz contains two replay testcases
 
t/mdev-17005_longer.test   uses a table t5 with more columns.
 
t/mdev-17005.test                  uses a table t5 with less columns.
 
./mysql-test-run.pl --mem --repeat=10 <testcase>

Comment by Elena Stepanova [ 2019-01-27 ]

Test cases attached by Matthias fail quite readily on 10.3 ASAN – mdev-17005.test fails for me with the ASAN failure described here, mdev-17005_longer.test – with MDEV-16222.
On some reason, neither failed for me within ~20 attempts on 10.2 ASAN.

Here is a shorter MTR test case. It's also non-deterministic, run with --repeat=N. It usually fails for me within first 1-2 attempts, on all of 10.2-10.4.

--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 (a INT, b INT AS (a), KEY(b)) ENGINE=InnoDB;
 
INSERT INTO t1 () VALUES (),();
 
 
 
--connect (con1,localhost,root,,test)
 
ALTER TABLE t1 ADD COLUMN x INT, ALGORITHM=COPY;
 
--send
 
DELETE FROM t1;
 
--connection default
 
INSERT INTO t1 (a) VALUES (1);
 
 
 
--connection con1
 
--reap
 
 
 
# Cleanup
 
--disconnect con1
 
--connection default
 
DROP TABLE t1;

10.2 3fb6d2587

 
==25900==ERROR: AddressSanitizer: heap-use-after-free on address 0x619000169af9 at pc 0x55f99896485a bp 0x7f5e50092d40 sp 0x7f5e50092d38
 
READ of size 4 at 0x619000169af9 thread T28
 
    #0 0x55f998964859 in innobase_get_computed_value(dtuple_t const*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**, mem_block_info_t*, dict_field_t const*, THD*, TABLE*, unsigned char*, dict_table_t const*, upd_t*, dict_foreign_t*) /data/src/10.2/storage/innobase/handler/ha_innodb.cc:21810
 
    #1 0x55f998c2e869 in row_upd_store_v_row /data/src/10.2/storage/innobase/row/row0upd.cc:2195
 
    #2 0x55f998c2ee40 in row_upd_store_row(upd_node_t*, THD*, TABLE*) /data/src/10.2/storage/innobase/row/row0upd.cc:2259
 
    #3 0x55f998c328c5 in row_upd_del_mark_clust_rec /data/src/10.2/storage/innobase/row/row0upd.cc:2982
 
    #4 0x55f998c336fe in row_upd_clust_step /data/src/10.2/storage/innobase/row/row0upd.cc:3165
 
    #5 0x55f998c3419f in row_upd /data/src/10.2/storage/innobase/row/row0upd.cc:3286
 
    #6 0x55f998c34eb8 in row_upd_step(que_thr_t*) /data/src/10.2/storage/innobase/row/row0upd.cc:3432
 
    #7 0x55f998b8e605 in row_update_for_mysql(row_prebuilt_t*) /data/src/10.2/storage/innobase/row/row0mysql.cc:1830
 
    #8 0x55f9989328d7 in ha_innobase::delete_row(unsigned char const*) /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9101
 
    #9 0x55f9981a7c12 in handler::ha_delete_row(unsigned char const*) /data/src/10.2/sql/handler.cc:6021
 
    #10 0x55f998573dbe in mysql_delete(THD*, TABLE_LIST*, Item*, SQL_I_List<st_order>*, unsigned long long, unsigned long long, select_result*) /data/src/10.2/sql/sql_delete.cc:583
 
    #11 0x55f997b97f16 in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:4636
 
    #12 0x55f997bada0d in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:8015
 
    #13 0x55f997b883fa in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1826
 
    #14 0x55f997b8548f in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1379
 
    #15 0x55f997ecba7c in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
 
    #16 0x55f997ecb491 in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
 
    #17 0x55f9988e6683 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
 
    #18 0x7f5e6c763493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
    #19 0x7f5e6ab4993e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
 
 
 
0x619000169af9 is located 377 bytes inside of 1100-byte region [0x619000169980,0x619000169dcc)
 
freed by thread T28 here:
 
    #0 0x7f5e6c9cd527 in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x54527)
 
    #1 0x55f99920756f in free_memory /data/src/10.2/mysys/safemalloc.c:279
 
    #2 0x55f999206b75 in sf_free /data/src/10.2/mysys/safemalloc.c:197
 
    #3 0x55f9991d5e04 in my_free /data/src/10.2/mysys/my_malloc.c:217
 
    #4 0x55f9991b73df in free_root /data/src/10.2/mysys/my_alloc.c:393
 
    #5 0x55f997e0a72d in TABLE_SHARE::destroy() /data/src/10.2/sql/table.cc:478
 
    #6 0x55f997e0a92b in free_table_share(TABLE_SHARE*) /data/src/10.2/sql/table.cc:494
 
    #7 0x55f99803f962 in THD::free_tmp_table_share(TMP_TABLE_SHARE*, bool) /data/src/10.2/sql/temporary_tables.cc:1431
 
    #8 0x55f99803b49b in THD::drop_temporary_table(TABLE*, bool*, bool) /data/src/10.2/sql/temporary_tables.cc:637
 
    #9 0x55f997daf9ee in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /data/src/10.2/sql/sql_table.cc:9649
 
    #10 0x55f997ed9f06 in Sql_cmd_alter_table::execute(THD*) /data/src/10.2/sql/sql_alter.cc:329
 
    #11 0x55f997ba2ed7 in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:6228
 
    #12 0x55f997bada0d in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:8015
 
    #13 0x55f997b883fa in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1826
 
    #14 0x55f997b8548f in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1379
 
    #15 0x55f997ecba7c in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
 
    #16 0x55f997ecb491 in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
 
    #17 0x55f9988e6683 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
 
    #18 0x7f5e6c763493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
 
 
previously allocated by thread T28 here:
 
    #0 0x7f5e6c9cd73f in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x5473f)
 
    #1 0x55f9992062e5 in sf_malloc /data/src/10.2/mysys/safemalloc.c:118
 
    #2 0x55f9991d553c in my_malloc /data/src/10.2/mysys/my_malloc.c:101
 
    #3 0x55f9991b63df in alloc_root /data/src/10.2/mysys/my_alloc.c:242
 
    #4 0x55f9991b7db0 in memdup_root /data/src/10.2/mysys/my_alloc.c:461
 
    #5 0x55f997e0fc38 in TABLE_SHARE::init_from_binary_frm_image(THD*, bool, unsigned char const*, unsigned long) /data/src/10.2/sql/table.cc:1264
 
    #6 0x55f99803cdeb in THD::create_temporary_table(handlerton*, st_mysql_const_unsigned_lex_string*, char const*, char const*, char const*) /data/src/10.2/sql/temporary_tables.cc:954
 
    #7 0x55f998038b2d in THD::create_and_open_tmp_table(handlerton*, st_mysql_const_unsigned_lex_string*, char const*, char const*, char const*, bool) /data/src/10.2/sql/temporary_tables.cc:74
 
    #8 0x55f997dae950 in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /data/src/10.2/sql/sql_table.cc:9511
 
    #9 0x55f997ed9f06 in Sql_cmd_alter_table::execute(THD*) /data/src/10.2/sql/sql_alter.cc:329
 
    #10 0x55f997ba2ed7 in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:6228
 
    #11 0x55f997bada0d in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:8015
 
    #12 0x55f997b883fa in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1826
 
    #13 0x55f997b8548f in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1379
 
    #14 0x55f997ecba7c in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
 
    #15 0x55f997ecb491 in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
 
    #16 0x55f9988e6683 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
 
    #17 0x7f5e6c763493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
 
 
Thread T28 created by T0 here:
 
    #0 0x7f5e6c99cbba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
 
    #1 0x55f9988e6c4b in spawn_thread_v1 /data/src/10.2/storage/perfschema/pfs.cc:1912
 
    #2 0x55f997981cce in inline_mysql_thread_create /data/src/10.2/include/mysql/psi/mysql_thread.h:1239
 
    #3 0x55f997996c6b in create_thread_to_handle_connection(CONNECT*) /data/src/10.2/sql/mysqld.cc:6466
 
    #4 0x55f997997370 in create_new_thread /data/src/10.2/sql/mysqld.cc:6536
 
    #5 0x55f997998387 in handle_connections_sockets() /data/src/10.2/sql/mysqld.cc:6811
 
    #6 0x55f9979961c0 in mysqld_main(int, char**) /data/src/10.2/sql/mysqld.cc:6085
 
    #7 0x55f99798006f in main /data/src/10.2/sql/main.cc:25
 
    #8 0x7f5e6aa812b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0)
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /data/src/10.2/storage/innobase/handler/ha_innodb.cc:21810 innobase_get_computed_value(dtuple_t const*, dict_v_col_t const*, dict_index_t const*, mem_block_info_t**, mem_block_info_t*, dict_field_t const*, THD*, TABLE*, unsigned char*, dict_table_t const*, upd_t*, dict_foreign_t*)
 
Shadow bytes around the buggy address:
 
  0x0c3280025300: fd fd fd fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c3280025310: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c3280025320: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c3280025330: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3280025340: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
=>0x0c3280025350: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd[fd]
 
  0x0c3280025360: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3280025370: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3280025380: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c3280025390: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c32800253a0: 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
 
==25900==ABORTING

Comment by Sergey Vojtovich [ 2019-04-03 ]

marko, according to the last test case provided by Elena, it is not "the MDL that could cause a race condition between LOAD DATA and ALTER TABLE" (because DELETE and INSERT and not LOAD DATA and ALTER TABLE are being executed concurrently, which are compatible from the MDL view).

Comment by Nikita Malyavin [ 2019-07-15 ]

marko, I confirm that it is the race between DELETE and INSERT (or other any two operations accessing to the table).
What should happen in good case:
1. ALTER TABLE is issued. vc_templ->default_rec is initialized with temporary share's default_fields
2. temporary share is freed, but datadict is still there, with garbage in vc_templ->default_rec
3. DELETE is issued. It is first after ALTER TABLE finished.
4. ha_innobase::open() is called, ib_table->get_ref_count() should be one
5. we reinitialize vc_templ, so no garbage anymore

What actually happens:
3. DELETE is issued.
4. ha_innobase::open() is called and ib_table->get_ref_count() is 1
5. INSERT (or SELECT etc.) is issued in parallel
6. ha_innobase::open() is called and ib_table->get_ref_count() is 1
7. we check ib_table->get_ref_count() and it is 2 in both threads when we want reinitialize vc_templ
8. garbage is there

Please, review the fix: https://github.com/MariaDB/server/commits/bb-10.2-MDEV-17005
there are three commits for now for your convenience.

Comment by Marko Mäkelä [ 2019-07-18 ]

Great work! I only have a minor suggestion that should reduce the probability of memory fragmentation: Make dict_vcol_templ_t::default_rec a variable-length array that is at the end of the structure. In this way, the memory could be allocated upfront.

But, now I realize that we do not know s_templ->rec_len = table->s->reclength before the table has been looked up, and thus we cannot allocate memory for default_rec when creating s_templ.

Your fix is OK to push, but I feel that this area of code needs to be redesigned and rewritten at some point.

Comment by Nikita Malyavin [ 2019-07-22 ]

marko I think that we shouldn't access TABLE_SHARE on each open. We can just store all the vcol info similar to usual columns in system innodb table, with additional flag, and fill out dict_vcol_templ_t once the dict_table_t has been created.

For now we can't do that because of architecture: real dict_table_t creation is deep inside innodb, and it shouldn't know anything about TABLE_SHARE there.

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

I would like to get rid of the InnoDB system tables (MDEV-11655), not extend the use of them. To my knowledge, InnoDB never stored the expressions of virtual columns, which are needed for evaluation. Those are only available via TABLE_SHARE (and .frm files).

I think that we should look at changing the undo logging. If the virtual column values are written in the undo log records in an appropriate way (MDEV-11657, MDEV-17466), then rollback and purge should not need to evaluate them, and the access to TABLE_SHARE could be removed altogether. (The processing of FOREIGN KEY constraints that involve ON…CASCADE or ON…SET NULL would still require the evaluation of indexed virtual columns, but that would happen as part of SQL statement execution, where we can assume the TABLE_SHARE to be available.)

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