[MDEV-32857] Assertion `thd->lex->sql_command == SQLCOM_XA_COMMIT || thd->lex->sql_command == SQLCOM_XA_ROLLBACK' failed in TC_LOG::run_commit_ordered Created: 2023-11-22  Updated: 2024-01-08  Resolved: 2023-11-22

Status: Closed
Project: MariaDB Server
Component/s: Binary Protocol, XA
Affects Version/s: N/A
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Roel Van de Paar Assignee: Andrei Elkin
Resolution: Fixed Votes: 0
Labels: regression

Issue Links:
Blocks
blocks MDEV-31949 slow parallel replication of user xa In Review
blocks MDEV-32830 refactor XA binlogging for better int... In Review
Problem/Incident
is caused by MDEV-32830 refactor XA binlogging for better int... In Review
Relates

 Description   

Fails in bb-10.6-andrei at commit 0d728f33b6ae806a48d995738718e2c34ee94f1e (MDEV-32830 patch, latest iteration), but not at the commit prior to that (i.e. pre-MDEV-32830). It also crashes the earlier same-branch revision 88b0738b7c61a25eaffc66dda0a5a7f850c89918.

--source include/have_innodb.inc
 
--source include/have_binlog_format_mixed.inc
 
CREATE TABLE t (c INT) ENGINE=InnoDB;
 
XA START 'a';
 
INSERT INTO t VALUES (1);
 
CREATE TEMPORARY TABLE t (d INT) ENGINE=InnoDB;
 
XA END 'a';
 
LOAD INDEX INTO CACHE t INDEX (PRIMARY) IGNORE LEAVES;

Leads to:

10.6.17 0d728f33b6ae806a48d995738718e2c34ee94f1e

 
mariadbd: /test/bb-10.6-andrei_dbg/sql/log.cc:9438: void TC_LOG::run_commit_ordered(THD*, bool, THD*): Assertion `thd->lex->sql_command == SQLCOM_XA_COMMIT || thd->lex->sql_command == SQLCOM_XA_ROLLBACK' failed.

10.6.17 0d728f33b6ae806a48d995738718e2c34ee94f1e

 
Core was generated by `/test/PATCH2_MD221123-mariadb-10.6.17-linux-x86_64-dbg/bin/mariadbd --defaults-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=22966355924544)
 
    at ./nptl/pthread_kill.c:44
 
[Current thread is 1 (Thread 0x14e3457c9640 (LWP 2247225))]
 
(gdb) bt
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=22966355924544) at ./nptl/pthread_kill.c:44
 
#1  __pthread_kill_internal (signo=6, threadid=22966355924544) at ./nptl/pthread_kill.c:78
 
#2  __GI___pthread_kill (threadid=22966355924544, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
 
#3  0x000014e34be42476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
 
#4  0x000014e34be287f3 in __GI_abort () at ./stdlib/abort.c:79
 
#5  0x000014e34be2871b in __assert_fail_base (fmt=0x14e34bfdd150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x558017ef7be0 "thd->lex->sql_command == SQLCOM_XA_COMMIT || thd->lex->sql_command == SQLCOM_XA_ROLLBACK", file=0x558017ef5ae8 "/test/bb-10.6-andrei_dbg/sql/log.cc", line=9438, function=<optimized out>) at ./assert/assert.c:92
 
#6  0x000014e34be39e96 in __GI___assert_fail (assertion=0x558017ef7be0 "thd->lex->sql_command == SQLCOM_XA_COMMIT || thd->lex->sql_command == SQLCOM_XA_ROLLBACK", file=0x558017ef5ae8 "/test/bb-10.6-andrei_dbg/sql/log.cc", line=9438, function=0x558017ef7ba8 "void TC_LOG::run_commit_ordered(THD*, bool, THD*)") at ./assert/assert.c:101
 
#7  0x00005580175734b1 in TC_LOG::run_commit_ordered (this=this@entry=0x5580186c9960 <mysql_bin_log>, thd=0x14e308000d58, all=true, leader_thd=0x14e308000d58) at /test/bb-10.6-andrei_dbg/sql/log.cc:9438
 
#8  0x000055801757ca9c in MYSQL_BIN_LOG::trx_group_commit_leader (this=this@entry=0x5580186c9960 <mysql_bin_log>, leader=leader@entry=0x14e3457c6eb0) at /test/bb-10.6-andrei_dbg/sql/log.cc:8616
 
#9  0x000055801757d0a8 in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=this@entry=0x5580186c9960 <mysql_bin_log>, entry=entry@entry=0x14e3457c6eb0) at /test/bb-10.6-andrei_dbg/sql/log.cc:8194
 
#10 0x000055801757d6d3 in MYSQL_BIN_LOG::write_transaction_to_binlog (this=this@entry=0x5580186c9960 <mysql_bin_log>, thd=thd@entry=0x14e308000d58, cache_mngr=cache_mngr@entry=0x14e3080609c8, end_ev=end_ev@entry=0x14e3457c7190, all=all@entry=true, using_stmt_cache=using_stmt_cache@entry=false, using_trx_cache=true, is_ro_1pc=false) at /test/bb-10.6-andrei_dbg/sql/log.cc:7791
 
#11 0x000055801757d8bc in binlog_flush_cache (thd=thd@entry=0x14e308000d58, cache_mngr=cache_mngr@entry=0x14e3080609c8, end_ev=end_ev@entry=0x14e3457c7190, all=all@entry=true, using_stmt=using_stmt@entry=false, using_trx=using_trx@entry=true, is_ro_1pc=false) at /test/bb-10.6-andrei_dbg/sql/log.cc:1771
 
#12 0x000055801757dd27 in binlog_rollback_flush_trx_cache (thd=thd@entry=0x14e308000d58, all=all@entry=true, cache_mngr=cache_mngr@entry=0x14e3080609c8) at /test/bb-10.6-andrei_dbg/sql/log.cc:1907
 
#13 0x000055801757e287 in binlog_rollback (hton=<optimized out>, thd=0x14e308000d58, all=<optimized out>) at /test/bb-10.6-andrei_dbg/sql/log.cc:2326
 
#14 0x000055801742e921 in ha_rollback_trans (thd=thd@entry=0x14e308000d58, all=all@entry=true) at /test/bb-10.6-andrei_dbg/sql/handler.cc:2278
 
#15 0x00005580172d571d in trans_rollback_implicit (thd=thd@entry=0x14e308000d58) at /test/bb-10.6-andrei_dbg/sql/transaction.cc:421
 
#16 0x00005580172d39ae in mysql_admin_table (thd=thd@entry=0x14e308000d58, tables=tables@entry=0x14e308014830, check_opt=check_opt@entry=0x0, operator_name=operator_name@entry=0x5580185e6100 <msg_preload_keys>, lock_type=lock_type@entry=TL_READ_NO_INSERT, org_open_for_modify=org_open_for_modify@entry=false, repair_table_use_frm=<optimized out>, extra_open_options=<optimized out>, prepare_func=<optimized out>, operator_func=<optimized out>, view_operator_func=<optimized out>, is_cmd_replicated=<optimized out>) at /test/bb-10.6-andrei_dbg/sql/sql_admin.cc:1395
 
#17 0x00005580172d4181 in mysql_preload_keys (thd=thd@entry=0x14e308000d58, tables=tables@entry=0x14e308014830) at /test/bb-10.6-andrei_dbg/sql/sql_admin.cc:1539
 
#18 0x0000558017170b89 in mysql_execute_command (thd=thd@entry=0x14e308000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/bb-10.6-andrei_dbg/sql/sql_parse.cc:4103
 
#19 0x0000558017177917 in mysql_parse (thd=thd@entry=0x14e308000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14e3457c81f0) at /test/bb-10.6-andrei_dbg/sql/sql_parse.cc:8051
 
#20 0x0000558017179c8d in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14e308000d58, packet=packet@entry=0x14e308112759 "", packet_length=packet_length@entry=53, blocking=blocking@entry=true) at /test/bb-10.6-andrei_dbg/sql/sql_class.h:241
 
#21 0x000055801717bda7 in do_command (thd=0x14e308000d58, blocking=blocking@entry=true) at /test/bb-10.6-andrei_dbg/sql/sql_parse.cc:1409
 
#22 0x00005580172c015d in do_handle_one_connection (connect=<optimized out>, connect@entry=0x558019999978, put_in_cache=put_in_cache@entry=true) at /test/bb-10.6-andrei_dbg/sql/sql_connect.cc:1416
 
#23 0x00005580172c0452 in handle_one_connection (arg=arg@entry=0x558019999978) at /test/bb-10.6-andrei_dbg/sql/sql_connect.cc:1318
 
#24 0x000055801770e656 in pfs_spawn_thread (arg=0x55801992c7e8) at /test/bb-10.6-andrei_dbg/storage/perfschema/pfs.cc:2201
 
#25 0x000014e34be94ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#26 0x000014e34bf26a40 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81



 Comments   
Comment by Andrei Elkin [ 2023-11-22 ]

MDEV-32455 is the reason of the assert that successfully catches an attempt to harm
an ACTIVE xa by a (disallowed in the current case) perpetrator query type.

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

It looks like this assert was newly added in the MDEV-32830 patch, and is now being triggered. As such, this is a new regression.
A fix could be to modify the assert until MDEV-32455 is fixed. This also ensures that testing trials are not stopped short due to this assert.

Comment by Andrei Elkin [ 2023-11-22 ]

Roel, I made my best to satisfy your proposal.

Generally though it may not be easy, and I from my side may
give up to ask you do something with your RQG grammar to exclude a particular sequence from being generated.
Once it's tested out why should we continue be interested in seeing it over again?

I'd love to discuss that.
Feel to reply on slack or zulip.

Comment by Andrei Elkin [ 2023-11-22 ]

The refined assert in `960e246b29d` .

Generated at Thu Feb 08 10:34:33 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.