[MDEV-13346] Excuting a stored procedure with a cursor with a certain combination of columns craches mysqld Created: 2017-07-19  Updated: 2017-08-19  Resolved: 2017-08-19

Status: Closed
Project: MariaDB Server
Component/s: Stored routines
Affects Version/s: 10.2.3, 10.2.7, 10.2
Fix Version/s: 10.2.8

Type: Bug Priority: Major
Reporter: P.R. Water Assignee: Igor Babaev
Resolution: Fixed Votes: 2
Labels: None
Environment:

CentOS Linux release 7.3.1611 (Core) x86_64


Issue Links:
Duplicate
duplicates MDEV-13380 Signal 11 with stored procedure using... Closed

 Description   

Executing the following stored procedure will cause a crash of mysqld.

create procedure nah_foo()
modifies sql data
-- type: log
begin
  declare l_done  boolean default false;
  declare l_text  varchar(255);
  declare l_count int;
 
  declare c_cursor cursor
  for
  select concat_ws(' ','hello','world') as hello_world
  ,      count(1)                       as count_1
  from   information_schema.TABLES
  ;
 
  declare continue handler for sqlstate '02000' set l_done = true;
 
  open c_cursor;
  loop1: loop
    fetch c_cursor
    into  l_text
    ,     l_count
    ;
 
    if (l_done) then
      close c_cursor;
      leave loop1;
    end if;
  end loop;
end

call nah_foo();
ERROR 2013 (HY000): Lost connection to MySQL server during query

Below is the error log of mysqld

170719  2:42:19 [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.2.6-MariaDB-log
key_buffer_size=33554432
read_buffer_size=131072
max_used_connections=1
max_threads=52
thread_count=7
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 146994 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x7fd400000a88
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 = 0x7fd40cd21d70 thread_stack 0x49000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x7fd426518c9e]
/usr/sbin/mysqld(handle_fatal_signal+0x30d)[0x7fd425f6793d]
/lib64/libpthread.so.0(+0xf370)[0x7fd4254d6370]
/usr/sbin/mysqld(_ZN19Materialized_cursor24send_result_set_metadataEP3THDR4ListI4ItemE+0xb9)[0x7fd4260a49e9]
/usr/sbin/mysqld(_ZN18Select_materialize24send_result_set_metadataER4ListI4ItemEj+0xe3)[0x7fd4260a4b73]
mysys/stacktrace.c:268(my_print_stacktrace)[0x7fd425e302e9]
sql/sql_select.cc:17930(JOIN::exec_inner())[0x7fd425e30c83]
sql/sql_select.cc:3668(mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*))[0x7fd425e30dda]
sql/sql_select.cc:373(handle_select(THD*, LEX*, select_result*, unsigned long))[0x7fd425e3191c]
sql/sql_parse.cc:6432(execute_sqlcom_select(THD*, TABLE_LIST*))[0x7fd425dd5586]
sql/sql_parse.cc:3448(mysql_execute_command(THD*))[0x7fd425de1807]
sql/sql_cursor.cc:142(mysql_open_cursor(THD*, select_result*, Server_side_cursor**))[0x7fd4260a4547]
sql/sp_rcontext.cc:459(sp_cursor::open(THD*))[0x7fd426096d3e]
sql/sp_head.cc:3832(sp_instr_copen::exec_core(THD*, unsigned int*))[0x7fd42608c677]
sql/sp_head.cc:2997(sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*))[0x7fd426092649]
sql/sp_head.cc:3818(sp_instr_copen::execute(THD*, unsigned int*))[0x7fd4260929d8]
sql/sp_head.cc:1325(sp_head::execute(THD*, bool))[0x7fd42608f4ee]
sql/sp_head.cc:2112(sp_head::execute_procedure(THD*, List<Item>*))[0x7fd426090c3f]
sql/sql_parse.cc:2883(do_execute_sp(THD*, sp_head*))[0x7fd425dd4f36]
sql/sql_parse.cc:5797(mysql_execute_command(THD*))[0x7fd425dddf42]
sql/sql_parse.cc:7875(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x7fd425de4dee]
sql/sql_parse.cc:1812(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x7fd425de7c2f]
sql/sql_parse.cc:1364(do_command(THD*))[0x7fd425de87d1]
sql/sql_connect.cc:1354(do_handle_one_connection(CONNECT*))[0x7fd425ea883a]
sql/sql_connect.cc:1262(handle_one_connection)[0x7fd425ea895d]
/lib64/libpthread.so.0(+0x7dc5)[0x7fd4254cedc5]
/lib64/libc.so.6(clone+0x6d)[0x7fd423b2176d]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fd400011100): call nah_foo()
Connection ID (thread ID): 23
Status: NOT_KILLED
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on

This stored procedure is running fine on MariaDB 10.1.x.



 Comments   
Comment by Elena Stepanova [ 2017-07-20 ]

Thanks for the report and test case. Reproducible as described.

The problem was introduced in 10.2.3 by this commit:

commit 665045f985787d77318a17ccddd67ec3ff92f7bc
Author: Igor Babaev
Date:   Mon Nov 21 10:33:06 2016 -0800
 
    Fixed bug mdev-11081.

10.2 debug bc75c57cfc18be64f167d91c431076f581b0382b

mysqld: /data/src/10.2/sql/sql_cursor.cc:267: int Materialized_cursor::send_result_set_metadata(THD*, List<Item>&): Assertion `send_result_set_metadata.elements == item_list.elements' failed.
170720 19:48:59 [ERROR] mysqld got signal 6 ;
 
#7  0x00007f027531a312 in __GI___assert_fail (assertion=0x7f0278731ab0 "send_result_set_metadata.elements == item_list.elements", file=0x7f0278731a60 "/data/src/10.2/sql/sql_cursor.cc", line=267, function=0x7f0278731bc0 <Materialized_cursor::send_result_set_metadata(THD*, List<Item>&)::__PRETTY_FUNCTION__> "int Materialized_cursor::send_result_set_metadata(THD*, List<Item>&)") at assert.c:101
#8  0x00007f0277fd75df in Materialized_cursor::send_result_set_metadata (this=0x7f02540e5d58, thd=0x7f0254000b00, send_result_set_metadata=...) at /data/src/10.2/sql/sql_cursor.cc:267
#9  0x00007f0277fd7f52 in Select_materialize::send_result_set_metadata (this=0x7f02541767d8, list=..., flags=5) at /data/src/10.2/sql/sql_cursor.cc:452
#10 0x00007f0277c1b50d in JOIN::exec_inner (this=0x7f02541781f8) at /data/src/10.2/sql/sql_select.cc:3476
#11 0x00007f0277c1a9f6 in JOIN::exec (this=0x7f02541781f8) at /data/src/10.2/sql/sql_select.cc:3278
#12 0x00007f0277c1bb9f in mysql_select (thd=0x7f0254000b00, tables=0x7f025406cb08, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684620544, result=0x7f02541767d8, unit=0x7f025416a770, select_lex=0x7f025416aea8) at /data/src/10.2/sql/sql_select.cc:3672
#13 0x00007f0277c104ea in handle_select (thd=0x7f0254000b00, lex=0x7f025416a6a8, result=0x7f02541767d8, setup_tables_done_option=0) at /data/src/10.2/sql/sql_select.cc:373
#14 0x00007f0277bdc3c8 in execute_sqlcom_select (thd=0x7f0254000b00, all_tables=0x7f025406cb08) at /data/src/10.2/sql/sql_parse.cc:6443
#15 0x00007f0277bd2407 in mysql_execute_command (thd=0x7f0254000b00) at /data/src/10.2/sql/sql_parse.cc:3458
#16 0x00007f0277fd70c4 in mysql_open_cursor (thd=0x7f0254000b00, result=0x7f0254015d88, pcursor=0x7f0254015dc0) at /data/src/10.2/sql/sql_cursor.cc:141
#17 0x00007f0277fc501e in sp_cursor::open (this=0x7f0254015d80, thd=0x7f0254000b00) at /data/src/10.2/sql/sp_rcontext.cc:459
#18 0x00007f0277fbf89b in sp_instr_copen::exec_core (this=0x7f025406b3c0, thd=0x7f0254000b00, nextp=0x7f026b7b21c4) at /data/src/10.2/sql/sp_head.cc:3832
#19 0x00007f0277fbd965 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7f025406afa0, thd=0x7f0254000b00, nextp=0x7f026b7b21c4, open_tables=false, instr=0x7f025406b3c0) at /data/src/10.2/sql/sp_head.cc:2998
#20 0x00007f0277fbf7dc in sp_instr_copen::execute (this=0x7f025406b3c0, thd=0x7f0254000b00, nextp=0x7f026b7b21c4) at /data/src/10.2/sql/sp_head.cc:3817
#21 0x00007f0277fb91e4 in sp_head::execute (this=0x7f02540098e8, thd=0x7f0254000b00, merge_da_on_success=true) at /data/src/10.2/sql/sp_head.cc:1324
#22 0x00007f0277fbb26f in sp_head::execute_procedure (this=0x7f02540098e8, thd=0x7f0254000b00, args=0x7f02540052f8) at /data/src/10.2/sql/sp_head.cc:2113
#23 0x00007f0277bd0aec in do_execute_sp (thd=0x7f0254000b00, sp=0x7f02540098e8) at /data/src/10.2/sql/sql_parse.cc:2889
#24 0x00007f0277bd9ba2 in mysql_execute_command (thd=0x7f0254000b00) at /data/src/10.2/sql/sql_parse.cc:5799
#25 0x00007f0277bdfd88 in mysql_parse (thd=0x7f0254000b00, rawbuf=0x7f0254012378 "call nah_foo()", length=14, parser_state=0x7f026b7b3200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7879
#26 0x00007f0277bcde34 in dispatch_command (command=COM_QUERY, thd=0x7f0254000b00, packet=0x7f0254163581 "call nah_foo()", packet_length=14, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1817
#27 0x00007f0277bcc775 in do_command (thd=0x7f0254000b00) at /data/src/10.2/sql/sql_parse.cc:1362
#28 0x00007f0277d184e7 in do_handle_one_connection (connect=0x7f027a1519f0) at /data/src/10.2/sql/sql_connect.cc:1354
#29 0x00007f0277d18274 in handle_one_connection (arg=0x7f027a1519f0) at /data/src/10.2/sql/sql_connect.cc:1260
#30 0x00007f027805f922 in pfs_spawn_thread (arg=0x7f027a1ec0a0) at /data/src/10.2/storage/perfschema/pfs.cc:1862
#31 0x00007f02771ef064 in start_thread (arg=0x7f026b7b4700) at pthread_create.c:309
#32 0x00007f02753d462d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

10.2 non-debug a76c05bba060f4da5ec7c56e5634eaafb6d2ebfe

#2  <signal handler called>
#3  Materialized_cursor::send_result_set_metadata (this=this@entry=0x7fc62405c1f0, thd=0x7fc6240009a8, send_result_set_metadata=...) at /data/src/10.2/sql/sql_cursor.cc:282
#4  0x00007fc63cbf4837 in Select_materialize::send_result_set_metadata (this=0x7fc6240984f0, list=..., flags=<optimized out>) at /data/src/10.2/sql/sql_cursor.cc:452
#5  0x00007fc63c9709d3 in JOIN::exec_inner (this=this@entry=0x7fc624099f10) at /data/src/10.2/sql/sql_select.cc:3476
#6  0x00007fc63c971043 in JOIN::exec (this=this@entry=0x7fc624099f10) at /data/src/10.2/sql/sql_select.cc:3278
#7  0x00007fc63c97118c in mysql_select (thd=thd@entry=0x7fc6240009a8, tables=0x7fc624089b60, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684620544, result=0x7fc6240984f0, unit=0x7fc62408c648, select_lex=0x7fc62408cd80) at /data/src/10.2/sql/sql_select.cc:3672
#8  0x00007fc63c971b77 in handle_select (thd=thd@entry=0x7fc6240009a8, lex=lex@entry=0x7fc62408c580, result=result@entry=0x7fc6240984f0, setup_tables_done_option=setup_tables_done_option@entry=0) at /data/src/10.2/sql/sql_select.cc:373
#9  0x00007fc63c90d17e in execute_sqlcom_select (thd=thd@entry=0x7fc6240009a8, all_tables=0x7fc624089b60) at /data/src/10.2/sql/sql_parse.cc:6443
#10 0x00007fc63c9186ba in mysql_execute_command (thd=thd@entry=0x7fc6240009a8) at /data/src/10.2/sql/sql_parse.cc:3458
#11 0x00007fc63cbf4ab4 in mysql_open_cursor (thd=0x7fc6240009a8, result=0x7fc6240127c0, pcursor=0x7fc6240127f8) at /data/src/10.2/sql/sql_cursor.cc:141
#12 0x00007fc63cbe684e in sp_cursor::open (this=<optimized out>, thd=<optimized out>) at /data/src/10.2/sql/sp_rcontext.cc:459
#13 0x00007fc63cbdbd97 in sp_instr_copen::exec_core (this=0x7fc6240a2668, thd=<optimized out>, nextp=0x7fc634e54844) at /data/src/10.2/sql/sp_head.cc:3832
#14 0x00007fc63cbe2c49 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fc6240a2248, thd=thd@entry=0x7fc6240009a8, nextp=0x7fc634e54844, open_tables=open_tables@entry=false, instr=0x7fc6240a2668) at /data/src/10.2/sql/sp_head.cc:2998
#15 0x00007fc63cbe3028 in sp_instr_copen::execute (this=<optimized out>, thd=0x7fc6240009a8, nextp=<optimized out>) at /data/src/10.2/sql/sp_head.cc:3817
#16 0x00007fc63cbdeda6 in sp_head::execute (this=this@entry=0x7fc62409e760, thd=thd@entry=0x7fc6240009a8, merge_da_on_success=merge_da_on_success@entry=true) at /data/src/10.2/sql/sp_head.cc:1324
#17 0x00007fc63cbe0480 in sp_head::execute_procedure (this=0x7fc62409e760, thd=thd@entry=0x7fc6240009a8, args=0x7fc624005060) at /data/src/10.2/sql/sp_head.cc:2113
#18 0x00007fc63c90c9d6 in do_execute_sp (thd=0x7fc6240009a8, sp=<optimized out>) at /data/src/10.2/sql/sql_parse.cc:2889
#19 0x00007fc63c917354 in mysql_execute_command (thd=thd@entry=0x7fc6240009a8) at /data/src/10.2/sql/sql_parse.cc:5809
#20 0x00007fc63c91b71a in mysql_parse (thd=0x7fc6240009a8, rawbuf=<optimized out>, length=14, parser_state=0x7fc634e56210, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.2/sql/sql_parse.cc:7879
#21 0x00007fc63c91e1f9 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fc6240009a8, packet=packet@entry=0x7fc624006c19 "call nah_foo()", packet_length=packet_length@entry=14, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.2/sql/sql_parse.cc:1817
#22 0x00007fc63c91ea84 in do_command (thd=0x7fc6240009a8) at /data/src/10.2/sql/sql_parse.cc:1362
#23 0x00007fc63c9f2042 in do_handle_one_connection (connect=connect@entry=0x7fc63e5c05d8) at /data/src/10.2/sql/sql_connect.cc:1354
#24 0x00007fc63c9f21dd in handle_one_connection (arg=arg@entry=0x7fc63e5c05d8) at /data/src/10.2/sql/sql_connect.cc:1260
#25 0x00007fc63cc614a1 in pfs_spawn_thread (arg=0x7fc63e576518) at /data/src/10.2/storage/perfschema/pfs.cc:1862
#26 0x00007fc63c006064 in start_thread (arg=0x7fc634e57700) at pthread_create.c:309
#27 0x00007fc63ac7962d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Comment by Elena Stepanova [ 2017-07-31 ]

Please also see a test case in MDEV-13380.

Comment by Igor Babaev [ 2017-08-19 ]

The patch fixing this bug was pushed into the 10.2 tree.

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