Assertion `!rec_offs_any_null_extern(rec, offsets)' in row_merge_read_clustered_index

Scenario:

1. Start the server and generate some initial data

2. 9 sessions run their usual DDL/DML battle

3. SIGKILL server during 2. is ongoing

4. Restart attempt with success

5. OPTIMIZE TABLE harvests a server crash

# 2021-05-20T16:59:44 [3828706] | [rr 3918438 51362]mysqld: /data/Server/bb-10.6-marko/storage/innobase/row/row0merge.cc:2117: dberr_t row_merge_read_clustered_index(trx_t*, TABLE*, const dict_table_t*, dict_table_t*, bool, dict_index_t**, dict_index_t*, fts_psort_t*, merge_file_t*, const ulint*, ulint, const dtuple_t*, const dict_add_v_col_t*, const ulint*, ulint, ib_sequence_t&, row_merge_block_t*, bool, pfs_os_file_t*, ut_stage_alter_t*, double, row_merge_block_t*, TABLE*, bool): Assertion `!rec_offs_any_null_extern(rec, offsets)' failed.

# 2021-05-20T16:59:44 [3828706] | Query (0x62b0000c4238): OPTIMIZE TABLE `test`.`t3`

# 2021-05-20T16:59:44 [3828706] | [rr 3918438 66081]

# 2021-05-20T16:59:44 [3828706] | Connection ID (thread ID): 5

# 2021-05-20T16:59:44 [3828706] | [rr 3918438 66083]Status: NOT_KILLED

(rr) bt

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

#1  0x00007aa72ec57859 in __GI_abort () at abort.c:79

#2  0x00007aa72ec57729 in __assert_fail_base (fmt=0x7aa72eded588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55e902fb3f40 "!rec_offs_any_null_extern(rec, offsets)", file=0x55e902fb1300 "/data/Server/bb-10.6-marko/storage/innobase/row/row0merge.cc", 

    line=2117, function=<optimized out>) at assert.c:92

#3  0x00007aa72ec68f36 in __GI___assert_fail (assertion=0x55e902fb3f40 "!rec_offs_any_null_extern(rec, offsets)", file=0x55e902fb1300 "/data/Server/bb-10.6-marko/storage/innobase/row/row0merge.cc", line=2117, 

    function=0x55e902fb3680 "dberr_t row_merge_read_clustered_index(trx_t*, TABLE*, const dict_table_t*, dict_table_t*, bool, dict_index_t**, dict_index_t*, fts_psort_t*, merge_file_t*, const ulint*, ulint, const dtuple_t*, const"...) at assert.c:101

#4  0x000055e901bb3673 in row_merge_read_clustered_index (trx=0x42092aaa2a48, table=0x1fee1b033080, old_table=0x61800000e508, new_table=0x6180000dd508, online=true, index=0x61900028dee0, fts_sort_idx=0x0, psort_info=0x0, files=0x60300000b320, 

    key_numbers=0x61900028def0, n_index=1, defaults=0x0, add_v=0x0, col_map=0x61d000381970, add_autoinc=18446744073709551615, sequence=..., block=0x736f6d029000 "", skip_pk_sort=true, tmpfd=0x1fee1b0314e0, stage=0x602000060f50, pct_cost=50, crypt_block=0x0, 

    eval_table=0x1fee1b033080, allow_not_null=true) at /data/Server/bb-10.6-marko/storage/innobase/row/row0merge.cc:2117

#5  0x000055e901bc38d2 in row_merge_build_indexes (trx=0x42092aaa2a48, old_table=0x61800000e508, new_table=0x6180000dd508, online=true, indexes=0x61900028dee0, key_numbers=0x61900028def0, n_indexes=1, table=0x1fee1b033080, defaults=0x0, col_map=0x61d000381970, 

    add_autoinc=18446744073709551615, sequence=..., skip_pk_sort=true, stage=0x602000060f50, add_v=0x0, eval_table=0x1fee1b033080, allow_not_null=true) at /data/Server/bb-10.6-marko/storage/innobase/row/row0merge.cc:4548

#6  0x000055e90190b036 in ha_innobase::inplace_alter_table (this=0x61d0003778b8, altered_table=0x1fee1b033080, ha_alter_info=0x1fee1b032980) at /data/Server/bb-10.6-marko/storage/innobase/handler/handler0alter.cc:8452

#7  0x000055e900a36752 in handler::ha_inplace_alter_table (this=0x61d0003778b8, altered_table=0x1fee1b033080, ha_alter_info=0x1fee1b032980) at /data/Server/bb-10.6-marko/sql/handler.h:4648

#8  0x000055e900a15d7a in mysql_inplace_alter_table (thd=0x62b0000bd218, table_list=0x62b0000c4368, table=0x61900028a098, altered_table=0x1fee1b033080, ha_alter_info=0x1fee1b032980, target_mdl_request=0x1fee1b032a80, ddl_log_state=0x1fee1b0327a0, 

    trigger_param=0x1fee1b0334d0, alter_ctx=0x1fee1b033f50) at /data/Server/bb-10.6-marko/sql/sql_table.cc:7352

#9  0x000055e900a297ab in mysql_alter_table (thd=0x62b0000bd218, new_db=0x55e902699a20 <null_clex_str>, new_name=0x55e902699a20 <null_clex_str>, create_info=0x1fee1b035370, table_list=0x62b0000c4368, alter_info=0x1fee1b035240, order_num=0, order=0x0, ignore=false, 

    if_exists=false) at /data/Server/bb-10.6-marko/sql/sql_table.cc:10176

#10 0x000055e900a31bca in mysql_recreate_table (thd=0x62b0000bd218, table_list=0x62b0000c4368, table_copy=false) at /data/Server/bb-10.6-marko/sql/sql_table.cc:11235

#11 0x000055e900bcabcc in admin_recreate_table (thd=0x62b0000bd218, table_list=0x62b0000c4368) at /data/Server/bb-10.6-marko/sql/sql_admin.cc:67

#12 0x000055e900bd228c in mysql_admin_table (thd=0x62b0000bd218, tables=0x62b0000c4368, check_opt=0x62b0000c2618, operator_name=0x55e90370b0a0 <msg_optimize>, lock_type=TL_WRITE, org_open_for_modify=true, repair_table_use_frm=false, extra_open_options=0, 

    prepare_func=0x0, operator_func=(int (handler::*)(class handler * const, class THD *, HA_CHECK_OPT *)) 0x55e900f615f0 <handler::ha_optimize(THD*, st_ha_check_opt*)>, view_operator_func=0x0, is_cmd_replicated=true)

    at /data/Server/bb-10.6-marko/sql/sql_admin.cc:1144

#13 0x000055e900bd4be1 in Sql_cmd_optimize_table::execute (this=0x62b0000c4a48, thd=0x62b0000bd218) at /data/Server/bb-10.6-marko/sql/sql_admin.cc:1521

#14 0x000055e9007bea0c in mysql_execute_command (thd=0x62b0000bd218) at /data/Server/bb-10.6-marko/sql/sql_parse.cc:5986

#15 0x000055e9007caf0f in mysql_parse (thd=0x62b0000bd218, rawbuf=0x62b0000c4238 "OPTIMIZE TABLE `test`.`t3`", length=26, parser_state=0x1fee1b037b20) at /data/Server/bb-10.6-marko/sql/sql_parse.cc:8019

#16 0x000055e9007a31ac in dispatch_command (command=COM_QUERY, thd=0x62b0000bd218, packet=0x6290000dc219 "", packet_length=26, blocking=true) at /data/Server/bb-10.6-marko/sql/sql_parse.cc:1897

#17 0x000055e9007a0581 in do_command (thd=0x62b0000bd218, blocking=true) at /data/Server/bb-10.6-marko/sql/sql_parse.cc:1406

#18 0x000055e900b9bfda in do_handle_one_connection (connect=0x608000003f38, put_in_cache=true) at /data/Server/bb-10.6-marko/sql/sql_connect.cc:1410

#19 0x000055e900b9b93c in handle_one_connection (arg=0x608000003f38) at /data/Server/bb-10.6-marko/sql/sql_connect.cc:1312

#20 0x00001dc322277609 in start_thread (arg=<optimized out>) at pthread_create.c:477

#21 0x00007aa72ed54293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

(rr)

pluto:/data/Results/1621525973/TBR-795/dev/shm/vardir/1621525973/6/1/rr

_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-0  # Fate of DB server till SIGKILL

_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-1  # Fate of DB Server since restart

GIT_SHOW: HEAD, origin/bb-10.6-marko 25d150d3fe193b5a41948a589c0ce30368c054e1 2021-05-20T18:36:07+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 \

--reporters=CrashRecovery1 \

--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 \

--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=--innodb_stats_persistent=off \

--mysqld=--innodb_adaptive_hash_index=on \

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

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

--threads=9 \

--mysqld=--innodb-use-native-aio=0 \

--rr=Extended \

--rr_options="--chaos --wait" \

--mysqld=--innodb_page_size=64K \

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

--no_mask \

--workdir=<local settings> \

--vardir=<local settings> \

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

--basedir1=<local settings> \

--script_debug=_nix

RQG error pattern

[ 'TBR-795-MDEV-25751', 'INFO: Reporter \'CrashRecovery1\': Attempting database recovery using the server.+ERROR: OPTIMIZE TABLE .{1,500} harvested 2013: Lost connection to MySQL server during query.+\[Note\] InnoDB: Starting crash recovery from checkpoint LSN.+\[Note\] .{1,200}mysqld: ready for connections.+mysqld: .{1,200}row0merge.cc:.{1,30} dberr_t row_merge_read_clustered_index.{1,500}: Assertion .\!rec_offs_any_null_extern\(rec, offsets\). failed..+RESULT: The RQG run ended with status STATUS_RECOVERY_FAILURE' ],