[MDEV-31304] Assertion failure in trx_rollback_last_sql_stat_for_mysql Created: 2023-05-18  Updated: 2023-11-28

Status: Confirmed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Stored routines, XA
Affects Version/s: 10.5, 10.6, 10.8, 10.9, 10.10, 10.11, 11.0
Fix Version/s: 10.5, 10.6, 10.11, 11.0

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Oleksandr Byelkin
Resolution: Unresolved Votes: 0
Labels: None


 Description   

--source include/have_innodb.inc
 
CREATE TABLE t (a INT) ENGINE=InnoDB;
CREATE FUNCTION f () RETURNS INT RETURN (SELECT COUNT(*) FROM t);
XA BEGIN 'x';
SELECT * FROM t;
XA END 'x';
XA PREPARE 'x';
--error ER_XAER_RMFAIL
SELECT f();
 
# Cleanup
XA ROLLBACK 'x';
DROP TABLE t;
DROP FUNCTION f;

10.5 c9eff1a1

#7  0x00007f2876045472 in __GI_abort () at ./stdlib/abort.c:79
#8  0x000055909725cde8 in ut_dbg_assertion_failed (expr=0x0, file=0x559098703be0 "/data/src/10.5/storage/innobase/trx/trx0roll.cc", line=323) at /data/src/10.5/storage/innobase/ut/ut0dbg.cc:60
#9  0x00005590972174df in trx_rollback_last_sql_stat_for_mysql (trx=0x7f286e67d9b0) at /data/src/10.5/storage/innobase/trx/trx0roll.cc:323
#10 0x0000559096ce403e in innobase_rollback (hton=0x615000002898, thd=0x62b00007e218, rollback_trx=false) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:4468
#11 0x000055909628fc2a in ha_rollback_trans (thd=0x62b00007e218, all=false) at /data/src/10.5/sql/handler.cc:2097
#12 0x0000559095ef6f13 in trans_rollback_stmt (thd=0x62b00007e218) at /data/src/10.5/sql/transaction.cc:535
#13 0x0000559095a86b30 in mysql_execute_command (thd=0x62b00007e218) at /data/src/10.5/sql/sql_parse.cc:6126
#14 0x0000559095a937e7 in mysql_parse (thd=0x62b00007e218, rawbuf=0x62b000085238 "SELECT f()", length=10, parser_state=0x7f2860d60c10, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:8106
#15 0x0000559095a69378 in dispatch_command (command=COM_QUERY, thd=0x62b00007e218, packet=0x629000280219 "", packet_length=10, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1891
#16 0x0000559095a65d15 in do_command (thd=0x62b00007e218) at /data/src/10.5/sql/sql_parse.cc:1375
#17 0x0000559095eb2feb in do_handle_one_connection (connect=0x6080000039b8, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1416
#18 0x0000559095eb29b3 in handle_one_connection (arg=0x608000003938) at /data/src/10.5/sql/sql_connect.cc:1318
#19 0x0000559096b0270c in pfs_spawn_thread (arg=0x61500000c898) at /data/src/10.5/storage/perfschema/pfs.cc:2201
#20 0x00007f28760a7fd4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#21 0x00007f28761285bc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Reproducible on debug- and non-debug builds alike.

The failure started happening after this commit in 10.5.4:

commit d1d472646d578608791dcd33c13ca6b2472e31b2
Author: Monty
Date:   Mon May 4 14:20:14 2020 +0300
 
    Change THD->transaction to a pointer to enable multiple transactions
    
    All changes (except one) is of type
 
 
    To handle the case that Aria doesn't support rollback, a new
    handlerton flag, HTON_NO_ROLLBACK, was added to engines that has
    transactions without rollback (for the moment only binlog and Aria).
    
    Other things
    - Moved freeing of MARIA_SHARE to a separate function as the MARIA_SHARE
      can be still part of a transaction even if the table has closed.
    - Changed Aria checkpoint to use the new MARIA_SHARE free function. This
      fixes a possible memory leak when using S3 tables
    - Changed testing of binlog_hton to instead test for HTON_NO_ROLLBACK
    - Removed checking of has_transaction_manager() in handler.cc as we can
      assume that as the transaction was started by the engine, it does
      support transactions.
    - Added new class 'start_new_trans' that can be used to start indepdendent
      sub transactions, for example while reading mysql.proc, using help or
      status tables etc.
    - open_system_tables...() and open_proc_table_for_Read() doesn't anymore
      take a Open_tables_backup list. This is now handled by 'start_new_trans'.
    - Split thd::has_transactions() to thd::has_transactions() and
      thd::has_transactions_and_rollback()
    - Added handlerton code to free cached transactions objects.
      Needed by InnoDB.
    
    squash! 2ed35999f2a2d84f1c786a21ade5db716b6f1bbc



 Comments   
Comment by Elena Stepanova [ 2023-05-18 ]

Despite the commit header, there are a lot of "other things" in that commit, which is why I'm pasting the whole commit comment.
The commit is mainly server-side, it doesn't even change InnoDB code as far as I can tell, but it does say that the part of changes were done for the sake of InnoDB, so I thought it could be reasonable if InnoDB does the initial analysis first. Please feel free to reassign as needed.

Comment by Elena Stepanova [ 2023-05-18 ]

For the record, an almost identical test case (EXPLAIN instead of SELECT, otherwise the same) produces a somewhat different stack trace.

--source include/have_innodb.inc
 
CREATE TABLE t (a INT) ENGINE=InnoDB;
CREATE FUNCTION f () RETURNS INT RETURN (SELECT COUNT(*) FROM t);
XA BEGIN 'x';
SELECT * FROM t;
XA END 'x';
XA PREPARE 'x';
--error ER_XAER_RMFAIL
EXPLAIN SELECT f();
 
# Cleanup
XA ROLLBACK 'x';
DROP TABLE t;
DROP FUNCTION f;

10.5 c9eff1a1

#8  0x0000561a47ec4de8 in ut_dbg_assertion_failed (expr=0x0, file=0x561a49387400 "/data/src/10.5/storage/innobase/trx/trx0trx.cc", line=1688) at /data/src/10.5/storage/innobase/ut/ut0dbg.cc:60
#9  0x0000561a47ea293b in trx_mark_sql_stat_end (trx=0x7f137bf729b0) at /data/src/10.5/storage/innobase/trx/trx0trx.cc:1688
#10 0x0000561a4794b981 in innobase_commit (hton=0x615000002898, thd=0x62b00007e218, commit_trx=false) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:4400
#11 0x0000561a46ef6e9d in commit_one_phase_2 (thd=0x62b00007e218, all=false, trans=0x62b0000819c8, is_real_trans=false) at /data/src/10.5/sql/handler.cc:1982
#12 0x0000561a46ef6bca in ha_commit_one_phase (thd=0x62b00007e218, all=false) at /data/src/10.5/sql/handler.cc:1961
#13 0x0000561a46ef4e6d in ha_commit_trans (thd=0x62b00007e218, all=false) at /data/src/10.5/sql/handler.cc:1755
#14 0x0000561a46b5e38e in trans_commit_stmt (thd=0x62b00007e218) at /data/src/10.5/sql/transaction.cc:472
#15 0x0000561a466eeb8a in mysql_execute_command (thd=0x62b00007e218) at /data/src/10.5/sql/sql_parse.cc:6133
#16 0x0000561a466fb7e7 in mysql_parse (thd=0x62b00007e218, rawbuf=0x62b000085238 "EXPLAIN SELECT f()", length=18, parser_state=0x7f1370ecac10, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:8106
#17 0x0000561a466d1378 in dispatch_command (command=COM_QUERY, thd=0x62b00007e218, packet=0x629000280219 "", packet_length=18, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1891
#18 0x0000561a466cdd15 in do_command (thd=0x62b00007e218) at /data/src/10.5/sql/sql_parse.cc:1375
#19 0x0000561a46b1afeb in do_handle_one_connection (connect=0x6080000039b8, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1416
#20 0x0000561a46b1a9b3 in handle_one_connection (arg=0x608000003938) at /data/src/10.5/sql/sql_connect.cc:1318
#21 0x0000561a4776a70c in pfs_spawn_thread (arg=0x61500000c898) at /data/src/10.5/storage/perfschema/pfs.cc:2201
#22 0x00007f13836a7fd4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#23 0x00007f13837285bc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

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

This seems to be a bug with stored routines. If I replace the function call

SELECT f();

with the equivalent SQL statement

SELECT COUNT(*) FROM t;

then the error will be properly caught and reported outside the storage engine layer:

mysqltest: At line 9: query 'SELECT COUNT(*) FROM t' failed: ER_XAER_RMFAIL (1399): XAER_RMFAIL: The command cannot be executed when global transaction is in the  PREPARED state

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