[MDEV-22848] Assertion `trx_is_registered_for_2pc(trx)' failed in innobase_xa_prepare on DROP and in innobase_savepoint on SAVEPOINT Created: 2020-06-09  Updated: 2023-11-28

Status: Confirmed
Project: MariaDB Server
Component/s: Replication, Storage Engine - InnoDB, Storage Engine - MyISAM
Affects Version/s: 10.1, 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10, 10.11, 11.0, 11.1, 11.2, 11.3
Fix Version/s: 10.4, 10.5, 10.6, 10.11, 11.0, 11.1, 11.2

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Andrei Elkin
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-463 Statistics: Failing assertion: trx_is... Closed

 Description    

# mysqld options required for replay: --log-bin
 
USE test;
 
SET autocommit=0;
 
CREATE TABLE t1 (c INT) ENGINE=MyISAM;
 
SET GLOBAL gtid_slave_pos="0-1-100";
 
INSERT INTO t1 VALUES (0);
 
DROP TABLE not_there;

Leads to:

10.5.4 6877ef9a7c9c7ee55d67e4baaf4e8f7b874c9f89

 
mysqld: /test/10.5_dbg/storage/innobase/handler/ha_innodb.cc:17193: int innobase_xa_prepare(handlerton*, THD*, bool): Assertion `trx_is_registered_for_2pc(trx)' failed.

10.5.4 6877ef9a7c9c7ee55d67e4baaf4e8f7b874c9f89

 
Core was generated by `/test/MD060620-mariadb-10.5.4-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
[Current thread is 1 (Thread 0x150ebf84a700 (LWP 3929910))]
 
(gdb) bt
 
(gdb) (gdb) #0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x000055dcba18200d in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
 
#2  0x000055dcb992bbbc in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x0000150ec0508801 in __GI_abort () at abort.c:79
 
#6  0x0000150ec04f839a in __assert_fail_base (fmt=0x150ec067f7d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55dcba56b3b8 "trx_is_registered_for_2pc(trx)", file=file@entry=0x55dcba56a668 "/test/10.5_dbg/storage/innobase/handler/ha_innodb.cc", line=line@entry=17193, function=function@entry=0x55dcba5665c0 <innobase_xa_prepare(handlerton*, THD*, bool)::__PRETTY_FUNCTION__> "int innobase_xa_prepare(handlerton*, THD*, bool)") at assert.c:92
 
#7  0x0000150ec04f8412 in __GI___assert_fail (assertion=assertion@entry=0x55dcba56b3b8 "trx_is_registered_for_2pc(trx)", file=file@entry=0x55dcba56a668 "/test/10.5_dbg/storage/innobase/handler/ha_innodb.cc", line=line@entry=17193, function=function@entry=0x55dcba5665c0 <innobase_xa_prepare(handlerton*, THD*, bool)::__PRETTY_FUNCTION__> "int innobase_xa_prepare(handlerton*, THD*, bool)") at assert.c:101
 
#8  0x000055dcb9ce1ac1 in innobase_xa_prepare (hton=0x150ebf043088, thd=0x150e9e815088, prepare_trx=<optimized out>) at /test/10.5_dbg/storage/innobase/handler/ha_innodb.cc:17193
 
#9  0x000055dcb99435b8 in prepare_or_error (ht=ht@entry=0x150ebf043088, thd=thd@entry=0x150e9e815088, all=all@entry=true) at /test/10.5_dbg/sql/handler.cc:1304
 
#10 0x000055dcb9944f33 in ha_commit_trans (thd=thd@entry=0x150e9e815088, all=all@entry=true) at /test/10.5_dbg/sql/handler.cc:1682
 
#11 0x000055dcb97e9b08 in trans_commit_implicit (thd=thd@entry=0x150e9e815088) at /test/10.5_dbg/sql/transaction.cc:319
 
#12 0x000055dcb9680de5 in mysql_execute_command (thd=thd@entry=0x150e9e815088) at /test/10.5_dbg/sql/sql_parse.cc:3749
 
#13 0x000055dcb968e322 in mysql_parse (thd=thd@entry=0x150e9e815088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x150ebf849350, 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:7992
 
#14 0x000055dcb967ae1c in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x150e9e815088, packet=packet@entry=0x150e9e867089 "DROP TABLE not_there", packet_length=packet_length@entry=20, 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:1874
 
#15 0x000055dcb96795f6 in do_command (thd=0x150e9e815088) at /test/10.5_dbg/sql/sql_parse.cc:1355
 
#16 0x000055dcb97d49f9 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x150ea1920aa8, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1411
 
#17 0x000055dcb97d5115 in handle_one_connection (arg=arg@entry=0x150ea1920aa8) at /test/10.5_dbg/sql/sql_connect.cc:1313
 
#18 0x000055dcb9c34104 in pfs_spawn_thread (arg=0x150ebf045b08) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
 
#19 0x0000150ec11eb6db in start_thread (arg=0x150ebf84a700) at pthread_create.c:463
 
#20 0x0000150ec05e988f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.1.46 (dbg), 10.2.33 (dbg), 10.3.24 (dbg), 10.4.14 (dbg), 10.5.4 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.46 (opt), 10.2.33 (opt), 10.3.24 (opt), 10.4.14 (opt), 10.5.4 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)

 Comments   
Comment by Marko Mäkelä [ 2020-06-10 ]

I believe that InnoDB is merely reporting an incorrect invocation on innobase_xa_prepare(). Because there is no XA statement from the SQL layer, that invocation must be due to some binlog-internal XA transaction that aims to keep the binlog in sync with the storage engine logs.

Comment by Andrei Elkin [ 2020-06-10 ]

Looks like an implicit insert statement by SET GLOBAL gtid_slave_pos="0-1-100"; does not follow
the commit protocol, specifically does not register the trx it starts for 2pc. When it's that simple I'll try to fix it soon.

Comment by Roel Van de Paar [ 2021-01-29 ]

Same assert, different stack. Also see MDEV-23073 which has a somewhat similar stack.

SET autocommit=0;
 
SET GLOBAL gtid_slave_pos= "0-1-50";
 
SAVEPOINT a;

Leads to:

10.6.0 3f871b339429441ad907ecf7dfabdc414797e664 (Debug)

 
mysqld: /data/builds/10.6_dbg/storage/innobase/handler/ha_innodb.cc:4390: int innobase_savepoint(handlerton*, THD*, void
 
*): Assertion `trx_is_registered_for_2pc(trx)' failed.

10.6.0 3f871b339429441ad907ecf7dfabdc414797e664 (Debug)

 
Core was generated by `/test/MD260121-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
[Current thread is 1 (Thread 0x152478757700 (LWP 2005155))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
#1  0x000055622fa67210 in my_write_core (sig=sig@entry=6) at /data/builds/10.6_dbg/mysys/stacktrace.c:424
 
#2  0x000055622f1fc2d0 in handle_fatal_signal (sig=6) at /data/builds/10.6_dbg/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#5  0x000015247b315859 in __GI_abort () at abort.c:79
 
#6  0x000015247b315729 in __assert_fail_base (fmt=0x15247b4ab588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55622fe13a48 "trx_is_registered_for_2pc(trx)", file=0x55622fe11dc8 "/data/builds/10.6_dbg/storage/innobase/handler/ha_innodb.cc", line=4390, function=<optimized out>) at assert.c:92
 
#7  0x000015247b326f36 in __GI___assert_fail (assertion=assertion@entry=0x55622fe13a48 "trx_is_registered_for_2pc(trx)", file=file@entry=0x55622fe11dc8 "/data/builds/10.6_dbg/storage/innobase/handler/ha_innodb.cc", line=line@entry=4390, function=function@entry=0x55622fe13a10 "int innobase_savepoint(handlerton*, THD*, void*)") at assert.c:101
 
#8  0x000055622f5ed643 in innobase_savepoint (hton=<optimized out>, thd=0x152428000db8, savepoint=0x1524280187a8) at /data/builds/10.6_dbg/storage/innobase/handler/ha_innodb.cc:4390
 
#9  0x000055622f202c32 in ha_savepoint (thd=thd@entry=0x152428000db8, sv=sv@entry=0x152428018770) at /data/builds/10.6_dbg/sql/handler.cc:2586
 
#10 0x000055622f0a7860 in trans_savepoint (thd=thd@entry=0x152428000db8, name=<optimized out>) at /data/builds/10.6_dbg/sql/transaction.cc:617
 
#11 0x000055622ef3c8b0 in mysql_execute_command (thd=thd@entry=0x152428000db8) at /data/builds/10.6_dbg/sql/sql_parse.cc:5577
 
#12 0x000055622ef2415e in mysql_parse (thd=thd@entry=0x152428000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1524787563d0) at /data/builds/10.6_dbg/sql/sql_parse.cc:7901
 
#13 0x000055622ef3224f in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x152428000db8, packet=packet@entry=0x15242801aac9 "SAVEPOINT a", packet_length=packet_length@entry=11) at /data/builds/10.6_dbg/sql/sql_class.h:1294
 
#14 0x000055622ef35581 in do_command (thd=0x152428000db8) at /data/builds/10.6_dbg/sql/sql_parse.cc:1365
 
#15 0x000055622f091079 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5562317758f8, put_in_cache=put_in_cache@entry=true) at /data/builds/10.6_dbg/sql/sql_connect.cc:1410
 
#16 0x000055622f09177d in handle_one_connection (arg=arg@entry=0x5562317758f8) at /data/builds/10.6_dbg/sql/sql_connect.cc:1312
 
#17 0x000055622f54443f in pfs_spawn_thread (arg=0x5562316aa138) at /data/builds/10.6_dbg/storage/perfschema/pfs.cc:2201
 
#18 0x000015247b823609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#19 0x000015247b412293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.2.37 (dbg), 10.3.28 (dbg), 10.4.18 (dbg), 10.5.9 (dbg), 10.6.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.37 (opt), 10.3.28 (opt), 10.4.18 (opt), 10.5.9 (opt), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.33 (dbg), 5.7.33 (opt), 8.0.23 (dbg), 8.0.23 (opt)

Comment by Elena Stepanova [ 2022-12-13 ]

Same failure without gtid_slave_pos failure tampering:

--source include/have_innodb.inc
 
--source include/have_log_bin.inc
 
 
 
CREATE SEQUENCE s ENGINE=MyISAM;
 
CREATE TEMPORARY TABLE tmp (a int) ENGINE=InnoDB;
 
CREATE OR REPLACE TEMPORARY TABLE tmp ENGINE=InnoDB AS SELECT NEXTVAL(s);
 
 
 
# Cleanup
 
DROP SEQUENCE s;

On a non-debug build, an error is produced:

10.3 602124bb

 
2022-12-13 17:20:09 10 [ERROR] Transaction not registered for MariaDB 2PC, but transaction is active

Comment by Roel Van de Paar [ 2023-11-01 ]

Additional testcase:

# mysqld options required for replay: --log-bin
 
CREATE TABLE t1 (id INT KEY) ENGINE=MyISAM;
 
SET GLOBAL gtid_slave_pos='100-100-100';
 
INSERT INTO t1 VALUES(1);
 
ALTER TABLE t4 CHANGE c1 c1 SMALLINT UNSIGNED ;


trx_is_registered_for_2pc(trx)|SIGABRT|innobase_xa_prepare|prepare_or_error|ha_commit_trans|trans_commit_implicit

Generated at Thu Feb 08 09:17:56 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.