[MDEV-20493] Server fails to produce a crash report with a stack trace in the error log Created: 2019-09-04  Updated: 2023-04-27

Status: Open
Project: MariaDB Server
Component/s: Prepared Statements, Server
Affects Version/s: 10.1, 10.2, 10.3, 10.4
Fix Version/s: 10.4

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Dmitry Shulga
Resolution: Unresolved Votes: 1
Labels: None

Issue Links:
Relates
relates to MDEV-19194 Server crash or ASAN use-after-poison... Confirmed

 Description   

This bug is not about the crash itself, this crash is reported as MDEV-19194. The test case is almost the same, with an addition of a prepared statement running SLEEP at the time of the crash. The difference it makes is that with this addition, the server reliably (at least for me, as of the moment, on all 10.x versions) fails to produce any stack trace in the error log. Without the PS with sleep it produces the stack trace from MDEV-19194 as expected.

It is a real problem, as we often receive similar meaningless error logs from customers and users. It needs to be solved, if at all possible.

--source include/have_innodb.inc
 
 
 
CREATE TABLE tx (pk INT PRIMARY KEY) ENGINE=InnoDB;
 
CREATE TABLE t1 (a INT, CONSTRAINT fk FOREIGN KEY (a) REFERENCES tx(pk)) ENGINE=InnoDB;
 
 
 
--connect (con1,localhost,root,,)
 
PREPARE stmt FROM ' SELECT SLEEP(0.001)';
 
--send
 
    EXECUTE stmt;
 
 
 
--connection default
 
ALTER IGNORE TABLE t1 DROP FOREIGN KEY fk, DROP FOREIGN KEY fk, ALGORITHM=COPY;
 
 
# Cleanup
 
--connection con1
 
--reap
 
--disconnect con1
 
--connection default
 
DROP TABLE t1, tx;

10.4 debug 18af13b8

 
Version: '10.4.8-MariaDB-debug-log'  socket: '/data/bld/10.4-debug-nightly/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
 
190904 15:08:20 [ERROR] mysqld got signal 11 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.4.8-MariaDB-debug-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=2
 
max_threads=153
 
thread_count=8
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63616 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7f54d4000b00
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x7f551a257e70 thread_stack 0x49000

If we look at all threads in the coredump, the thread 1 is the PS thread, not the crashing ALTER:

Thread 1 (Thread 0x7f551a20d700 (LWP 27039)):
 
#0  0x0000559d7a47fa95 in Protocol::send_result_set_row (this=0x7f54c80010c8, row_items=0x7f54c801afd8) at /data/src/10.4/sql/protocol.cc:1035
 
#1  0x0000559d7a536138 in select_send::send_data (this=0x7f54c801bd10, items=...) at /data/src/10.4/sql/sql_class.cc:3003
 
#2  0x0000559d7a5fe727 in JOIN::exec_inner (this=0x7f54c8011ee8) at /data/src/10.4/sql/sql_select.cc:4259
 
#3  0x0000559d7a5fdfc4 in JOIN::exec (this=0x7f54c8011ee8) at /data/src/10.4/sql/sql_select.cc:4173
 
#4  0x0000559d7a5ff6e7 in mysql_select (thd=0x7f54c8000b00, tables=0x0, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2416184064, result=0x7f54c801bd10, unit=0x7f54c80193a8, select_lex=0x7f54c801ae90) at /data/src/10.4/sql/sql_select.cc:4605
 
#5  0x0000559d7a5ef4c7 in handle_select (thd=0x7f54c8000b00, lex=0x7f54c80192e0, result=0x7f54c801bd10, setup_tables_done_option=0) at /data/src/10.4/sql/sql_select.cc:425
 
#6  0x0000559d7a5b57a2 in execute_sqlcom_select (thd=0x7f54c8000b00, all_tables=0x0) at /data/src/10.4/sql/sql_parse.cc:6357
 
#7  0x0000559d7a5aad4c in mysql_execute_command (thd=0x7f54c8000b00) at /data/src/10.4/sql/sql_parse.cc:3899
 
#8  0x0000559d7a5d99a2 in Prepared_statement::execute (this=0x7f54c8018e80, expanded_query=0x7f551a20b560, open_cursor=false) at /data/src/10.4/sql/sql_prepare.cc:4760
 
#9  0x0000559d7a5d7da7 in Prepared_statement::execute_loop (this=0x7f54c8018e80, expanded_query=0x7f551a20b560, open_cursor=false, packet=0x0, packet_end=0x0) at /data/src/10.4/sql/sql_prepare.cc:4246
 
#10 0x0000559d7a5d57e5 in mysql_sql_stmt_execute (thd=0x7f54c8000b00) at /data/src/10.4/sql/sql_prepare.cc:3363
 
#11 0x0000559d7a5aad91 in mysql_execute_command (thd=0x7f54c8000b00) at /data/src/10.4/sql/sql_parse.cc:3915
 
#12 0x0000559d7a5b98ec in mysql_parse (thd=0x7f54c8000b00, rawbuf=0x7f54c8011d58 "EXECUTE stmt", length=12, parser_state=0x7f551a20c170, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7909
 
#13 0x0000559d7a5a48ec in dispatch_command (command=COM_QUERY, thd=0x7f54c8000b00, packet=0x7f54c8008321 "", packet_length=12, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1843
 
#14 0x0000559d7a5a2f36 in do_command (thd=0x7f54c8000b00) at /data/src/10.4/sql/sql_parse.cc:1360
 
#15 0x0000559d7a72cc47 in do_handle_one_connection (connect=0x559d7ecea290) at /data/src/10.4/sql/sql_connect.cc:1412
 
#16 0x0000559d7a72c996 in handle_one_connection (arg=0x559d7ecea290) at /data/src/10.4/sql/sql_connect.cc:1316
 
#17 0x0000559d7b162da3 in pfs_spawn_thread (arg=0x559d7ec2e300) at /data/src/10.4/storage/perfschema/pfs.cc:1862
 
#18 0x00007f5526a0c4a4 in start_thread (arg=0x7f551a20d700) at pthread_create.c:456
 
#19 0x00007f5524f54d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

The crashing alter is also there, as some intermediate thread:

Thread 21 (Thread 0x7f551a258700 (LWP 27034)):
 
#0  0x00007f5524f4d603 in select () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x0000559d7b1f91f2 in my_addr_resolve (ptr=0x559d7b1d75ff <my_print_stacktrace+64>, loc=0x7f551a252570) at /data/src/10.4/mysys/my_addr_resolve.c:241
 
#2  0x0000559d7b1d7532 in print_with_addr_resolve (addrs=0x7f551a2525d0, n=15) at /data/src/10.4/mysys/stacktrace.c:254
 
#3  0x0000559d7b1d763e in my_print_stacktrace (stack_bottom=0x7f551a257e70 "", thread_stack=299008, silent=0 '\000') at /data/src/10.4/mysys/stacktrace.c:273
 
#4  0x0000559d7a908aaf in handle_fatal_signal (sig=11) at /data/src/10.4/sql/signal_handler.cc:207
 
#5  <signal handler called>
 
#6  0x0000559d7a69b312 in fk_prepare_copy_alter_table (thd=0x7f54d4000b00, table=0x7f54d4150e50, alter_info=0x7f551a255c50, alter_ctx=0x7f551a255130) at /data/src/10.4/sql/sql_table.cc:9020
 
#7  0x0000559d7a69e209 in mysql_alter_table (thd=0x7f54d4000b00, new_db=0x7f54d40052b8, new_name=0x7f54d40056c0, create_info=0x7f551a255d10, table_list=0x7f54d4013260, alter_info=0x7f551a255c50, order_num=0, order=0x0, ignore=true) at /data/src/10.4/sql/sql_table.cc:10114
 
#8  0x0000559d7a736485 in Sql_cmd_alter_table::execute (this=0x7f54d4013970, thd=0x7f54d4000b00) at /data/src/10.4/sql/sql_alter.cc:508
 
#9  0x0000559d7a5b41a3 in mysql_execute_command (thd=0x7f54d4000b00) at /data/src/10.4/sql/sql_parse.cc:6099
 
#10 0x0000559d7a5b98ec in mysql_parse (thd=0x7f54d4000b00, rawbuf=0x7f54d4013118 "ALTER IGNORE TABLE t1 DROP FOREIGN KEY fk, DROP FOREIGN KEY fk, ALGORITHM=COPY", length=78, parser_state=0x7f551a257170, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:7909
 
#11 0x0000559d7a5a48ec in dispatch_command (command=COM_QUERY, thd=0x7f54d4000b00, packet=0x7f54d419e201 "ALTER IGNORE TABLE t1 DROP FOREIGN KEY fk, DROP FOREIGN KEY fk, ALGORITHM=COPY", packet_length=78, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1843
 
#12 0x0000559d7a5a2f36 in do_command (thd=0x7f54d4000b00) at /data/src/10.4/sql/sql_parse.cc:1360
 
#13 0x0000559d7a72cc47 in do_handle_one_connection (connect=0x559d7ecea290) at /data/src/10.4/sql/sql_connect.cc:1412
 
#14 0x0000559d7a72c996 in handle_one_connection (arg=0x559d7ecea290) at /data/src/10.4/sql/sql_connect.cc:1316
 
#15 0x0000559d7b162da3 in pfs_spawn_thread (arg=0x559d7ec2df60) at /data/src/10.4/storage/perfschema/pfs.cc:1862
 
#16 0x00007f5526a0c4a4 in start_thread (arg=0x7f551a258700) at pthread_create.c:456
 
#17 0x00007f5524f54d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97



 Comments   
Comment by Elena Stepanova [ 2019-09-04 ]

Prepare statement with a sleep apparently isn't the only concurrent call which can cause it. Here are examples of other occurrences with a different first thread and empty server crash report. The actual crashing thread is the same as in the description, in fk_prepare_copy_alter_table.

Thread 1 (Thread 0x7f979d3c4700 (LWP 339221)):
 
#0  0x000055ecaf0d08ea in Protocol::send_result_set_metadata (this=0x7f97140010d8, list=0x7f979d3c2560, flags=5) at /home/elenst/src/10.2-enterprise/sql/protocol.cc:833
 
#1  0x000055ecaf16f3af in mysqld_show_warnings (thd=0x7f9714000b10, levels_to_show=7) at /home/elenst/src/10.2-enterprise/sql/sql_error.cc:852
 
#2  0x000055ecaf19bc9f in mysql_execute_command (thd=0x7f9714000b10) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:3609
 
#3  0x000055ecaf1a8e2a in mysql_parse (thd=0x7f9714000b10, rawbuf=0x7f9714011198 "SHOW WARNINGS", length=13, parser_state=0x7f979d3c3250, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:7788
 
#4  0x000055ecaf197019 in dispatch_command (command=COM_QUERY, thd=0x7f9714000b10, packet=0x7f9714008921 "", packet_length=13, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:1831
 
#5  0x000055ecaf19588c in do_command (thd=0x7f9714000b10) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:1385
 
#6  0x000055ecaf2ed68f in do_handle_one_connection (connect=0x55ecb45bf7e0) at /home/elenst/src/10.2-enterprise/sql/sql_connect.cc:1336
 
#7  0x000055ecaf2ed3da in handle_one_connection (arg=0x55ecb45bf7e0) at /home/elenst/src/10.2-enterprise/sql/sql_connect.cc:1241
 
#8  0x00007f97b4e47dd5 in start_thread () from /lib64/libpthread.so.0
 
#9  0x00007f97b3afeead in clone () from /lib64/libc.so.6


Thread 1 (Thread 0x7f13a54a2700 (LWP 338377)):
 
#0  0x00005556c3586dd2 in Alter_drop::clone (this=0x8f8f8f8f8f8f8f8f, mem_root=0x7f1328005ce0) at /home/elenst/src/10.2-enterprise/sql/sql_class.h:275
 
#1  0x00005556c358706d in list_copy_and_replace_each_value<Alter_drop> (list=..., mem_root=0x7f1328005ce0) at /home/elenst/src/10.2-enterprise/sql/sql_list.h:835
 
#2  0x00005556c3585a4e in Alter_info::Alter_info (this=0x7f13a549fd60, rhs=..., mem_root=0x7f1328005ce0) at /home/elenst/src/10.2-enterprise/sql/sql_alter.cc:45
 
#3  0x00005556c35865bc in Sql_cmd_alter_table::execute (this=0x7f1328011aa8, thd=0x7f1328000b10) at /home/elenst/src/10.2-enterprise/sql/sql_alter.cc:227
 
#4  0x00005556c3437f7b in mysql_execute_command (thd=0x7f1328000b10) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:5999
 
#5  0x00005556c343ce2a in mysql_parse (thd=0x7f1328000b10, rawbuf=0x7f1328011198 "ALTER TABLE `view_B` /* 100301 NOWAIT */ ADD KEY(`col_int_nokey`, tscol3), ALGORITHM=INPLACE, LOCK=DEFAULT  /* QNO 33207 CON_ID 16 */", length=133, parser_state=0x7f13a54a1250, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:7788
 
#6  0x00005556c342b019 in dispatch_command (command=COM_QUERY, thd=0x7f1328000b10, packet=0x7f1328068cb1 "ALTER TABLE `view_B` /*!100301 NOWAIT */ ADD KEY(`col_int_nokey`, tscol3), ALGORITHM=INPLACE, LOCK=DEFAULT  /* QNO 33207 CON_ID 16 */ ", packet_length=134, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:1831
 
#7  0x00005556c342988c in do_command (thd=0x7f1328000b10) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:1385
 
#8  0x00005556c358168f in do_handle_one_connection (connect=0x5556c92fc8a0) at /home/elenst/src/10.2-enterprise/sql/sql_connect.cc:1336
 
#9  0x00005556c35813da in handle_one_connection (arg=0x5556c92fc8a0) at /home/elenst/src/10.2-enterprise/sql/sql_connect.cc:1241
 
#10 0x00007f13bcebddd5 in start_thread () from /lib64/libpthread.so.0
 
#11 0x00007f13bbb74ead in clone () from /lib64/libc.so.6


Thread 1 (Thread 0x7fb015043700 (LWP 332908)):
 
#0  0x000055858315c439 in TABLE_LIST::prepare_security (this=0x7faf88011408, thd=0x7faf88000b10) at /home/elenst/src/10.2-enterprise/sql/table.cc:5598
 
#1  0x00005585831495a1 in mysql_make_view (thd=0x7faf88000b10, share=0x7faf88161138, table=0x7faf88011408, open_view_no_parse=false) at /home/elenst/src/10.2-enterprise/sql
 
/sql_view.cc:1734
 
#2  0x0000558582fd88e6 in open_table (thd=0x7faf88000b10, table_list=0x7faf88011408, ot_ctx=0x7fb015041000) at /home/elenst/src/10.2-enterprise/sql/sql_base.cc:1942
 
#3  0x0000558582fdbcb9 in open_and_process_table (thd=0x7faf88000b10, tables=0x7faf88011408, counter=0x7fb015041094, flags=0, prelocking_strategy=0x7fb015041110, has_preloc
 
king_list=false, ot_ctx=0x7fb015041000) at /home/elenst/src/10.2-enterprise/sql/sql_base.cc:3722
 
#4  0x0000558582fdcf6c in open_tables (thd=0x7faf88000b10, options=..., start=0x7fb015041078, counter=0x7fb015041094, flags=0, prelocking_strategy=0x7fb015041110) at /home/
 
elenst/src/10.2-enterprise/sql/sql_base.cc:4222
 
#5  0x0000558582fde7b0 in open_and_lock_tables (thd=0x7faf88000b10, options=..., tables=0x7faf88011408, derived=true, flags=0, prelocking_strategy=0x7fb015041110) at /home/
 
elenst/src/10.2-enterprise/sql/sql_base.cc:4980
 
#6  0x0000558582fd0d93 in open_and_lock_tables (thd=0x7faf88000b10, tables=0x7faf88011408, derived=true, flags=0) at /home/elenst/src/10.2-enterprise/sql/sql_base.h:518
 
#7  0x0000558583055a5a in execute_sqlcom_select (thd=0x7faf88000b10, all_tables=0x7faf88011408) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:6175
 
#8  0x000055858304c962 in mysql_execute_command (thd=0x7faf88000b10) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:3534
 
#9  0x0000558583059e2a in mysql_parse (thd=0x7faf88000b10, rawbuf=0x7faf88011198 "SELECT * FROM `view_B` INTO OUTFILE 'load_view_B'  /* QNO 28654 CON_ID 18 */", length=76, 
parser_state=0x7fb015042250, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:7788
 
#10 0x0000558583048019 in dispatch_command (command=COM_QUERY, thd=0x7faf88000b10, packet=0x7faf88008921 "SELECT * FROM `view_B` INTO OUTFILE 'load_view_B'  /* QNO 28654 CO
 
N_ID 18 */ ", packet_length=77, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:1831
 
#11 0x000055858304688c in do_command (thd=0x7faf88000b10) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:1385
 
#12 0x000055858319e68f in do_handle_one_connection (connect=0x558589cfb7e0) at /home/elenst/src/10.2-enterprise/sql/sql_connect.cc:1336
 
#13 0x000055858319e3da in handle_one_connection (arg=0x558589cfb7e0) at /home/elenst/src/10.2-enterprise/sql/sql_connect.cc:1241
 
#14 0x00007fb02ca38dd5 in start_thread () from /lib64/libpthread.so.0
 
#15 0x00007fb02b6efead in clone () from /lib64/libc.so.6


Thread 1 (Thread 0x7fb2881b3700 (LWP 315770)):
 
#0  0x0000555cfe090051 in fk_truncate_illegal_if_parent (thd=0x7fb20c000b10, table=0x7fb20c5f06d0) at /home/elenst/src/10.2-enterprise/sql/sql_truncate.cc:153
 
#1  0x0000555cfe09031a in Sql_cmd_truncate_table::handler_truncate (this=0x7fb20c0118e0, thd=0x7fb20c000b10, table_ref=0x7fb20c0112c8, is_tmp_table=false) at /home/elenst/s
 
rc/10.2-enterprise/sql/sql_truncate.cc:239
 
#2  0x0000555cfe090b22 in Sql_cmd_truncate_table::truncate_table (this=0x7fb20c0118e0, thd=0x7fb20c000b10, table_ref=0x7fb20c0112c8) at /home/elenst/src/10.2-enterprise/sql
 
/sql_truncate.cc:458
 
#3  0x0000555cfe090c94 in Sql_cmd_truncate_table::execute (this=0x7fb20c0118e0, thd=0x7fb20c000b10) at /home/elenst/src/10.2-enterprise/sql/sql_truncate.cc:515
 
#4  0x0000555cfdc3df7b in mysql_execute_command (thd=0x7fb20c000b10) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:5999
 
#5  0x0000555cfdc42e2a in mysql_parse (thd=0x7fb20c000b10, rawbuf=0x7fb20c011198 "TRUNCATE TABLE table_multipart /* QNO 31358 CON_ID 16 */", length=56, parser_state=0x7fb28
 
81b2250, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:7788
 
#6  0x0000555cfdc31019 in dispatch_command (command=COM_QUERY, thd=0x7fb20c000b10, packet=0x7fb20c068d21 "TRUNCATE TABLE table_multipart /* QNO 31358 CON_ID 16 */ ", packet
 
_length=57, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:1831
 
#7  0x0000555cfdc2f88c in do_command (thd=0x7fb20c000b10) at /home/elenst/src/10.2-enterprise/sql/sql_parse.cc:1385
 
#8  0x0000555cfdd8768f in do_handle_one_connection (connect=0x555d04ca7a60) at /home/elenst/src/10.2-enterprise/sql/sql_connect.cc:1336
 
#9  0x0000555cfdd873da in handle_one_connection (arg=0x555d04ca7a60) at /home/elenst/src/10.2-enterprise/sql/sql_connect.cc:1241
 
#10 0x00007fb2a89ecdd5 in start_thread () from /lib64/libpthread.so.0
 
#11 0x00007fb2a76a3ead in clone () from /lib64/libc.so.6

and so on

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