[MDEV-19114] gcol.innodb_virtual_debug failed in buildbot with Assertion `n_fields > 0' failure Created: 2019-04-01  Updated: 2020-06-04  Resolved: 2020-05-19

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Tests
Affects Version/s: 10.2.16, 10.3.8, 10.4.0, 10.5.0
Fix Version/s: 10.5.4, 10.2.33, 10.3.24, 10.4.14

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 1
Labels: None

Issue Links:
Problem/Incident
is caused by MDEV-16376 ASAN: heap-use-after-free in gcol.inn... Closed

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/16894/steps/mtr_ps_emb/logs/stdio

10.3 f03f4da66373161d604b8ecf3c23ae18d08c0461

 
gcol.innodb_virtual_debug 'innodb'       w4 [ fail ]
 
        Test ended at 2019-03-25 05:16:44
 
 
 
CURRENT_TEST: gcol.innodb_virtual_debug
 
Warning: /mnt/buildbot/build/mariadb-10.3.14/libmysqld/examples/mysqltest_embedded: unknown variable 'loose-ssl-ca=/mnt/buildbot/build/mariadb-10.3.14/mysql-test/std_data/cacert.pem'
 
Warning: /mnt/buildbot/build/mariadb-10.3.14/libmysqld/examples/mysqltest_embedded: unknown variable 'loose-ssl-cert=/mnt/buildbot/build/mariadb-10.3.14/mysql-test/std_data/client-cert.pem'
 
Warning: /mnt/buildbot/build/mariadb-10.3.14/libmysqld/examples/mysqltest_embedded: unknown variable 'loose-ssl-key=/mnt/buildbot/build/mariadb-10.3.14/mysql-test/std_data/client-key.pem'
 
Warning: /mnt/buildbot/build/mariadb-10.3.14/libmysqld/examples/mysqltest_embedded: unknown option '--loose-skip-ssl'
 
mysqltest_embedded: /home/buildbot/buildbot/build/mariadb-10.3.14/storage/innobase/include/rem0rec.ic:1244: void rec_offs_set_n_fields(ulint*, ulint): Assertion `n_fields > 0' failed.
 
mysqltest got signal 6
 
read_command_buf (0x82d91c98): ALTE
 
conn->name (0x82e14dd8): 
conn->cur_query (0x83081df8): ALTER TABLE t ADD INDEX idc(c)
 
Attempting backtrace...
 
stack_bottom = 0x0 thread_stack 0x49000
 
/mnt/buildbot/build/mariadb-10.3.14/libmysqld/examples/mysqltest_embedded(my_print_stacktrace+0x3c)[0x8038ddb6]
 
/mnt/buildbot/build/mariadb-10.3.14/libmysqld/examples/mysqltest_embedded(+0x30e5bd)[0x803705bd]
 
mysys/stacktrace.c:269(my_print_stacktrace)[0x803705fb]
 
addr2line: '': No such file
 
[0xb77a9c14]
 
[0xb77a9c31]
 
/lib/i386-linux-gnu/libc.so.6(gsignal+0x39)[0xb7115e89]
 
/lib/i386-linux-gnu/libc.so.6(abort+0x157)[0xb71173e7]
 
/lib/i386-linux-gnu/libc.so.6(+0x24d07)[0xb710ed07]
 
/lib/i386-linux-gnu/libc.so.6(+0x24d8b)[0xb710ed8b]
 
/mnt/buildbot/build/mariadb-10.3.14/libmysqld/examples/mysqltest_embedded(+0xb4bd35)[0x80badd35]
 
/mnt/buildbot/build/mariadb-10.3.14/libmysqld/examples/mysqltest_embedded(+0xb4e0c8)[0x80bb00c8]
 
/mnt/buildbot/build/mariadb-10.3.14/libmysqld/examples/mysqltest_embedded(+0xafcc24)[0x80b5ec24]
 
/mnt/buildbot/build/mariadb-10.3.14/libmysqld/examples/mysqltest_embedded(+0xace12a)[0x80b3012a]
 
include/rem0rec.ic:1245(rec_offs_set_n_fields(unsigned int*, unsigned int))[0x80ab9962]
 
rem/rem0rec.cc:867(rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned int*, bool, unsigned int, char const*, unsigned int, mem_block_info_t**))[0x80abc1bb]
 
page/page0cur.cc:745(page_cur_search_with_match_bytes(buf_block_t const*, dict_index_t const*, dtuple_t const*, page_cur_mode_t, unsigned int*, unsigned int*, unsigned int*, unsigned int*, page_cur_t*))[0x80bea076]
 
btr/btr0cur.cc:1837(btr_cur_search_to_nth_level_func(dict_index_t*, unsigned int, dtuple_t const*, page_cur_mode_t, unsigned int, btr_cur_t*, rw_lock_t*, char const*, unsigned int, mtr_t*, unsigned long long))[0x80bea630]
 
include/btr0pcur.ic:459(btr_pcur_open_low(dict_index_t*, unsigned int, dtuple_t const*, page_cur_mode_t, unsigned int, btr_pcur_t*, char const*, unsigned int, unsigned long long, mtr_t*))[0x80beb251]
 
row/row0row.cc:1136(row_search_index_entry(dict_index_t*, dtuple_t const*, unsigned int, btr_pcur_t*, mtr_t*))[0x80bebfd7]
 
row/row0purge.cc:569(row_purge_remove_sec_if_poss_leaf(purge_node_t*, dict_index_t*, dtuple_t const*))[0x80bec195]
 
row/row0purge.cc:893(row_purge_upd_exist_or_extern_func(que_thr_t const*, purge_node_t*, unsigned char*))[0x80bec3ca]
 
row/row0purge.cc:1206(row_purge_record_func(purge_node_t*, unsigned char*, que_thr_t const*, bool))[0x80bf29d2]
 
row/row0purge.cc:1250(row_purge(purge_node_t*, unsigned char*, que_thr_t*))[0x80bf2c17]
 
row/row0purge.cc:1311(row_purge_step(que_thr_t*))[0x80bf2e19]
 
que/que0que.cc:1042(que_thr_step(que_thr_t*))[0x80aab044]
 
trx/trx0purge.cc:1603(trx_purge(unsigned int, bool))[0x80d007c4]
 
srv/srv0srv.cc:2595(srv_do_purge(unsigned int*))[0x80d00c09]
 
/lib/i386-linux-gnu/libpthread.so.0(+0x62b5)[0xb77802b5]
 
/lib/i386-linux-gnu/libc.so.6(clone+0x6e)[0xb71d116e]
 
Writing a core file...



 Comments   
Comment by Elena Stepanova [ 2019-09-07 ]

On 10.2 05b35cf4c1cc11f2078ebf0a16a1aa82:
http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/18831

Comment by Elena Stepanova [ 2019-11-03 ]

Also observed in concurrent tests on 10.4:

10.4 903f5fea

 
mysqld: /home/elenst/src/10.4/storage/innobase/include/rem0rec.ic:1222: void rec_offs_set_n_fields(ulint*, ulint): Assertion `n_fields > 0' failed.
 
191103  2:38:27 [ERROR] mysqld got signal 6 ;
 
 
 
#9  0x00007f9e175b00d2 in __assert_fail () from /lib64/libc.so.6
 
#10 0x000055ee600ea6fa in rec_offs_set_n_fields (offsets=0x7f9dcfffd060, n_fields=0) at /home/elenst/src/10.4/storage/innobase/include/rem0rec.ic:1222
 
#11 0x000055ee600ecfc3 in rec_get_offsets_func (rec=0x7f9dc00104c6 "\230\037B", index=0x7f9d98218218, offsets=0x7f9dcfffd060, leaf=true, n_fields=3, file=0x55ee60800838 "/home/elenst/src/10.4/storage/innobase/rem/rem0rec.cc", line=1883, heap=0x7f9dcfffd000) at /home/elenst/src/10.4/storage/innobase/rem/rem0rec.cc:918
 
#12 0x000055ee600eee96 in rec_copy_prefix_to_dtuple (tuple=0x7f9dc0011c88, rec=0x7f9dc00104c6 "\230\037B", index=0x7f9d98218218, is_leaf=true, n_fields=3, heap=0x7f9dc0011c00) at /home/elenst/src/10.4/storage/innobase/rem/rem0rec.cc:1883
 
#13 0x000055ee603054ba in dict_index_build_data_tuple (rec=0x7f9dc00104c6 "\230\037B", index=0x7f9d98218218, leaf=true, n_fields=3, heap=0x7f9dc0011c00) at /home/elenst/src/10.4/storage/innobase/dict/dict0dict.cc:5012
 
#14 0x000055ee6027bd29 in btr_pcur_restore_position_func (latch_mode=8194, cursor=0x7f9dcfffdef0, file=0x55ee60828c98 "/home/elenst/src/10.4/storage/innobase/row/row0purge.cc", line=258, mtr=0x7f9dcfffe150) at /home/elenst/src/10.4/storage/innobase/btr/btr0pcur.cc:364
 
#15 0x000055ee6016e828 in row_purge_restore_vsec_cur (node=0x55ee6348da98, index=0x7f9d98218218, sec_pcur=0x7f9dcfffdef0, sec_mtr=0x7f9dcfffe150, is_tree=false) at /home/elenst/src/10.4/storage/innobase/row/row0purge.cc:256
 
#16 0x000055ee6016efc0 in row_purge_poss_sec (node=0x55ee6348da98, index=0x7f9d98218218, entry=0x7f9dc00117f8, sec_pcur=0x7f9dcfffdef0, sec_mtr=0x7f9dcfffe150, is_tree=false) at /home/elenst/src/10.4/storage/innobase/row/row0purge.cc:365
 
#17 0x000055ee6016fa6b in row_purge_remove_sec_if_poss_leaf (node=0x55ee6348da98, index=0x7f9d98218218, entry=0x7f9dc00117f8) at /home/elenst/src/10.4/storage/innobase/row/row0purge.cc:583
 
#18 0x000055ee6016ff7a in row_purge_remove_sec_if_poss (node=0x55ee6348da98, index=0x7f9d98218218, entry=0x7f9dc00117f8) at /home/elenst/src/10.4/storage/innobase/row/row0purge.cc:696
 
#19 0x000055ee60170186 in row_purge_del_mark (node=0x55ee6348da98) at /home/elenst/src/10.4/storage/innobase/row/row0purge.cc:770
 
#20 0x000055ee60171dad in row_purge_record_func (node=0x55ee6348da98, undo_rec=0x7f9dc8009bf8 "\002\a\016", thr=0x55ee6348d8c8, updated_extern=false) at /home/elenst/src/10.4/storage/innobase/row/row0purge.cc:1196
 
#21 0x000055ee601720ea in row_purge (node=0x55ee6348da98, undo_rec=0x7f9dc8009bf8 "\002\a\016", thr=0x55ee6348d8c8) at /home/elenst/src/10.4/storage/innobase/row/row0purge.cc:1263
 
#22 0x000055ee601724a7 in row_purge_step (thr=0x55ee6348d8c8) at /home/elenst/src/10.4/storage/innobase/row/row0purge.cc:1342
 
#23 0x000055ee600ddf78 in que_thr_step (thr=0x55ee6348d8c8) at /home/elenst/src/10.4/storage/innobase/que/que0que.cc:1037
 
#24 0x000055ee600de209 in que_run_threads_low (thr=0x55ee6348d8c8) at /home/elenst/src/10.4/storage/innobase/que/que0que.cc:1099
 
#25 0x000055ee600de455 in que_run_threads (thr=0x55ee6348d8c8) at /home/elenst/src/10.4/storage/innobase/que/que0que.cc:1139
 
#26 0x000055ee601bce97 in srv_task_execute (slot=0x55ee6102d010 <srv_sys+1104>) at /home/elenst/src/10.4/storage/innobase/srv/srv0srv.cc:2464
 
#27 0x000055ee601bd11b in srv_worker_thread (arg=0x0) at /home/elenst/src/10.4/storage/innobase/srv/srv0srv.cc:2519
 
#28 0x00007f9e194c7dd5 in start_thread () from /lib64/libpthread.so.0

Comment by Aleksey Midenkov [ 2020-04-04 ]

10.5: http://buildbot.askmonty.org/buildbot/builders/win32-debug/builds/16745/steps/test/logs/stdio

ucrtbase.dll!_wassert()
 
mysqld.exe!rec_offs_set_n_fields()[rem0rec.ic:1016]
 
mysqld.exe!rec_get_offsets_func()[rem0rec.cc:912]
 
mysqld.exe!page_cur_try_search_shortcut()[page0cur.cc:78]
 
mysqld.exe!page_cur_search_with_match()[page0cur.cc:333]
 
mysqld.exe!btr_cur_search_to_nth_level_func()[btr0cur.cc:1991]
 
mysqld.exe!btr_pcur_open_low()[btr0pcur.ic:441]
 
mysqld.exe!row_search_index_entry()[row0row.cc:1300]
 
mysqld.exe!row_purge_remove_sec_if_poss_leaf()[row0purge.cc:456]
 
mysqld.exe!row_purge_remove_sec_if_poss()[row0purge.cc:569]
 
mysqld.exe!row_purge_upd_exist_or_extern_func()[row0purge.cc:762]
 
mysqld.exe!row_purge_record_func()[row0purge.cc:1072]
 
mysqld.exe!row_purge()[row0purge.cc:1111]
 
mysqld.exe!row_purge_step()[row0purge.cc:1160]
 
mysqld.exe!que_thr_step()[que0que.cc:1040]
 
mysqld.exe!que_run_threads_low()[que0que.cc:1102]
 
mysqld.exe!que_run_threads()[que0que.cc:1142]
 
mysqld.exe!srv_task_execute()[srv0srv.cc:2054]
 
mysqld.exe!purge_worker_callback()[srv0srv.cc:2204]
 
mysqld.exe!tpool::task_group::execute()[task_group.cc:55]
 
mysqld.exe!tpool::task::execute()[task.cc:49]
 
mysqld.exe!tpool::thread_pool_win::task_callback()[tpool_win.cc:263]

Comment by Eugene Kosov (Inactive) [ 2020-05-19 ]

n_fields == 0 comes from:

(rr) bt
 
#0  ha_innobase_inplace_ctx::clear_added_indexes (this=0x7fa9ac014ab8) at /home/mleich/10.4/storage/innobase/handler/handler0alter.cc:1065
 
#1  0x0000560f29d85697 in ha_innobase::inplace_alter_table (this=0x7fa9af4ac850, altered_table=0x7faa2c0a9e40, ha_alter_info=0x7faa2c0a9da0)
 
    at /home/mleich/10.4/storage/innobase/handler/handler0alter.cc:8568
 
#2  0x0000560f2988b4cf in handler::ha_inplace_alter_table (this=0x7fa9af4ac850, altered_table=0x7faa2c0a9e40, ha_alter_info=0x7faa2c0a9da0)
 
    at /home/mleich/10.4/sql/handler.h:4371
 
#3  0x0000560f2987f65b in mysql_inplace_alter_table (thd=0x7fa9ac000ce8, table_list=0x7fa9ac011628, table=0x7fa9af4ad7a8, altered_table=0x7faa2c0a9e40, 
    ha_alter_info=0x7faa2c0a9da0, inplace_supported=HA_ALTER_INPLACE_NOCOPY_NO_LOCK, target_mdl_request=0x7faa2c0aac10, alter_ctx=0x7faa2c0ab740)
 
    at /home/mleich/10.4/sql/sql_table.cc:7724
 
#4  0x0000560f29886516 in mysql_alter_table (thd=0x7fa9ac000ce8, new_db=0x7fa9ac0054a8, new_name=0x7fa9ac0058b0, create_info=0x7faa2c0ac320, table_list=0x7fa9ac011628, 
    alter_info=0x7faa2c0ac260, order_num=0, order=0x0, ignore=false) at /home/mleich/10.4/sql/sql_table.cc:10130
 
#5  0x0000560f2991e1ce in Sql_cmd_alter_table::execute (this=0x7fa9ac011e10, thd=0x7fa9ac000ce8) at /home/mleich/10.4/sql/sql_alter.cc:514
 
#6  0x0000560f2979d3b7 in mysql_execute_command (thd=0x7fa9ac000ce8) at /home/mleich/10.4/sql/sql_parse.cc:6101
 
#7  0x0000560f297a286d in mysql_parse (thd=0x7fa9ac000ce8, 
    rawbuf=0x7fa9ac011470 "ALTER TABLE t3 ADD UNIQUE INDEX `uidx1` ( col1, col_int ), ALGORITHM = DEFAULT, LOCK = EXCLUSIVE  /* E_R Thread3 QNO 192 CON_ID 19 */", 
    length=133, parser_state=0x7faa2c0ad5a0, is_com_multi=false, is_next_command=false) at /home/mleich/10.4/sql/sql_parse.cc:7900
 
#8  0x0000560f2978ee28 in dispatch_command (command=COM_QUERY, thd=0x7fa9ac000ce8, 
    packet=0x7fa9ac008119 " ALTER TABLE t3 ADD UNIQUE INDEX `uidx1` ( col1, col_int ), ALGORITHM = DEFAULT, LOCK = EXCLUSIVE  /* E_R Thread3 QNO 192 CON_ID 19 */ ", 
    packet_length=135, is_com_multi=false, is_next_command=false) at /home/mleich/10.4/sql/sql_parse.cc:1841
 
#9  0x0000560f2978d5c9 in do_command (thd=0x7fa9ac000ce8) at /home/mleich/10.4/sql/sql_parse.cc:1359
 
#10 0x0000560f29914bf8 in do_handle_one_connection (connect=0x560f2c7d9768) at /home/mleich/10.4/sql/sql_connect.cc:1412
 
#11 0x0000560f29914947 in handle_one_connection (arg=0x560f2c7d9768) at /home/mleich/10.4/sql/sql_connect.cc:1316
 
#12 0x00007faa4eda36db in start_thread (arg=0x7faa2c0ae700) at pthread_create.c:463
 
#13 0x00007faa4df8988f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
(rr) l 1065
 
1060		void clear_added_indexes()
 
1061		{
 
1062			for (ulint i = 0; i < num_to_add_index; i++) {
 
1063				if (!add_index[i]->is_committed()) {
 
1064					add_index[i]->detach_columns();
 
1065					add_index[i]->n_fields = 0;
 
1066				}
 
1067			}
 
1068		}
 
1069

Comment by Marko Mäkelä [ 2020-05-19 ]

The n_fields assignment was moved in MDEV-22456 from dict_index_t::detach_columns() to ha_innobase_inplace_ctx::clear_added_indexes(), but it should not affect this failure.

It may feel strange that purge is operating on an uncommitted secondary index, but it must be so by design, because concurrent DML must update a completely created secondary index as if the change had already been committed. Only duplicate key errors must be reported by the not-yet-committed DDL transaction, leading to a rollback of the operation.

In the case of this failure, no concurrent DML is involved, though. The index is created by the following at event 119954:

ALTER TABLE t3 ADD UNIQUE INDEX `uidx1` ( col1, col_int ), ALGORITHM = DEFAULT, LOCK = EXCLUSIVE;

At event 120108 we cleared the n_fields from 3 to 0, because we flagged an error (most likely, a unique key violation). The assignment is only needed for avoiding a duplicated execution of dict_col_t::detach() on indexed virtual columns. It was originally added in MDEV-16376.

I will try to find a better solution, which could involve resetting dict_field_t::col to NULL in dict_index_t::detach_columns().

Comment by Marko Mäkelä [ 2020-05-19 ]

mleich, please test bb-10.2-marko with CREATE UNIQUE INDEX on virtual columns (expecting duplicate key errors) and avoiding not only table rebuilds, but also add/drop virtual column. The fix passed my local ASAN test.

Comment by Matthias Leich [ 2020-05-19 ] 

commit 4c0f3b3be76343c155b00feff3309d91e1e11441 origin/bb-10.2-marko
 
I made ~ 4000 runs of the RQG test the rr trace above belongs to. No replay of the assert.
 
Two other asserts which showed up were already known and observed months ago.
 
Also the battery for broad range coverage did not show unknown/new problems.

Comment by Marko Mäkelä [ 2020-05-19 ]

This bug is not limited to virtual columns, and it is not an innocent test failure. It could affect any user of ALTER TABLE…ADD [UNIQUE] INDEX or CREATE [UNIQUE] INDEX when the operation is rolled back due to MDL upgrade timeout or duplicate key error.

Comment by Marko Mäkelä [ 2020-05-20 ]

I got yet another crash on INSERT after a failed ADD UNIQUE INDEX on a virtual column, when merging this to 10.5. So, I pushed a follow-up fix. For some reason, I was unable to reproduce that crash on 10.4. The crash occurred every now and then for the following snippet of gcol.innodb_virtual_basic:

# Bug 21941320 - GCOLS: FAILING ASSERTION: N_IDX > 0
 
create table t(a int) engine=innodb;
 
insert into t set a=1;
 
alter table t add column c int generated always as (1) virtual;
 
insert into t set a=2;
 
 
 
# Following will cause create index fail, we need to make sure the column
 
# ord_part is reset
 
--error ER_DUP_ENTRY
 
alter table t add unique index(c);
 
insert into t set a=1;
 
drop table t;

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