[MDEV-14134] gcol.innodb_virtual_debug sporadically failed in buildbot, row0upd.cc:2427: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed Created: 2017-10-26  Updated: 2018-12-03  Resolved: 2018-10-25

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Tests, Virtual Columns
Affects Version/s: 10.2, 10.3
Fix Version/s: 10.2.16, 10.3.8

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Marko Mäkelä
Resolution: Duplicate Votes: 0
Labels: None

Attachments: File mdev14134.test    
Issue Links:
Relates
relates to MDEV-17548 Incorrect access to off-page column f... Closed
relates to MDEV-17890 Server crash on DELETE with YEAR fiel... Closed
relates to MDEV-15114 ASAN heap-use-after-free in mem_heap_... Closed
relates to MDEV-16222 Assertion `0' failed in row_purge_rem... Closed
Sprint: 10.2.13

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/10116/steps/test_2/logs/stdio
http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/10116/steps/test_1/logs/stdio

gcol.innodb_virtual_debug 'innodb'       w2 [ fail ]
 
        Test ended at 2017-10-24 22:18:29
 
 
 
CURRENT_TEST: gcol.innodb_virtual_debug
 
mysqltest: At line 87: query 'DELETE FROM t WHERE a = 0' failed: 2013: Lost connection to MySQL server during query
 
 
 
The result from queries just before the failure was:
 
< snip >
 
start transaction;
 
update t set b=b+1;
 
rollback;
 
SET DEBUG_SYNC = 'now SIGNAL go_ahead';
 
connection default;
 
check table t;
 
Table	Op	Msg_type	Msg_text
 
test.t	check	status	OK
 
SELECT c FROM t;
 
c
 
NULL
 
3
 
19
 
29
 
SET DEBUG_SYNC = 'innodb_inplace_alter_table_enter SIGNAL start_create WAIT_FOR go_ahead';
 
ALTER TABLE t ADD COLUMN x2 INT;
 
connection con1;
 
SET DEBUG_SYNC = 'now WAIT_FOR start_create';
 
start transaction;
 
DELETE FROM t WHERE a = 0;
 
 
 
More results from queries before failure can be found in /mnt/buildbot/build/mariadb-10.3.3/mysql-test/var/2/log/innodb_virtual_debug.log
 
 
 
 
 
Server [mysqld.1 - pid: 22229, winpid: 22229, exit: 256] failed during test run
 
Server log from this test:
 
----------SERVER LOG START-----------
 
2017-10-24 22:18:28 44 [ERROR] InnoDB: Record in index `idx` of table `test`.`t` was not found on update: TUPLE (info_bits=0, 2 fields): {[4]    (0x00000000),[6]     b(0x000000000802)} at: COMPACT RECORD(info_bits=0, 2 fields): {NULL,[6]     e(0x000000000805)}
 
2017-10-24 22:18:28 44 [Note] InnoDB: GIS MBR INFO: 6.32404e-322 and 3.23508e-316, -nan, -2.18566e-311
 
 
 
mysqld: /home/buildbot/buildbot/build/mariadb-10.3.3/storage/innobase/row/row0upd.cc:2427: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed.
 
171024 22:18:28 [ERROR] mysqld got signal 6 ;
 
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.3.3-MariaDB-debug-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=2
 
max_threads=153
 
thread_count=8
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61908 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0xabb08108
 
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...
 
stack_bottom = 0xacab82a0 thread_stack 0x49000
 
/mnt/buildbot/build/mariadb-10.3.3/sql/mysqld(my_print_stacktrace+0x3b)[0x8df3153]
 
/mnt/buildbot/build/mariadb-10.3.3/sql/mysqld(handle_fatal_signal+0x3cf)[0x863fb53]
 
[0xb776b400]
 
[0xb776b424]
 
/lib/i386-linux-gnu/libc.so.6(gsignal+0x4f)[0xb72471ef]
 
/lib/i386-linux-gnu/libc.so.6(abort+0x175)[0xb724a835]
 
/lib/i386-linux-gnu/libc.so.6(+0x27095)[0xb7240095]
 
/lib/i386-linux-gnu/libc.so.6(+0x27147)[0xb7240147]
 
/mnt/buildbot/build/mariadb-10.3.3/sql/mysqld[0x8b1bf85]
 
/mnt/buildbot/build/mariadb-10.3.3/sql/mysqld[0x8b1c6c1]
 
/mnt/buildbot/build/mariadb-10.3.3/sql/mysqld[0x8b1edd5]
 
mysys/stacktrace.c:269(my_print_stacktrace)[0x8b1f122]
 
row/row0upd.cc:2431(row_upd_sec_index_entry)[0x8aba8fc]
 
handler/ha_innodb.cc:9245(ha_innobase::delete_row(unsigned char const*))[0x8966932]
 
sql/handler.cc:6110(handler::ha_delete_row(unsigned char const*))[0x864fea7]
 
sql/sql_delete.cc:637(mysql_delete(THD*, TABLE_LIST*, Item*, SQL_I_List<st_order>*, unsigned long long, unsigned long long, select_result*))[0x87dd5c7]
 
sql/sql_parse.cc:4883(mysql_execute_command(THD*))[0x838f83a]
 
sql/sql_parse.cc:7921(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x8399aa3]
 
sql/sql_parse.cc:1821(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x83867ed]
 
sql/sql_parse.cc:1370(do_command(THD*))[0x83852a7]
 
sql/sql_connect.cc:1418(do_handle_one_connection(CONNECT*))[0x84cdb17]
 
sql/sql_connect.cc:1325(handle_one_connection)[0x84cd8a5]
 
perfschema/pfs.cc:1864(pfs_spawn_thread)[0x8862625]
 
/lib/i386-linux-gnu/libpthread.so.0(+0x6d4c)[0xb74f3d4c]
 
/lib/i386-linux-gnu/libc.so.6(clone+0x5e)[0xb7303ace]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0xabb17d38): DELETE FROM t WHERE a = 0
 
Connection ID (thread ID): 44
 
Status: NOT_KILLED
 
 
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_grouping_derived=on
 
 
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
information that should help you find out what is causing the crash.
 
Writing a core file
 
----------SERVER LOG END-------------



 Comments   
Comment by Elena Stepanova [ 2018-01-31 ]

It might be the same problem as, or related to, MDEV-15114.

I have a test case which on my local machine with decent probability causes the same failure with current 10.2. It doesn't happen on two other machines that I tried (same tree, same revision, same build options), so there is no point trying hard to get the crash; but with ASAN, it fails reliably everywhere with errors seemingly identical to MDEV-15114.

10.2 b56f9fbe2f6a8 crash on local machine

 
2018-02-01  0:35:56 139624354711296 [ERROR] InnoDB: Record in index `vcol_blob` of table `test`.`t1` was not found on update: TUPLE (info_bits=0, 2 fields): {[64]em genetic construct oversee develop die majority extraordin
 
ary (0x050D0007050E0504090300030F0E030402050304000F06050203050500040506050C0F0000040905000D010A0F020904090005080402010F0204090E01020900),[4]    (0x00000001)} at: COMPACT RECORD(info_bits=0, 1 fields): {[8]infimum (0x090E06
 
090D050D00)}
 
2018-02-01  0:35:56 139624354711296 [Note] InnoDB: GIS MBR INFO: 4.91014e+252 and 8.9039e+252, 5.81816e+180, 2.10494e+262
 
 
 
mysqld: /data/src/10.2/storage/innobase/row/row0upd.cc:2440: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed.
 
180201  0:35:56 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007efcda22cee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x00005579dc47c391 in row_upd_sec_index_entry (node=0x7efc88090b80, thr=0x7efc8805eba8) at /data/src/10.2/storage/innobase/row/row0upd.cc:2440
 
#9  0x00005579dc47ca07 in row_upd_sec_step (node=0x7efc88090b80, thr=0x7efc8805eba8) at /data/src/10.2/storage/innobase/row/row0upd.cc:2553
 
#10 0x00005579dc47ece4 in row_upd (node=0x7efc88090b80, thr=0x7efc8805eba8) at /data/src/10.2/storage/innobase/row/row0upd.cc:3306
 
#11 0x00005579dc47f03b in row_upd_step (thr=0x7efc8805eba8) at /data/src/10.2/storage/innobase/row/row0upd.cc:3423
 
#12 0x00005579dc422afb in row_update_for_mysql (prebuilt=0x7efc8808faa8) at /data/src/10.2/storage/innobase/row/row0mysql.cc:1923
 
#13 0x00005579dc2e7260 in ha_innobase::delete_row (this=0x7efc8800b888, record=0x7efc88009c90 "\241\001") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9341
 
#14 0x00005579dbfdd2b6 in handler::ha_delete_row (this=0x7efc8800b888, buf=0x7efc88009c90 "\241\001") at /data/src/10.2/sql/handler.cc:6061
 
#15 0x00005579dbd3ab7d in write_record (thd=0x7efc88000b00, table=0x7efc8814d2a0, info=0x7efcd4106040) at /data/src/10.2/sql/sql_insert.cc:1892
 
#16 0x00005579dc176c1e in read_sep_field (thd=0x7efc88000b00, info=..., table_list=0x7efc88012650, fields_vars=..., set_fields=..., set_values=..., read_info=..., enclosed=..., skip_lines=0, ignore_check_option_errors=false) at /data/src/10.2/sql/sql_load.cc:1254
 
#17 0x00005579dc174db6 in mysql_load (thd=0x7efc88000b00, ex=0x7efc880125c8, table_list=0x7efc88012650, fields_vars=..., set_fields=..., set_values=..., handle_duplicates=DUP_REPLACE, ignore=false, read_file_from_client=false) at /data/src/10.2/sql/sql_load.cc:647
 
#18 0x00005579dbd615e5 in mysql_execute_command (thd=0x7efc88000b00) at /data/src/10.2/sql/sql_parse.cc:4816
 
#19 0x00005579dbd6ad5d in mysql_parse (thd=0x7efc88000b00, rawbuf=0x7efc880124e8 "LOAD DATA INFILE 'load_t1' REPLACE INTO TABLE t1", length=48, parser_state=0x7efcd4107200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7898
 
#20 0x00005579dbd58cf7 in dispatch_command (command=COM_QUERY, thd=0x7efc88000b00, packet=0x7efc88034621 "LOAD DATA INFILE 'load_t1' REPLACE INTO TABLE t1", packet_length=48, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1806
 
#21 0x00005579dbd5765a in do_command (thd=0x7efc88000b00) at /data/src/10.2/sql/sql_parse.cc:1360
 
#22 0x00005579dbea58c4 in do_handle_one_connection (connect=0x5579deb0eeb0) at /data/src/10.2/sql/sql_connect.cc:1335
 
#23 0x00005579dbea5651 in handle_one_connection (arg=0x5579deb0eeb0) at /data/src/10.2/sql/sql_connect.cc:1241
 
#24 0x00005579dc2c4e10 in pfs_spawn_thread (arg=0x5579dea72800) at /data/src/10.2/storage/perfschema/pfs.cc:1862
 
#25 0x00007efcdbf03494 in start_thread (arg=0x7efcd4108700) at pthread_create.c:333
 
#26 0x00007efcda2e993f in clone () from /lib/x86_64-linux-gnu/libc.so.6

10.2 30289a271380 ASAN build

 
==458==ERROR: AddressSanitizer: heap-use-after-free on address 0x62f000118488 at pc 0x5643ce09fc4d bp 0x7f740d86d000 sp 0x7f740d86cff8
 
READ of size 52995 at 0x62f000118488 thread T27
 
    #0 0x5643ce09fc4c in mem_heap_dup(mem_block_info_t*, void const*, unsigned long) /data/src/10.2/storage/innobase/mem/mem0mem.cc:56
 
    #1 0x5643ce247d82 in dfield_dup /data/src/10.2/storage/innobase/include/data0data.ic:285
 
    #2 0x5643ce251ef4 in row_upd_index_replace_new_col_val /data/src/10.2/storage/innobase/row/row0upd.cc:1287
 
    #3 0x5643ce25247e in row_upd_index_replace_new_col_vals_index_pos(dtuple_t*, dict_index_t*, upd_t const*, unsigned long, mem_block_info_t*) /data/src/10.2/storage/innobase/row/row0upd.cc:1367
 
    #4 0x5643ce3869a4 in btr_cur_pessimistic_update(unsigned long, btr_cur_t*, unsigned long**, mem_block_info_t**, mem_block_info_t*, big_rec_t**, upd_t*, unsigned long, que_thr_t*, unsigned long, mtr_t*) /data/src/10.2/storage/innobase/btr/btr0cur.cc:4206
 
    #5 0x5643ce169b72 in row_ins_clust_index_entry_by_modify /data/src/10.2/storage/innobase/row/row0ins.cc:394
 
    #6 0x5643ce1735c3 in row_ins_clust_index_entry_low(unsigned long, unsigned long, dict_index_t*, unsigned long, dtuple_t*, unsigned long, que_thr_t*, bool) /data/src/10.2/storage/innobase/row/row0ins.cc:2688
 
    #7 0x5643ce175937 in row_ins_clust_index_entry(dict_index_t*, dtuple_t*, que_thr_t*, unsigned long, bool) /data/src/10.2/storage/innobase/row/row0ins.cc:3218
 
    #8 0x5643ce175dc6 in row_ins_index_entry /data/src/10.2/storage/innobase/row/row0ins.cc:3314
 
    #9 0x5643ce176805 in row_ins_index_entry_step /data/src/10.2/storage/innobase/row/row0ins.cc:3464
 
    #10 0x5643ce1770d0 in row_ins /data/src/10.2/storage/innobase/row/row0ins.cc:3606
 
    #11 0x5643ce1781d1 in row_ins_step(que_thr_t*) /data/src/10.2/storage/innobase/row/row0ins.cc:3843
 
    #12 0x5643ce1aea11 in row_insert_for_mysql(unsigned char const*, row_prebuilt_t*) /data/src/10.2/storage/innobase/row/row0mysql.cc:1469
 
    #13 0x5643cdf4e4c4 in ha_innobase::write_row(unsigned char*) /data/src/10.2/storage/innobase/handler/ha_innodb.cc:8595
 
    #14 0x5643cd7cc5b0 in handler::ha_write_row(unsigned char*) /data/src/10.2/sql/handler.cc:6001
 
    #15 0x5643cd176486 in write_record(THD*, TABLE*, st_copy_info*) /data/src/10.2/sql/sql_insert.cc:1654
 
    #16 0x5643cdbadffe in read_sep_field /data/src/10.2/sql/sql_load.cc:1217
 
    #17 0x5643cdba9e5e 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:612
 
    #18 0x5643cd1d599f in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:4809
 
    #19 0x5643cd1e91e0 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:7891
 
    #20 0x5643cd1c469b in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1806
 
    #21 0x5643cd1c173f in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1360
 
    #22 0x5643cd4fb8d5 in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
 
    #23 0x5643cd4fb2ea in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
 
    #24 0x5643cdf04489 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
 
    #25 0x7f741e2d3493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
    #26 0x7f741c6b993e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
 
 
 
0x62f000118488 is located 136 bytes inside of 53136-byte region [0x62f000118400,0x62f000125390)
 
freed by thread T27 here:
 
    #0 0x7f741e53d527 in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x54527)
 
    #1 0x5643ce0a1951 in mem_heap_block_free(mem_block_info_t*, mem_block_info_t*) /data/src/10.2/storage/innobase/mem/mem0mem.cc:440
 
    #2 0x5643ce24738f in mem_heap_free /data/src/10.2/storage/innobase/include/mem0mem.ic:535
 
    #3 0x5643ce25550a in row_upd_store_v_row(upd_node_t*, upd_t const*, THD*, TABLE*) /data/src/10.2/storage/innobase/row/row0upd.cc:2166
 
    #4 0x5643ce255a39 in row_upd_store_row(upd_node_t*, THD*, TABLE*) /data/src/10.2/storage/innobase/row/row0upd.cc:2220
 
    #5 0x5643ce259843 in row_upd_del_mark_clust_rec /data/src/10.2/storage/innobase/row/row0upd.cc:2960
 
    #6 0x5643ce25a6d4 in row_upd_clust_step /data/src/10.2/storage/innobase/row/row0upd.cc:3144
 
    #7 0x5643ce25b18b in row_upd /data/src/10.2/storage/innobase/row/row0upd.cc:3261
 
    #8 0x5643ce25bead in row_upd_step(que_thr_t*) /data/src/10.2/storage/innobase/row/row0upd.cc:3407
 
    #9 0x5643ce1b1436 in row_update_for_mysql(row_prebuilt_t*) /data/src/10.2/storage/innobase/row/row0mysql.cc:1927
 
    #10 0x5643cdf53109 in ha_innobase::delete_row(unsigned char const*) /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9488
 
    #11 0x5643cd7cd420 in handler::ha_delete_row(unsigned char const*) /data/src/10.2/sql/handler.cc:6061
 
    #12 0x5643cd1762a0 in write_record(THD*, TABLE*, st_copy_info*) /data/src/10.2/sql/sql_insert.cc:1892
 
    #13 0x5643cdbadffe in read_sep_field /data/src/10.2/sql/sql_load.cc:1217
 
    #14 0x5643cdba9e5e 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:612
 
    #15 0x5643cd1d599f in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:4809
 
    #16 0x5643cd1e91e0 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:7891
 
    #17 0x5643cd1c469b in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1806
 
    #18 0x5643cd1c173f in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1360
 
    #19 0x5643cd4fb8d5 in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
 
    #20 0x5643cd4fb2ea in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
 
    #21 0x5643cdf04489 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
 
    #22 0x7f741e2d3493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
 
 
previously allocated by thread T27 here:
 
    #0 0x7f741e53d73f in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x5473f)
 
    #1 0x5643ce0a0fdf in mem_heap_create_block_func(mem_block_info_t*, unsigned long, char const*, unsigned int, unsigned long) /data/src/10.2/storage/innobase/mem/mem0mem.cc:296
 
    #2 0x5643ce0a16ee in mem_heap_add_block(mem_block_info_t*, unsigned long) /data/src/10.2/storage/innobase/mem/mem0mem.cc:397
 
    #3 0x5643ce36d557 in mem_heap_alloc /data/src/10.2/storage/innobase/include/mem0mem.ic:203
 
    #4 0x5643ce393342 in btr_copy_externally_stored_field(unsigned long*, unsigned char const*, page_size_t const&, unsigned long, mem_block_info_t*) /data/src/10.2/storage/innobase/btr/btr0cur.cc:7766
 
    #5 0x5643cdf87d3e 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*, dict_table_t const*, upd_t*, dict_foreign_t*) /data/src/10.2/storage/innobase/handler/ha_innodb.cc:22321
 
    #6 0x5643ce255495 in row_upd_store_v_row(upd_node_t*, upd_t const*, THD*, TABLE*) /data/src/10.2/storage/innobase/row/row0upd.cc:2159
 
    #7 0x5643ce255a39 in row_upd_store_row(upd_node_t*, THD*, TABLE*) /data/src/10.2/storage/innobase/row/row0upd.cc:2220
 
    #8 0x5643ce259843 in row_upd_del_mark_clust_rec /data/src/10.2/storage/innobase/row/row0upd.cc:2960
 
    #9 0x5643ce25a6d4 in row_upd_clust_step /data/src/10.2/storage/innobase/row/row0upd.cc:3144
 
    #10 0x5643ce25b18b in row_upd /data/src/10.2/storage/innobase/row/row0upd.cc:3261
 
    #11 0x5643ce25bead in row_upd_step(que_thr_t*) /data/src/10.2/storage/innobase/row/row0upd.cc:3407
 
    #12 0x5643ce1b1436 in row_update_for_mysql(row_prebuilt_t*) /data/src/10.2/storage/innobase/row/row0mysql.cc:1927
 
    #13 0x5643cdf53109 in ha_innobase::delete_row(unsigned char const*) /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9488
 
    #14 0x5643cd7cd420 in handler::ha_delete_row(unsigned char const*) /data/src/10.2/sql/handler.cc:6061
 
    #15 0x5643cd1762a0 in write_record(THD*, TABLE*, st_copy_info*) /data/src/10.2/sql/sql_insert.cc:1892
 
    #16 0x5643cdbadffe in read_sep_field /data/src/10.2/sql/sql_load.cc:1217
 
    #17 0x5643cdba9e5e 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:612
 
    #18 0x5643cd1d599f in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:4809
 
    #19 0x5643cd1e91e0 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:7891
 
    #20 0x5643cd1c469b in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1806
 
    #21 0x5643cd1c173f in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1360
 
    #22 0x5643cd4fb8d5 in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1335
 
    #23 0x5643cd4fb2ea in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
 
    #24 0x5643cdf04489 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1862
 
    #25 0x7f741e2d3493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
 
 
 
Thread T27 created by T0 here:
 
    #0 0x7f741e50cbba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
 
    #1 0x5643cdf04a51 in spawn_thread_v1 /data/src/10.2/storage/perfschema/pfs.cc:1912
 
    #2 0x5643ccfc370f in inline_mysql_thread_create /data/src/10.2/include/mysql/psi/mysql_thread.h:1239
 
    #3 0x5643ccfd8458 in create_thread_to_handle_connection(CONNECT*) /data/src/10.2/sql/mysqld.cc:6423
 
    #4 0x5643ccfd8b5d in create_new_thread /data/src/10.2/sql/mysqld.cc:6493
 
    #5 0x5643ccfd9b6e in handle_connections_sockets() /data/src/10.2/sql/mysqld.cc:6768
 
    #6 0x5643ccfd79a5 in mysqld_main(int, char**) /data/src/10.2/sql/mysqld.cc:6042
 
    #7 0x5643ccfc1c3f in main /data/src/10.2/sql/main.cc:25
 
    #8 0x7f741c5f12b0 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/mem/mem0mem.cc:56 mem_heap_dup(mem_block_info_t*, void const*, unsigned long)
 
Shadow bytes around the buggy address:
 
  0x0c5e8001b040: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5e8001b050: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5e8001b060: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5e8001b070: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5e8001b080: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
=>0x0c5e8001b090: fd[fd]fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5e8001b0a0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5e8001b0b0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5e8001b0c0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5e8001b0d0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5e8001b0e0: 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
 
==458==ABORTING

Test case doesn't fit, I'll attach it instead. It's only 6 statements, but the inserted text is ~50K, apparently JIRA doesn't like it.
mdev14134.test

Comment by Marko Mäkelä [ 2018-10-25 ]

I ran mdev14134.test with ASAN both before and after the MDEV-17548 fix, and it passed for me.

Comment by Marko Mäkelä [ 2018-10-25 ]

This definitely is a duplicate of MDEV-15114. mdev14134.test does not fail with ASAN using the following commit, and fails with its parent commit:

commit ab194666564acab29a4bcb7ca763e0ae0e691d1f
 
Author: Monty <monty@mariadb.org>
 
Date:   Sun Jun 17 14:19:51 2018 +0300
 
 
 
    MDEV-15114 ASAN heap-use-after-free in mem_heap_dup or dfield_data_is_binary_equal

Comment by Elena Stepanova [ 2018-12-03 ]

MDEV-15114 is in 10.4, but I'm still getting a similar failure:

10.4 f89a27b4

 
2018-12-03  3:40:38 16 [ERROR] InnoDB: Record in index `vcol_datetime` of table `test`.`t5` was not found on update: TUPLE (info_bits=0, 4 fields): {[6]   -  (0x99BB9D2DEF00),NULL,[64]isqdkfykpraagyrwswotqllacxfargqphiaxjbjptzyomlqmecqikprnstjejxkt(0x697371646B66796B707261616779727773776F74716C6C616378666172677170686961786A626A70747A796F6D6C716D656371696B70726E73746A656A786B74),[8]        (0x000000000000000F)} at: COMPACT RECORD(info_bits=0, 4 fields): {[6]  Z U (0x99BB5AB45500),[2]  (0x0003),[1]i(0x69),[8]        (0x00000000000002EC)}
 
mysqld: /home/travis/src/storage/innobase/row/row0upd.cc:2426: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed.
 
181203  3:40:38 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f450bc4ac82 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x000055ba563800a9 in row_upd_sec_index_entry (node=0x55ba596f51a8, thr=0x55ba59a124c8) at /home/travis/src/storage/innobase/row/row0upd.cc:2426
 
#9  0x000055ba56380787 in row_upd_sec_step (node=0x55ba596f51a8, thr=0x55ba59a124c8) at /home/travis/src/storage/innobase/row/row0upd.cc:2539
 
#10 0x000055ba563831c6 in row_upd (node=0x55ba596f51a8, thr=0x55ba59a124c8) at /home/travis/src/storage/innobase/row/row0upd.cc:3317
 
#11 0x000055ba5638352f in row_upd_step (thr=0x55ba59a124c8) at /home/travis/src/storage/innobase/row/row0upd.cc:3432
 
#12 0x000055ba56331142 in row_update_for_mysql (prebuilt=0x55ba59b5ee38) at /home/travis/src/storage/innobase/row/row0mysql.cc:1889
 
#13 0x000055ba561cc55d in ha_innobase::delete_row (this=0x55ba5940a0b8, record=0x55ba59769060 "") at /home/travis/src/storage/innobase/handler/ha_innodb.cc:8940
 
#14 0x000055ba55fbae0c in handler::ha_delete_row (this=0x55ba5940a0b8, buf=0x55ba59769060 "") at /home/travis/src/sql/handler.cc:6326
 
#15 0x000055ba55c5ead8 in write_record (thd=0x55ba5988b720, table=0x55ba59a91960, info=0x7f4508544780) at /home/travis/src/sql/sql_insert.cc:1972
 
#16 0x000055ba55c9076b in read_sep_field (thd=0x55ba5988b720, info=..., table_list=0x55ba5989b8c0, fields_vars=..., set_fields=..., set_values=..., read_info=..., enclosed=..., skip_lines=0, ignore_check_option_errors=false) at /home/travis/src/sql/sql_load.cc:1153
 
#17 0x000055ba55c8ed44 in mysql_load (thd=0x55ba5988b720, ex=0x55ba5989b838, table_list=0x55ba5989b8c0, fields_vars=..., set_fields=..., set_values=..., handle_duplicates=DUP_REPLACE, ignore=false, read_file_from_client=false) at /home/travis/src/sql/sql_load.cc:661
 
#18 0x000055ba55ca3b7b in mysql_execute_command (thd=0x55ba5988b720) at /home/travis/src/sql/sql_parse.cc:5132
 
#19 0x000055ba55cad158 in mysql_parse (thd=0x55ba5988b720, rawbuf=0x55ba5989b728 "LOAD DATA INFILE 'load_t5' REPLACE INTO TABLE t5 /* QNO 506 CON_ID 16 */", length=72, parser_state=0x7f4508545650, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:8092
 
#20 0x000055ba55c9a116 in dispatch_command (command=COM_QUERY, thd=0x55ba5988b720, packet=0x55ba598935f1 " LOAD DATA INFILE 'load_t5' REPLACE INTO TABLE t5 /* QNO 506 CON_ID 16 */ ", packet_length=74, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1851
 
#21 0x000055ba55c98b33 in do_command (thd=0x55ba5988b720) at /home/travis/src/sql/sql_parse.cc:1396
 
#22 0x000055ba55e03f04 in do_handle_one_connection (connect=0x55ba5956d120) at /home/travis/src/sql/sql_connect.cc:1402
 
#23 0x000055ba55e03c55 in handle_one_connection (arg=0x55ba5956d120) at /home/travis/src/sql/sql_connect.cc:1308
 
#24 0x00007f450c88f6ba in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
 
#25 0x00007f450bd2441d in clone () from /lib/x86_64-linux-gnu/libc.so.6

However, the initial report was about an MTR test, and it indeed doesn't fail in buildbot this way anymore, so I'll create a separate one for my failure.

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