Details
-
Bug
-
Status: Confirmed (View Workflow)
-
Major
-
Resolution: Unresolved
-
10.3(EOL), 10.4(EOL), 10.5, 10.6, 10.7(EOL), 10.8(EOL), 10.9(EOL), 10.10(EOL)
-
None
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)
Attachments
Issue Links
- relates to
-
-
- Confirmed
-
- split to
-
-
- Confirmed
-
Activity
Roel, thanks for a pretty clear report! What do you mean in 'UniqueID' ? Would it something that developers can make use of?
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
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?)?
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.
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
|
It looks like some elements in this bug are related to 1) replication while some other elements are related to 2) setting enforce_storage_engine.
SET sql_mode=''; |
SET enforce_storage_engine=InnoDB; |
SET GLOBAL tx_read_only=1; |
SET GLOBAL general_log='ON'; |
ALTER TABLE mysql.general_log ENGINE=MyISAM; |
SET GLOBAL init_slave='SELECT 1'; |
SET GLOBAL log_output="FILE,TABLE"; |
CHANGE MASTER TO master_host='127.0.0.1'; |
Also leads to:
thd->transaction->stmt.is_empty() || thd->in_sub_stmt|SIGABRT|mysql_execute_command|mysql_parse|dispatch_command|do_command
|
However, removing the sql_mode we'll see this:
|
11.5.0 eeba940311ed17d160023280783fd2bbb64abef3 (Debug) |
11.5.0-dbg>ALTER TABLE mysql.general_log ENGINE=MyISAM;
|
ERROR 1286 (42000): Unknown storage engine 'MyISAM'
|
And the engine stays CSV. However, leaving the sql_mode in the testcase, we see:
|
11.5.0 eeba940311ed17d160023280783fd2bbb64abef3 (Debug) |
11.5.0-dbg>ALTER TABLE mysql.general_log ENGINE=MyISAM;
|
Query OK, 0 rows affected, 1 warning (0.023 sec)
|
Records: 0 Duplicates: 0 Warnings: 1
|
|
|
11.5.0-dbg>SHOW WARNINGS;
|
+-------+------+-----------------------------------------------------+
|
| Level | Code | Message |
|
+-------+------+-----------------------------------------------------+
|
| Note | 1266 | Using storage engine InnoDB for table 'general_log' |
|
+-------+------+-----------------------------------------------------+
|
1 row in set (0.000 sec)
|
Yet outright attempting InnoDB will result in:
|
11.5.0 eeba940311ed17d160023280783fd2bbb64abef3 (Debug) |
11.5.0-dbg>ALTER TABLE mysql.general_log ENGINE=InnoDB;
|
ERROR 1579 (HY000): Storage engine InnoDB cannot be used for log tables
|
Irrespective of whether sql_mode is used or not. This potentially shows an enforce_storage_engine bug.
Additionally, the full testcase with an additional START SLAVE SQL_THREAD; produces another stack on Optimized builds, but this looks to be a different (InnoDB) bug.
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_commandthd->transaction.stmt.is_empty() || thd->in_sub_stmt|SIGABRT|mysql_execute_command|mysql_parse|dispatch_command|execute_init_commandthd->transaction.stmt.is_empty() || thd->in_sub_stmt|SIGABRT|mysql_execute_command|mysql_parse|dispatch_command|do_commandthd->transaction->stmt.is_empty() || thd->in_sub_stmt|SIGABRT|mysql_execute_command|mysql_parse|dispatch_command|do_command