[MDEV-15494] InnoDB: Assertion failure in file trx/trx0roll.cc line 326 in trx_rollback_last_sql_stat_for_mysql Created: 2018-03-06  Updated: 2023-12-11

Status: Confirmed
Project: MariaDB Server
Component/s: Prepared Statements, Storage Engine - InnoDB, XA
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: Elena Stepanova Assignee: Alexander Barkov
Resolution: Unresolved Votes: 0
Labels: None


 Description   

Update: See comments for the test case

10.2 8f98835bb86550a68a6c412d8417cc169dfdc206

 
2018-03-06 14:09:17 140281232664448 [Warning] No argument was provided to --log-bin and neither --log-basename or --log-bin-index where used;  This may cause repliction to break when this server acts as a master and has its hostname changed! Please use '--log-basename=travis-job-7b5ef115-5276-4b5c-ad07-c19c10ba4d04' or '--log-bin=mysql-bin' to avoid this problem.
 
Version: '10.2.14-MariaDB-debug-log'  socket: '/home/travis/logs/vardir1_1/mysql.sock'  port: 19300  Source distribution
 
2018-03-06 14:13:59 140281148442368 [ERROR] Event Scheduler: [rqg@localhost][testdb_S.e1_2_S] Table 'testdb_S.t1_merge1_N' doesn't exist
 
2018-03-06 14:14:00 0x7f95a415f700  InnoDB: Assertion failure in file /home/travis/src/storage/innobase/trx/trx0roll.cc line 334
 
 
 
Query (0x7f95a0013578): HANDLER handler_a READ `col_int_key` NEXT  /* QNO 6893 CON_ID 16 */
 
Connection ID (thread ID): 88
 
Status: NOT_KILLED
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on


#5  0x00007f95c2e0f028 in __GI_abort () at abort.c:89
 
#6  0x0000557b914ade4c in ut_dbg_assertion_failed (expr=0x0, file=0x557b91a68340 "/home/travis/src/storage/innobase/trx/trx0roll.cc", line=334) at /home/travis/src/storage/innobase/ut/ut0dbg.cc:61
 
#7  0x0000557b9148ceb2 in trx_rollback_last_sql_stat_for_mysql (trx=0x7f95c0a79c90) at /home/travis/src/storage/innobase/trx/trx0roll.cc:334
 
#8  0x0000557b9129a48f in innobase_rollback (hton=0x557b949a3860, thd=0x7f95a0002b20, rollback_trx=false) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:4879
 
#9  0x0000557b91092f41 in ha_rollback_trans (thd=0x7f95a0002b20, all=false) at /home/travis/src/sql/handler.cc:1672
 
#10 0x0000557b90f77ad7 in trans_rollback_stmt (thd=0x7f95a0002b20) at /home/travis/src/sql/transaction.cc:565
 
#11 0x0000557b90deffb6 in mysql_ha_read (thd=0x7f95a0002b20, tables=0x7f95a0013750, mode=RNEXT, keyname=0x7f95a0013d70 "col_int_key", key_expr=0x0, ha_rkey_mode=HA_READ_KEY_EXACT, cond=0x0, select_limit_cnt=1, offset_limit_cnt=0) at /home/travis/src/sql/sql_handler.cc:914
 
#12 0x0000557b90e1ec87 in mysql_execute_command (thd=0x7f95a0002b20) at /home/travis/src/sql/sql_parse.cc:5519
 
#13 0x0000557b90e25b2f in mysql_parse (thd=0x7f95a0002b20, rawbuf=0x7f95a0013578 "HANDLER handler_a READ `col_int_key` NEXT  /* QNO 6893 CON_ID 16 */", length=67, parser_state=0x7f95a415e210, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:7902
 
#14 0x0000557b90e13a65 in dispatch_command (command=COM_QUERY, thd=0x7f95a0002b20, packet=0x7f95a0008b41 "HANDLER handler_a READ `col_int_key` NEXT  /* QNO 6893 CON_ID 16 */ ", packet_length=68, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1806
 
#15 0x0000557b90e123c8 in do_command (thd=0x7f95a0002b20) at /home/travis/src/sql/sql_parse.cc:1360
 
#16 0x0000557b90f6190a in do_handle_one_connection (connect=0x557b94febeb0) at /home/travis/src/sql/sql_connect.cc:1335
 
#17 0x0000557b90f61697 in handle_one_connection (arg=0x557b94febeb0) at /home/travis/src/sql/sql_connect.cc:1241
 
#18 0x00007f95c39c6184 in start_thread (arg=0x7f95a415f700) at pthread_create.c:312
 
#19 0x00007f95c2ed303d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111



 Comments   
Comment by Roel Van de Paar [ 2020-06-12 ] 

USE test;
 
SET @@global.log_bin_trust_function_creators=1;
 
CREATE TABLE t(pk TIMESTAMP DEFAULT '0000-00-00 00:00:00.00',b DATE,KEY (pk));
 
CREATE FUNCTION f() RETURNS INT RETURN (SELECT notthere FROM t LIMIT 1);
 
XA BEGIN 'a';
 
SELECT f(@b,'a');
 
XA END 'a';
 
XA PREPARE 'a';
 
SELECT f(@a,@b);

Binary logging option is not required.

Leads to:

10.5.4 07d1c8567cbfe94398a9857c47fb9919cad42651

 
2020-06-12 20:13:00 0 [Note] /test/MD120620-mariadb-10.5.4-linux-x86_64-dbg/bin/mysqld: ready for connections.
 
Version: '10.5.4-MariaDB'  socket: '/test/MD120620-mariadb-10.5.4-linux-x86_64-dbg/socket.sock'  port: 15523  MariaDB Server
 
2020-06-12 20:13:26 0x149388886700  InnoDB: Assertion failure in file /test/10.5_opt/storage/innobase/trx/trx0roll.cc line 326
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
 
InnoDB: If you get repeated assertion failures or crashes, even
 
InnoDB: immediately after the mysqld startup, there may be
 
InnoDB: corruption in the InnoDB tablespace. Please refer to
 
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
 
InnoDB: about forcing recovery.
 
200612 20:13:26 [ERROR] mysqld got signal 6 ;
 
...
 
Query (0x149363047030): SELECT f(@a,@b)
 
Connection ID (thread ID): 4
 
Status: NOT_KILLED

10.5.4 07d1c8567cbfe94398a9857c47fb9919cad42651 (dbg)

 
Core was generated by `/test/MD120620-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 0x14f353a46700 (LWP 3458208))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x000055e72108d9e7 in my_write_core (sig=sig@entry=6) at /test/10.5_opt/mysys/stacktrace.c:518
 
#2  0x000055e720a58daa in handle_fatal_signal (sig=6) at /test/10.5_opt/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  0x000014f351cdc801 in __GI_abort () at abort.c:79
 
#6  0x000055e72075ffaa in ut_dbg_assertion_failed (expr=expr@entry=0x0, file=file@entry=0x55e7213c01b0 "/test/10.5_opt/storage/innobase/trx/trx0roll.cc", line=line@entry=326) at /test/10.5_opt/storage/innobase/ut/ut0dbg.cc:60
 
#7  0x000055e720eb5c47 in trx_rollback_last_sql_stat_for_mysql (trx=trx@entry=0x14f33e4021b0) at /test/10.5_opt/storage/innobase/trx/trx0roll.cc:326
 
#8  0x000055e720d71dc8 in innobase_rollback (hton=<optimized out>, thd=0x14f32c812018, rollback_trx=<optimized out>) at /test/10.5_opt/storage/innobase/handler/ha_innodb.cc:4470
 
#9  0x000055e720a5c6d7 in ha_rollback_trans (thd=thd@entry=0x14f32c812018, all=all@entry=false) at /test/10.5_opt/sql/handler.cc:1987
 
#10 0x000055e720961105 in trans_rollback_stmt (thd=thd@entry=0x14f32c812018) at /test/10.5_opt/sql/transaction.cc:525
 
#11 0x000055e7208612e3 in mysql_execute_command (thd=thd@entry=0x14f32c812018) at /test/10.5_opt/sql/sql_parse.cc:6003
 
#12 0x000055e7208698fc in mysql_parse (thd=0x14f32c812018, rawbuf=<optimized out>, length=15, parser_state=0x14f353a45430, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /test/10.5_opt/sql/sql_parse.cc:7992
 
#13 0x000055e72085ebe5 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14f32c812018, packet=packet@entry=0x14f32c83a019 "", packet_length=packet_length@entry=15, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_opt/sql/sql_parse.cc:1874
 
#14 0x000055e72085cfd4 in do_command (thd=0x14f32c812018) at /test/10.5_opt/sql/sql_parse.cc:1355
 
#15 0x000055e720952681 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x14f350833958, put_in_cache=put_in_cache@entry=true) at /test/10.5_opt/sql/sql_connect.cc:1411
 
#16 0x000055e7209529e4 in handle_one_connection (arg=arg@entry=0x14f350833958) at /test/10.5_opt/sql/sql_connect.cc:1313
 
#17 0x000055e720cc040a in pfs_spawn_thread (arg=0x14f35084e818) at /test/10.5_opt/storage/perfschema/pfs.cc:2201
 
#18 0x000014f3529bf6db in start_thread (arg=0x14f353a46700) at pthread_create.c:463
 
#19 0x000014f351dbd88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

10.5.4 07d1c8567cbfe94398a9857c47fb9919cad42651 (opt)

 
Core was generated by `/test/MD120620-mariadb-10.5.4-linux-x86_64-opt/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 0x1490a6fef700 (LWP 3493453))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x000055b8783e39e7 in my_write_core (sig=sig@entry=6) at /test/10.5_opt/mysys/stacktrace.c:518
 
#2  0x000055b877daedaa in handle_fatal_signal (sig=6) at /test/10.5_opt/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  0x00001490a5285801 in __GI_abort () at abort.c:79
 
#6  0x000055b877ab5faa in ut_dbg_assertion_failed (expr=expr@entry=0x0, file=file@entry=0x55b8787161b0 "/test/10.5_opt/storage/innobase/trx/trx0roll.cc", line=line@entry=326) at /test/10.5_opt/storage/innobase/ut/ut0dbg.cc:60
 
#7  0x000055b87820bc47 in trx_rollback_last_sql_stat_for_mysql (trx=trx@entry=0x1490920021b0) at /test/10.5_opt/storage/innobase/trx/trx0roll.cc:326
 
#8  0x000055b8780c7dc8 in innobase_rollback (hton=<optimized out>, thd=0x149081012018, rollback_trx=<optimized out>) at /test/10.5_opt/storage/innobase/handler/ha_innodb.cc:4470
 
#9  0x000055b877db26d7 in ha_rollback_trans (thd=thd@entry=0x149081012018, all=all@entry=false) at /test/10.5_opt/sql/handler.cc:1987
 
#10 0x000055b877cb7105 in trans_rollback_stmt (thd=thd@entry=0x149081012018) at /test/10.5_opt/sql/transaction.cc:525
 
#11 0x000055b877bb72e3 in mysql_execute_command (thd=thd@entry=0x149081012018) at /test/10.5_opt/sql/sql_parse.cc:6003
 
#12 0x000055b877bbf8fc in mysql_parse (thd=0x149081012018, rawbuf=<optimized out>, length=15, parser_state=0x1490a6fee430, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /test/10.5_opt/sql/sql_parse.cc:7992
 
#13 0x000055b877bb4be5 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x149081012018, packet=packet@entry=0x14908103a019 "", packet_length=packet_length@entry=15, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_opt/sql/sql_parse.cc:1874
 
#14 0x000055b877bb2fd4 in do_command (thd=0x149081012018) at /test/10.5_opt/sql/sql_parse.cc:1355
 
#15 0x000055b877ca8681 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x1490a3c33958, put_in_cache=put_in_cache@entry=true) at /test/10.5_opt/sql/sql_connect.cc:1411
 
#16 0x000055b877ca89e4 in handle_one_connection (arg=arg@entry=0x1490a3c33958) at /test/10.5_opt/sql/sql_connect.cc:1313
 
#17 0x000055b87801640a in pfs_spawn_thread (arg=0x1490a3c4e818) at /test/10.5_opt/storage/perfschema/pfs.cc:2201
 
#18 0x00001490a5f686db in start_thread (arg=0x1490a6fef700) at pthread_create.c:463
 
#19 0x00001490a536688f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

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

Bug confirmed not present in:
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)

Comment by Elena Stepanova [ 2023-02-06 ]

Cleaned up test case:

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

For 10.5+ the first SELECT f() can be replaced by simple SELECT * FROM t.

Comment by Roel Van de Paar [ 2023-10-13 ]

Ran into this one again during testing of MDEV-31949. While testing I noticed that the select inside the function can also be SELECT * FROM t:

--source include/have_innodb.inc
 
CREATE FUNCTION f() RETURNS INT RETURN (SELECT * FROM t);
 
CREATE TABLE t (a INT) ENGINE=InnoDB;
 
XA START 'a';
 
SELECT * FROM t;
 
XA END 'a';
 
XA PREPARE 'a';
 
SELECT f();
 
DROP FUNCTION f;
 
DROP TABLE t;

Confirmed 10.5-11.3 dbg+opt. Interestingly, on MySQL 8.0 there is a thread hang (note the missing XA ROLLBACK in the testcase above):

MySQL 8.0.33 ea7087d885006918ad54458e7aad215b1650312c (Optimized)

 
mysql> SHOW PROCESSLIST;
 
+----+-----------------+-----------+------+---------+------+---------------------------------+------------------+
 
| Id | User            | Host      | db   | Command | Time | State                           | Info             |
 
+----+-----------------+-----------+------+---------+------+---------------------------------+------------------+
 
|  5 | event_scheduler | localhost | NULL | Daemon  |  313 | Waiting on empty queue          | NULL             |
 
|  9 | root            | localhost | test | Query   |  311 | Waiting for table metadata lock | DROP TABLE t     |
 
| 10 | root            | localhost | test | Query   |    0 | init                            | SHOW PROCESSLIST |
 
+----+-----------------+-----------+------+---------+------+---------------------------------+------------------+
 
3 rows in set (0.00 sec)

The CLI will hang on the DROP TABLE. MySQL 5.7 will not:

MySQL 5.7.40 c4f63caa8d9f30b2850672291e0ad0928dd89d0e (Debug)

 
5.7.40-dbg>SELECT f();
 
ERROR 1399 (XAE07): XAER_RMFAIL: The command cannot be executed when global transaction is in the  PREPARED state
 
5.7.40-dbg>DROP FUNCTION f;
 
ERROR 1399 (XAE07): XAER_RMFAIL: The command cannot be executed when global transaction is in the  PREPARED state
 
5.7.40-dbg>DROP TABLE t;
 
ERROR 1399 (XAE07): XAER_RMFAIL: The command cannot be executed when global transaction is in the  PREPARED state

Comment by Marko Mäkelä [ 2023-12-10 ]

To me, this looks like a bug in the SQL layer. A statement that would start a transaction must be refused if the current client connection is attached to a transaction that is in the XA PREPARE state. InnoDB is only the messenger here.

Comment by Sergei Golubchik [ 2023-12-11 ]

Yes, SELECT shouldn't be allowed after XA PREPARE

Generated at Thu Feb 08 08:21:44 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.