[MDEV-16222] Assertion `0' failed in row_purge_remove_sec_if_poss_leaf on table with virtual columns and indexes Created: 2018-05-19  Updated: 2020-05-26  Resolved: 2019-07-09

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

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Aleksey Midenkov
Resolution: Fixed Votes: 0
Labels: ASAN, affects-tests

Issue Links:
Duplicate
duplicates MDEV-17976 [Draft] Assertion `lock->magic_n == 2... Closed
Problem/Incident
causes MDEV-20015 Assertion `!in_use->is_error()' faile... Closed
causes MDEV-20528 innodb.purge_secondary_mdev-16222 fai... Closed
Relates
relates to MDEV-5800 indexes on virtual (not materialized)... Closed
relates to MDEV-14134 gcol.innodb_virtual_debug sporadicall... Closed
relates to MDEV-15114 ASAN heap-use-after-free in mem_heap_... Closed
relates to MDEV-15165 InnoDB purge for index on virtual col... Closed
relates to MDEV-15855 Assertion `mysql_table' failed in inn... Closed
relates to MDEV-17466 Virtual column value not available du... Closed
relates to MDEV-17548 Incorrect access to off-page column f... Closed
relates to MDEV-17976 [Draft] Assertion `lock->magic_n == 2... Closed
relates to MDEV-18546 ASAN heap-use-after-free in innobase_... Closed
relates to MDEV-19859 ASAN heap-use-after-free dict0mem.h:5... Open
relates to MDEV-20640 [ERROR] InnoDB: tried to purge non-de... Closed

 Description   

Note: run the test with --repeat=N if it doesn't fail right away. N=20 has always been enough for me (usually N=3 is enough), but it can vary on different machines and different builds.

--source include/have_innodb.inc
 
CREATE TABLE t1 ( 
  pk SERIAL,
  vb TINYBLOB AS (b) VIRTUAL,
  b TINYBLOB,
  y YEAR,
  c CHAR(255),
  PRIMARY KEY(pk),
  INDEX (y,vb(64))
) ENGINE=InnoDB;
 
INSERT IGNORE INTO t1 (b,y,c) VALUES ('foo',1981,'bar');
 
SELECT * FROM t1 INTO OUTFILE 'load.data';
LOAD DATA INFILE 'load.data' REPLACE INTO TABLE t1;
 
# Cleanup
DROP TABLE t1;
--let $datadir= `SELECT @@datadir`
--remove_file $datadir/test/load.data

10.3 36779e624d8

2018-05-19 21:12:11 3 [ERROR] InnoDB: tried to purge non-delete-marked record in index `y` of table `test`.`t1`: tuple: TUPLE (info_bits=0, 3 fields): {[1]Q(0x01),[3]foo(0x060F0F),[8]        (0x0000000000000001)}, record: COMPACT RECORD(info_bits=0, 3 fields): {[1]Q(0x01),[3]foo(0x060F0F),[8]        (0x0000000000000001)}
mysqld: /data/src/10.3/storage/innobase/row/row0purge.cc:494: bool row_purge_remove_sec_if_poss_leaf(purge_node_t*, dict_index_t*, const dtuple_t*): Assertion `0' failed.
180519 21:12:11 [ERROR] mysqld got signal 6 ;
 
#7  0x00007f6138286ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#8  0x0000560ed2d7a311 in row_purge_remove_sec_if_poss_leaf (node=0x560ed5884208, index=0x7f60e01269c8, entry=0x7f6100014018) at /data/src/10.3/storage/innobase/row/row0purge.cc:494
#9  0x0000560ed2d7a64d in row_purge_remove_sec_if_poss (node=0x560ed5884208, index=0x7f60e01269c8, entry=0x7f6100014018) at /data/src/10.3/storage/innobase/row/row0purge.cc:584
#10 0x0000560ed2d7a849 in row_purge_del_mark (node=0x560ed5884208) at /data/src/10.3/storage/innobase/row/row0purge.cc:654
#11 0x0000560ed2d7bca9 in row_purge_record_func (node=0x560ed5884208, undo_rec=0x560ed58847b8 "", thr=0x560ed5884038, updated_extern=false) at /data/src/10.3/storage/innobase/row/row0purge.cc:1042
#12 0x0000560ed2d7bfc6 in row_purge (node=0x560ed5884208, undo_rec=0x560ed58847b8 "", thr=0x560ed5884038) at /data/src/10.3/storage/innobase/row/row0purge.cc:1107
#13 0x0000560ed2d7c2c7 in row_purge_step (thr=0x560ed5884038) at /data/src/10.3/storage/innobase/row/row0purge.cc:1186
#14 0x0000560ed2d00c86 in que_thr_step (thr=0x560ed5884038) at /data/src/10.3/storage/innobase/que/que0que.cc:1046
#15 0x0000560ed2d00eb9 in que_run_threads_low (thr=0x560ed5884038) at /data/src/10.3/storage/innobase/que/que0que.cc:1108
#16 0x0000560ed2d010aa in que_run_threads (thr=0x560ed5884038) at /data/src/10.3/storage/innobase/que/que0que.cc:1148
#17 0x0000560ed2dccc45 in srv_task_execute () at /data/src/10.3/storage/innobase/srv/srv0srv.cc:2437
#18 0x0000560ed2dccdea in srv_worker_thread (arg=0x0) at /data/src/10.3/storage/innobase/srv/srv0srv.cc:2485
#19 0x00007f6139f5d494 in start_thread (arg=0x7f611cff9700) at pthread_create.c:333
#20 0x00007f613834393f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Could not reproduce on 10.2.



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

The problem seems to be outside InnoDB. ha_innobase::write_row() is being passed a pointer to a freed TINYBLOB value, and the table definition inside InnoDB contains two indexes for the pk SERIAL, PRIMARY KEY(pk).

AddressSanitizer reports an error earlier, in both 10.2 (6e63db265f9c81518a144a0d4e89ea0ce09b3bd3) and 10.3. The 10.3 failure is below:

10.3 611488e3d9029f617884e10e47da208b0a77efec

==1125==ERROR: AddressSanitizer: heap-use-after-free on address 0x617000047624 at pc 0x7ffff6ed0bd9 bp 0x7fffe35927f0 sp 0x7fffe3591fa0
READ of size 3 at 0x617000047624 thread T27
    #0 0x7ffff6ed0bd8  (/usr/lib/x86_64-linux-gnu/libasan.so.4+0xabbd8)
    #1 0x55555757d156 in dfield_data_is_binary_equal /mariadb/10.3/storage/innobase/include/data0data.ic:334
    #2 0x555557588fd6 in row_upd_build_difference_binary(dict_index_t*, dtuple_t const*, unsigned char const*, unsigned long const*, bool, trx_t*, mem_block_info_t*, TABLE*) /mariadb/10.3/storage/innobase/row/row0upd.cc:1126
    #3 0x555557455a1b in row_ins_clust_index_entry_by_modify /mariadb/10.3/storage/innobase/row/row0ins.cc:358
    #4 0x555557462ad0 in row_ins_clust_index_entry_low(unsigned long, unsigned long, dict_index_t*, unsigned long, dtuple_t*, unsigned long, que_thr_t*, bool) /mariadb/10.3/storage/innobase/row/row0ins.cc:2725
    #5 0x555557465d14 in row_ins_clust_index_entry(dict_index_t*, dtuple_t*, que_thr_t*, unsigned long, bool) /mariadb/10.3/storage/innobase/row/row0ins.cc:3248
    #6 0x555557466961 in row_ins_index_entry /mariadb/10.3/storage/innobase/row/row0ins.cc:3375
    #7 0x555557467516 in row_ins_index_entry_step /mariadb/10.3/storage/innobase/row/row0ins.cc:3525
    #8 0x555557467f41 in row_ins /mariadb/10.3/storage/innobase/row/row0ins.cc:3667
    #9 0x55555746968a in row_ins_step(que_thr_t*) /mariadb/10.3/storage/innobase/row/row0ins.cc:3921
    #10 0x5555574b2210 in row_insert_for_mysql(unsigned char const*, row_prebuilt_t*, ins_mode_t) /mariadb/10.3/storage/innobase/row/row0mysql.cc:1452
    #11 0x555557193c27 in ha_innobase::write_row(unsigned char*) /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:8090
    #12 0x555556c376fa in handler::ha_write_row(unsigned char*) /mariadb/10.3/sql/handler.cc:6195
    #13 0x555556469458 in write_record(THD*, TABLE*, st_copy_info*) /mariadb/10.3/sql/sql_insert.cc:1700
    #14 0x5555564df72f in read_sep_field /mariadb/10.3/sql/sql_load.cc:1157
    #15 0x5555564db341 in mysql_load(THD*, sql_exchange const*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool, bool) /mariadb/10.3/sql/sql_load.cc:663
    #16 0x55555650a241 in mysql_execute_command(THD*) /mariadb/10.3/sql/sql_parse.cc:5123
    #17 0x55555651ec78 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /mariadb/10.3/sql/sql_parse.cc:8020
    #18 0x5555564f3df0 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /mariadb/10.3/sql/sql_parse.cc:1845
    #19 0x5555564f0895 in do_command(THD*) /mariadb/10.3/sql/sql_parse.cc:1390
    #20 0x5555568a543e in do_handle_one_connection(CONNECT*) /mariadb/10.3/sql/sql_connect.cc:1402
    #21 0x5555568a4d30 in handle_one_connection /mariadb/10.3/sql/sql_connect.cc:1308
    #22 0x7ffff6c0e5a9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x75a9)
    #23 0x7ffff57bacbe in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xf6cbe)
 
0x617000047624 is located 164 bytes inside of 664-byte region [0x617000047580,0x617000047818)
freed by thread T27 here:
    #0 0x7ffff6efe8c8 in __interceptor_free (/usr/lib/x86_64-linux-gnu/libasan.so.4+0xd98c8)
    #1 0x555557348db0 in mem_heap_block_free(mem_block_info_t*, mem_block_info_t*) /mariadb/10.3/storage/innobase/mem/mem0mem.cc:417
    #2 0x55555757b8ac in mem_heap_free_heap_top /mariadb/10.3/storage/innobase/include/mem0mem.ic:272
    #3 0x55555757bbd0 in mem_heap_empty /mariadb/10.3/storage/innobase/include/mem0mem.ic:303
    #4 0x555557596fb8 in row_upd /mariadb/10.3/storage/innobase/row/row0upd.cc:3324
    #5 0x555557597777 in row_upd_step(que_thr_t*) /mariadb/10.3/storage/innobase/row/row0upd.cc:3419
    #6 0x5555574b5a6d in row_update_for_mysql(row_prebuilt_t*) /mariadb/10.3/storage/innobase/row/row0mysql.cc:1881
    #7 0x5555571998df in ha_innobase::delete_row(unsigned char const*) /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:8985
    #8 0x555556c38996 in handler::ha_delete_row(unsigned char const*) /mariadb/10.3/sql/handler.cc:6283
    #9 0x55555646c026 in write_record(THD*, TABLE*, st_copy_info*) /mariadb/10.3/sql/sql_insert.cc:1976
    #10 0x5555564df72f in read_sep_field /mariadb/10.3/sql/sql_load.cc:1157
    #11 0x5555564db341 in mysql_load(THD*, sql_exchange const*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool, bool) /mariadb/10.3/sql/sql_load.cc:663
    #12 0x55555650a241 in mysql_execute_command(THD*) /mariadb/10.3/sql/sql_parse.cc:5123
    #13 0x55555651ec78 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /mariadb/10.3/sql/sql_parse.cc:8020
    #14 0x5555564f3df0 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /mariadb/10.3/sql/sql_parse.cc:1845
    #15 0x5555564f0895 in do_command(THD*) /mariadb/10.3/sql/sql_parse.cc:1390
    #16 0x5555568a543e in do_handle_one_connection(CONNECT*) /mariadb/10.3/sql/sql_connect.cc:1402
    #17 0x5555568a4d30 in handle_one_connection /mariadb/10.3/sql/sql_connect.cc:1308
    #18 0x7ffff6c0e5a9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x75a9)
 
previously allocated by thread T27 here:
    #0 0x7ffff6efec20 in __interceptor_malloc (/usr/lib/x86_64-linux-gnu/libasan.so.4+0xd9c20)
    #1 0x555557347ee1 in mem_heap_create_block_func(mem_block_info_t*, unsigned long, char const*, unsigned int, unsigned long) /mariadb/10.3/storage/innobase/mem/mem0mem.cc:271
    #2 0x555557348a1c in mem_heap_add_block(mem_block_info_t*, unsigned long) /mariadb/10.3/storage/innobase/mem/mem0mem.cc:376
    #3 0x55555750955c in mem_heap_alloc /mariadb/10.3/storage/innobase/include/mem0mem.ic:203
    #4 0x555557514608 in row_build_low /mariadb/10.3/storage/innobase/row/row0row.cc:424
    #5 0x55555751531c in row_build(unsigned long, dict_index_t const*, unsigned char const*, unsigned long const*, dict_table_t const*, dtuple_t const*, unsigned long const*, row_ext_t**, mem_block_info_t*) /mariadb/10.3/storage/innobase/row/row0row.cc:608
    #6 0x55555758f1af in row_upd_store_row(upd_node_t*, THD*, TABLE*) /mariadb/10.3/storage/innobase/row/row0upd.cc:2234
    #7 0x5555575946eb in row_upd_del_mark_clust_rec /mariadb/10.3/storage/innobase/row/row0upd.cc:2961
    #8 0x555557595b41 in row_upd_clust_step /mariadb/10.3/storage/innobase/row/row0upd.cc:3149
    #9 0x555557596802 in row_upd /mariadb/10.3/storage/innobase/row/row0upd.cc:3275
    #10 0x555557597777 in row_upd_step(que_thr_t*) /mariadb/10.3/storage/innobase/row/row0upd.cc:3419
    #11 0x5555574b5a6d in row_update_for_mysql(row_prebuilt_t*) /mariadb/10.3/storage/innobase/row/row0mysql.cc:1881
    #12 0x5555571998df in ha_innobase::delete_row(unsigned char const*) /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:8985
    #13 0x555556c38996 in handler::ha_delete_row(unsigned char const*) /mariadb/10.3/sql/handler.cc:6283
    #14 0x55555646c026 in write_record(THD*, TABLE*, st_copy_info*) /mariadb/10.3/sql/sql_insert.cc:1976
    #15 0x5555564df72f in read_sep_field /mariadb/10.3/sql/sql_load.cc:1157
    #16 0x5555564db341 in mysql_load(THD*, sql_exchange const*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool, bool) /mariadb/10.3/sql/sql_load.cc:663
    #17 0x55555650a241 in mysql_execute_command(THD*) /mariadb/10.3/sql/sql_parse.cc:5123
    #18 0x55555651ec78 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /mariadb/10.3/sql/sql_parse.cc:8020
    #19 0x5555564f3df0 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /mariadb/10.3/sql/sql_parse.cc:1845
    #20 0x5555564f0895 in do_command(THD*) /mariadb/10.3/sql/sql_parse.cc:1390
    #21 0x5555568a543e in do_handle_one_connection(CONNECT*) /mariadb/10.3/sql/sql_connect.cc:1402
    #22 0x5555568a4d30 in handle_one_connection /mariadb/10.3/sql/sql_connect.cc:1308
    #23 0x7ffff6c0e5a9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x75a9)

The memory heap that was emptied is ha_innobase::m_prebuilt->upd_node->heap. Here is a stack trace with function parameters:

gdb

(gdb) set env ASAN_OPTIONS=abort_on_error=1
(gdb) run
Thread 28 "mysqld" received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffe3599700 (LWP 1174)]
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
51	../sysdeps/unix/sysv/linux/raise.c: Tiedostoa tai hakemistoa ei ole.
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007ffff56fa231 in __GI_abort () at abort.c:79
#2  0x00007ffff6f1e65b in ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.4
#3  0x00007ffff6f25e08 in ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.4
#4  0x00007ffff6f08ccd in ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.4
#5  0x00007ffff6ed0bf8 in ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.4
#6  0x000055555757d157 in dfield_data_is_binary_equal (field=0x617000046f98, 
    len=3, data=0x7ffff043c094 "fooQbar", ' ' <repeats 193 times>...)
    at /mariadb/10.3/storage/innobase/include/data0data.ic:334
#7  0x0000555557588fd7 in row_upd_build_difference_binary (
    index=0x617000043708, entry=0x617000046f08, rec=0x7ffff043c07f "", 
    offsets=0x7fffe35929e0, no_sys=true, trx=0x7ffff07bfb90, 
    heap=0x61a000075680, mysql_table=0x61f000030288)
    at /mariadb/10.3/storage/innobase/row/row0upd.cc:1126
#8  0x0000555557455a1c in row_ins_clust_index_entry_by_modify (
    pcur=0x7fffe3593130, flags=0, mode=2, offsets=0x7fffe3593030, 
    offsets_heap=0x7fffe3592ff0, heap=0x61a000075680, entry=0x617000046f08, 
    thr=0x621000081748, mtr=0x7fffe3593590)
    at /mariadb/10.3/storage/innobase/row/row0ins.cc:358
#9  0x0000555557462ad1 in row_ins_clust_index_entry_low (flags=0, mode=2, 
    index=0x617000043708, n_uniq=1, entry=0x617000046f08, n_ext=0, 
    thr=0x621000081748, dup_chk_only=false)
    at /mariadb/10.3/storage/innobase/row/row0ins.cc:2725
#10 0x0000555557465d15 in row_ins_clust_index_entry (index=0x617000043708, 
    entry=0x617000046f08, thr=0x621000081748, n_ext=0, dup_chk_only=false)
    at /mariadb/10.3/storage/innobase/row/row0ins.cc:3248
#11 0x0000555557466962 in row_ins_index_entry (index=0x617000043708, 
    entry=0x617000046f08, thr=0x621000081748)
    at /mariadb/10.3/storage/innobase/row/row0ins.cc:3375
#12 0x0000555557467517 in row_ins_index_entry_step (node=0x621000081378, 
    thr=0x621000081748) at /mariadb/10.3/storage/innobase/row/row0ins.cc:3525
#13 0x0000555557467f42 in row_ins (node=0x621000081378, thr=0x621000081748)
    at /mariadb/10.3/storage/innobase/row/row0ins.cc:3667
#14 0x000055555746968b in row_ins_step (thr=0x621000081748)
    at /mariadb/10.3/storage/innobase/row/row0ins.cc:3921
#15 0x00005555574b2211 in row_insert_for_mysql (
    mysql_rec=0x6190000a4ba0 "\360\001", prebuilt=0x621000080d88, 
    ins_mode=ROW_INS_NORMAL)
    at /mariadb/10.3/storage/innobase/row/row0mysql.cc:1452
#16 0x0000555557193c28 in ha_innobase::write_row (this=0x61d0001590a0, 
    record=0x6190000a4ba0 "\360\001")
    at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:8090
#17 0x0000555556c376fb in handler::ha_write_row (this=0x61d0001590a0, 
    buf=0x6190000a4ba0 "\360\001") at /mariadb/10.3/sql/handler.cc:6195
#18 0x0000555556469459 in write_record (thd=0x62a0000ae208, 
    table=0x61f000030288, info=0x7fffe3595430)
    at /mariadb/10.3/sql/sql_insert.cc:1700
#19 0x00005555564df730 in read_sep_field (thd=0x62a0000ae208, info=..., 
    table_list=0x62b000000398, fields_vars=..., set_fields=..., 
    set_values=..., read_info=..., enclosed=..., skip_lines=0, 
    ignore_check_option_errors=false) at /mariadb/10.3/sql/sql_load.cc:1157
#20 0x00005555564db342 in mysql_load (thd=0x62a0000ae208, ex=0x62b000000310, 
    table_list=0x62b000000398, fields_vars=..., set_fields=..., 
    set_values=..., handle_duplicates=DUP_REPLACE, ignore=false, 
    read_file_from_client=false) at /mariadb/10.3/sql/sql_load.cc:663
#21 0x000055555650a242 in mysql_execute_command (thd=0x62a0000ae208)
    at /mariadb/10.3/sql/sql_parse.cc:5123
#22 0x000055555651ec79 in mysql_parse (thd=0x62a0000ae208, 
    rawbuf=0x62b000000220 "LOAD DATA INFILE 'load.data' REPLACE INTO TABLE t1", length=50, parser_state=0x7fffe3597d40, is_com_multi=false, 
    is_next_command=false) at /mariadb/10.3/sql/sql_parse.cc:8020
(gdb) fra 6
#6  0x000055555757d157 in dfield_data_is_binary_equal (field=0x617000046f98, 
    len=3, data=0x7ffff043c094 "fooQbar", ' ' <repeats 193 times>...)
    at /mariadb/10.3/storage/innobase/include/data0data.ic:334
(gdb) p *field
$1 = {data = 0x617000047624, ext = 0, spatial_status = 3, len = 3, type = {
    prtype = 4130044, mtype = 5, len = 9, mbminlen = 1, mbmaxlen = 1}}
(gdb) p *(char*)field->data@3
$2 = "foo"

So, we are comparing 'foo'='foo', but the 'foo' in field->data points to freed memory.
The error occurs when comparing column b in the clustered index.

If the column vb is omitted from the secondary index, the test passes.
There are 3 calls to ha_innobase::write_row(). The first two are:

  1. INSERT IGNORE INTO t1 (b,y,c) VALUES ('foo',1981,'bar');
  2. LOAD DATA INFILE 'load.data' REPLACE INTO TABLE t1; (inserting the same row, returning a duplicate key error for the PRIMARY KEY)

At this point, row_search_mvcc() will be invoked to locate the record (pk=1,b='foo',y=1981,c='bar'). Then, the pre-existing record will be deleted by write_record():

          if (!table->versioned(VERS_TIMESTAMP))
            error= table->file->ha_delete_row(table->record[1]);

2 of the 3 blocks in prebuilt->upd_node->heap will be freed here:

#0  mem_heap_empty (heap=0x612000072640)
    at /mariadb/10.3/storage/innobase/include/mem0mem.ic:303
#1  0x0000555557596fb9 in row_upd (node=0x621000081a68, thr=0x6250000c3248)
    at /mariadb/10.3/storage/innobase/row/row0upd.cc:3324
#2  0x0000555557597778 in row_upd_step (thr=0x6250000c3248)
    at /mariadb/10.3/storage/innobase/row/row0upd.cc:3419
#3  0x00005555574b5a6e in row_update_for_mysql (prebuilt=0x621000080d88)
    at /mariadb/10.3/storage/innobase/row/row0mysql.cc:1881
#4  0x00005555571998e0 in ha_innobase::delete_row (this=0x61d0001590a0, 
    record=0x6190000a4cc0 "\240\001")
    at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:8985
#5  0x0000555556c38997 in handler::ha_delete_row (this=0x61d0001590a0, 
    buf=0x6190000a4cc0 "\240\001") at /mariadb/10.3/sql/handler.cc:6283
#6  0x000055555646c027 in write_record (thd=0x62a0000ae208, 
    table=0x61f000030288, info=0x7fffe3595430)
    at /mariadb/10.3/sql/sql_insert.cc:1976
#7  0x00005555564df730 in read_sep_field (thd=0x62a0000ae208, info=..., 
    table_list=0x62b000000398, fields_vars=..., set_fields=..., 
    set_values=..., read_info=..., enclosed=..., skip_lines=0, 
    ignore_check_option_errors=false) at /mariadb/10.3/sql/sql_load.cc:1157

The data must have been evaluated for the indexed virtual column vb. Let me look at prebuilt->ins_node->entry_list and prebuilt->table->indexes at this point of time.

Interestingly, there are two indexes on the column pk. Only one should suffice. The extra one is named pk. The third index is the index that contains our virtual column.

gdb

(gdb) p *prebuilt->ins_node->entry_list.start
$28 = {info_bits = 0, n_fields = 6, n_fields_cmp = 1, 
  fields = 0x617000036fd0, n_v_fields = 1, v_fields = 0x617000037060, 
  tuple_list = {prev = 0x0, next = 0x617000037078}, magic_n = 65478679}
(gdb) p *prebuilt->ins_node->entry_list.start.tuple_list.next
$29 = {info_bits = 0, n_fields = 1, n_fields_cmp = 1, 
  fields = 0x6170000370c0, n_v_fields = 0, v_fields = 0x0, tuple_list = {
    prev = 0x617000036f88, next = 0x6170000370d8}, magic_n = 65478679}
(gdb) p *prebuilt->ins_node->entry_list.end
$30 = {info_bits = 0, n_fields = 3, n_fields_cmp = 3, 
  fields = 0x617000037120, n_v_fields = 0, v_fields = 0x0, tuple_list = {
    prev = 0x617000037078, next = 0x0}, magic_n = 65478679}
(gdb) p/x *$28.fields@$28.n_fields
$36 = {{data = 0x621000081461, ext = 0x0, spatial_status = 0x3, len = 0x8, 
    type = {prtype = 0x708, mtype = 0x6, len = 0x8, mbminlen = 0x0, 
      mbmaxlen = 0x0}}, {data = 0x62100008141e, ext = 0x0, 
    spatial_status = 0x3, len = 0x6, type = {prtype = 0x101, mtype = 0x8, 
      len = 0x6, mbminlen = 0x0, mbmaxlen = 0x0}}, {data = 0x621000081424, 
    ext = 0x0, spatial_status = 0x3, len = 0x7, type = {prtype = 0x102, 
      mtype = 0x8, len = 0x7, mbminlen = 0x0, mbmaxlen = 0x0}}, {
    data = 0x6020001a2518, ext = 0x0, spatial_status = 0x3, len = 0x3, 
    type = {prtype = 0x3f04fc, mtype = 0x5, len = 0x9, mbminlen = 0x1, 
      mbmaxlen = 0x1}}, {data = 0x621000081472, ext = 0x0, 
    spatial_status = 0x3, len = 0x1, type = {prtype = 0x60d, mtype = 0x6, 
      len = 0x1, mbminlen = 0x0, mbmaxlen = 0x0}}, {data = 0x6190000a4bb3, 
    ext = 0x0, spatial_status = 0x3, len = 0xff, type = {prtype = 0x800fe, 
      mtype = 0x2, len = 0xff, mbminlen = 0x1, mbmaxlen = 0x1}}}
(gdb) p/x *$28.v_fields@$28.n_v_fields
$37 = {{data = 0x60d000026cb8, ext = 0x0, spatial_status = 0x3, len = 0x3, 
    type = {prtype = 0x3f24fc, mtype = 0x5, len = 0x9, mbminlen = 0x1, 
      mbmaxlen = 0x1}}}
(gdb) p/x *$29.fields@$29.n_fields
$38 = {{data = 0x621000081461, ext = 0x0, spatial_status = 0x3, len = 0x8, 
    type = {prtype = 0x708, mtype = 0x6, len = 0x8, mbminlen = 0x0, 
      mbmaxlen = 0x0}}}
(gdb) p/x *$29.v_fields@$29.n_v_fields
Invalid number 0 of repetitions.
(gdb) p/x *$30.fields@$30.n_fields
$39 = {{data = 0x621000081472, ext = 0x0, spatial_status = 0x3, len = 0x1, 
    type = {prtype = 0x60d, mtype = 0x6, len = 0x1, mbminlen = 0x0, 
      mbmaxlen = 0x0}}, {data = 0x60d000026be8, ext = 0x0, 
    spatial_status = 0x3, len = 0x3, type = {prtype = 0x3f24fc, mtype = 0x5, 
      len = 0x9, mbminlen = 0x1, mbmaxlen = 0x1}}, {data = 0x621000081461, 
    ext = 0x0, spatial_status = 0x3, len = 0x8, type = {prtype = 0x708, 
      mtype = 0x6, len = 0x8, mbminlen = 0x0, mbmaxlen = 0x0}}}
(gdb) p/x *$30.v_fields@$30.n_v_fields
Invalid number 0 of repetitions.

The dtuple_t::v_fields holds the values of virtual columns. It is misleadingly stored in the primary key tuple, while it really should be in the table row tuple only.

The main observation is that the problematic pointer (0x6170000376a4 in this run) is nowhere to be seen in the prebuilt->ins_node. We get the problematic pointer in the third and failing call to ha_innobase::write_row():

gdb

(gdb) c
Continuing.
 
Thread 28 "mysqld" hit Breakpoint 1, ha_innobase::write_row (
    this=0x61d0001590a0, record=0x6190000a4ba0 "\360\001")
    at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:8018
(gdb) p *record@table_share.rec_buff_length
$40 = "\360\001\000\000\000\000\000\000\000\003\244v\003\000pa\000\000Qbar", ' ' <repeats 252 times>, "\003\070+\032\000 `\000\000\245\245\245\245\245"

In this string, the substring \244v\003\000pa represents the freed pointer 0x6170000376a4.

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

This looks very similar to MDEV-15114 where thiru pointed out a MySQL 5.7 fix that could address the issue.

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

This could share a fix with MDEV-15114.

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

MDEV-17548 might remove the crash, and MDEV-17466 suggests that purge can leave some garbage in the indexes on virtual columns.

Comment by Alice Sherepa [ 2018-12-11 ]

Got it on 10.4 8cf7e3459d7309ce1228241

mysqld: /home/alice/git/10.4/storage/innobase/row/row0purge.cc:624: bool row_purge_remove_sec_if_poss_leaf(purge_node_t*, dict_index_t*, const dtuple_t*): Assertion `0' failed.
 
row/row0purge.cc:631(row_purge_remove_sec_if_poss_leaf(purge_node_t*, dict_index_t*, dtuple_t const*))[0x55d9fd3ac08d]
row/row0purge.cc:720(row_purge_remove_sec_if_poss(purge_node_t*, dict_index_t*, dtuple_t const*))[0x55d9fd3ac4da]
row/row0purge.cc:796(row_purge_del_mark(purge_node_t*))[0x55d9fd3ac946]
row/row0purge.cc:1194(row_purge_record_func(purge_node_t*, unsigned char*, que_thr_t const*, bool))[0x55d9fd3af5d0]
row/row0purge.cc:1261(row_purge(purge_node_t*, unsigned char*, que_thr_t*))[0x55d9fd3afcee]
row/row0purge.cc:1349(row_purge_step(que_thr_t*))[0x55d9fd3b04b5]
que/que0que.cc:1042(que_thr_step(que_thr_t*))[0x55d9fd2c5531]
que/que0que.cc:1104(que_run_threads_low(que_thr_t*))[0x55d9fd2c5930]
que/que0que.cc:1146(que_run_threads(que_thr_t*))[0x55d9fd2c5c77]
srv/srv0srv.cc:2450(srv_task_execute())[0x55d9fd4246c8]
srv/srv0srv.cc:2497(srv_worker_thread)[0x55d9fd4248d1]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f1516b9b6ba]
x86_64/clone.S:111(clone)[0x7f151603041d]

Comment by Vladislav Vaintroub [ 2018-12-19 ]

got it on 10,2 in buildbot , in gcol.innodb_virtual_basic test

http://buildbot.askmonty.org/buildbot/builders/winx64-debug/builds/11474/steps/test/logs/stdio

----------SERVER LOG START-----------
2018-12-18 21:27:02 7060 [ERROR] InnoDB: tried to purge non-delete-marked record in index `idx` of table `test`.`t`: tuple: TUPLE (info_bits=0, 3 fields): {[100]2222222222222222222222222222222222222222222222222222222222222222222222222222222222222222222222222222(0x32323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232),[20]bbbbbbbbbbbbbbbbbbbb(0x6262626262626262626262626262626262626262),[4]    (0x80000001)}, record: COMPACT RECORD(info_bits=0, 3 fields): {[100]2222222222222222222222222222222222222222222222222222222222222222222222222222222222222222222222222222(0x32323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232323232),[20]bbbbbbbbbbbbbbbbbbbb(0x6262626262626262626262626262626262626262),[4]    (0x80000001)}
Assertion failed: 0, file d:\winx64-debug\build\src\storage\innobase\row\row0purge.cc, line 621
...
mysqld.exe!my_sigabrt_handler()[my_thr_init.c:487]
mysqld.exe!raise()[signal.cpp:516]
mysqld.exe!abort()[abort.cpp:71]
mysqld.exe!common_assert_to_stderr<wchar_t>()[assert.cpp:149]
mysqld.exe!_wassert()[assert.cpp:404]
mysqld.exe!row_purge_remove_sec_if_poss_leaf()[row0purge.cc:621]
mysqld.exe!row_purge_remove_sec_if_poss()[row0purge.cc:717]
mysqld.exe!row_purge_del_mark()[row0purge.cc:793]
mysqld.exe!row_purge_record_func()[row0purge.cc:1102]
mysqld.exe!row_purge()[row0purge.cc:1163]
mysqld.exe!row_purge_step()[row0purge.cc:1251]
mysqld.exe!que_thr_step()[que0que.cc:1045]
mysqld.exe!que_run_threads_low()[que0que.cc:1107]
mysqld.exe!que_run_threads()[que0que.cc:1149]
mysqld.exe!srv_task_execute()[srv0srv.cc:2537]
mysqld.exe!srv_worker_thread()[srv0srv.cc:2582]
KERNEL32.DLL!BaseThreadInitThunk()
ntdll.dll!RtlUserThreadStart()

Comment by Nikita Malyavin [ 2019-05-23 ]

Further analysis here:
https://github.com/tempesta-tech/mariadb/issues/594

Comment by Aleksey Midenkov [ 2019-06-19 ]

I don't confirm, that ASAN crash is the same bug. Further analysis is here:
https://github.com/midenok/mariadb/issues/51

Related to: MDEV-15165, MDEV-15855

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