[MDEV-32262] InnoDB: Failing assertion: m_prebuilt->trx == thd_to_trx(m_user_thd) in ha_innobase::change_active_index Created: 2023-09-27  Updated: 2023-11-28

Status: Confirmed
Project: MariaDB Server
Component/s: Locking, Replication
Affects Version/s: 10.5, 10.6, 10.9, 10.10, 10.11, 11.0, 11.1, 11.2, 11.3
Fix Version/s: 10.5, 10.6, 10.11, 11.0, 11.1, 11.2

Type: Bug Priority: Major
Reporter: Ramesh Sivaraman Assignee: Andrei Elkin
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-30941 ASAN: heap-use-after-free in std::__a... Confirmed
relates to MDEV-32272 lock_release_on_prepare_try() does no... Closed

 Description   

CREATE TEMPORARY SEQUENCE s0;
CREATE TABLE t (a INT,b INT);
XA START 'a';
SET SESSION pseudo_slave_mode=ON;
INSERT INTO t VALUES (0,0);
XA END 'a';
XA PREPARE 'a';
LOCK TABLE t READ;
SELECT NEXT VALUE FOR s0;

Leads to:

11.3.0 8ad1e26b1bafa4ed9928306efc10c047f2274108 (Optimized)

InnoDB: Failing assertion: m_prebuilt->trx == thd_to_trx(m_user_thd)

11.3.0 8ad1e26b1bafa4ed9928306efc10c047f2274108 (Optimized)

Core was generated by `/test/MD080923-mariadb-11.3.0-linux-x86_64-opt/bin/mariadbd --no-defaults --cor'.
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 0x147e8d55d700 (LWP 2219148))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x0000147ea62d7859 in __GI_abort () at abort.c:79
#2  0x00005586d27a0a09 in ut_dbg_assertion_failed (expr=expr@entry=0x5586d3383bd8 "m_prebuilt->trx == thd_to_trx(m_user_thd)", file=file@entry=0x5586d33815b0 "/test/11.3_opt/storage/innobase/handler/ha_innodb.cc", line=line@entry=9147) at /test/11.3_opt/storage/innobase/ut/ut0dbg.cc:60
#3  0x00005586d277fb44 in ha_innobase::change_active_index (this=0x147e5001afa0, keynr=64) at /test/11.3_opt/storage/innobase/handler/ha_innodb.cc:9147
#4  0x00005586d2e087a8 in ha_innobase::rnd_init (this=0x147e5001afa0, scan=<optimized out>) at /test/11.3_opt/storage/innobase/handler/ha_innodb.cc:9432
#5  0x00005586d2b7cab6 in handler::ha_rnd_init (scan=true, this=0x147e5001afa0) at /test/11.3_opt/sql/handler.h:3522
#6  handler::update_first_row (this=0x147e5001afa0, new_data=0x147e50017dd8 "\377\351\003") at /test/11.3_opt/sql/handler.cc:7932
#7  0x00005586d2db5d11 in ha_sequence::write_row (this=0x147e500181f0, buf=0x147e50017dd8 "\377\351\003") at /test/11.3_opt/sql/ha_sequence.cc:283
#8  0x00005586d2b83ec0 in handler::ha_write_row (this=0x147e500181f0, buf=0x147e50017dd8 "\377\351\003") at /test/11.3_opt/sql/handler.cc:7840
#9  0x00005586d2ae3b09 in sequence_definition::write (this=this@entry=0x147e50019390, table=table@entry=0x147e500179c8, all_fields=<optimized out>) at /test/11.3_opt/sql/sql_sequence.cc:670
#10 0x00005586d2ae4324 in SEQUENCE::next_value (this=0x147e50019390, table=0x147e500179c8, second_round=<optimized out>, error=0x147e8d55aed4) at /test/11.3_opt/sql/sql_sequence.cc:779
#11 0x00005586d2be8d94 in Item_func_nextval::val_int (this=0x147e50011538) at /test/11.3_opt/sql/item_func.cc:7090
#12 0x00005586d2acbced in Type_handler::Item_send_longlong (this=<optimized out>, item=0x147e50011538, protocol=0x147e500011e0, buf=<optimized out>) at /test/11.3_opt/sql/sql_type.cc:7490
#13 0x00005586d283b276 in Protocol::send_result_set_row (this=this@entry=0x147e500011e0, row_items=row_items@entry=0x147e50010be8) at /test/11.3_opt/sql/protocol.cc:1332
#14 0x00005586d28b4197 in select_send::send_data (this=0x147e50011f18, items=@0x147e50010be8: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x147e500115f8, last = 0x147e500115f8, elements = 1}, <No data fields>}) at /test/11.3_opt/sql/sql_class.cc:3127
#15 0x00005586d2988287 in select_result_sink::send_data_with_check (u=<optimized out>, sent=0, items=<optimized out>, this=<optimized out>) at /test/11.3_opt/sql/sql_class.h:5801
#16 select_result_sink::send_data_with_check (sent=0, u=<optimized out>, items=<optimized out>, this=<optimized out>) at /test/11.3_opt/sql/sql_class.h:5791
#17 JOIN::exec_inner (this=0x147e50011f40) at /test/11.3_opt/sql/sql_select.cc:4801
#18 0x00005586d29886ee in JOIN::exec (this=this@entry=0x147e50011f40) at /test/11.3_opt/sql/sql_select.cc:4712
#19 0x00005586d298680c in mysql_select (thd=0x147e50000c58, tables=0x0, fields=<optimized out>, conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=<optimized out>, result=0x147e50011f18, unit=0x147e50004db0, select_lex=0x147e50010930) at /test/11.3_opt/sql/sql_select.cc:5243
#20 0x00005586d2986f77 in handle_select (thd=thd@entry=0x147e50000c58, lex=lex@entry=0x147e50004cd0, result=result@entry=0x147e50011f18, setup_tables_done_option=setup_tables_done_option@entry=0) at /test/11.3_opt/sql/sql_select.cc:628
#21 0x00005586d29040be in execute_sqlcom_select (thd=0x147e50000c58, all_tables=0x147e50010e20) at /test/11.3_opt/sql/sql_parse.cc:6023
#22 0x00005586d2911cf7 in mysql_execute_command (thd=0x147e50000c58, is_called_from_prepared_stmt=<optimized out>) at /test/11.3_opt/sql/sql_parse.cc:3922
#23 0x00005586d28ff085 in mysql_parse (rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, thd=0x147e50000c58) at /test/11.3_opt/sql/sql_parse.cc:7760
#24 mysql_parse (thd=0x147e50000c58, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /test/11.3_opt/sql/sql_parse.cc:7682
#25 0x00005586d290aed2 in dispatch_command (command=COM_QUERY, thd=0x147e50000c58, packet=<optimized out>, packet_length=<optimized out>, blocking=<optimized out>) at /test/11.3_opt/sql/sql_class.h:1489
#26 0x00005586d290cdbe in do_command (thd=0x147e50000c58, blocking=blocking@entry=true) at /test/11.3_opt/sql/sql_parse.cc:1406
#27 0x00005586d2a2e38f in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5586d4d12b38, put_in_cache=put_in_cache@entry=true) at /test/11.3_opt/sql/sql_connect.cc:1445
#28 0x00005586d2a2e67d in handle_one_connection (arg=0x5586d4d12b38) at /test/11.3_opt/sql/sql_connect.cc:1347
#29 0x0000147ea67e8609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#30 0x0000147ea63d4133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.5.23 (dbg), 10.5.23 (opt), 10.6.16 (dbg), 10.6.16 (opt), 10.9.8 (dbg), 10.9.8 (opt), 10.10.7 (dbg), 10.10.7 (opt), 10.11.6 (dbg), 10.11.6 (opt), 11.0.4 (dbg), 11.0.4 (opt), 11.1.3 (dbg), 11.1.3 (opt), 11.2.2 (dbg), 11.2.2 (opt), 11.3.0 (dbg), 11.3.0 (opt)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.4.32 (dbg), 10.4.32 (opt)



 Comments   
Comment by Marko Mäkelä [ 2023-09-27 ]

InnoDB will start a new transaction (instead of using the pre-existing one that is in XA PREPARE state) in:

10.6 52e7016248d3e3f80c6a912ddc0399a15d868efc

#0  0x000055d42463e080 in innobase_trx_allocate (thd=0x7f4004000c68) at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:2904
#1  check_trx_exists (thd=0x7f4004000c68) at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:2927
#2  ha_innobase::extra (this=0x7f4004128e90, operation=HA_EXTRA_ADD_CHILDREN_LIST) at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:15742
#3  0x000055d4242c383a in open_and_process_table (ot_ctx=0x7f40122e4d60, has_prelocking_list=<optimized out>, prelocking_strategy=<optimized out>, flags=<optimized out>, counter=<optimized out>, 
    tables=0x7f400401d178, thd=0x7f4004000c68) at /mariadb/10.6/sql/sql_base.cc:3932
#4  open_tables (thd=thd@entry=0x7f4004000c68, options=@0x7f40040061a8: {m_options = DDL_options_st::OPT_NONE}, start=start@entry=0x7f40122e4de8, counter=counter@entry=0x7f40122e4df4, flags=flags@entry=0, 
    prelocking_strategy=prelocking_strategy@entry=0x7f40122e4df8) at /mariadb/10.6/sql/sql_base.cc:4341
#5  0x000055d424370563 in open_tables (prelocking_strategy=0x7f40122e4df8, flags=0, counter=0x7f40122e4df4, tables=0x7f40122e4de8, thd=0x7f4004000c68) at /mariadb/10.6/sql/sql_base.h:268
#6  lock_tables_open_and_lock_tables (thd=thd@entry=0x7f4004000c68, tables=<optimized out>) at /mariadb/10.6/sql/sql_parse.cc:2867
#7  0x000055d42437ac79 in mysql_execute_command (thd=thd@entry=0x7f4004000c68, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /mariadb/10.6/sql/sql_parse.cc:5155
#8  0x000055d42437bb43 in mysql_parse (thd=0x7f4004000c68, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /mariadb/10.6/sql/sql_parse.cc:8050
#9  0x000055d42437d762 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f4004000c68, packet=packet@entry=0x7f400408ccf9 "LOCK TABLE t READ", packet_length=packet_length@entry=17, 
    blocking=blocking@entry=true) at /mariadb/10.6/sql/sql_parse.cc:1995

If I omit the statement SET SESSION pseudo_slave_mode=ON, the first error will be reported at:

10.6 52e7016248d3e3f80c6a912ddc0399a15d868efc

#0  my_error (nr=1399, MyFlags=0) at /mariadb/10.6/mysys/my_error.c:109
#1  0x000055680fa912e1 in trans_check (thd=thd@entry=0x7f443c000c68) at /mariadb/10.6/sql/transaction.cc:89
#2  trans_commit_implicit (thd=thd@entry=0x7f443c000c68) at /mariadb/10.6/sql/transaction.cc:311
#3  0x000055680f94e118 in mysql_execute_command (thd=thd@entry=0x7f443c000c68, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /mariadb/10.6/sql/sql_parse.cc:5110
#4  0x000055680f94fb43 in mysql_parse (thd=0x7f443c000c68, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>) at /mariadb/10.6/sql/sql_parse.cc:8050
#5  0x000055680f951762 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f443c000c68, packet=packet@entry=0x7f443c08ccf9 "LOCK TABLE t READ", packet_length=packet_length@entry=17, 
    blocking=blocking@entry=true) at /mariadb/10.6/sql/sql_parse.cc:1995

The test without setting pseudo_slave_mode=ON will not crash, but will report an appropriate error code for both invalid statements:

--source include/have_innodb.inc
CREATE TEMPORARY SEQUENCE s0 ENGINE=InnoDB;
CREATE TABLE t (a INT,b INT) ENGINE=InnoDB;
XA START 'a';
--echo # do not SET SESSION pseudo_slave_mode=ON;
INSERT INTO t VALUES (0,0);
XA END 'a';
XA PREPARE 'a';
--error ER_XAER_RMFAIL
LOCK TABLE t READ;
--error ER_XAER_RMFAIL
SELECT NEXT VALUE FOR s0;

Comment by Andrei Elkin [ 2023-09-28 ]

marko thank you!
Sure it's a similar abusive exploitation of the prepared trx.
This should be on my laps 'cos of SET SESSION pseudo_slave_mode=ON (ramesh, next time please don't hesitate to send it to replication).

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