[MDEV-27857] Assertion `thd->transaction->stmt.is_empty() || thd->in_sub_stmt' failed from execute_init_command on START SLAVE Created: 2022-02-16  Updated: 2023-04-27

Status: Confirmed
Project: MariaDB Server
Component/s: Binary Protocol, Replication
Affects Version/s: 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: Andrei Elkin
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-24706 Assertion `thd->transaction->stmt.is_... Confirmed

 Description   

Sporadic; repeat a few times if server does not immediately crash.

CREATE OR REPLACE TABLE mysql.general_log (a INT);
SET SESSION sql_log_off=1;
SET GLOBAL init_slave='SELECT 3';
SET GLOBAL log_output='TABLE';
SET GLOBAL general_log=1;
CHANGE MASTER TO master_host='127.0.0.1';
START SLAVE sql_thread;

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 0x14dd481fb700 (LWP 1601813))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x000014dd5f6e9859 in __GI_abort () at abort.c:79
#2  0x000014dd5f6e9729 in __assert_fail_base (fmt=0x14dd5f87f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x557df50ebb88 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=0x557df50e7eb8 "/test/10.9_dbg/sql/sql_parse.cc", line=3477, function=<optimized out>) at assert.c:92
#3  0x000014dd5f6faf36 in __GI___assert_fail (assertion=assertion@entry=0x557df50ebb88 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=file@entry=0x557df50e7eb8 "/test/10.9_dbg/sql/sql_parse.cc", line=line@entry=3477, function=function@entry=0x557df50ebb08 "int mysql_execute_command(THD*, bool)") at assert.c:101
#4  0x0000557df4413fca in mysql_execute_command (thd=thd@entry=0x14dca8001c58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.9_dbg/sql/handler.h:1882
#5  0x0000557df4401315 in mysql_parse (thd=thd@entry=0x14dca8001c58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14dd481f9d90) at /test/10.9_dbg/sql/sql_parse.cc:8027
#6  0x0000557df440ffb1 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14dca8001c58, packet=packet@entry=0x14dca8010590 "SELECT 3", packet_length=packet_length@entry=8, blocking=blocking@entry=true) at /test/10.9_dbg/sql/sql_class.h:1362
#7  0x0000557df4412957 in execute_init_command (thd=0x14dca8001c58, init_command=<optimized out>, var_lock=<optimized out>) at /test/10.9_dbg/sql/sql_parse.cc:954
#8  0x0000557df43227eb in handle_slave_sql (arg=arg@entry=0x557df7fedfe0) at /test/10.9_dbg/sql/slave.cc:5520
#9  0x0000557df4a14d67 in pfs_spawn_thread (arg=0x557df7ecb9b8) at /test/10.9_dbg/storage/perfschema/pfs.cc:2201
#10 0x000014dd5fbf8609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#11 0x000014dd5f7e6293 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)



 Comments   
Comment by Roel Van de Paar [ 2022-02-16 ]

UniqueID's seen across versions (dbg builds)

thd->transaction->stmt.is_empty() || thd->in_sub_stmt|SIGABRT|mysql_execute_command|mysql_parse|dispatch_command|execute_init_command 
thd->transaction.stmt.is_empty() || thd->in_sub_stmt|SIGABRT|mysql_execute_command|mysql_parse|dispatch_command|execute_init_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() || thd->in_sub_stmt|SIGABRT|mysql_execute_command|mysql_parse|dispatch_command|do_command

Comment by Andrei Elkin [ 2022-02-16 ]

Roel, thanks for a pretty clear report! What do you mean in 'UniqueID' ? Would it something that developers can make use of?

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

Elkin Thank you for the nice comment. When I started at MariaDB, I developed a UniqueID system which will take the form of

ASSERT_MESSAGE|SIGABRT|1st_frame|2nd_frame|3rd_frame|4th_frame

or

SIGSEGV|1st_frame|2nd_frame|3rd_frame|4th_frame

It has been super handy to filter out existing bugs from test run results. The list regularly gets checked for fixed bugs. You can see the full list here: https://github.com/mariadb-corporation/mariadb-qa/blob/master/known_bugs.strings - fixed bugs are at the end of the list and bug numbers are near the end of each line. The current bugs are under the ##### CURRENT BUGS ##### header around line 65-70.

More recently I also developed a similar system for *SAN bugs. Here is the list for this one: https://github.com/mariadb-corporation/mariadb-qa/blob/master/known_bugs.strings.SAN

The script for crashes/asserts/cores is build into the pquery framework but can likely be used to just run against any core dump with a few minor updates (if any) to generate a UniqueID. The *SAN UniqueID script is here.

If you end up testing the crash/assert/core script against a setup, let me know and I can make some patches if required, likely just minor path provisions/adjustments etc. (we use tarball builds in our test setups, as they are handy to go back to previous setups quickly when needed).

You can also search the known asserts/crashes bug list with:

set +H && grep --binary-files=text -Fi "mybug" known_bugs.strings    # mybug: The full UniqueID

And one can also use partial searches (one specific frame out of the first four for example). I think this is handy for support team to see if a bug they ran into is known already, with either exact or partial matching.

Finally, I have found UniqueID's handy to more easily/visually see - like in the last comment - how offset various stacks (and or signals/asserts) are. Hence I regularly post them to bug reports if there are more than 1-2 so developers are aided in their work.

Hope this helps

Comment by Andrei Elkin [ 2022-02-17 ]

Roel, thanks for reminding me! It makes sense to classify the assert/segfault stack such a way. Unique-ness though is pseudo strongly speaking, correct? I mean a stack can vary across the versions.

Couple of questions from a potential user :

You said about ' The list regularly gets checked for fixed bugs', which must mean an existing record in CURRENT BUGS gets relocated
(upward ?) or just just discarded?

How/when CURRENT BUGS section is populated? I am guessing - somehow manually by you. If so could be integrated with BB and done automatically (e.g by a mtr post-run hook?)?

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

Elkin Yes. However, we keep track of all differences in stacks (i.e. the framework checks all versions in both dbg+opt and lists all newly seen UniqueID's and all those get added to the known bugs list, leading to some lines that look very similar. Note this is up to the 4th (in "most significant" order) frame, which is enough to identify as good as all crashing/asserting bugs.

Any new UniqueID seen, in any version (MariaDB only, not MySQL), gets added to the top of "CURRENT BUGS". Once it is fixed, it moves all the way to the end of the file under FIXED BUGS. I guess the location in the file (except for CURRENT vs FIXED) does not matter as the grep will show it either with a leading "#" (i.e. fixed) as well as the text "Fixed" before the bug number, or without those two reminders and in such case it is almost definitely (unless it was recently changed) an open/current bug.

All bugs/updates are added manually when we see them in testing. The "fixed" updates are semi-automatic (scripted, with manual finalization). Some BB integration may be possible, however it would require some thinking/discussion on best approaches and foreseeable ROI.

Comment by Ramesh Sivaraman [ 2022-06-09 ]

Reproduced the similar crash without async replication commands.

SET GLOBAL log_output='TABLE';
SET SESSION sql_mode='no_auto_value_on_zero';
SET SESSION enforce_storage_engine=InnoDB;
ALTER TABLE mysql.general_log ENGINE=MyISAM;
SET GLOBAL general_log=1;
SELECT 1;

10.4.25 8a322b6b0ce1b2f9ae1c057d0c47fd7ac414c647 (Debug)

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

10.4.25 8a322b6b0ce1b2f9ae1c057d0c47fd7ac414c647 (Debug)

Core was generated by `/test/GAL_MD200422-mariadb-10.4.25-linux-x86_64-dbg/bin/mysqld --no-defaults --'.
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 0x146cfc088700 (LWP 311095))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1  0x00005620813255f5 in my_write_core (sig=sig@entry=6) at /test/10.4_dbg/mysys/stacktrace.c:386
#2  0x0000562080a7f01e in handle_fatal_signal (sig=6) at /test/10.4_dbg/sql/signal_handler.cc:356
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#5  0x0000146cfda71859 in __GI_abort () at abort.c:79
#6  0x0000146cfda71729 in __assert_fail_base (fmt=0x146cfdc07588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5620814b0428 "thd->transaction.stmt.is_empty() || thd->in_sub_stmt", file=0x5620814afb78 "/test/10.4_dbg/sql/sql_parse.cc", line=3518, function=<optimized out>) at assert.c:92
#7  0x0000146cfda83006 in __GI___assert_fail (assertion=assertion@entry=0x5620814b0428 "thd->transaction.stmt.is_empty() || thd->in_sub_stmt", file=file@entry=0x5620814afb78 "/test/10.4_dbg/sql/sql_parse.cc", line=line@entry=3518, function=function@entry=0x5620814b03b0 "int mysql_execute_command(THD*)") at assert.c:101
#8  0x00005620807c5e45 in mysql_execute_command (thd=thd@entry=0x146c90000d90) at /test/10.4_dbg/sql/handler.h:1712
#9  0x00005620807d1fd3 in mysql_parse (thd=thd@entry=0x146c90000d90, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x146cfc087490, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_parse.cc:8011
#10 0x00005620807d4a96 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x146c90000d90, packet=packet@entry=0x146c9001a371 "SELECT 1", packet_length=packet_length@entry=8, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_class.h:1201
#11 0x00005620807d83ba in do_command (thd=0x146c90000d90) at /test/10.4_dbg/sql/sql_parse.cc:1378
#12 0x0000562080918d2a in do_handle_one_connection (connect=connect@entry=0x562084287840) at /test/10.4_dbg/sql/sql_connect.cc:1420
#13 0x0000562080918e49 in handle_one_connection (arg=0x562084287840) at /test/10.4_dbg/sql/sql_connect.cc:1316
#14 0x0000146cfdf82609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#15 0x0000146cfdb6e163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

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