[MDEV-23046] InnoDB: Assertion failure in file innobase/trx/trx0trx.cc in trx_mark_sql_stat_end when enabling general_log or slow_query_log Created: 2020-06-30  Updated: 2023-11-28

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

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

Issue Links:
Relates
relates to MDEV-22726 Add check to ensure one can't change ... Closed

 Description   

I expect this bug will be 'masked/hidden' by MDEV-22726 soon. However, this particular bug/issue may (and 'likely') stands separate from that bug: please have a look if there is a separate unhandled or incorrectly handled situation here, which may appear in other scenario setups also.

USE test;
 
SET SQL_MODE='';
 
SET SESSION enforce_storage_engine=InnoDB;
 
CREATE TABLE t(f0 INT) ENGINE=InnoDB;
 
ALTER TABLE mysql.general_log ENGINE=MyISAM;
 
XA START '0';
 
INSERT INTO t VALUES (0);
 
XA END '0';
 
XA PREPARE '0';
 
SET GLOBAL general_log=ON;

Leads to:

10.5.5 e1013725ce0f3f947e728491eef75d9985e8db2f

 
2020-06-30 12:22:42 0 [Note] /test/MD250620-mariadb-10.5.5-linux-x86_64-dbg/bin/mysqld: ready for connections.
 
Version: '10.5.5-MariaDB-debug'  socket: '/test/MD250620-mariadb-10.5.5-linux-x86_64-dbg/socket.sock'  port: 17468  MariaDB Server
 
2020-06-30 12:22:57 0x1506ff42a700  InnoDB: Assertion failure in file /test/10.5_dbg/storage/innobase/trx/trx0trx.cc line 1767
 
InnoDB: We intentionally generate a memory trap.

10.5.5 e1013725ce0f3f947e728491eef75d9985e8db2f

 
Core was generated by `/test/MD250620-mariadb-10.5.5-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 0x14ce47c37700 (LWP 2542546))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x00005593675577d0 in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
 
#2  0x0000559366d1047a 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  0x000014ce45ecd801 in __GI_abort () at abort.c:79
 
#6  0x000055936732844c in ut_dbg_assertion_failed (expr=expr@entry=0x0, file=file@entry=0x5593679d4cb8 "/test/10.5_dbg/storage/innobase/trx/trx0trx.cc", line=line@entry=1767) at /test/10.5_dbg/storage/innobase/ut/ut0dbg.cc:60
 
#7  0x0000559367312b5a in trx_mark_sql_stat_end (trx=trx@entry=0x14ce32802390) at /test/10.5_dbg/storage/innobase/trx/trx0trx.cc:1767
 
#8  0x00005593670cc786 in innobase_commit (hton=<optimized out>, thd=0x14ce23815088, commit_trx=<optimized out>) at /test/10.5_dbg/storage/innobase/handler/ha_innodb.cc:4397
 
#9  0x0000559366d1263b in commit_one_phase_2 (thd=thd@entry=0x14ce23815088, all=all@entry=false, trans=trans@entry=0x14ce23818688, is_real_trans=is_real_trans@entry=false) at /test/10.5_dbg/sql/handler.cc:1914
 
#10 0x0000559366d15888 in ha_commit_one_phase (thd=thd@entry=0x14ce23815088, all=all@entry=false) at /test/10.5_dbg/sql/handler.cc:1894
 
#11 0x0000559366d29adf in ha_commit_trans (thd=thd@entry=0x14ce23815088, all=all@entry=false) at /test/10.5_dbg/sql/handler.cc:1694
 
#12 0x0000559366bce989 in trans_commit_stmt (thd=thd@entry=0x14ce23815088) at /test/10.5_dbg/sql/transaction.cc:472
 
#13 0x0000559366a6b6dc in mysql_execute_command (thd=thd@entry=0x14ce23815088) at /test/10.5_dbg/sql/sql_parse.cc:6013
 
#14 0x0000559366a72638 in mysql_parse (thd=thd@entry=0x14ce23815088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14ce47c36350, 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:7995
 
#15 0x0000559366a5f110 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14ce23815088, packet=packet@entry=0x14ce23867089 "SET GLOBAL general_log=ON", packet_length=packet_length@entry=25, 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
 
#16 0x0000559366a5d8ea in do_command (thd=0x14ce23815088) at /test/10.5_dbg/sql/sql_parse.cc:1355
 
#17 0x0000559366bb915f in do_handle_one_connection (connect=<optimized out>, connect@entry=0x14ce26cd2808, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1411
 
#18 0x0000559366bb987b in handle_one_connection (arg=arg@entry=0x14ce26cd2808) at /test/10.5_dbg/sql/sql_connect.cc:1313
 
#19 0x000055936701c11c in pfs_spawn_thread (arg=0x14ce44846508) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
 
#20 0x000014ce46bb06db in start_thread (arg=0x14ce47c37700) at pthread_create.c:463
 
#21 0x000014ce45fae88f 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.5 (dbg), 10.5.5 (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)

 Comments   
Comment by Roel Van de Paar [ 2023-01-13 ] 

CREATE OR REPLACE TABLE mysql.general_log (c INT) ENGINE=InnoDB;
 
SET max_session_mem_used=32768;
 
XA START 'a';
 
XA END 'a';
 
SET GLOBAL general_log=ON;
 
XA PREPARE 'a';
 
SET GLOBAL general_log=ON;

Leads to:

11.0.1 b075191ba8598af6aff5549e6e19f6255aef258a (Debug)

 
Core was generated by `/test/MD090123-mariadb-11.0.1-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=23308975728192)
 
    at ./nptl/pthread_kill.c:44
 
[Current thread is 1 (Thread 0x15330b37e640 (LWP 480346))]
 
(gdb) bt
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=23308975728192) at ./nptl/pthread_kill.c:44
 
#1  __pthread_kill_internal (signo=6, threadid=23308975728192) at ./nptl/pthread_kill.c:78
 
#2  __GI___pthread_kill (threadid=23308975728192, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
 
#3  0x000015333b828476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
 
#4  0x000015333b80e7f3 in __GI_abort () at ./stdlib/abort.c:79
 
#5  0x000055ed2190bfb2 in ut_dbg_assertion_failed (expr=expr@entry=0x0, file=file@entry=0x55ed21e0ed08 "/test/11.0_dbg/storage/innobase/trx/trx0trx.cc", line=line@entry=1671) at /test/11.0_dbg/storage/innobase/ut/ut0dbg.cc:60
 
#6  0x000055ed218fb3af in trx_mark_sql_stat_end (trx=trx@entry=0x153332fa8b80) at /test/11.0_dbg/storage/innobase/trx/trx0trx.cc:1671
 
#7  0x000055ed216fd844 in innobase_commit (hton=<optimized out>, thd=0x1532e4000d58, commit_trx=<optimized out>) at /test/11.0_dbg/storage/innobase/handler/ha_innodb.cc:4544
 
#8  0x000055ed21425411 in commit_one_phase_2 (thd=thd@entry=0x1532e4000d58, all=all@entry=false, trans=trans@entry=0x1532e4004748, is_real_trans=false) at /test/11.0_dbg/sql/handler.cc:2085
 
#9  0x000055ed214255ea in ha_commit_one_phase (thd=thd@entry=0x1532e4000d58, all=all@entry=false) at /test/11.0_dbg/sql/handler.cc:2038
 
#10 0x000055ed21435856 in ha_commit_trans (thd=thd@entry=0x1532e4000d58, all=all@entry=false) at /test/11.0_dbg/sql/handler.cc:1832
 
#11 0x000055ed212c8790 in trans_commit_stmt (thd=thd@entry=0x1532e4000d58) at /test/11.0_dbg/sql/transaction.cc:472
 
#12 0x000055ed21165748 in mysql_execute_command (thd=thd@entry=0x1532e4000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/11.0_dbg/sql/sql_parse.cc:6061
 
#13 0x000055ed21166934 in mysql_parse (thd=thd@entry=0x1532e4000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x15330b37d2c0) at /test/11.0_dbg/sql/sql_parse.cc:8000
 
#14 0x000055ed21168ac8 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x1532e4000d58, packet=packet@entry=0x1532e400ae09 "SET GLOBAL general_log=ON", packet_length=packet_length@entry=25, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_class.h:243
 
#15 0x000055ed2116a921 in do_command (thd=0x1532e4000d58, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_parse.cc:1407
 
#16 0x000055ed212b49ea in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55ed2397cbf8, put_in_cache=put_in_cache@entry=true) at /test/11.0_dbg/sql/sql_connect.cc:1416
 
#17 0x000055ed212b4c4e in handle_one_connection (arg=0x55ed2397cbf8) at /test/11.0_dbg/sql/sql_connect.cc:1318
 
#18 0x000015333b87ab43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#19 0x000015333b90ca00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Bug confirmed present in:
MariaDB: 10.3.38 (dbg), 10.3.38 (opt), 10.4.28 (dbg), 10.4.28 (opt), 10.5.19 (dbg), 10.5.19 (opt), 10.6.12 (dbg), 10.6.12 (opt), 10.7.8 (opt), 10.7.8 (dbg), 10.8.7 (dbg), 10.8.7 (opt), 10.9.5 (dbg), 10.9.5 (opt), 10.10.3 (dbg), 10.10.3 (opt), 10.11.2 (dbg), 10.11.2 (opt), 11.0.1 (dbg), 11.0.1 (opt)

Bug (or feature/syntax) confirmed not present in:
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.40 (dbg), 5.7.40 (opt), 8.0.31 (dbg), 8.0.31 (opt)

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

Additional testcase with slightly different stack:

CREATE TABLE t (c INT) ENGINE=InnoDB;
 
CREATE OR REPLACE TABLE mysql.slow_log (c INT);
 
XA START 'a';
 
INSERT INTO t VALUES (1);
 
XA END 'a';
 
XA PREPARE 'a';
 
SET GLOBAL slow_query_log=1;

Leads to:

11.0.1 f2dc4d4c10ac36a73b5c1eb765352d3aee808d66 (Debug)

 
Core was generated by `/test/MD180223-mariadb-11.0.1-linux-x86_64-dbg/bin/mariadbd --no-defaults --cor'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=23454524851776)
 
    at ./nptl/pthread_kill.c:44
 
[Current thread is 1 (Thread 0x1554ee9f4640 (LWP 2525856))]
 
(gdb) bt
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=23454524851776) at ./nptl/pthread_kill.c:44
 
#1  __pthread_kill_internal (signo=6, threadid=23454524851776) at ./nptl/pthread_kill.c:78
 
#2  __GI___pthread_kill (threadid=23454524851776, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
 
#3  0x0000155523cb4476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
 
#4  0x0000155523c9a7f3 in __GI_abort () at ./stdlib/abort.c:79
 
#5  0x0000555ea34ffb02 in ut_dbg_assertion_failed (expr=expr@entry=0x0, file=file@entry=0x555ea3aca3e8 "/test/11.0_dbg/storage/innobase/trx/trx0trx.cc", line=line@entry=1671) at /test/11.0_dbg/storage/innobase/ut/ut0dbg.cc:60
 
#6  0x0000555ea34eee92 in trx_mark_sql_stat_end (trx=trx@entry=0x15551b434b80) at /test/11.0_dbg/storage/innobase/trx/trx0trx.cc:1671
 
#7  0x0000555ea3308c1c in innobase_commit (hton=<optimized out>, thd=0x1554ac000d58, commit_trx=<optimized out>) at /test/11.0_dbg/storage/innobase/handler/ha_innodb.cc:4511
 
#8  0x0000555ea3035fe4 in commit_one_phase_2 (thd=thd@entry=0x1554ac000d58, all=all@entry=false, trans=trans@entry=0x1554ac004750, is_real_trans=false) at /test/11.0_dbg/sql/handler.cc:2125
 
#9  0x0000555ea30361bd in ha_commit_one_phase (thd=thd@entry=0x1554ac000d58, all=all@entry=false) at /test/11.0_dbg/sql/handler.cc:2078
 
#10 0x0000555ea3046b14 in ha_commit_trans (thd=thd@entry=0x1554ac000d58, all=all@entry=false) at /test/11.0_dbg/sql/handler.cc:1872
 
#11 0x0000555ea2ed56c7 in trans_commit_stmt (thd=thd@entry=0x1554ac000d58) at /test/11.0_dbg/sql/transaction.cc:472
 
#12 0x0000555ea2d6b5e3 in mysql_execute_command (thd=thd@entry=0x1554ac000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/11.0_dbg/sql/sql_parse.cc:6063
 
#13 0x0000555ea2d6c7cf in mysql_parse (thd=thd@entry=0x1554ac000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1554ee9f32c0) at /test/11.0_dbg/sql/sql_parse.cc:8002
 
#14 0x0000555ea2d6e963 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x1554ac000d58, packet=packet@entry=0x1554ac00ae19 "SET GLOBAL slow_query_log=1", packet_length=packet_length@entry=27, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_class.h:242
 
#15 0x0000555ea2d707bc in do_command (thd=0x1554ac000d58, blocking=blocking@entry=true) at /test/11.0_dbg/sql/sql_parse.cc:1407
 
#16 0x0000555ea2ec16e2 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x555ea5920fd8, put_in_cache=put_in_cache@entry=true) at /test/11.0_dbg/sql/sql_connect.cc:1416
 
#17 0x0000555ea2ec1941 in handle_one_connection (arg=0x555ea5920fd8) at /test/11.0_dbg/sql/sql_connect.cc:1318
 
#18 0x0000155523d06b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#19 0x0000155523d98a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Bug confirmed present in:
MariaDB: 10.3.38 (dbg), 10.3.38 (opt), 10.3.39 (dbg), 10.3.39 (opt), 10.4.29 (dbg), 10.4.29 (opt), 10.5.20 (dbg), 10.5.20 (opt), 10.6.13 (dbg), 10.6.13 (opt), 10.7.8 (dbg), 10.7.8 (opt), 10.8.8 (dbg), 10.8.8 (opt), 10.9.6 (dbg), 10.9.6 (opt), 10.10.4 (dbg), 10.10.4 (opt), 10.11.2 (dbg), 10.11.2 (opt), 10.11.3 (dbg), 10.11.3 (opt), 11.0.1 (dbg), 11.0.1 (opt)

Comment by Marko Mäkelä [ 2023-04-01 ]

As far as I can tell, vlad.lesin’s fix associated with MDEV-22726 only affects the Aria engine. I do not think that these system tables can easily be supported in a storage engine that supports distributed transactions (XA PREPARE) unless the SQL layer is fixed accordingly. MyRocks could be affected as well.

One more nasty test could be to try to partition the affected system tables and see what happens.

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