[MDEV-18361] row0log.cc:3057: dberr_t row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*): Assertion `0' failed. Created: 2019-01-23  Updated: 2024-01-24  Resolved: 2024-01-24

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.4.2, 10.3.14
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Matthias Leich
Resolution: Cannot Reproduce Votes: 1
Labels: None
Environment:

Linux Ubuntu 17

Attachments: HTML File prt2     File ts_15.tgz    
Issue Links:
Blocks
is blocked by MDEV-28706 ALTER TABLE ... FORCE harvests 1879: ... Closed
is blocked by MDEV-31025 Redundant table alter fails when fixe... Closed
Relates
relates to MDEV-26198 Assertion `0' failed in row_log_table... Closed
relates to MDEV-28122 OPTIMIZE TABLE crash Closed

 Description    

Problem found during RQG testing on
 
10.4 b7a784ae259c0fd8ed1adc88b84dcdaa2441987c 2019-01-23
 
The problem was not reproducible on
 
10.3 d4144c8e010b61a440d422d0f1ca5b066532d173 2019-01-21
 
 
 
Version: '10.4.2-MariaDB-debug-log'  socket: 'bld_debug/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
 
mysqld: storage/innobase/row/row0log.cc:3057: dberr_t row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*): Assertion `0' failed.
 
190123 18:48:13 [ERROR] mysqld got signal 6 ;
 
...
 
Query (0x7fe3b0013340): ALTER TABLE t4 MODIFY COLUMN col2 INT NOT NULL /* E_R Thread2 QNO 22 CON_ID 16 */
 
Connection ID (thread ID): 11
 
Status: NOT_KILLED
 
...
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x00007fe415a3ef5d in __GI_abort () at abort.c:90
 
#6  0x00007fe415a34f17 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x55beb1bd1e71 "0", file=file@entry=0x55beb1bd36a8 "storage/innobase/row/row0log.cc", line=line@entry=3057, function=function@entry=0x55beb1bd7800 <row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*)::__PRETTY_FUNCTION__> "dberr_t row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*)") at assert.c:92
 
#7  0x00007fe415a34fc2 in __GI___assert_fail (assertion=0x55beb1bd1e71 "0", file=0x55beb1bd36a8 "storage/innobase/row/row0log.cc", line=3057, function=0x55beb1bd7800 <row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*)::__PRETTY_FUNCTION__> "dberr_t row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*)") at assert.c:101
 
#8  0x000055beb14362b7 in row_log_table_apply_ops (thr=0x7fe3b0055818, dup=0x7fe40ac810a0, stage=0x7fe3b0055d20) at storage/innobase/row/row0log.cc:3057
 
#9  0x000055beb143666c in row_log_table_apply (thr=0x7fe3b0055818, old_table=0x7fe3b0026588, table=0x7fe3b005ad98, stage=0x7fe3b0055d20, new_table=0x7fe3b0020948) at storage/innobase/row/row0log.cc:3131
 
#10 0x000055beb130a9c1 in commit_try_rebuild (ha_alter_info=0x7fe40ac825c0, ctx=0x7fe3b0015798, altered_table=0x7fe3b005ad98, old_table=0x7fe3b0042df8, trx=0x7fe410044390, table_name=0x7fe3b0041d25 "t4") at storage/innobase/handler/handler0alter.cc:9761
 
#11 0x000055beb12fd99a in ha_innobase::commit_inplace_alter_table (this=0x7fe3b0055e30, altered_table=0x7fe3b005ad98, ha_alter_info=0x7fe40ac825c0, commit=true) at storage/innobase/handler/handler0alter.cc:10786
 
#12 0x000055beb10976f3 in handler::ha_commit_inplace_alter_table (this=0x7fe3b0055e30, altered_table=0x7fe3b005ad98, ha_alter_info=0x7fe40ac825c0, commit=true) at sql/handler.cc:4666
 
#13 0x000055beb0e39604 in mysql_inplace_alter_table (thd=0x7fe3b0000ce8, table_list=0x7fe3b0013490, table=0x7fe3b0042df8, altered_table=0x7fe3b005ad98, ha_alter_info=0x7fe40ac825c0, inplace_supported=HA_ALTER_INPLACE_COPY_NO_LOCK, target_mdl_request=0x7fe40ac826f0, alter_ctx=0x7fe40ac832e0) at sql/sql_table.cc:7578
 
#14 0x000055beb0e3f442 in mysql_alter_table (thd=0x7fe3b0000ce8, new_db=0x7fe3b00053a8, new_name=0x7fe3b0005778, create_info=0x7fe40ac83ed0, table_list=0x7fe3b0013490, alter_info=0x7fe40ac83e10, order_num=0, order=0x0, ignore=false) at sql/sql_table.cc:9676
 
#15 0x000055beb0eca299 in Sql_cmd_alter_table::execute (this=0x7fe3b0013be8, thd=0x7fe3b0000ce8) at sql/sql_alter.cc:493
 
#16 0x000055beb0d67385 in mysql_execute_command (thd=0x7fe3b0000ce8) at sql/sql_parse.cc:6345
 
#17 0x000055beb0d6c76a in mysql_parse (thd=0x7fe3b0000ce8, rawbuf=0x7fe3b0013340 "ALTER TABLE t4 MODIFY COLUMN col2 INT NOT NULL /* E_R Thread2 QNO 22 CON_ID 16 */", length=81, parser_state=0x7fe40ac851f0, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:8156
 
#18 0x000055beb0d57cc2 in dispatch_command (command=COM_QUERY, thd=0x7fe3b0000ce8, packet=0x7fe3b000b019 "ALTER TABLE t4 MODIFY COLUMN col2 INT NOT NULL /* E_R Thread2 QNO 22 CON_ID 16 */ ", packet_length=82, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:1841
 
#19 0x000055beb0d5660e in do_command (thd=0x7fe3b0000ce8) at sql/sql_parse.cc:1394
 
#20 0x000055beb0ec41d7 in do_handle_one_connection (connect=0x55beb4815788) at sql/sql_connect.cc:1398
 
#21 0x000055beb0ec3f45 in handle_one_connection (arg=0x55beb4815788) at sql/sql_connect.cc:1301
 
#22 0x000055beb17e9676 in pfs_spawn_thread (arg=0x55beb4872798) at storage/perfschema/pfs.cc:1862
 
#23 0x00007fe4168e47fc in start_thread (arg=0x7fe40ac86700) at pthread_create.c:465



 Comments   
Comment by Matthias Leich [ 2019-01-23 ]

prt2 – Protocol of my MTR test run
ts_15.tgz – Achive with the MTR test case.

How to reproduce the problem?
Please use a Linux because the test invokes a shellscript.
cd <source tree>/mysql-test
tar xvzf ts_15.tgz
./mysql-test-run.pl --mem ts_15

This is a plain brute force test (two users run a DDL/DML mix and one user observes).
You might need several runs of that test till you get the assert.
But at least I hit the assert with every run of the test.

Comment by Matthias Leich [ 2019-03-21 ] 

I hit the same bug during RQG grammar simplification (for other bugs) on actual 10.3.
 
 
 
10.3, origin/10.3 482710b20c28e2cdc598dc37468cc5dc06c53ac1 2019-03-21T10:14:57+02:00
 
# 2019-03-21T20:26:57 [274576] | Version: '10.3.14-MariaDB-debug-log'  socket:...
 
# 2019-03-21T20:26:57 [274576] | mysqld:  storage/innobase/row/row0log.cc:3060: dberr_t row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*): Assertion `0' failed.
 
...
 
# 2019-03-21T20:26:57 [274576] | stack_bottom = 0x7fc525a70ec0 thread_stack 0x49000
 
# 2019-03-21T20:26:57 [274576] | /work/10.3/bld_debug/sql/mysqld(my_print_stacktrace+0x40)[0x55f241525f01]
 
# 2019-03-21T20:26:57 [274576] | mysys/stacktrace.c:269(my_print_stacktrace)[0x55f240d72936]
 
# 2019-03-21T20:26:57 [274576] | /lib/x86_64-linux-gnu/libpthread.so.0(+0x11670)[0x7fc53bdaa670]
 
# 2019-03-21T20:26:57 [274576] | linux/raise.c:58(__GI_raise)[0x7fc53b15f77f]
 
# 2019-03-21T20:26:57 [274576] | stdlib/abort.c:91(__GI_abort)[0x7fc53b16137a]
 
# 2019-03-21T20:26:57 [274576] | assert/assert.c:92(__assert_fail_base)[0x7fc53b157b47]
 
# 2019-03-21T20:26:57 [274576] | /lib/x86_64-linux-gnu/libc.so.6(+0x2dbf2)[0x7fc53b157bf2]
 
# 2019-03-21T20:26:57 [274576] | /work/10.3/bld_debug/sql/mysqld(+0xd3e2ce)[0x55f2410fe2ce]
 
# 2019-03-21T20:26:57 [274576] | row/row0log.cc:3064(row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*))[0x55f2410fe68f]
 
# 2019-03-21T20:26:57 [274576] | row/row0log.cc:3134(row_log_table_apply(que_thr_t*, dict_table_t*, TABLE*, ut_stage_alter_t*, dict_table_t*))[0x55f240fc8ba6]
 
# 2019-03-21T20:26:57 [274576] | handler/handler0alter.cc:7257(ha_innobase::inplace_alter_table(TABLE*, Alter_inplace_info*))[0x55f240b60079]
 
# 2019-03-21T20:26:57 [274576] | sql/handler.h:4193(handler::ha_inplace_alter_table(TABLE*, Alter_inplace_info*))[0x55f240b55820]
 
# 2019-03-21T20:26:57 [274576] | sql/sql_table.cc:9756(mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool))[0x55f240b5bba8]
 
# 2019-03-21T20:26:57 [274576] | sql/sql_alter.cc:488(Sql_cmd_alter_table::execute(THD*))[0x55f240be3539]
 
# 2019-03-21T20:26:57 [274576] | sql/sql_parse.cc:6284(mysql_execute_command(THD*))[0x55f240a85485]
 
# 2019-03-21T20:26:57 [274576] | sql/sql_parse.cc:8091(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x55f240a8a7ad]
 
# 2019-03-21T20:26:57 [274576] | sql/sql_parse.cc:1859(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x55f240a777d8]
 
# 2019-03-21T20:26:57 [274576] | sql/sql_parse.cc:1402(do_command(THD*))[0x55f240a761fd]
 
# 2019-03-21T20:26:57 [274576] | sql/sql_connect.cc:1402(do_handle_one_connection(CONNECT*))[0x55f240bddafd]
 
# 2019-03-21T20:26:57 [274576] | sql/sql_connect.cc:1309(handle_one_connection)[0x55f240bdd874]
 
# 2019-03-21T20:26:57 [274576] | nptl/pthread_create.c:456(start_thread)[0x7fc53bda06da]
 
# 2019-03-21T20:26:57 [274576] | x86_64/clone.S:107(clone)[0x7fc53b232d7f]
 
...
 
# 2019-03-21T20:26:57 [274576] | Query (0x7fc4a4014b30): ALTER TABLE t2 ADD PRIMARY KEY IF NOT EXISTS ( col_int, col1 ), ALGORITHM = DEFAULT  /* E_R Thread2 QNO 589 CON_ID 40 */
 
# 2019-03-21T20:26:57 [274576] | Connection ID (thread ID): 40
 
# 2019-03-21T20:26:57 [274576] | Status: NOT_KILLED
 
 
 
No core file available.

Comment by Alice Sherepa [ 2022-01-21 ]

still reproducible. on bb-10.8-MDEV-11675 (based on the latest 10.8 a855d6d93acf0af)

mysqld: /10.8/storage/innobase/row/row0log.cc:2471: 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.
 
220120 12:03:18 [ERROR] mysqld got signal 6 ;
 
 
 
Server version: 10.8.0-MariaDB-debug-log
 
 
 
linux/raise.c:51(__GI_raise)[0x7f92b9a247bb]
 
stdlib/abort.c:81(__GI_abort)[0x7f92b9a0f535]
 
??:0(__assert_fail)[0x7f92b9a1d102]
 
row/row0log.cc:2472(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 short*))[0x55eb825fdd10]
 
row/row0log.cc:3066(row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*))[0x55eb82603ce7]
 
row/row0log.cc:3174(row_log_table_apply(que_thr_t*, dict_table_t*, TABLE*, ut_stage_alter_t*, dict_table_t*))[0x55eb82604aeb]
 
handler/handler0alter.cc:8485(ha_innobase::inplace_alter_table(TABLE*, Alter_inplace_info*))[0x55eb822dddbd]
 
sql/handler.h:4630(handler::ha_inplace_alter_table(TABLE*, Alter_inplace_info*))[0x55eb81230674]
 
sql/sql_table.cc:7631(mysql_inplace_alter_table(THD*, TABLE_LIST*, TABLE*, TABLE*, Alter_inplace_info*, MDL_request*, st_ddl_log_state*, TRIGGER_RENAME_PARAM*, Alter_table_ctx*, bool&, unsigned long long&, bool))[0x55eb8120c1c8]
 
sql/sql_table.cc:10629(mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool, bool))[0x55eb81222349]
 
sql/sql_table.cc:11725(mysql_recreate_table(THD*, TABLE_LIST*, bool))[0x55eb8122b688]
 
sql/sql_admin.cc:67(admin_recreate_table(THD*, TABLE_LIST*))[0x55eb813ef572]
 
sql/sql_admin.cc:1185(mysql_admin_table(THD*, TABLE_LIST*, st_ha_check_opt*, st_mysql_const_lex_string const*, thr_lock_type, bool, bool, unsigned int, int (*)(THD*, TABLE_LIST*, st_ha_check_opt*), int (handler::*)(THD*, st_ha_check_opt*), int (*)(THD*, TABLE_LIST*, st_ha_check_opt*), bool))[0x55eb813f728f]
 
sql/sql_admin.cc:1566(Sql_cmd_optimize_table::execute(THD*))[0x55eb813fa41e]
 
sql/sql_parse.cc:5989(mysql_execute_command(THD*, bool))[0x55eb80f4c70a]
 
sql/sql_parse.cc:8028(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x55eb80f59a4a]
 
sql/sql_parse.cc:1896(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool))[0x55eb80f301a1]
 
sql/sql_parse.cc:1402(do_command(THD*, bool))[0x55eb80f2ce96]
 
sql/sql_connect.cc:1418(do_handle_one_connection(CONNECT*, bool))[0x55eb813babc8]
 
sql/sql_connect.cc:1314(handle_one_connection)[0x55eb813ba44d]
 
perfschema/pfs.cc:2203(pfs_spawn_thread)[0x55eb82027ba0]
 
nptl/pthread_create.c:487(start_thread)[0x7f92b9edbfa3]
 
x86_64/clone.S:97(clone)[0x7f92b9ae64cf]
 
 
 
Query (0x6290006f92a8): OPTIMIZE  TABLE `alt_t8`

Comment by Marko Mäkelä [ 2023-09-19 ]

I see that the test in ts_15.tgz creates a ROW_FORMAT=REDUNDANT table. I was not able to reproduce the bug on the current 10.5 6c05edfdcd335b9587ba140ebef5d9b082cc9810. Next, I will see if reverting MDEV-31025 and MDEV-28706 might bring the crash back.

Comment by Marko Mäkelä [ 2023-09-19 ]

I can’t repeat this on the latest 10.5 even after the following:

git revert --no-commit 2bfd04e3145b238df5f31143b98b1df501f43d1e
 
git revert --no-commit e34f8781397ed451a84c1a3fdc5766c5b1e28d41

The 10.8 commit that alice mentioned does not include either fix.

Comment by Matthias Leich [ 2024-01-24 ]

The MTR based replay test does no more replay.

The corresponding assertion was replayed with RQG last time on
origin/10.5 d3f35aa47bc3ee0c9b2798555f9a79057895809a 2023-02-16T10:16:38+02:00

Hence I assume that the problem is fixed.

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