bk commit into 5.0 tree (aelkin:1.2542) BUG#27571

[Andrei Elkin]

Below is the list of changes that have just been committed into a local
5.0 repository of elkin. When elkin does a push these changes will
be propagated to the main repository and, within 24 hours after the
push, to the public repository.
For information on how to access the public repository
see http://dev.mysql.com/doc/mysql/en/installing-source-tree.html

ChangeSet@stripped, 2007-10-16 18:02:13+03:00, aelkin@stripped
+5 -0
  Bug #27571 asynchronousity in setting mysql_`query`::error and
Query_log_event::error_code
  
  A query can perform completely having the local var error of mysql_$query zero,
  where $query in insert, update, delete, load,
  and be  binlogged with error_code e.g KILLED_QUERY while there is no reason do to so.
  That can happen because Query_log_event consults thd->killed flag to evaluate
  error_code.
  
  Fixed with implementing a scheme suggested and partly implemented at time of bug@22725
work-on.
  error_status is cached immediatly after the control leaves the main rows-loop. The
cached value
  is passed to Query_log_event constructor, not the default thd->killed which can be
changed
  in between of the caching and the constructing.
  
  A simulation test is provided although it can not be easily made deterministic. So it
has to be moved
  to the manual suite.
  
  The current changeset is limited to capture only UPDATE query. The rest of modifying
DMS:s will be handled
  by deploying the current pattern upon successful review of it.
  

  mysql-test/r/binlog_killed.result@stripped, 2007-10-16 18:02:11+03:00,
aelkin@stripped +52 -0
    results changed

  mysql-test/t/binlog_killed.test@stripped, 2007-10-16 18:02:11+03:00,
aelkin@stripped +93 -0
    Demonstrating that effective killing during rows-loop execution leads to the speficied
actions:
    binlog with the error for a query modified a not-transactional table and
    roll back effects for transactional table.
    
    fixing possible non-determinism with ID.

  mysql-test/t/binlog_killed_bug27571-master.opt@stripped, 2007-10-16 18:02:11+03:00,
aelkin@stripped +1 -0
    post rows-loop killing simulation's options

  mysql-test/t/binlog_killed_bug27571-master.opt@stripped, 2007-10-16 18:02:11+03:00,
aelkin@stripped +0 -0

  mysql-test/t/binlog_killed_bug27571.test@stripped, 2007-10-16 18:02:11+03:00,
aelkin@stripped +68 -0
    Checking that if killing happens inbetween of the end of rows loop and
    recording into binlog that will not lead to recording any error incl
    the killed error.

  mysql-test/t/binlog_killed_bug27571.test@stripped, 2007-10-16 18:02:11+03:00,
aelkin@stripped +0 -0

  sql/sql_update.cc@stripped, 2007-10-16 18:02:11+03:00,
aelkin@stripped +14 -34
    Impementing the fix as described in the comments left by bug@22725.
    Also simulation of killing after the loop that would affect binlogging in the old
code.

diff -Nrup a/mysql-test/r/binlog_killed.result b/mysql-test/r/binlog_killed.result
--- a/mysql-test/r/binlog_killed.result	2007-05-30 10:54:48 +03:00
+++ b/mysql-test/r/binlog_killed.result	2007-10-16 18:02:11 +03:00
@@ -9,4 +9,56 @@ insert into t2 values (null, null), (nul
 select @result /* must be zero either way */;
 @result
 0
+delete from t1;
+delete from t2;
+insert into t1 values (1,1),(2,2);
+reset master;
+begin;
+update t1 set b=11 where a=2;
+update t1 set b=b+10;
+kill query ID;
+rollback;
+select * from t1 /* must be the same as before (1,1),(2,2) */;
+a	b
+1	1
+2	2
+create function bug27563(n int) 
+RETURNS int(11)
+DETERMINISTIC
+begin
+if n > 1 then
+select get_lock("a", 10)  into @a;
+end if;
+return n;
+end|
+delete from t2;
+insert into t2 values (1,1), (2,2);
+reset master;
+select get_lock("a", 20);
+get_lock("a", 20)
+1
+update t2 set b=b + bug27563(b) order by a;
+kill query ID;
+ERROR 70100: Query execution was interrupted
+select * from t2 /* must be (1,2), (2,2) */;
+a	b
+1	2
+2	2
+show master status  /* must have the update event more to FD */;
+File	Position	Binlog_Do_DB	Binlog_Ignore_DB
+master-bin.000001	211		
+select
+(@a:=load_file("MYSQLTEST_VARDIR/tmp/binlog_killed_bug27571.binlog"))
+is not null;
+(@a:=load_file("MYSQLTEST_VARDIR/tmp/binlog_killed_bug27571.binlog"))
+is not null
+1
+select 0 /* must return 0 to mean the killed query is in */;
+0
+0
+select RELEASE_LOCK("a");
+RELEASE_LOCK("a")
+1
+drop function bug27563;
 drop table t1,t2,t3;
+end of the tests
diff -Nrup a/mysql-test/t/binlog_killed.test b/mysql-test/t/binlog_killed.test
--- a/mysql-test/t/binlog_killed.test	2007-06-07 21:25:21 +03:00
+++ b/mysql-test/t/binlog_killed.test	2007-10-16 18:02:11 +03:00
@@ -32,6 +32,7 @@ disable_abort_on_error;
 disable_query_log;
 disable_result_log;
 
+--replace_result $ID ID
 eval kill query $ID;
 
 connection con2;
@@ -99,6 +100,7 @@ let $ID= `select connection_id()`;
 send insert into t1 values (bug27563(),1);
 
 connection con1;
+--replace_result $ID ID
 eval kill query $ID;
 
 connection con2;
@@ -120,6 +122,7 @@ begin;
 send insert into t1 values (bug27563(),1);
 
 connection con1;
+--replace_result $ID ID
 eval kill query $ID;
 connection con2;
 # todo (re-record test): after bugs 27563,27565 got fixed affected rows will report zero
@@ -141,6 +144,7 @@ let $ID= `select connection_id()`;
 send insert into t2 values (bug27563(),1);
 
 connection con1;
+--replace_result $ID ID
 eval kill query $ID;
 
 connection con2;
@@ -175,6 +179,7 @@ let $ID= `select connection_id()`;
 send update t2 set b=bug27565()-1 where a=1;
 
 connection con1;
+--replace_result $ID ID
 eval kill query $ID;
 commit;
 
@@ -201,6 +206,7 @@ let $ID= `select connection_id()`;
 send insert into t3 values  (0,0),(1,bug27565());
 
 connection con1;
+--replace_result $ID ID
 eval kill query $ID;
 rollback;
 
@@ -225,6 +231,7 @@ let $ID= `select connection_id()`;
 send insert into t2 values (0,0),(1,bug27565()) /* non-ta t2 */;
 
 connection con1;
+--replace_result $ID ID
 eval kill query $ID;
 rollback;
 
@@ -244,5 +251,91 @@ drop function bug27565;
 
 system rm $MYSQLTEST_VARDIR/tmp/kill_query_calling_sp.binlog ;
 
+#
+# bug#27571 asynchronous setting mysql_`query`::error and Query_log_e::error_code
+#
+
+# checking that killing inside of select loops is safe as before
+# killing after the loop can be only simulated - another test
+
+delete from t1;
+delete from t2;
+insert into t1 values (1,1),(2,2);
+let $ID= `select connection_id()`;
+
+reset master;
+connection con1;
+begin; update t1 set b=11 where a=2;
+
+connection con2;
+send update t1 set b=b+10;
+
+connection con1;
+--replace_result $ID ID
+eval kill query $ID;
+rollback;
+
+connection con2;
+--error 0,ER_QUERY_INTERRUPTED
+reap;
+select * from t1 /* must be the same as before (1,1),(2,2) */;
+
+
+delimiter |;
+create function bug27563(n int) 
+RETURNS int(11)
+DETERMINISTIC
+begin
+  if n > 1 then
+     select get_lock("a", 10)  into @a;
+  end if;
+  return n;
+end|
+delimiter ;|
+
+
+# non-ta table case: killing must be recorded in binlog
+delete from t2;
+insert into t2 values (1,1), (2,2);
+reset master;
+connection con1;
+select get_lock("a", 20);
+
+connection con2;
+let $ID= `select connection_id()`;
+send update t2 set b=b + bug27563(b) order by a;
+
+connection con1;
+--replace_result $ID ID
+eval kill query $ID;
+
+connection con2;
+--error ER_QUERY_INTERRUPTED
+reap;
+select * from t2 /* must be (1,2), (2,2) */;
+show master status  /* must have the update event more to FD */;
+
+# a proof the query is binlogged with an error
+
+--exec $MYSQL_BINLOG --start-position=98 $MYSQLTEST_VARDIR/log/master-bin.000001 >
$MYSQLTEST_VARDIR/tmp/binlog_killed_bug27571.binlog
+--replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
+eval select
+(@a:=load_file("$MYSQLTEST_VARDIR/tmp/binlog_killed_bug27571.binlog"))
+is not null;
+--replace_result $MYSQL_TEST_DIR MYSQL_TEST_DIR
+let $error_code= `select @a like "%#%error_code=0%" /* must return 0*/`;
+eval select $error_code /* must return 0 to mean the killed query is in */;
+# bug#27571 cleanup
+
+connection con1;
+select RELEASE_LOCK("a");
+system rm $MYSQLTEST_VARDIR/tmp/binlog_killed_bug27571.binlog;
+drop function bug27563;
+
+#
+# common cleanup 
+#
+
 drop table t1,t2,t3;
 
+--echo end of the tests
diff -Nrup a/mysql-test/t/binlog_killed_bug27571-master.opt
b/mysql-test/t/binlog_killed_bug27571-master.opt
--- /dev/null	Wed Dec 31 16:00:00 196900
+++ b/mysql-test/t/binlog_killed_bug27571-master.opt	2007-10-16 18:02:11 +03:00
@@ -0,0 +1 @@
+--loose-debug=d,stop_after_row_loop_done
diff -Nrup a/mysql-test/t/binlog_killed_bug27571.test
b/mysql-test/t/binlog_killed_bug27571.test
--- /dev/null	Wed Dec 31 16:00:00 196900
+++ b/mysql-test/t/binlog_killed_bug27571.test	2007-10-16 18:02:11 +03:00
@@ -0,0 +1,68 @@
+--source include/have_innodb.inc
+--source include/not_embedded.inc
+--source include/have_log_bin.inc
+
+#
+# bug#27571 asynchronous setting mysql_`query`::error and Query_log_e::error_code
+# 
+# Checking that if killing happens inbetween of the end of rows loop and
+# recording into binlog that will not lead to recording any error incl 
+# the killed error.
+#
+
+connect (looser, localhost, root,,);
+connect (killer, localhost, root,,);
+
+create table t1 (a int auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB;
+
+delete from t1;
+insert into t1 values (1,1),(2,2);
+reset master;
+
+connection looser;
+let $ID= `select connection_id()`;
+send update t1 set b=11 where a=2;
+
+connection killer;
+sleep 1; # let 1 second for the update to get to the sleeping point
+--replace_result $ID ID
+eval kill query $ID;
+
+connection looser;
+--error 0 # zero even though the query must be got killed while it was sleepin for 5 secs
+reap;
+
+#
+# this is another possible artifact. The killed error was not caught
+# as that is logical as killing was not effective:
+# data are ok and well as binlog event is without killed error (further).
+# The reason of the following `show error' is to prove that 
+# killing simulation was effective
+#
+show errors; 
+
+connection killer;
+
+# nothing is rolled back
+
+select * from t1 where a=2 /* must be 11 */;
+
+# a proof the query is binlogged with an error
+
+--exec $MYSQL_BINLOG --start-position=98 $MYSQLTEST_VARDIR/log/master-bin.000001 >
$MYSQLTEST_VARDIR/tmp/binlog_killed_bug27571.binlog
+--replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
+eval select
+(@a:=load_file("$MYSQLTEST_VARDIR/tmp/binlog_killed_bug27571.binlog"))
+is not null;
+--replace_result $MYSQL_TEST_DIR MYSQL_TEST_DIR
+let $error_code= `select @a like "%#%error_code=0%"`;
+
+eval select $error_code  /* must return 1*/;
+
+#
+# cleanup
+#
+
+drop table t1;
+
+--echo end of the tests
diff -Nrup a/sql/sql_update.cc b/sql/sql_update.cc
--- a/sql/sql_update.cc	2007-10-13 15:49:39 +03:00
+++ b/sql/sql_update.cc	2007-10-16 18:02:11 +03:00
@@ -134,6 +134,7 @@ int mysql_update(THD *thd,
   SELECT_LEX    *select_lex= &thd->lex->select_lex;
   bool need_reopen;
   List<Item> all_fields;
+  THD::killed_state killed_status= THD::NOT_KILLED;
   DBUG_ENTER("mysql_update");
 
   LINT_INIT(timestamp_query_id);
@@ -519,43 +520,22 @@ int mysql_update(THD *thd,
       table->file->unlock_row();
     thd->row_count++;
   }
+  /*
+    caching the killed status to pass as the arg to query event constuctor;
+    the status not the cached value can change since this point 
+    still w/o any harm for binlogging.
+    It's assumed that if an error was set in combination with an effective 
+    killed status then the error is due to killing.
+  */
+  killed_status= thd->killed; // get the status of the volatile 
+  /* a test that uses the sleep in not fully deterministic */
+  DBUG_EXECUTE_IF("stop_after_row_loop_done", sleep(5););
+  error= (killed_status == THD::NOT_KILLED)?  error : 1;
+  
 
   if (!transactional_table && updated > 0)
     thd->transaction.stmt.modified_non_trans_table= TRUE;
 
-
-  /*
-    todo bug#27571: to avoid asynchronization of `error' and
-    `error_code' of binlog event constructor
-
-    The concept, which is a bit different for insert(!), is to
-    replace `error' assignment with the following lines
-
-       killed_status= thd->killed; // get the status of the volatile 
-    
-    Notice: thd->killed is type of "state" whereas the lhs has
-    "status" the suffix which translates according to WordNet: a state
-    at a particular time - at the time of the end of per-row loop in
-    our case. Binlogging ops are conducted with the status.
-
-       error= (killed_status == THD::NOT_KILLED)?  error : 1;
-    
-    which applies to most mysql_$query functions.
-    Event's constructor will accept `killed_status' as an argument:
-    
-       Query_log_event qinfo(..., killed_status);
-    
-    thd->killed might be changed after killed_status had got cached and this
-    won't affect binlogging event but other effects remain.
-
-    Open issue: In a case the error happened not because of KILLED -
-    and then KILLED was caught later still within the loop - we shall
-    do something to avoid binlogging of incorrect ER_SERVER_SHUTDOWN
-    error_code.
-  */
-
-  if (thd->killed && !error)
-    error= 1;					// Aborted
   end_read_record(&info);
   free_io_cache(table);				// If ORDER BY
   delete select;
@@ -587,7 +567,7 @@ int mysql_update(THD *thd,
       if (error < 0)
         thd->clear_error();
       Query_log_event qinfo(thd, thd->query, thd->query_length,
-			    transactional_table, FALSE);
+			    transactional_table, FALSE, killed_status);
       if (mysql_bin_log.write(&qinfo) && transactional_table)
 	error=1;				// Rollback update
     }