Alter table corrupts while applying the modification log

Problem found during RQG testing.

# 2019-03-25T18:56:06 [74161] | Version: '10.3.14-MariaDB-debug-log'  socket: ...

# 2019-03-25T18:56:06 [74161] | mysqld: storage/innobase/row/row0log.cc:2432: const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, ulint*): Assertion `0' failed.

# 2019-03-25T18:56:06 [74161] | 190325 18:55:33 [ERROR] mysqld got signal 6 ;

...

Query (0x7f1a70012ac0): ALTER TABLE t3 ADD PRIMARY KEY IF NOT EXISTS ( col2 ), ADD UNIQUE INDEX IF NOT EXISTS uidX3 ( col_int ) /* E_R Thread7 QNO 499 CON_ID 75 */

Connection ID (thread ID): 75

Status: NOT_KILLED

...

#3  <signal handler called>

#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:58

#5  0x00007f1b2676a37a in __GI_abort () at abort.c:89

#6  0x00007f1b26760b47 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x560760074deb "0", file=file@entry=0x5607600764a8 "storage/innobase/row/row0log.cc", line=line@entry=2432, function=function@entry=0x56076007a6c0 <row_log_table_apply_op(que_thr_t*, unsigned long, row_merge_dup_t*, dberr_t*, mem_block_info_t*, mem_block_info_t*, unsigned char const*, unsigned char const*, unsigned long*)::__PRETTY_FUNCTION__> "const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, ulint*)") at assert.c:92

#7  0x00007f1b26760bf2 in __GI___assert_fail (assertion=0x560760074deb "0", file=0x5607600764a8 "storage/innobase/row/row0log.cc", line=2432, function=0x56076007a6c0 <row_log_table_apply_op(que_thr_t*, unsigned long, row_merge_dup_t*, dberr_t*, mem_block_info_t*, mem_block_info_t*, unsigned char const*, unsigned char const*, unsigned long*)::__PRETTY_FUNCTION__> "const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, ulint*)") at assert.c:101

#8  0x000056075f9001a8 in row_log_table_apply_op (thr=0x7f1a70081cd8, new_trx_id_col=1, dup=0x7f1b1c4bd5b0, error=0x7f1b1c4bd32c, offsets_heap=0x7f1a700c77f0, heap=0x7f1a700a1260, mrec=0x7f1b1c02e026 "", mrec_end=0x7f1b1c02e042 "", offsets=0x7f1a70086430) at storage/innobase/row/row0log.cc:2432

#9  0x000056075f90264d in row_log_table_apply_ops (thr=0x7f1a70081cd8, dup=0x7f1b1c4bd5b0, stage=0x7f1a700a0210) at storage/innobase/row/row0log.cc:3029

#10 0x000056075f902c5e in row_log_table_apply (thr=0x7f1a70081cd8, old_table=0x7f1a7008b4e8, table=0x7f1a70090778, stage=0x7f1a700a0210, new_table=0x7f1a7008b188) at storage/innobase/row/row0log.cc:3135

#11 0x000056075f7ccd12 in ha_innobase::inplace_alter_table (this=0x7f1a7407c720, altered_table=0x7f1a70090778, ha_alter_info=0x7f1b1c4bdfd0) at storage/innobase/handler/handler0alter.cc:7260

#12 0x000056075f363ee9 in handler::ha_inplace_alter_table (this=0x7f1a7407c720, altered_table=0x7f1a70090778, ha_alter_info=0x7f1b1c4bdfd0) at sql/handler.h:4192

#13 0x000056075f35968c in mysql_inplace_alter_table (thd=0x7f1a70000a98, table_list=0x7f1a70012c88, table=0x7f1a7407bb48, altered_table=0x7f1a70090778, ha_alter_info=0x7f1b1c4bdfd0, inplace_supported=HA_ALTER_INPLACE_COPY_NO_LOCK, target_mdl_request=0x7f1b1c4be1c0, alter_ctx=0x7f1b1c4be920) at sql/sql_table.cc:7547

#14 0x000056075f35fa16 in mysql_alter_table (thd=0x7f1a70000a98, new_db=0x7f1a70005168, new_name=0x7f1a70005528, create_info=0x7f1b1c4bf510, table_list=0x7f1a70012c88, alter_info=0x7f1b1c4bf450, order_num=0, order=0x0, ignore=false) at sql/sql_table.cc:9756

#15 0x000056075f3e73bd in Sql_cmd_alter_table::execute (this=0x7f1a70013470, thd=0x7f1a70000a98) at sql/sql_alter.cc:488

#16 0x000056075f289352 in mysql_execute_command (thd=0x7f1a70000a98) at sql/sql_parse.cc:6283

#17 0x000056075f28e670 in mysql_parse (thd=0x7f1a70000a98, rawbuf=0x7f1a70012ac0 "ALTER TABLE t3 ADD PRIMARY KEY IF NOT EXISTS ( col2 ), ADD UNIQUE INDEX IF NOT EXISTS uidX3 ( col_int ) /* E_R Thread7 QNO 499 CON_ID 75 */", length=139, parser_state=0x7f1b1c4c0640, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:8089

#18 0x000056075f27b6b4 in dispatch_command (command=COM_QUERY, thd=0x7f1a70000a98, packet=0x7f1a7000a7c9 "ALTER TABLE t3 ADD PRIMARY KEY IF NOT EXISTS ( col2 ), ADD UNIQUE INDEX IF NOT EXISTS uidX3 ( col_int ) /* E_R Thread7 QNO 499 CON_ID 75 */ ", packet_length=140, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:1857

#19 0x000056075f27a0d9 in do_command (thd=0x7f1a70000a98) at sql/sql_parse.cc:1402

#20 0x000056075f3e1981 in do_handle_one_connection (connect=0x560761f86ef8) at sql/sql_connect.cc:1402

#21 0x000056075f3e16f8 in handle_one_connection (arg=0x560761f86ef8) at sql/sql_connect.cc:1308

#22 0x00007f1b273a96da in start_thread (arg=0x7f1b1c4c1700) at pthread_create.c:456

#23 0x00007f1b2683bd7f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105

Replay on

10.3 commit dbc0d576a3f402ae52423fe424ed0a68f49537ef 2019-03-25T16:14:39+02:00

10.4 commit 8b480df63ec76963fd96d2e00b911a801b912591 2019-03-25T17:18:15+02:00

The problem might be caused by a similar reason like

https://jira.mariadb.org/browse/MDEV-18361

because the RQG test tends to fail either with the current assert or MDEV-18361

but not with other asserts or SEGV or .... 

###########

origin/10.6 b3c470a3c7e8bb497bca5bc9fca4cf52cfc9e88e 2021-03-19T18:12:26+03:00

# 2021-03-20T16:27:33 [2352135] | [rr 2352767 84442]mysqld: /Server/10.6N/storage/innobase/row/row0log.cc:2468: const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, rec_offs*): Assertion `0' failed.

# 2021-03-20T16:27:33 [2352135] | Thread 3 (Thread 2352767.2354385):

# 2021-03-20T16:27:33 [2352135] | #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50

# 2021-03-20T16:27:33 [2352135] | #1  0x00005a8b0ccb8859 in __GI_abort () at abort.c:79

# 2021-03-20T16:27:33 [2352135] | #2  0x00005a8b0ccb8729 in __assert_fail_base (fmt=0x5a8b0ce4e588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55e8bcab9800 "0", file=0x55e8bcac3cc0 "/Server/10.6N/storage/innobase/row/row0log.cc", line=2468, function=<optimized out>) at assert.c:92

# 2021-03-20T16:27:33 [2352135] | #3  0x00005a8b0ccc9f36 in __GI___assert_fail (assertion=0x55e8bcab9800 "0", file=0x55e8bcac3cc0 "/Server/10.6N/storage/innobase/row/row0log.cc", line=2468, function=0x55e8bcac73e0 "const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, rec_offs*)") at assert.c:101

# 2021-03-20T16:27:33 [2352135] | #4  0x000055e8bb3c789f in row_log_table_apply_op (thr=0x61a00026f5d8, new_trx_id_col=2, dup=0x6400035b8820, error=0x6400035b8170, offsets_heap=0x631000294818, heap=0x631000280818, mrec=0x59dd1b05e033 '1' <repeats 757 times>, mrec_end=0x59dd1b05e35a "", offsets=0x607000087b88) at /Server/10.6N/storage/innobase/row/row0log.cc:2468

# 2021-03-20T16:27:33 [2352135] | #5  0x000055e8bb3cd989 in row_log_table_apply_ops (thr=0x61a00026f5d8, dup=0x6400035b8820, stage=0x608000051938) at /Server/10.6N/storage/innobase/row/row0log.cc:3063

# 2021-03-20T16:27:33 [2352135] | #6  0x000055e8bb3ce7ce in row_log_table_apply (thr=0x61a00026f5d8, old_table=0x618000063920, table=0x6400035ba770, stage=0x608000051938, new_table=0x618000064120) at /Server/10.6N/storage/innobase/row/row0log.cc:3171

# 2021-03-20T16:27:33 [2352135] | #7  0x000055e8bb0afb10 in alter_rebuild_apply_log (ctx=0x62b000136da0, ha_alter_info=0x6400035ba280, altered_table=0x6400035ba770) at /Server/10.6N/storage/innobase/handler/handler0alter.cc:10804

# 2021-03-20T16:27:33 [2352135] | #8  0x000055e8bb0b1db5 in ha_innobase::commit_inplace_alter_table (this=0x61d000ccbab8, altered_table=0x6400035ba770, ha_alter_info=0x6400035ba280, commit=true) at /Server/10.6N/storage/innobase/handler/handler0alter.cc:11007

# 2021-03-20T16:27:33 [2352135] | #9  0x000055e8ba4e8494 in handler::ha_commit_inplace_alter_table (this=0x61d000ccbab8, altered_table=0x6400035ba770, ha_alter_info=0x6400035ba280, commit=true) at /Server/10.6N/sql/handler.cc:4856

# 2021-03-20T16:27:33 [2352135] | #10 0x000055e8b9f63b60 in mysql_inplace_alter_table (thd=0x62b00012d218, table_list=0x62b0001343c8, table=0x619000783c98, altered_table=0x6400035ba770, ha_alter_info=0x6400035ba280, target_mdl_request=0x6400035ba370, alter_ctx=0x6400035bb1e0) at /Server/10.6N/sql/sql_table.cc:8191

# 2021-03-20T16:27:33 [2352135] | #11 0x000055e8b9f771ff in mysql_alter_table (thd=0x62b00012d218, new_db=0x62b000131c98, new_name=0x62b0001320b8, create_info=0x6400035bc5c0, table_list=0x62b0001343c8, alter_info=0x6400035bc490, order_num=0, order=0x0, ignore=false, if_exists=false) at /Server/10.6N/sql/sql_table.cc:10779

# 2021-03-20T16:27:33 [2352135] | #12 0x000055e8ba1151d4 in Sql_cmd_alter_table::execute (this=0x62b000134c10, thd=0x62b00012d218) at /Server/10.6N/sql/sql_alter.cc:540

# 2021-03-20T16:27:33 [2352135] | #13 0x000055e8b9cd6182 in mysql_execute_command (thd=0x62b00012d218) at /Server/10.6N/sql/sql_parse.cc:5973

# 2021-03-20T16:27:33 [2352135] | #14 0x000055e8b9ce3963 in mysql_parse (thd=0x62b00012d218, rawbuf=0x62b000134238 "ALTER TABLE t4 ADD PRIMARY KEY ( col_text(9), col_int ) /* E_R Thread1 QNO 36 CON_ID 16 */", length=90, parser_state=0x6400035bdbc0) at /Server/10.6N/sql/sql_parse.cc:8004

# 2021-03-20T16:27:33 [2352135] | #15 0x000055e8b9cba420 in dispatch_command (command=COM_QUERY, thd=0x62b00012d218, packet=0x629000bbd219 "ALTER TABLE t4 ADD PRIMARY KEY ( col_text(9), col_int ) /* E_R Thread1 QNO 36 CON_ID 16 */ ", packet_length=91, blocking=true) at /Server/10.6N/sql/sql_parse.cc:1888

# 2021-03-20T16:27:33 [2352135] | #16 0x000055e8b9cb714f in do_command (thd=0x62b00012d218, blocking=true) at /Server/10.6N/sql/sql_parse.cc:1399

# 2021-03-20T16:27:33 [2352135] | #17 0x000055e8ba0f8fdd in do_handle_one_connection (connect=0x6080000033b8, put_in_cache=true) at /Server/10.6N/sql/sql_connect.cc:1410

# 2021-03-20T16:27:33 [2352135] | #18 0x000055e8ba0f893f in handle_one_connection (arg=0x6080000033b8) at /Server/10.6N/sql/sql_connect.cc:1312

# 2021-03-20T16:27:33 [2352135] | #19 0x000055e8badf65dd in pfs_spawn_thread (arg=0x61500000af98) at /Server/10.6N/storage/perfschema/pfs.cc:2201

# 2021-03-20T16:27:33 [2352135] | #20 0x000000007000b609 in start_thread (arg=<optimized out>) at pthread_create.c:477

# 2021-03-20T16:27:33 [2352135] | #21 0x00005a8b0cdb5293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Query:   ALTER TABLE t4 ADD PRIMARY KEY ( col_text(9), col_int )

Status: NOT_KILLED

pluto:/data/Results/TBR-957/left_over/dev/shm/vardir/1616257591/4/1/rr

_RR_TRACE_DIR="." rr replay --mark-stdio

perl rqg.pl \                   

--duration=100 \

--queries=10000000 \

--no_mask \

--seed=random \

--rpl_mode=none \

--gendata_sql=conf/mariadb/table_stress.sql \

--engine=InnoDB \

--gendata=conf/mariadb/table_stress.zz \

--mysqld=--innodb_stats_persistent=off \

--mysqld=--innodb-buffer-pool-size=24M \

--mysqld=--log_bin_trust_function_creators=1 \

--mysqld=--loose-idle_transaction_timeout=0 \

--mysqld=--file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \

--mysqld=--loose-idle_readonly_transaction_timeout=0 \

--mysqld=--innodb-lock-wait-timeout=50 \

--mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \

--mysqld=--loose-debug_assert_on_not_freed_memory=0 \

--mysqld=--connect_timeout=60 \

--mysqld=--lock-wait-timeout=86400 \

--mysqld=--slave_net_timeout=60 \

--mysqld=--innodb_page_size=64K \

--mysqld=--loose-table_lock_wait_timeout=50 \

--mysqld=--interactive_timeout=28800 \

--mysqld=--loose_innodb_use_native_aio=0 \

--mysqld=--plugin-load-add=file_key_management.so \

--mysqld=--wait_timeout=28800 \

--mysqld=--loose-idle_write_transaction_timeout=0 \

--mysqld=--net_read_timeout=30 \

--mysqld=--net_write_timeout=60 \

--mysqld=--log-output=none \

--mysqld=--log-bin \

--mysqld=--loose-max-statement-time=30 \

--validators=None \

--grammar=MDEV-19044_2.yy \

--threads=2 \

--grammar=/data/Results/1616257591/c00000.yy \

--workdir=<local settings> \

--vardir=<local settings> \

--mtr-build-thread=<local settings> \

--basedir1=/Server_bin/10.6N_asan \

--script_debug=_nix_ \

--rr=Extended \

--rr_options=--chaos