Assertion `0' failed in row_log_table_apply_op during redundant table rebuild

mysqld: /data/Server/10.5B/storage/innobase/row/row0log.cc:2450: 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-07-20T16:23:03 [3471815] | Query (0x62b000268238): ALTER TABLE t4 ADD PRIMARY KEY ( col_text(9), col_string )  /* E_R Thread28 QNO 1005 CON_ID 235 */

# 2021-07-20T16:23:03 [3471815] | 

# 2021-07-20T16:23:03 [3471815] | Connection ID (thread ID): 235

# 2021-07-20T16:23:03 [3471815] | Status: NOT_KILLED

# 2021-07-20T16:23:03 [3471815] #3  <signal handler called>

# 2021-07-20T16:23:03 [3471815] #4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50

# 2021-07-20T16:23:03 [3471815] #5  0x00007f9d5dc6a859 in __GI_abort () at abort.c:79

# 2021-07-20T16:23:03 [3471815] #6  0x00007f9d5dc6a729 in __assert_fail_base (fmt=0x7f9d5de00588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55fa2761ede0 "0", file=0x55fa27628520 "/data/Server/10.5B/storage/innobase/row/row0log.cc", line=2450, function=<optimized out>) at assert.c:92

# 2021-07-20T16:23:03 [3471815] #7  0x00007f9d5dc7bf36 in __GI___assert_fail (assertion=0x55fa2761ede0 "0", file=0x55fa27628520 "/data/Server/10.5B/storage/innobase/row/row0log.cc", line=2450, function=0x55fa2762b9e0 "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-07-20T16:23:03 [3471815] #8  0x000055fa26402b1f in row_log_table_apply_op (thr=0x6190000cead0, new_trx_id_col=2, dup=0x7f9d3acbfec0, error=0x7f9d3acbf830, offsets_heap=0x631000ac8800, heap=0x631002cec800, mrec=0x7f9d395d204f '3' <repeats 747 times>, mrec_end=0x7f9d395d237e "", offsets=0x604000b9d990) at /data/Server/10.5B/storage/innobase/row/row0log.cc:2450

# 2021-07-20T16:23:03 [3471815] #9  0x000055fa2640891b in row_log_table_apply_ops (thr=0x6190000cead0, dup=0x7f9d3acbfec0, stage=0x602000043810) at /data/Server/10.5B/storage/innobase/row/row0log.cc:3040

# 2021-07-20T16:23:03 [3471815] #10 0x000055fa264097a5 in row_log_table_apply (thr=0x6190000cead0, old_table=0x6180000de508, table=0x7f9d3acc1990, stage=0x602000043810, new_table=0x618000229908) at /data/Server/10.5B/storage/innobase/row/row0log.cc:3149

# 2021-07-20T16:23:03 [3471815] #11 0x000055fa261063db in ha_innobase::inplace_alter_table (this=0x61d0011c88b8, altered_table=0x7f9d3acc1990, ha_alter_info=0x7f9d3acc12b0) at /data/Server/10.5B/storage/innobase/handler/handler0alter.cc:8493

# 2021-07-20T16:23:03 [3471815] #12 0x000055fa25245504 in handler::ha_inplace_alter_table (this=0x61d0011c88b8, altered_table=0x7f9d3acc1990, ha_alter_info=0x7f9d3acc12b0) at /data/Server/10.5B/sql/handler.h:4536

# 2021-07-20T16:23:03 [3471815] #13 0x000055fa25227548 in mysql_inplace_alter_table (thd=0x62b000299218, table_list=0x62b0002683d8, table=0x61900015b398, altered_table=0x7f9d3acc1990, ha_alter_info=0x7f9d3acc12b0, target_mdl_request=0x7f9d3acc1390, alter_ctx=0x7f9d3acc23f0) at /data/Server/10.5B/sql/sql_table.cc:8113

# 2021-07-20T16:23:03 [3471815] #14 0x000055fa252394e7 in mysql_alter_table (thd=0x62b000299218, new_db=0x62b00029da88, new_name=0x62b00029dea8, create_info=0x7f9d3acc3760, table_list=0x62b0002683d8, alter_info=0x7f9d3acc3650, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/Server/10.5B/sql/sql_table.cc:10730

# 2021-07-20T16:23:03 [3471815] #15 0x000055fa253acda5 in Sql_cmd_alter_table::execute (this=0x62b000268c30, thd=0x62b000299218) at /data/Server/10.5B/sql/sql_alter.cc:539

# 2021-07-20T16:23:03 [3471815] #16 0x000055fa24fceb35 in mysql_execute_command (thd=0x62b000299218) at /data/Server/10.5B/sql/sql_parse.cc:6052

# 2021-07-20T16:23:03 [3471815] #17 0x000055fa24fdb072 in mysql_parse (thd=0x62b000299218, rawbuf=0x62b000268238 "ALTER TABLE t4 ADD PRIMARY KEY ( col_text(9), col_string )  /* E_R Thread28 QNO 1005 CON_ID 235 */", length=98, parser_state=0x7f9d3acc4cb0, is_com_multi=false, is_next_command=false) at /data/Server/10.5B/sql/sql_parse.cc:8096

# 2021-07-20T16:23:03 [3471815] #18 0x000055fa24fb3158 in dispatch_command (command=COM_QUERY, thd=0x62b000299218, packet=0x629000d4d219 " ALTER TABLE t4 ADD PRIMARY KEY ( col_text(9), col_string )  /* E_R Thread28 QNO 1005 CON_ID 235 */ ", packet_length=100, is_com_multi=false, is_next_command=false) at /data/Server/10.5B/sql/sql_parse.cc:1891

# 2021-07-20T16:23:03 [3471815] #19 0x000055fa24fb01f1 in do_command (thd=0x62b000299218) at /data/Server/10.5B/sql/sql_parse.cc:1370

# 2021-07-20T16:23:03 [3471815] #20 0x000055fa25394751 in do_handle_one_connection (connect=0x60800004e9b8, put_in_cache=true) at /data/Server/10.5B/sql/sql_connect.cc:1410

# 2021-07-20T16:23:03 [3471815] #21 0x000055fa253940b5 in handle_one_connection (arg=0x6080000ac138) at /data/Server/10.5B/sql/sql_connect.cc:1312

# 2021-07-20T16:23:03 [3471815] #22 0x00007f9d5e191609 in start_thread (arg=<optimized out>) at pthread_create.c:477

# 2021-07-20T16:23:03 [3471815] #23 0x00007f9d5dd67293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

origin/10.5 b4ec3313f6bb3a222b3528b5a8a6dca73b870c20 2021-07-20T09:32:11+03:00

RQG

---

git clone https://github.com/mleich1/rqg --branch experimental RQG

perl rqg.pl \

--grammar=conf/mariadb/table_stress_innodb.yy \

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

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

--mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \

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

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

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

--mysqld=--connect_timeout=60 \

--mysqld=--interactive_timeout=28800 \

--mysqld=--slave_net_timeout=60 \

--mysqld=--net_read_timeout=30 \

--mysqld=--net_write_timeout=60 \

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

--mysqld=--wait_timeout=28800 \

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

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

--no-mask \

--queries=10000000 \

--seed=random \

--reporters=Backtrace \

--reporters=ErrorLog \

--reporters=Deadlock1 \

--validators=None \

--mysqld=--log_output=none \

--mysqld=--log_bin_trust_function_creators=1 \

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

--engine=InnoDB \

--restart_timeout=240 \

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

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

--duration=300 \

--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \

--mysqld=--loose-innodb-sync-debug \

--mysqld=--innodb_stats_persistent=off \

--mysqld=--innodb_adaptive_hash_index=on \

--mysqld=--log-bin \

--mysqld=--sync-binlog=1 \

--mysqld=--loose-innodb_evict_tables_on_commit_debug=off \

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

--threads=33 \

--mysqld=--innodb_use_native_aio=1 \

--mysqld=--innodb_page_size=64K \

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

--no_mask \

--workdir=<local settings> \

--vardir=<local settings> \

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

--basedir1=<local settings> \

--script_debug=_nix

table_stress_innodb.yy is slightly modified in order to do the buffer pool resizing

all 30s instead of the default 60s.

Error pattern:

[ 'TBR-957', 'mysqld: .{1,200}row0log.cc:.{1,20}: const mrec_t\* row_log_table_apply_op.{1,200}: Assertion \`0\' failed.+The RQG run ended with status STATUS_SERVER_CRASHED' ],