Bug #27563 killing noticed in SF() stack but the error gets missed in action and wrong rslt
Submitted: 31 Mar 2007 14:09 Modified: 18 Jun 2007 17:57
Reporter: Andrei Elkin Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Stored Routines Severity:S3 (Non-critical)
Version:5.0.38 OS:Any
Assigned to: Evgeny Potemkin CPU Architecture:Any

[31 Mar 2007 14:09] Andrei Elkin
Description:
if the query gets killed while executing the body of a SF() we can see that the error due to thd->killed == KILLED_QUERY is noticed and starts to be propagated upward the stack:

#0  sp_head::execute (this=0x8be2de8, thd=0x8bbdbf8) at sp_head.cc:1046
#1  0x08304d3c in sp_head::execute_function (this=0x8be2de8, thd=0x8bbdbf8, 
    argp=0x8f8f8f8f, argcount=0, return_value_fld=0x8bd3b70) at sp_head.cc:1499
#2  0x0813b1cc in Item_func_sp::execute_impl (this=0x8bd3088, thd=0x8bbdbf8, 
    return_value_fld=0x8bd3b70) at item_func.cc:5171
#3  0x081411e8 in Item_func_sp::execute (this=0x8bd3088, flp=0x8bd310c)
    at item_func.cc:5129
#4  0x081477b6 in Item_func_sp::val_int (this=0x8bd3088) at item_func.h:1441

Run till exit from #0  0x081411e8 in Item_func_sp::execute (this=0x8bd3088, 
    flp=0x8bd310c) at item_func.cc:5129
0x081477b6 in Item_func_sp::val_int (this=0x8bd3088) at item_func.h:1441

Value returned is $9 = true

the error was caught --^
~~~~~~~~~~~~~~~~~~~~~~~~

However, it gets slipped away in

#5  0x0811e640 in Item::save_in_field (this=0x8bd3088, field=0x8ba1980, 
    no_conversions=false) at item.cc:4421

  {
    longlong nr=val_int();  // <- there was the error, but the following code
                            // does not propagate it anymore

    if (null_value)
      return set_field_to_null_with_conversions(field, no_conversions);

where INSERT work continues using the result of SF() and the query completes
despite SF()'s GET_LOCK got killed.

This artifact might stand in the way of fixing bug#22725.

How to repeat:
delimiter |;
create function bug22725() 
RETURNS int(11)
DETERMINISTIC
begin
  set @a= get_lock("a", 100);
  return 1;
end|
delimiter ;|

--enable_info
create table t1 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB;
create table t2 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=MyISAM;
--disable_info
reset master;

# ta table case: killing cause rollback
# a - autocommit ON
connection con1;
select get_lock("a", 100);

(gdb) br sp_head::execute

connection con2;
let $ID= `select connection_id()`;
send insert into t1 values (bug22725(),1);

(gdb) fin
# and trace propagation of the error when con2 gets active; the error gets 
# dropped off as described

# to inflict early exit by con2 from sp_head::execute with the error
connection con1;
eval kill query $ID;

Suggested fix:
Looks like the logic of propagation like in

sub_select
  \
    evaluate_join_record

       if (error > 0 || (*report_error))  // Fatal error
          return NESTED_LOOP_ERROR;

does not apply always.
[31 Mar 2007 15:32] Andrei Elkin
An interesting and harmful(!!!) pecularity  of the bug is that what actually got inserted is wrong:

mysql> select * from t1;
+---+------+
| a | b    |
+---+------+
| 2 |    1 | 
+---+------+

To get to this I modified bug22725() to use SELECT:

create function bug22725() 
RETURNS int(11)
DETERMINISTIC
begin
  select get_lock("a", 10)  into @a;
  return 1;
end|
delimiter ;|

How to repeat remains the same, but instead of (1,1) in the table t1 there is
(2,1).
[31 Mar 2007 17:24] Andrei Elkin
And one more artifact to gather:
the client of the connection of killed query does not get any messages despite
thd->killed is KILL_QUERY after mysql_insert() (i checked mysql_update() too)
finishes.
There is something that blocks client error generation.
[31 Mar 2007 19:00] Andrei Elkin
Missed query killed error to the client might relate to another
Bug #27565 killed query of SF() is not reported correctly
[20 Apr 2007 9:30] Sveta Smirnova
Thank you for the report.

Original description verified as described using last BK sources.

gdb output:

(gdb) br sp_head::execute
Breakpoint 2 at 0x83b1bcf: file sp_head.cc, line 908.
(gdb) c
Continuing.
[New Thread -1297257552 (LWP 943)]
[New Thread -1297458256 (LWP 944)]
[Switching to Thread -1297458256 (LWP 944)]

Breakpoint 2, sp_head::execute (this=0xa383270, thd=0xa3729d8) at sp_head.cc:908
908       DBUG_ENTER("sp_head::execute");
(gdb) fin
Run till exit from #0  sp_head::execute (this=0xa383270, thd=0xa3729d8) at sp_head.cc:908
0x083b7553 in sp_head::execute_function (this=0xa383270, thd=0xa3729d8, argp=0x8f8f8f8f, argcount=0, return_value_fld=0xa37cf30) at sp_head.cc:1505
1505      err_status= execute(thd);
Value returned is $1 = true
(gdb) bt
#0  0x083b7553 in sp_head::execute_function (this=0xa383270, thd=0xa3729d8, argp=0x8f8f8f8f, argcount=0, return_value_fld=0xa37cf30) at sp_head.cc:1505
#1  0x081acb8c in Item_func_sp::execute_impl (this=0xa37c4b0, thd=0xa3729d8) at item_func.cc:5222
#2  0x081acbfc in Item_func_sp::execute (this=0xa37c4b0) at item_func.cc:5170
#3  0x081af025 in Item_func_sp::val_int (this=0xa37c4b0) at item_func.h:1444
#4  0x0817eb3f in Item::save_in_field (this=0xa37c4b0, field=0xa38ada8, no_conversions=false) at item.cc:4419
#5  0x0826b182 in fill_record (thd=0xa3729d8, ptr=0xa38ad7c, values=@0xa37c428, ignore_errors=false) at sql_base.cc:5448
#6  0x0826b247 in fill_record_n_invoke_before_triggers (thd=0xa3729d8, ptr=0xa38ad78, values=@0xa37c428, ignore_errors=false, triggers=0x0, event=TRG_EVENT_INSERT) at sql_base.cc:5491
#7  0x082a50c1 in mysql_insert (thd=0xa3729d8, table_list=0xa37c280, fields=@0xa373be4, values_list=@0xa373c08, update_fields=@0xa373bfc, update_values=@0xa373bf0, duplic=DUP_ERROR, ignore=false)
    at sql_insert.cc:679
#8  0x0823ac90 in mysql_execute_command (thd=0xa3729d8) at sql_parse.cc:3499
#9  0x08240579 in mysql_parse (thd=0xa3729d8, inBuf=0xa37c1f0 "insert into t1 values (bug22725(),1)", length=36) at sql_parse.cc:6018
#10 0x08241078 in dispatch_command (command=COM_QUERY, thd=0xa3729d8, packet=0xa374051 "insert into t1 values (bug22725(),1)", packet_length=37) at sql_parse.cc:1802
#11 0x082425e1 in do_command (thd=0xa3729d8) at sql_parse.cc:1581
#12 0x08242ace in handle_one_connection (arg=0xa3729d8) at sql_parse.cc:1193
#13 0x0045fbd4 in start_thread () from /lib/libpthread.so.0
#14 0x003b74fe in clone () from /lib/libc.so.6
(gdb) info f 4
Stack frame at 0xb2aa4150:
 eip = 0x817eb3f in Item::save_in_field(Field*, bool) (item.cc:4419); saved eip 0x826b182
 called by frame at 0xb2aa41b0, caller of frame at 0xb2aa3df0
 source language c++.
 Arglist at 0xb2aa4148, args: this=0xa37c4b0, field=0xa38ada8, no_conversions=false
 Locals at 0xb2aa4148, Previous frame's sp is 0xb2aa4150
 Saved registers:
  ebx at 0xb2aa4140, ebp at 0xb2aa4148, esi at 0xb2aa4144, eip at 0xb2aa414c
(gdb) f 4
#4  0x0817eb3f in Item::save_in_field (this=0xa37c4b0, field=0xa38ada8, no_conversions=false) at item.cc:4419
4419        longlong nr=val_int();
(gdb) print nr
$2 = 583467835530559816

Problem with SELECT is not repeatable in my environment.
[23 May 2007 14:03] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/27218

ChangeSet@1.2493, 2007-05-23 18:00:43+04:00, evgen@moonbone.local +5 -0
  Bug#27563: Stored functions and triggers wasn't throwing an error when killed.
  
  If a stored function or a trigger was killed it had aborted but no error
  was thrown. This allows the caller statement to continue without a notice.
  This may lead to a wrong data being inserted/updated to/deleted as in such
  cases the correct result of a stored function isn't guaranteed. In the case
  of triggers it allows the caller statement to ignore of kill signal and to
  waste of time because of re-evaluation of triggers that always will fail due
  to thd->killed flag still set.
  
  Now the Item_func_sp::execute() and the sp_head::execute_trigger() functions
  are checking whether a function or a trigger were killed during execution and
  throws an appropriate error if so.
  Now the fill_record() function stops filling record if an error was reported
  through thd->net.report_error.
[23 May 2007 19:27] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/27236

ChangeSet@1.2493, 2007-05-23 23:24:16+04:00, evgen@moonbone.local +5 -0
  Bug#27563: Stored functions and triggers wasn't throwing an error when killed.
  
  If a stored function or a trigger was killed it had aborted but no error
  was thrown. This allows the caller statement to continue without a notice.
  This may lead to a wrong data being inserted/updated to/deleted as in such
  cases the correct result of a stored function isn't guaranteed. In the case
  of triggers it allows the caller statement to ignore kill signal and to
  waste time because of re-evaluation of triggers that always will fail
  because thd->killed flag is still on.
  
  Now the Item_func_sp::execute() and the sp_head::execute_trigger() functions
  check whether a function or a trigger were killed during execution and
  throws an appropriate error if so.
  Now the fill_record() function stops filling record if an error was reported
  through thd->net.report_error.
[4 Jun 2007 21:21] Bugs System
Pushed into 5.1.20-beta
[4 Jun 2007 21:23] Bugs System
Pushed into 5.0.44
[18 Jun 2007 17:57] Paul Dubois
Noted in 5.0.44, 5.1.20 changelogs.
[3 Aug 2007 15:36] Konstantin Osipov
Bug #27550  	No error message if a query was interrupted with KILL QUERY statement was marked a duplicate of this bug.
[3 Aug 2007 15:38] Konstantin Osipov
Bug #27565 killed query of SF() is not reported correctly was marked a duplicate of this bug.