[MDEV-34204] Assertion `!*detailed_error' failed in void trx_t::assert_freed() const - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.5, 10.6, 10.11, 11.0(EOL), 11.1(EOL), 11.2(EOL), 11.3(EOL), 11.4, 11.5(EOL)
Fix Version/s: 10.5.26, 10.6.19, 10.11.9, 11.1.6, 11.2.5, 11.4.3
Component/s: Storage Engine - InnoDB, XA
Labels:
- debug
- foreign-keys

Description

11.4.2 b86a2f03b6a9a0b5e222fb2f52b07c85c491479e (Debug)
mariadbd: /test/11.4_dbg/storage/innobase/include/trx0trx.h:1108: void trx_t::assert_freed() const: Assertion `!*detailed_error' failed.

11.4.2 b86a2f03b6a9a0b5e222fb2f52b07c85c491479e (Debug)
Core was generated by `/test/MD140524-mariadb-11.4.2-linux-x86_64-dbg/bin/mariadbd --no-defaults --max'.
Program terminated with signal SIGABRT, Aborted.
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
[Current thread is 1 (Thread 0x1508953ec980 (LWP 1415389))]
(gdb) bt
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x00001508955c5859 in __GI_abort () at abort.c:79
#2 0x00001508955c5729 in __assert_fail_base (fmt=0x15089575b588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55f6e8bfee0d "!*detailed_error", file=0x55f6e8baa698 "/test/11.4_dbg/storage/innobase/include/trx0trx.h", line=1108, function=<optimized out>) at assert.c:92
#3 0x00001508955d6fd6 in __GI___assert_fail (assertion=assertion@entry=0x55f6e8bfee0d "!*detailed_error", file=file@entry=0x55f6e8baa698 "/test/11.4_dbg/storage/innobase/include/trx0trx.h", line=line@entry=1108, function=function@entry=0x55f6e8bfed60 "void trx_t::assert_freed() const") at assert.c:101
#4 0x000055f6e856bf63 in trx_t::assert_freed (this=this@entry=0x15088c377b80) at /test/11.4_dbg/storage/innobase/include/trx0trx.h:1108
#5 0x000055f6e856852e in trx_t::free (this=this@entry=0x15088c377b80) at /test/11.4_dbg/storage/innobase/trx/trx0trx.cc:390
#6 0x000055f6e856930c in trx_free_at_shutdown (trx=trx@entry=0x15088c377b80) at /test/11.4_dbg/storage/innobase/trx/trx0trx.cc:541
#7 0x000055f6e85604c3 in rw_trx_hash_t::rw_trx_hash_shutdown_destructor (arg=<optimized out>) at /test/11.4_dbg/storage/innobase/include/trx0sys.h:422
#8 0x000055f6e8779fd2 in lf_hash_destroy (hash=hash@entry=0x55f6e931c980 <trx_sys+49536>) at /test/11.4_dbg/mysys/lf_hash.cc:388
#9 0x000055f6e855fe3d in rw_trx_hash_t::destroy (this=0x55f6e931c980 <trx_sys+49536>) at /test/11.4_dbg/storage/innobase/include/trx0sys.h:547
#10 trx_sys_t::close (this=0x55f6e9310800 <trx_sys>) at /test/11.4_dbg/storage/innobase/trx/trx0sys.cc:322
#11 0x000055f6e852be51 in innodb_shutdown () at /test/11.4_dbg/storage/innobase/srv/srv0start.cc:2075
#12 0x000055f6e8329b14 in innobase_end () at /test/11.4_dbg/storage/innobase/handler/ha_innodb.cc:4243
#13 0x000055f6e7fbc2b9 in ha_finalize_handlerton (plugin=0x55f6eb69a420) at /test/11.4_dbg/sql/handler.cc:596
#14 0x000055f6e7cb0a7d in plugin_deinitialize (plugin=0x55f6eb69a420, ref_check=ref_check@entry=true) at /test/11.4_dbg/sql/sql_plugin.cc:1270
#15 0x000055f6e7cb2f30 in reap_plugins () at /test/11.4_dbg/sql/sql_plugin.cc:1344
#16 0x000055f6e7cb45ea in plugin_shutdown () at /test/11.4_dbg/sql/sql_plugin.cc:2099
#17 0x000055f6e7b59a1e in clean_up (print_message=print_message@entry=true) at /test/11.4_dbg/sql/mysqld.cc:1999
#18 0x000055f6e7b670dd in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /test/11.4_dbg/sql/mysqld.cc:5996
#19 0x000055f6e7b57bf6 in main (argc=<optimized out>, argv=<optimized out>) at /test/11.4_dbg/sql/main.cc:34

Attachments

Activity

Descending order - Click to sort in ascending order

Marko Mäkelä added a comment - 2024-05-21 06:10 - edited

Here is some information from an rr replay trace. The detailed_error was set in a transaction on which XA PREPARE was executed right before the server was shut down and the assertion failed:

10.5 1e5b0ff9778b16801d5afa08b6433070948f0910
#3 0x0000563a4047e7bb in fread (__stream=0x563a43c123f0, __n=255, __size=1, __ptr=0x563a43bf1dc8) at /usr/include/x86_64-linux-gnu/bits/stdio2.h:297
#4 os_file_read_string (file=0x563a43c123f0, str=0x563a43bf1dc8 "", size=size@entry=256) at /test/10.5_dbg/storage/innobase/os/os0file.cc:399
#5 0x0000563a40600fc1 in trx_set_detailed_error_from_file (trx=trx@entry=0x6c663bd251c0, file=<optimized out>) at /test/10.5_dbg/storage/innobase/trx/trx0trx.cc:99
#6 0x0000563a4050f272 in row_ins_set_detailed (trx=trx@entry=0x6c663bd251c0, foreign=foreign@entry=0x66517c023448) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:684
#7 0x0000563a4050ffd3 in row_ins_foreign_report_add_err (trx=trx@entry=0x6c663bd251c0, foreign=foreign@entry=0x66517c023448, rec=0x6651705b8070 "supremum", entry=entry@entry=0x66517c020b28)
at /test/10.5_dbg/storage/innobase/row/row0ins.cc:807
#8 0x0000563a40513868 in row_ins_check_foreign_constraint (check_ref=check_ref@entry=1, foreign=foreign@entry=0x66517c023448, table=table@entry=0x66517c022468, entry=entry@entry=0x66517c020b28,
thr=thr@entry=0x66517c077450) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:1807
#9 0x0000563a40514507 in row_ins_check_foreign_constraints (table=0x66517c022468, index=index@entry=0x66517c023b78, pk=pk@entry=true, entry=entry@entry=0x66517c020b28, thr=thr@entry=0x66517c077450)
at /test/10.5_dbg/storage/innobase/row/row0ins.cc:1981
#10 0x0000563a40514979 in row_ins_clust_index_entry (index=index@entry=0x66517c023b78, entry=entry@entry=0x66517c020b28, thr=thr@entry=0x66517c077450, n_ext=n_ext@entry=0)
at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3234
#11 0x0000563a40516c00 in row_ins_index_entry (thr=0x66517c077450, entry=0x66517c020b28, index=0x66517c023b78) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3404
#12 row_ins_index_entry_step (thr=0x66517c077450, node=<optimized out>) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3572
#13 row_ins (thr=0x66517c077450, node=<optimized out>) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3709
#14 row_ins_step (thr=thr@entry=0x66517c077450) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3852
#15 0x0000563a4053af22 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x66517c0760e8 "\377\001", prebuilt=0x66517c076d38, ins_mode=ROW_INS_NORMAL) at /test/10.5_dbg/storage/innobase/row/row0mysql.cc:1394
#16 0x0000563a403a5037 in ha_innobase::write_row (this=0x66517c0764e0, record=0x66517c0760e8 "\377\001") at /test/10.5_dbg/storage/innobase/handler/ha_innodb.cc:7709
#17 0x0000563a3fffa503 in handler::ha_write_row (this=0x66517c0764e0, buf=0x66517c0760e8 "\377\001") at /test/10.5_dbg/sql/handler.cc:7348
#18 0x0000563a3fcd6ce0 in write_record (thd=thd@entry=0x66517c000d48, table=table@entry=0x66517c075cb8, info=info@entry=0x5c7a60e5bba0, sink=sink@entry=0x0) at /test/10.5_dbg/sql/sql_insert.cc:2197
#19 0x0000563a3fce21e9 in mysql_insert (thd=thd@entry=0x66517c000d48, table_list=<optimized out>, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0)
at /test/10.5_dbg/sql/sql_insert.cc:1127
#20 0x0000563a3fd25727 in mysql_execute_command (thd=thd@entry=0x66517c000d48) at /test/10.5_dbg/sql/sql_parse.cc:4650
#21 0x0000563a3fd1052a in mysql_parse (thd=thd@entry=0x66517c000d48, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x5c7a60e5c2c0, is_com_multi=is_com_multi@entry=false,
is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:8203
#22 0x0000563a3fd1ece7 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x66517c000d48, packet=packet@entry=0x66517c00aa19 "INSERT INTO t2 VALUES (1)", packet_length=packet_length@entry=25,
is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_class.h:1328

Based on this, I guessed the following test case:

--source include/have_innodb.inc

create table t0(a int primary key) engine=innodb;

create table t1(a int primary key references t0(a)) engine=innodb;

xa start 'a';

insert into t0 set a=0;

--error ER_NO_REFERENCED_ROW_2

insert into t1 set a=1;

xa end 'a';

xa prepare 'a';

--source include/restart_mysqld.inc

xa commit 'a';

drop table t1, t0;

This will reproduce the problem:

10.11 f01e6503f4151a8d3d3f0495dab22c47ec794e67
mariadbd: /mariadb/10.11/storage/innobase/include/trx0trx.h:1110: void trx_t::assert_freed() const: Assertion `!*detailed_error' failed.
Attempting backtrace. You can use the following information to find out
2024-05-21 9:02:31 0 [Warning] Found 1 prepared XA transactions
^ Found warnings in /dev/shm/10.11/mysql-test/var/log/mysqld.1.err

If I move the xa commit (or xa rollback; it does not matter which one we use) before the server restart, there will be no crash. Therefore, it would seem that we simply need to work around this assertion when freeing prepared transactions during shutdown:

diff --git a/storage/innobase/trx/trx0trx.cc b/storage/innobase/trx/trx0trx.cc

index 606416e677e..7f1f26547dc 100644

--- a/storage/innobase/trx/trx0trx.cc

+++ b/storage/innobase/trx/trx0trx.cc

@@ -554,6 +554,7 @@ trx_free_at_shutdown(trx_t *trx)

 	trx->state = TRX_STATE_NOT_STARTED;

 	ut_ad(!UT_LIST_GET_LEN(trx->lock.trx_locks));

 	trx->id = 0;

+	ut_d(*trx->detailed_error = '\0');

 	trx->free();

In trx_t::commit_in_memory(), which would be invoked by xa commit or xa rollback, we already clear this field.

Marko Mäkelä added a comment - 2024-05-21 06:10 - edited Here is some information from an rr replay trace. The detailed_error was set in a transaction on which XA PREPARE was executed right before the server was shut down and the assertion failed: 10.5 1e5b0ff9778b16801d5afa08b6433070948f0910 #3 0x0000563a4047e7bb in fread (__stream=0x563a43c123f0, __n=255, __size=1, __ptr=0x563a43bf1dc8) at /usr/include/x86_64-linux-gnu/bits/stdio2.h:297 #4 os_file_read_string (file=0x563a43c123f0, str=0x563a43bf1dc8 "", size=size@entry=256) at /test/10.5_dbg/storage/innobase/os/os0file.cc:399 #5 0x0000563a40600fc1 in trx_set_detailed_error_from_file (trx=trx@entry=0x6c663bd251c0, file=<optimized out>) at /test/10.5_dbg/storage/innobase/trx/trx0trx.cc:99 #6 0x0000563a4050f272 in row_ins_set_detailed (trx=trx@entry=0x6c663bd251c0, foreign=foreign@entry=0x66517c023448) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:684 #7 0x0000563a4050ffd3 in row_ins_foreign_report_add_err (trx=trx@entry=0x6c663bd251c0, foreign=foreign@entry=0x66517c023448, rec=0x6651705b8070 "supremum", entry=entry@entry=0x66517c020b28) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:807 #8 0x0000563a40513868 in row_ins_check_foreign_constraint (check_ref=check_ref@entry=1, foreign=foreign@entry=0x66517c023448, table=table@entry=0x66517c022468, entry=entry@entry=0x66517c020b28, thr=thr@entry=0x66517c077450) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:1807 #9 0x0000563a40514507 in row_ins_check_foreign_constraints (table=0x66517c022468, index=index@entry=0x66517c023b78, pk=pk@entry=true, entry=entry@entry=0x66517c020b28, thr=thr@entry=0x66517c077450) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:1981 #10 0x0000563a40514979 in row_ins_clust_index_entry (index=index@entry=0x66517c023b78, entry=entry@entry=0x66517c020b28, thr=thr@entry=0x66517c077450, n_ext=n_ext@entry=0) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3234 #11 0x0000563a40516c00 in row_ins_index_entry (thr=0x66517c077450, entry=0x66517c020b28, index=0x66517c023b78) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3404 #12 row_ins_index_entry_step (thr=0x66517c077450, node=<optimized out>) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3572 #13 row_ins (thr=0x66517c077450, node=<optimized out>) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3709 #14 row_ins_step (thr=thr@entry=0x66517c077450) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3852 #15 0x0000563a4053af22 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x66517c0760e8 "\377\001", prebuilt=0x66517c076d38, ins_mode=ROW_INS_NORMAL) at /test/10.5_dbg/storage/innobase/row/row0mysql.cc:1394 #16 0x0000563a403a5037 in ha_innobase::write_row (this=0x66517c0764e0, record=0x66517c0760e8 "\377\001") at /test/10.5_dbg/storage/innobase/handler/ha_innodb.cc:7709 #17 0x0000563a3fffa503 in handler::ha_write_row (this=0x66517c0764e0, buf=0x66517c0760e8 "\377\001") at /test/10.5_dbg/sql/handler.cc:7348 #18 0x0000563a3fcd6ce0 in write_record (thd=thd@entry=0x66517c000d48, table=table@entry=0x66517c075cb8, info=info@entry=0x5c7a60e5bba0, sink=sink@entry=0x0) at /test/10.5_dbg/sql/sql_insert.cc:2197 #19 0x0000563a3fce21e9 in mysql_insert (thd=thd@entry=0x66517c000d48, table_list=<optimized out>, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0) at /test/10.5_dbg/sql/sql_insert.cc:1127 #20 0x0000563a3fd25727 in mysql_execute_command (thd=thd@entry=0x66517c000d48) at /test/10.5_dbg/sql/sql_parse.cc:4650 #21 0x0000563a3fd1052a in mysql_parse (thd=thd@entry=0x66517c000d48, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x5c7a60e5c2c0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:8203 #22 0x0000563a3fd1ece7 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x66517c000d48, packet=packet@entry=0x66517c00aa19 "INSERT INTO t2 VALUES (1)", packet_length=packet_length@entry=25, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_class.h:1328 Based on this, I guessed the following test case: --source include/have_innodb.inc create table t0(a int primary key ) engine=innodb; create table t1(a int primary key references t0(a)) engine=innodb; xa start 'a' ; insert into t0 set a=0; --error ER_NO_REFERENCED_ROW_2 insert into t1 set a=1; xa end 'a' ; xa prepare 'a' ; --source include/restart_mysqld.inc xa commit 'a' ; drop table t1, t0; This will reproduce the problem: 10.11 f01e6503f4151a8d3d3f0495dab22c47ec794e67 mariadbd: /mariadb/10.11/storage/innobase/include/trx0trx.h:1110: void trx_t::assert_freed() const: Assertion `!*detailed_error' failed. Attempting backtrace. You can use the following information to find out 2024-05-21 9:02:31 0 [Warning] Found 1 prepared XA transactions ^ Found warnings in /dev/shm/10.11/mysql-test/var/log/mysqld.1.err If I move the xa commit (or xa rollback ; it does not matter which one we use) before the server restart, there will be no crash. Therefore, it would seem that we simply need to work around this assertion when freeing prepared transactions during shutdown: diff --git a/storage/innobase/trx/trx0trx.cc b/storage/innobase/trx/trx0trx.cc index 606416e677e..7f1f26547dc 100644 --- a/storage/innobase/trx/trx0trx.cc +++ b/storage/innobase/trx/trx0trx.cc @@ -554,6 +554,7 @@ trx_free_at_shutdown(trx_t *trx) trx->state = TRX_STATE_NOT_STARTED; ut_ad(!UT_LIST_GET_LEN(trx->lock.trx_locks)); trx->id = 0; + ut_d(*trx->detailed_error = '\0'); trx->free(); } In trx_t::commit_in_memory() , which would be invoked by xa commit or xa rollback , we already clear this field.

Ramesh Sivaraman added a comment - 2024-05-21 05:54

As discussed `rr` trace is saved on galapq server /test/MD130524-mariadb-10.5.25-linux-x86_64-dbg/rr/

Ramesh Sivaraman added a comment - 2024-05-21 05:54 As discussed `rr` trace is saved on galapq server /test/MD130524-mariadb-10.5.25-linux-x86_64-dbg/rr/

Marko Mäkelä added a comment - 2024-05-21 04:58

Can you provide any more details, such as the detailed_error string? The purpose of trx_t::assert_freed() is to catch cases where some data members of an object have not been cleared. We have a special allocator for trx_t objects in order to minimize overhead.

Marko Mäkelä added a comment - 2024-05-21 04:58 Can you provide any more details, such as the detailed_error string? The purpose of trx_t::assert_freed() is to catch cases where some data members of an object have not been cleared. We have a special allocator for trx_t objects in order to minimize overhead.

MariaDB Server

Assertion `!*detailed_error' failed in void trx_t::assert_freed() const

Details

Description

Attachments

Activity

People

Dates

Git Integration