Bug #86260 Assert on KILL'ing a stored routine invocation
Submitted: 10 May 2017 6:47 Modified: 17 Jan 2018 17:00
Reporter: Laurynas Biveinis (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Stored Routines Severity:S2 (Serious)
Version:5.6.36 OS:Any
Assigned to: CPU Architecture:Any
Tags: KILL, regression, stored routines

[10 May 2017 6:47] Laurynas Biveinis
Description:
Killing a stored routine invocation results in a debug assert.

Assertion failed: (m_status == DA_ERROR), function sql_errno, file /Users/laurynas/percona/mysql-server/sql/sql_error.h, line 655.
06:41:26 UTC - mysqld got signal 6 ;
...
  thread #18, stop reason = signal SIGSTOP
    frame #0: 0x00007fffcb217d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fffcb3055bf libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x0000000102f30fab mysqld-debug`my_write_core(sig=6) at stacktrace.c:424
    frame #3: 0x0000000102b919c9 mysqld-debug`::handle_fatal_signal(sig=6) at signal_handler.cc:230
    frame #4: 0x00007fffcb2f8b3a libsystem_platform.dylib`_sigtramp + 26
    frame #5: 0x00007fffcb217d43 libsystem_kernel.dylib`__pthread_kill + 11
    frame #6: 0x00007fffcb3055bf libsystem_pthread.dylib`pthread_kill + 90
    frame #7: 0x00007fffcb17d420 libsystem_c.dylib`abort + 129
    frame #8: 0x00007fffcb144893 libsystem_c.dylib`__assert_rtn + 320
    frame #9: 0x0000000102a08500 mysqld-debug`Diagnostics_area::sql_errno(this=0x00007fce01981b28) const at sql_error.h:655
    frame #10: 0x0000000102ba372c mysqld-debug`sp_lex_instr::reset_lex_and_exec_core(this=0x00007fce0087e210, thd=0x00007fce0197ea00, nextp=0x00007000049d0478, open_tables=false) at sp_instr.cc:460
    frame #11: 0x0000000102ba41b1 mysqld-debug`sp_lex_instr::validate_lex_and_execute_core(this=0x00007fce0087e210, thd=0x00007fce0197ea00, nextp=0x00007000049d0478, open_tables=false) at sp_instr.cc:688
    frame #12: 0x0000000102ba4757 mysqld-debug`sp_instr_stmt::execute(this=0x00007fce0087e210, thd=0x00007fce0197ea00, nextp=0x00007000049d0478) at sp_instr.cc:865
    frame #13: 0x0000000102b9ca32 mysqld-debug`sp_head::execute(this=0x00007fce0087c610, thd=0x00007fce0197ea00, merge_da_on_success=true) at sp_head.cc:648
    frame #14: 0x0000000102b9e34b mysqld-debug`sp_head::execute_function(this=0x00007fce0087c610, thd=0x00007fce0197ea00, argp=0x8f8f8f8f8f8f8f8f, argcount=0, return_value_fld=0x00007fce019903c8) at sp_head.cc:1094
    frame #15: 0x0000000102aad64b mysqld-debug`Item_func_sp::execute_impl(this=0x00007fce0198e8b0, thd=0x00007fce0197ea00) at item_func.cc:6939
    frame #16: 0x0000000102aad38a mysqld-debug`Item_func_sp::execute(this=0x00007fce0198e8b0) at item_func.cc:6868
    frame #17: 0x0000000102ab1939 mysqld-debug`Item_func_sp::val_int(this=0x00007fce0198e8b0) at item_func.h:2133
    frame #18: 0x0000000102a381da mysqld-debug`Item::send(this=0x00007fce0198e8b0, protocol=0x00007fce0197ef68, buffer=0x00007000049d1938) at item.cc:6925
    frame #19: 0x0000000102b86827 mysqld-debug`Protocol::send_result_set_row(this=0x00007fce0197ef68, row_items=0x00007fce019810e8) at protocol.cc:844
    frame #20: 0x0000000102c2b62a mysqld-debug`select_send::send_data(this=0x00007fce0198ff10, items=0x00007fce019810e8) at sql_class.cc:2541
    frame #21: 0x0000000102c4d7b9 mysqld-debug`JOIN::exec(this=0x00007fce0198ff38) at sql_executor.cc:151
    frame #22: 0x0000000102d1dfe6 mysqld-debug`mysql_execute_select(thd=0x00007fce0197ea00, select_lex=0x00007fce01980fc8, free_join=true) at sql_select.cc:1101
    frame #23: 0x0000000102d1c5f5 mysqld-debug`mysql_select(thd=0x00007fce0197ea00, tables=0x0000000000000000, wild_num=0, fields=0x00007fce019810e8, conds=0x0000000000000000, order=0x00007fce01981190, group=0x00007fce019810c8, having=0x0000000000000000, select_options=2147748608, result=0x00007fce0198ff10, unit=0x00007fce01980980, select_lex=0x00007fce01980fc8) at sql_select.cc:1222
    frame #24: 0x0000000102d1c1e9 mysqld-debug`handle_select(thd=0x00007fce0197ea00, result=0x00007fce0198ff10, setup_tables_done_option=0) at sql_select.cc:101
    frame #25: 0x0000000102cc593d mysqld-debug`execute_sqlcom_select(thd=0x00007fce0197ea00, all_tables=0x0000000000000000) at sql_parse.cc:5182
    frame #26: 0x0000000102cbb2fa mysqld-debug`mysql_execute_command(thd=0x00007fce0197ea00) at sql_parse.cc:2690
    frame #27: 0x0000000102cb88e3 mysqld-debug`mysql_parse(thd=0x00007fce0197ea00, rawbuf="SELECT f1()", length=11, parser_state=0x00007000049d5380) at sql_parse.cc:6434
    frame #28: 0x0000000102cb51ff mysqld-debug`dispatch_command(command=COM_QUERY, thd=0x00007fce0197ea00, packet="", packet_length=11) at sql_parse.cc:1372
    frame #29: 0x0000000102cb7dfb mysqld-debug`do_command(thd=0x00007fce0197ea00) at sql_parse.cc:1039
    frame #30: 0x0000000102c3b8e2 mysqld-debug`do_handle_one_connection(thd_arg=0x00007fce0197ea00) at sql_connect.cc:982
    frame #31: 0x0000000102c3b68d mysqld-debug`::handle_one_connection(arg=0x00007fce0197ea00) at sql_connect.cc:899
    frame #32: 0x000000010330a35d mysqld-debug`::pfs_spawn_thread(arg=0x00007fcdfff54590) at pfs.cc:1860
    frame #33: 0x00007fffcb3029af libsystem_pthread.dylib`_pthread_body + 180
    frame #34: 0x00007fffcb3028fb libsystem_pthread.dylib`_pthread_start + 286
    frame #35: 0x00007fffcb302101 libsystem_pthread.dylib`thread_start + 13

How to repeat:
Source code patch for debug sync:

diff --git a/sql/sp_instr.cc b/sql/sp_instr.cc
index 2de6c99bc56..ea12e9f9b94 100644
--- a/sql/sp_instr.cc
+++ b/sql/sp_instr.cc
@@ -28,6 +28,7 @@
 #include "sql_prepare.h" // reinit_stmt_before_use
 #include "transaction.h" // trans_commit_stmt
 #include "sql_audit.h"
+#include "debug_sync.h" // DEBUG_SYNC

 #include <algorithm>

@@ -397,6 +398,8 @@ bool sp_lex_instr::reset_lex_and_exec_core(THD *thd,
   }
   else
   {
+ DEBUG_SYNC(thd, "sp_lex_instr_before_exec_core");
+
     rc= exec_core(thd, nextp);
     DBUG_PRINT("info",("exec_core returned: %d", rc));
   }

MTR testcase:

--source include/have_debug_sync.inc
--source include/count_sessions.inc

CREATE TABLE t1 (a INT);

DELIMITER |;

CREATE FUNCTION f1() RETURNS INT
BEGIN
  INSERT INTO t1 VALUES (1);
  RETURN 1;
END|

DELIMITER ;|

--connect(con1,localhost,root)

--connection default
--let $sp_con_id= `SELECT CONNECTION_ID()`
SET DEBUG_SYNC= "sp_lex_instr_before_exec_core SIGNAL sp_ready WAIT_FOR sp_finish";
send SELECT f1();

--connection con1
SET DEBUG_SYNC="now WAIT_FOR sp_ready";
--replace_result $sp_con_id sp_con_id
--eval KILL $sp_con_id
SET DEBUG_SYNC="now SIGNAL sp_finish";

--connection default
reap;

disconnect con1;

--source include/wait_until_count_sessions.inc
[10 May 2017 6:48] Laurynas Biveinis
This appears to be a regression introduced by

commit d7b37d4d141a95f577916448650c429f0d6e193d
Author: Sreeharsha Ramanavarapu <sreeharsha.ramanavarapu@oracle.com>
Date:   Wed Feb 22 11:02:07 2017 +0530

    Bug #25053286: USE VIEW WITH CONDITION IN PROCEDURE CAUSES
                   INCORRECT BEHAVIOR
    
    Issue:
    ------
    This problem occurs when a stored procedure contains a
    query with a view. While resolving the columns in the
    WHERE condition, find_field_in_view insists on creating a
    Item_direct_view_ref object every time an execution
    happens. This object is not destroyed at the end of the
    execution.
    
    In the next execution, a new object is created and will be
    appended to the free_list. Hence the size of the free_list
    is growing and the cleanup phase at the end of each execute
    takes increasingly longer time.
    
    Solution:
    ---------
    This is a regression due to the fix for BUG#19897405.
    
    Ideally the Item_direct_view_ref object (which is related
    to the view's column in WHERE clause) should be created at
    the beginning of every execution and destroyed at the end.
    This doesn't happen because the check related to the status
    (STMT_INITIALIZED_FOR_SP / STMT_EXECUTED) had been removed.
    This check has been re-introduced.
    
    Scenario 1 in BUG#19897405:
    --------------------------
    a) SP is executed--> The view fields are resolved/fixed.
    b) FLUSH TABLE <table-name>.
    c) SP is executed--> Triggers re-prepare--> Query arena
       state is not reset and remains as 'STMT_EXECUTED'.
       Previously created Item_direct_view_ref object is
       destroyed. The view fields are resolved/fixed
       using the execution mem_root. It creates a new
       Item_direct_view_ref object, this is destroyed at the
       end of the execution.
    d) SP is executed--> Server crashes while trying to access
       the resolved view columns allocated on the execution
       mem_root which was freed after execution(c).
    
    Solution to Scenario 1 in BUG#19897405:
    ---------------------------------------
    The root cause of the problem mentioned in BUG#19897405 is
    that when a re-prepare error is raised due to a
    FLUSH TABLE / DROP TABLE, the state of statement arena
    should be switched to STMT_INITIALIZED_FOR_SP. Without
    this, the statement is unaware that previously created
    Item_direct_view_ref have been destroyed after the table
    re-open. While it creates a new Item_direct_view_ref
    object, this is destroyed at the end of the execution.
    Hence the execution that follows will not have any
    Item_direct_view_ref to use.
    
    The fix here is to set the state to STMT_INITIALIZED_FOR_SP
    after the re-prepare error is raised.
    
    
    Problem 2 in BUG#19897405:
    --------------------------
    a) SP is executed--> The view fields are resolved/fixed.
    b) SP is executed--> Gets re-prepare error. Destroys
       Item_direct_view_ref object. At the end "TABLE EXISTS"
       error is raised and state is set to EXECUTED
    c) DROP TABLE <table-created-in-sp>
    d) SP is executed--> Creates new item_direct_view_ref
       object. Destroys the object at the end of the statement.
    d) DROP TABLE <table-created-in-sp>
    e) SP is executed--> Server crashes while trying to
       access the resolved view columns allocated on the
       execution mem_root which was freed after execution.
    
    Solution to Scenario 2 in BUG#19897405:
    ---------------------------------------
    CREATE TABLE ... SELECT statement in an SP requires some
    special handling. The state is always set to
    STMT_INITIALIZED_FOR_SP in such a case.
[10 May 2017 7:11] Roel Van de Paar
Also see bug 76912
[11 May 2017 5:55] Umesh Shastry
Hello Laurynas,

Thank you for the report and feedback!

Thanks,
Umesh
[11 May 2017 5:55] Umesh Shastry
test results

Attachment: 86260_5.6.36.results (application/octet-stream, text), 164.25 KiB.

[25 May 2017 9:47] Laurynas Biveinis
Bug 86260 fix for 5.6

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: bug86260-5.6.patch (application/octet-stream, text), 7.07 KiB.

[25 May 2017 9:48] Laurynas Biveinis
Bug 86260 fix for 5.7

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: bug86260-5.7.patch (application/octet-stream, text), 7.09 KiB.

[25 May 2017 9:48] Laurynas Biveinis
Bug 86260 regression testcase for 8.0.1

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: bug86260-8.0.1-testcase.patch (application/octet-stream, text), 2.39 KiB.

[25 May 2017 9:49] Laurynas Biveinis
Submitted fixes for 5.6 and 5.7. The issue did not reproduce under 8.0.1, I haven't researched why, the 8.0.1 patch contains only the testcase.
[17 Jan 2018 17:00] Paul Dubois
Posted by developer:
 
Fixed in 5.6.40, 5.7.22, 8.0.5, 9.0.0.

For debug builds, using KILL to terminate a stored routine could
raise an assertion. Thanks to Laurynas Biveinis for the patch.