[MDEV-24706] Assertion `thd->transaction->stmt.is_empty() || thd->in_sub_stmt' failed in mysql_execute_command (from mysql_parse) and in trans_check Created: 2021-01-27  Updated: 2023-06-29

Status: Confirmed
Project: MariaDB Server
Component/s: Events
Affects Version/s: 10.2, 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10
Fix Version/s: 10.4, 10.5, 10.6

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Oleksandr Byelkin
Resolution: Unresolved Votes: 0
Labels: affects-tests, hang

Issue Links:
Relates
relates to MDEV-31584 Assertion `thd->transaction->stmt.is_... Confirmed
relates to MDEV-26373 Various crashes & asserts and UBSAN n... Confirmed
relates to MDEV-27857 Assertion `thd->transaction->stmt.is_... Confirmed

 Description   

The following testcase, when repeated:

# Repeat 3+ times
CREATE OR REPLACE TABLE mysql.slow_log (a INT);
DROP EVENT one_event;
CREATE EVENT one_event ON SCHEDULE EVERY 10 SECOND DO SELECT 123;
SET GLOBAL slow_query_log=ON;
SET GLOBAL event_scheduler= 1;
SET GLOBAL log_output=',TABLE';
SET GLOBAL long_query_time=0.001;
SELECT SLEEP (3);

Leads to:

10.6.0 3f871b339429441ad907ecf7dfabdc414797e664 (Debug)

mysqld: /data/builds/10.6_dbg/sql/sql_parse.cc:3250: int mysql_execute_command(THD*): Assertion `thd->transaction->stmt.is_empty() || thd->in_sub_stmt' failed.

10.6.0 3f871b339429441ad907ecf7dfabdc414797e664 (Debug)

Core was generated by `/test/MD260121-mariadb-10.6.0-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:56
[Current thread is 1 (Thread 0x1490e811c700 (LWP 4114450))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1  0x0000563c9a539210 in my_write_core (sig=sig@entry=6) at /data/builds/10.6_dbg/mysys/stacktrace.c:424
#2  0x0000563c99cce2d0 in handle_fatal_signal (sig=6) at /data/builds/10.6_dbg/sql/signal_handler.cc:330
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#5  0x00001490ea4d7859 in __GI_abort () at abort.c:79
#6  0x00001490ea4d7729 in __assert_fail_base (fmt=0x1490ea66d588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x563c9a6aab70 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=0x563c9a6a72b8 "/data/builds/10.6_dbg/sql/sql_parse.cc", line=3250, function=<optimized out>) at assert.c:92
#7  0x00001490ea4e8f36 in __GI___assert_fail (assertion=assertion@entry=0x563c9a6aab70 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=file@entry=0x563c9a6a72b8 "/data/builds/10.6_dbg/sql/sql_parse.cc", line=line@entry=3250, function=function@entry=0x563c9a6aaaf8 "int mysql_execute_command(THD*)") at assert.c:101
#8  0x0000563c99a08117 in mysql_execute_command (thd=thd@entry=0x149098000db8) at /data/builds/10.6_dbg/sql/handler.h:1844
#9  0x0000563c999f615e in mysql_parse (thd=thd@entry=0x149098000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1490e811b3d0) at /data/builds/10.6_dbg/sql/sql_parse.cc:7901
#10 0x0000563c99a0424f in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x149098000db8, packet=packet@entry=0x14909801aac9 "CREATE EVENT one_event ON SCHEDULE EVERY 10 SECOND DO SELECT 123", packet_length=packet_length@entry=64) at /data/builds/10.6_dbg/sql/sql_class.h:1294
#11 0x0000563c99a07581 in do_command (thd=0x149098000db8) at /data/builds/10.6_dbg/sql/sql_parse.cc:1365
#12 0x0000563c99b63079 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x563c9c7170d8, put_in_cache=put_in_cache@entry=true) at /data/builds/10.6_dbg/sql/sql_connect.cc:1410
#13 0x0000563c99b6377d in handle_one_connection (arg=arg@entry=0x563c9c7170d8) at /data/builds/10.6_dbg/sql/sql_connect.cc:1312
#14 0x0000563c9a01643f in pfs_spawn_thread (arg=0x563c9c64b2a8) at /data/builds/10.6_dbg/storage/perfschema/pfs.cc:2201
#15 0x00001490ea9e5609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#16 0x00001490ea5d4293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

However, if you remove the second line (DROP EVENT), and repeat it a few times, you may see:

10.6.0 3f871b339429441ad907ecf7dfabdc414797e664 (Debug)

mysqld: /data/builds/10.6_dbg/sql/transaction.cc:79: bool trans_check(THD*): Assertion `thd->transaction->stmt.is_empty()' failed.

10.6.0 3f871b339429441ad907ecf7dfabdc414797e664 (Debug)

Core was generated by `/test/MD260121-mariadb-10.6.0-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:56
[Current thread is 1 (Thread 0x1495740b4700 (LWP 9775))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1  0x000055cafdb0e210 in my_write_core (sig=sig@entry=6) at /data/builds/10.6_dbg/mysys/stacktrace.c:424
#2  0x000055cafd2a32d0 in handle_fatal_signal (sig=6) at /data/builds/10.6_dbg/sql/signal_handler.cc:330
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#5  0x000014957e71a859 in __GI_abort () at abort.c:79
#6  0x000014957e71a729 in __assert_fail_base (fmt=0x14957e8b0588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55cafdc6b998 "thd->transaction->stmt.is_empty()", file=0x55cafdcae148 "/data/builds/10.6_dbg/sql/transaction.cc", line=79, function=<optimized out>) at assert.c:92
#7  0x000014957e72bf36 in __GI___assert_fail (assertion=assertion@entry=0x55cafdc6b998 "thd->transaction->stmt.is_empty()", file=file@entry=0x55cafdcae148 "/data/builds/10.6_dbg/sql/transaction.cc", line=line@entry=79, function=function@entry=0x55cafdcae69b "bool trans_check(THD*)") at assert.c:101
#8  0x000055cafd14d29b in trans_check (thd=thd@entry=0x149528000db8) at /data/builds/10.6_dbg/sql/handler.h:1844
#9  0x000055cafd14debc in trans_rollback (thd=thd@entry=0x149528000db8) at /data/builds/10.6_dbg/sql/transaction.cc:366
#10 0x000055cafcf69c78 in THD::cleanup (this=this@entry=0x149528000db8, have_mutex=have_mutex@entry=false) at /data/builds/10.6_dbg/sql/sql_class.cc:1570
#11 0x000055cafcec09a2 in unlink_thd (thd=0x149528000db8) at /data/builds/10.6_dbg/sql/mysqld.cc:2601
#12 0x000055cafd1385a5 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55cb0004f118, put_in_cache=put_in_cache@entry=true) at /data/builds/10.6_dbg/sql/sql_connect.cc:1421
#13 0x000055cafd13877d in handle_one_connection (arg=arg@entry=0x55cb0004f118) at /data/builds/10.6_dbg/sql/sql_connect.cc:1312
#14 0x000055cafd5eb43f in pfs_spawn_thread (arg=0x55cafff83158) at /data/builds/10.6_dbg/storage/perfschema/pfs.cc:2201
#15 0x000014957ec28609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#16 0x000014957e817293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Shutting down the server after a few testcases attempts where the server did not crash yet may also lead to the above result.

{noformat:title=10.5.9 927a882341eb1087e71d64de4e8cd89ab520de89 (Debug)}
mysqld: /data/builds/10.5_dbg/sql/sql_parse.cc:3398: int mysql_execute_command(THD*): Assertion `thd->transaction->stmt.is_empty() || thd->in_sub_stmt' failed.

10.5.9 927a882341eb1087e71d64de4e8cd89ab520de89 (Debug)

Core was generated by `/test/MD260121-mariadb-10.5.9-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:56
[Current thread is 1 (Thread 0x147d18081700 (LWP 240587))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1  0x00005589d4a8f64e in my_write_core (sig=sig@entry=6) at /data/builds/10.5_dbg/mysys/stacktrace.c:424
#2  0x00005589d41e41a8 in handle_fatal_signal (sig=6) at /data/builds/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:50
#5  0x0000147d192e4859 in __GI_abort () at abort.c:79
#6  0x0000147d192e4729 in __assert_fail_base (fmt=0x147d1947a588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5589d4c017d8 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=0x5589d4bfdef8 "/data/builds/10.5_dbg/sql/sql_parse.cc", line=3398, function=<optimized out>) at assert.c:92
#7  0x0000147d192f5f36 in __GI___assert_fail (assertion=assertion@entry=0x5589d4c017d8 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=file@entry=0x5589d4bfdef8 "/data/builds/10.5_dbg/sql/sql_parse.cc", line=line@entry=3398, function=function@entry=0x5589d4c01760 "int mysql_execute_command(THD*)") at assert.c:101
#8  0x00005589d3f1decc in mysql_execute_command (thd=thd@entry=0x147cc0000db8) at /data/builds/10.5_dbg/sql/handler.h:1844
#9  0x00005589d3f0b8d8 in mysql_parse (thd=thd@entry=0x147cc0000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x147d180803d0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/builds/10.5_dbg/sql/sql_parse.cc:8062
#10 0x00005589d3f19be2 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x147cc0000db8, packet=packet@entry=0x147cc001ad29 "CREATE EVENT one_event ON SCHEDULE EVERY 10 SECOND DO SELECT 123", packet_length=packet_length@entry=64, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/builds/10.5_dbg/sql/sql_class.h:1256
#11 0x00005589d3f1d32f in do_command (thd=0x147cc0000db8) at /data/builds/10.5_dbg/sql/sql_parse.cc:1370
#12 0x00005589d4078c83 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5589d6aa0f38, put_in_cache=put_in_cache@entry=true) at /data/builds/10.5_dbg/sql/sql_connect.cc:1410
#13 0x00005589d4079387 in handle_one_connection (arg=arg@entry=0x5589d6aa0f38) at /data/builds/10.5_dbg/sql/sql_connect.cc:1312
#14 0x00005589d452d79d in pfs_spawn_thread (arg=0x5589d698d9e8) at /data/builds/10.5_dbg/storage/perfschema/pfs.cc:2201
#15 0x0000147d197f2609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#16 0x0000147d193e1293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Except for an expected '2021-01-27 22:15:06 12 [ERROR] Failed to write to mysql.slow_log' error, optimized builds do not see to be affected.



 Comments   
Comment by Roel Van de Paar [ 2021-08-16 ]

Deterministic testcase thanks to MDEV-26373 testing

SET sql_mode='';
CREATE OR REPLACE TABLE mysql.general_log (a INT) ENGINE=InnoDB;
CREATE TABLE t (c INT);
SET GLOBAL general_log=1;
SET GLOBAL log_output='TABLE,TABLE';
SET SESSION tx_read_only=1;

Leads to:

10.7.0 52505bf20de0ce77a5c0b0a74af021051987bb0d (Debug)

mysqld: /test/10.7_dbg/sql/sql_parse.cc:3479: int mysql_execute_command(THD*, bool): Assertion `thd->transaction->stmt.is_empty() || thd->in_sub_stmt' failed.

10.7.0 52505bf20de0ce77a5c0b0a74af021051987bb0d (Debug)

Core was generated by `/test/MD160821-mariadb-10.7.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
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 0x15158015f700 (LWP 817549))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x0000151597606859 in __GI_abort () at abort.c:79
#2  0x0000151597606729 in __assert_fail_base (fmt=0x15159779c588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55d0d1c32088 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=0x55d0d1c2e578 "/test/10.7_dbg/sql/sql_parse.cc", line=3479, function=<optimized out>) at assert.c:92
#3  0x0000151597617f36 in __GI___assert_fail (assertion=assertion@entry=0x55d0d1c32088 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=file@entry=0x55d0d1c2e578 "/test/10.7_dbg/sql/sql_parse.cc", line=line@entry=3479, function=function@entry=0x55d0d1c32008 "int mysql_execute_command(THD*, bool)") at assert.c:101
#4  0x000055d0d0fab6bb in mysql_execute_command (thd=thd@entry=0x151540000db8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.7_dbg/sql/handler.h:1942
#5  0x000055d0d0f98ac3 in mysql_parse (thd=thd@entry=0x151540000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x15158015e400) at /test/10.7_dbg/sql/sql_parse.cc:8030
#6  0x000055d0d0fa76c8 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x151540000db8, packet=packet@entry=0x15154000b739 "SET SESSION tx_read_only=1", packet_length=packet_length@entry=26, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_class.h:1357
#7  0x000055d0d0faaae9 in do_command (thd=0x151540000db8, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_parse.cc:1404
#8  0x000055d0d1120dd6 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55d0d3b70c78, put_in_cache=put_in_cache@entry=true) at /test/10.7_dbg/sql/sql_connect.cc:1418
#9  0x000055d0d11213db in handle_one_connection (arg=arg@entry=0x55d0d3b70c78) at /test/10.7_dbg/sql/sql_connect.cc:1312
#10 0x000055d0d1589ce4 in pfs_spawn_thread (arg=0x55d0d3a56fd8) at /test/10.7_dbg/storage/perfschema/pfs.cc:2201
#11 0x0000151597b15609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#12 0x0000151597703293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.2.41 (dbg), 10.3.32 (dbg), 10.4.22 (dbg), 10.5.13 (dbg), 10.6.5 (dbg), 10.7.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.41 (opt), 10.3.32 (opt), 10.4.22 (opt), 10.5.13 (opt), 10.6.5 (opt), 10.7.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.35 (dbg), 5.7.35 (opt), 8.0.26 (dbg), 8.0.26 (opt)

Comment by Roel Van de Paar [ 2022-02-19 ]

CREATE OR REPLACE TABLE mysql.general_log (a INT) ENGINE=InnoDB;
SET GLOBAL event_scheduler=ON,general_log=1,log_output='TABLE';
SET sql_log_off=ON;

Leads to:

10.9.0 b5852ffbeebc3000982988383daeefb0549e058a (Debug)

mysqld: /test/10.9_dbg/sql/sql_parse.cc:3477: int mysql_execute_command(THD*, bool): Assertion `thd->transaction->stmt.is_empty() || thd->in_sub_stmt' failed.

10.9.0 b5852ffbeebc3000982988383daeefb0549e058a (Debug)

Core was generated by `/test/MD140222-mariadb-10.9.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
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 0x14efa59ec700 (LWP 3819107))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x000014efc5498859 in __GI_abort () at abort.c:79
#2  0x000014efc5498729 in __assert_fail_base (fmt=0x14efc562e588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5563fb464b88 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=0x5563fb460eb8 "/test/10.9_dbg/sql/sql_parse.cc", line=3477, function=<optimized out>) at assert.c:92
#3  0x000014efc54a9f36 in __GI___assert_fail (assertion=assertion@entry=0x5563fb464b88 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=file@entry=0x5563fb460eb8 "/test/10.9_dbg/sql/sql_parse.cc", line=line@entry=3477, function=function@entry=0x5563fb464b08 "int mysql_execute_command(THD*, bool)") at assert.c:101
#4  0x00005563fa78cfca in mysql_execute_command (thd=thd@entry=0x14ef04000db8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.9_dbg/sql/handler.h:1882
#5  0x00005563fa77a315 in mysql_parse (thd=thd@entry=0x14ef04000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14efa59eb400) at /test/10.9_dbg/sql/sql_parse.cc:8027
#6  0x00005563fa788fb1 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14ef04000db8, packet=packet@entry=0x14ef0400b889 "SET sql_log_off=ON", packet_length=packet_length@entry=18, blocking=blocking@entry=true) at /test/10.9_dbg/sql/sql_class.h:1362
#7  0x00005563fa78c3f8 in do_command (thd=0x14ef04000db8, blocking=blocking@entry=true) at /test/10.9_dbg/sql/sql_parse.cc:1402
#8  0x00005563fa906fc4 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5563fe441df8, put_in_cache=put_in_cache@entry=true) at /test/10.9_dbg/sql/sql_connect.cc:1418
#9  0x00005563fa9075c9 in handle_one_connection (arg=arg@entry=0x5563fe441df8) at /test/10.9_dbg/sql/sql_connect.cc:1312
#10 0x00005563fad8dd67 in pfs_spawn_thread (arg=0x5563fe384838) at /test/10.9_dbg/storage/perfschema/pfs.cc:2201
#11 0x000014efc59a7609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#12 0x000014efc5595293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.2.42 (dbg), 10.3.33 (dbg), 10.4.23 (dbg), 10.5.14 (dbg), 10.6.6 (dbg), 10.7.2 (dbg), 10.8.1 (dbg), 10.9.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.42 (opt), 10.3.33 (opt), 10.4.23 (opt), 10.5.14 (opt), 10.6.6 (opt), 10.7.2 (opt), 10.8.1 (opt), 10.9.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.36 (dbg), 5.7.36 (opt), 8.0.27 (dbg), 8.0.27 (opt)

Comment by Roel Van de Paar [ 2022-02-19 ]

Additional stacks with this testcase:

# Repeat 1-2 times
CREATE OR REPLACE TABLE mysql.general_log (a INT);
SET SESSION sql_log_off=ON;
SET GLOBAL event_scheduler=ON,general_log=1,log_output='TABLE';
CREATE EVENT two_event ON SCHEDULE EVERY 20 SECOND ON COMPLETION NOT PRESERVE COMMENT 'two EVENT' DO SELECT 123;

Leads to:

10.9.0 b5852ffbeebc3000982988383daeefb0549e058a (Debug)

mysqld: /test/10.9_dbg/sql/sql_parse.cc:3477: int mysql_execute_command(THD*, bool): Assertion `thd->transaction->stmt.is_empty() || thd->in_sub_stmt' failed.

10.9.0 b5852ffbeebc3000982988383daeefb0549e058a (Debug)

Core was generated by `/test/MD140222-mariadb-10.9.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
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 0x154a440ca700 (LWP 389837))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x0000154a4ebc4859 in __GI_abort () at abort.c:79
#2  0x0000154a4ebc4729 in __assert_fail_base (fmt=0x154a4ed5a588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55c8545e5b88 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=0x55c8545e1eb8 "/test/10.9_dbg/sql/sql_parse.cc", line=3477, function=<optimized out>) at assert.c:92
#3  0x0000154a4ebd5f36 in __GI___assert_fail (assertion=assertion@entry=0x55c8545e5b88 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=file@entry=0x55c8545e1eb8 "/test/10.9_dbg/sql/sql_parse.cc", line=line@entry=3477, function=function@entry=0x55c8545e5b08 "int mysql_execute_command(THD*, bool)") at assert.c:101
#4  0x000055c85390dfca in mysql_execute_command (thd=0x1549c00019f8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.9_dbg/sql/handler.h:1882
#5  0x000055c8538261cc in sp_instr_stmt::exec_core (this=0x1549c4003840, thd=<optimized out>, nextp=0x154a440c8a8c) at /test/10.9_dbg/sql/sp_head.cc:3834
#6  0x000055c853834c4b in sp_lex_keeper::reset_lex_and_exec_core (this=this@entry=0x1549c4003888, thd=thd@entry=0x1549c00019f8, nextp=nextp@entry=0x154a440c8a8c, open_tables=open_tables@entry=false, instr=instr@entry=0x1549c4003840) at /test/10.9_dbg/sql/sp_head.cc:3560
#7  0x000055c853835566 in sp_instr_stmt::execute (this=0x1549c4003840, thd=0x1549c00019f8, nextp=0x154a440c8a8c) at /test/10.9_dbg/sql/sp_head.cc:3740
#8  0x000055c85382cbcd in sp_head::execute (this=this@entry=0x1549c4001cb0, thd=thd@entry=0x1549c00019f8, merge_da_on_success=merge_da_on_success@entry=true) at /test/10.9_dbg/sql/sp_head.cc:1437
#9  0x000055c85382f24e in sp_head::execute_procedure (this=this@entry=0x1549c4001cb0, thd=thd@entry=0x1549c00019f8, args=args@entry=0x154a440c9230) at /test/10.9_dbg/sql/sp_head.cc:2424
#10 0x000055c853a5f650 in Event_job_data::execute (this=this@entry=0x154a440c9b40, thd=thd@entry=0x1549c00019f8, drop=<optimized out>) at /test/10.9_dbg/sql/event_data_objects.cc:1485
#11 0x000055c853e05157 in Event_worker_thread::run (this=this@entry=0x154a440c9ddf, thd=thd@entry=0x1549c00019f8, event=event@entry=0x1549c0000f70) at /test/10.9_dbg/sql/event_scheduler.cc:323
#12 0x000055c853e05343 in event_worker_thread (arg=arg@entry=0x1549c0000f70) at /test/10.9_dbg/sql/event_scheduler.cc:268
#13 0x000055c853f0ed67 in pfs_spawn_thread (arg=0x55c856297118) at /test/10.9_dbg/storage/perfschema/pfs.cc:2201
#14 0x0000154a4f0d3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#15 0x0000154a4ecc1293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

10.4.23 12cad0c3468d734e041d4ef0cd5a26d2a28606fc (Debug)

mysqld: /test/10.4_dbg/sql/sql_parse.cc:3502: int mysql_execute_command(THD*): Assertion `thd->transaction.stmt.is_empty() || thd->in_sub_stmt' failed.

10.4.23 12cad0c3468d734e041d4ef0cd5a26d2a28606fc (Debug)

Core was generated by `/test/MD290122-mariadb-10.4.23-linux-x86_64-dbg/bin/mysqld --no-defaults --core'.
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 0x154db4056700 (LWP 390159))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x0000154dca790859 in __GI_abort () at abort.c:79
#2  0x0000154dca790729 in __assert_fail_base (fmt=0x154dca926588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55f6343f52c8 "thd->transaction.stmt.is_empty() || thd->in_sub_stmt", file=0x55f6343f4a18 "/test/10.4_dbg/sql/sql_parse.cc", line=3502, function=<optimized out>) at assert.c:92
#3  0x0000154dca7a1f36 in __GI___assert_fail (assertion=assertion@entry=0x55f6343f52c8 "thd->transaction.stmt.is_empty() || thd->in_sub_stmt", file=file@entry=0x55f6343f4a18 "/test/10.4_dbg/sql/sql_parse.cc", line=line@entry=3502, function=function@entry=0x55f6343f5250 "int mysql_execute_command(THD*)") at assert.c:101
#4  0x000055f6337138e0 in mysql_execute_command (thd=0x154d540015b0) at /test/10.4_dbg/sql/handler.h:1790
#5  0x000055f63363e52d in sp_instr_stmt::exec_core (this=0x154d480036a0, thd=<optimized out>, nextp=0x154db4054f9c) at /test/10.4_dbg/sql/sp_head.cc:3692
#6  0x000055f63364bda5 in sp_lex_keeper::reset_lex_and_exec_core (this=this@entry=0x154d480036e8, thd=thd@entry=0x154d540015b0, nextp=nextp@entry=0x154db4054f9c, open_tables=open_tables@entry=false, instr=instr@entry=0x154d480036a0) at /test/10.4_dbg/sql/sp_head.cc:3423
#7  0x000055f63364c6f3 in sp_instr_stmt::execute (this=0x154d480036a0, thd=0x154d540015b0, nextp=0x154db4054f9c) at /test/10.4_dbg/sql/sp_head.cc:3598
#8  0x000055f6336440b2 in sp_head::execute (this=this@entry=0x154d48001d28, thd=thd@entry=0x154d540015b0, merge_da_on_success=merge_da_on_success@entry=true) at /test/10.4_dbg/sql/sp_head.cc:1364
#9  0x000055f6336464a3 in sp_head::execute_procedure (this=this@entry=0x154d48001d28, thd=thd@entry=0x154d540015b0, args=args@entry=0x154db40555c0) at /test/10.4_dbg/sql/sp_head.cc:2370
#10 0x000055f63383f445 in Event_job_data::execute (this=this@entry=0x154db4055d40, thd=thd@entry=0x154d540015b0, drop=<optimized out>) at /test/10.4_dbg/sql/event_data_objects.cc:1460
#11 0x000055f633be4571 in Event_worker_thread::run (this=this@entry=0x154db4055e4f, thd=thd@entry=0x154d540015b0, event=event@entry=0x154d54000d20) at /test/10.4_dbg/sql/event_scheduler.cc:313
#12 0x000055f633be4768 in event_worker_thread (arg=0x154d54000d20) at /test/10.4_dbg/sql/event_scheduler.cc:267
#13 0x0000154dcac9f609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#14 0x0000154dca88d293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.2.42 (dbg), 10.3.33 (dbg), 10.4.23 (dbg), 10.5.14 (dbg), 10.6.6 (dbg), 10.7.2 (dbg), 10.8.1 (dbg), 10.9.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.42 (opt), 10.3.33 (opt), 10.4.23 (opt), 10.5.14 (opt), 10.6.6 (opt), 10.7.2 (opt), 10.8.1 (opt), 10.9.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.36 (dbg), 5.7.36 (opt), 8.0.27 (dbg), 8.0.27 (opt)

Comment by Roel Van de Paar [ 2022-02-19 ]

UniqueID's seen thus far

thd->transaction->stmt.is_empty() || thd->in_sub_stmt|SIGABRT|mysql_execute_command|mysql_parse|dispatch_command|do_command
thd->transaction.stmt.is_empty() || thd->in_sub_stmt|SIGABRT|mysql_execute_command|mysql_parse|dispatch_command|do_command
thd->transaction->stmt.is_empty()|SIGABRT|trans_check|trans_rollback|THD::cleanup|unlink_thd
thd->transaction.stmt.is_empty()|SIGABRT|trans_check|trans_rollback|THD::cleanup|unlink_thd
thd->transaction->stmt.is_empty() || thd->in_sub_stmt|SIGABRT|mysql_execute_command|sp_instr_stmt::exec_core|sp_lex_keeper::reset_lex_and_exec_core|sp_instr_stmt::execute
thd->transaction.stmt.is_empty() || thd->in_sub_stmt|SIGABRT|mysql_execute_command|sp_instr_stmt::exec_core|sp_lex_keeper::reset_lex_and_exec_core|sp_instr_stmt::execute
thd->transaction->stmt.is_empty()|SIGABRT|trans_check|trans_rollback|THD::cleanup|THD::free_connection
thd->transaction.stmt.is_empty()|SIGABRT|trans_check|trans_rollback|THD::cleanup|THD::free_connection

Comment by Roel Van de Paar [ 2022-07-29 ]

New testcase, and slightly new stack

CREATE EVENT four_event ON SCHEDULE EVERY 1 SECOND DO SELECT 1;
CREATE OR REPLACE TABLE mysql.slow_log (a INT);
SET GLOBAL event_scheduler=ON;
SET GLOBAL log_output='FILE,TABLE';
SET GLOBAL slow_query_log=ON;
SET GLOBAL long_query_time=FALSE;

Leads to:

10.10.0 2db18fdb3d68d906fbd188ec570a64502ba55849 (Debug)

mysqld: /test/bb-10.10-MDEV-28883_dbg/sql/transaction.cc:79: bool trans_check(THD*): Assertion `thd->transaction->stmt.is_empty()' failed.

10.10.0 2db18fdb3d68d906fbd188ec570a64502ba55849 (Debug)

Core was generated by `/test/MDEV-28883_MD280622-mariadb-10.10.0-linux-x86_64-dbg/bin/mysqld --no-defa'.
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 0x14e790093700 (LWP 2381994))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x000014e79d1d1859 in __GI_abort () at abort.c:79
#2  0x000014e79d1d1729 in __assert_fail_base (fmt=0x14e79d367588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x558b4dd39860 "thd->transaction->stmt.is_empty()", file=0x558b4dd7c3a8 "/test/bb-10.10-MDEV-28883_dbg/sql/transaction.cc", line=79, function=<optimized out>) at assert.c:92
#3  0x000014e79d1e2fd6 in __GI___assert_fail (assertion=assertion@entry=0x558b4dd39860 "thd->transaction->stmt.is_empty()", file=file@entry=0x558b4dd7c3a8 "/test/bb-10.10-MDEV-28883_dbg/sql/transaction.cc", line=line@entry=79, function=function@entry=0x558b4dd7c8f7 "bool trans_check(THD*)") at assert.c:101
#4  0x0000558b4d2e3811 in trans_check (thd=thd@entry=0x14e70803a718) at /test/bb-10.10-MDEV-28883_dbg/sql/handler.h:1827
#5  0x0000558b4d2e444a in trans_rollback (thd=thd@entry=0x14e70803a718) at /test/bb-10.10-MDEV-28883_dbg/sql/transaction.cc:366
#6  0x0000558b4d102e3c in THD::cleanup (this=this@entry=0x14e70803a718) at /test/bb-10.10-MDEV-28883_dbg/sql/sql_class.cc:1537
#7  0x0000558b4d103f45 in THD::free_connection (this=this@entry=0x14e70803a718) at /test/bb-10.10-MDEV-28883_dbg/sql/sql_class.cc:1603
#8  0x0000558b4d10c025 in THD::~THD (this=0x14e70803a718, __in_chrg=<optimized out>) at /test/bb-10.10-MDEV-28883_dbg/sql/sql_class.cc:1682
#9  0x0000558b4d10c4cd in THD::~THD (this=0x14e70803a718, __in_chrg=<optimized out>) at /test/bb-10.10-MDEV-28883_dbg/sql/sql_class.cc:1652
#10 0x0000558b4d62d442 in deinit_event_thread (thd=thd@entry=0x14e70803a718) at /test/bb-10.10-MDEV-28883_dbg/sql/event_scheduler.cc:156
#11 0x0000558b4d62d956 in Event_worker_thread::run (this=this@entry=0x14e790092e2f, thd=0x14e70803a718, event=0x14e708018f60) at /test/bb-10.10-MDEV-28883_dbg/sql/event_scheduler.cc:342
#12 0x0000558b4d62d9eb in event_worker_thread (arg=<optimized out>) at /test/bb-10.10-MDEV-28883_dbg/sql/event_scheduler.cc:268
#13 0x000014e79d6e2609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#14 0x000014e79d2ce133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

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