MySQL Lists are EOL. Please join:

List:Commits« Previous MessageNext Message »
From:Alfranio Correia Date:July 6 2009 7:42am
Subject:bzr commit into mysql-5.1-bugteam branch (alfranio.correia:2999)
Bug#44581
View as plain text  
#At file:///home/acorreia/workspace.sun/repository.mysql/bzrwork/bug-44581/mysql-5.1-bugteam-push/ based on revid:ramil@stripped

 2999 Alfranio Correia	2009-07-06
      BUG#44581 Slave stops when transaction with non-transactional table gets lock wait
      timeout
            
      In STMT and MIXED modes, a statement that changes both non-transactional and
      transactional tables must be written to the binary log whenever there are
      changes to non-transactional tables. This means that the statement gets into the
      binary log even when the changes to the transactional tables fail. In particular
      , in the presence of a failure such statement is annotated with the error number
      and wrapped in a begin/rollback. On the slave, while applying the statement, it
      is expected the same failure and the rollback prevents the transactional changes
      to be persisted.
            
      Unfortunately, statements that fail due to concurrency issues (e.g. deadlocks,
      timeouts) are logged in the same way causing the slave to stop as the statements
      are applied sequentially by the SQL Thread. To fix this bug, we automatically
      ignore concurrency failures on the slave. Specifically, the following failures
      are ignored: ER_LOCK_WAIT_TIMEOUT, ER_LOCK_DEADLOCK and ER_XA_RBDEADLOCK.

    added:
      mysql-test/suite/rpl/r/rpl_concurrency_error.result
      mysql-test/suite/rpl/t/rpl_concurrency_error-master.opt
      mysql-test/suite/rpl/t/rpl_concurrency_error.test
    modified:
      sql/log_event.cc
      sql/slave.cc
      sql/slave.h
=== added file 'mysql-test/suite/rpl/r/rpl_concurrency_error.result'
--- a/mysql-test/suite/rpl/r/rpl_concurrency_error.result	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/r/rpl_concurrency_error.result	2009-07-06 07:42:37 +0000
@@ -0,0 +1,119 @@
+stop slave;
+drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
+reset master;
+reset slave;
+drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
+start slave;
+########################################################################
+#                             Environment
+########################################################################
+CREATE TABLE t (i INT, PRIMARY KEY(i), f CHAR(8)) engine = Innodb;
+CREATE TABLE n (d DATETIME, f CHAR(32)) engine = MyIsam;
+CREATE TRIGGER tr AFTER UPDATE ON t FOR EACH ROW 
+BEGIN 
+INSERT INTO n VALUES ( now(), concat( 'updated t: ', old.f, ' -> ', new.f ) ); 
+END |
+INSERT INTO t VALUES (4,'black'), (2,'red'), (3,'yelow'), (1,'cyan');
+########################################################################
+#                     Testing ER_LOCK_WAIT_TIMEOUT
+########################################################################
+SET AUTOCOMMIT = 1;
+BEGIN;
+UPDATE t SET f = 'yellow 2' WHERE i = 3;
+SET AUTOCOMMIT = 1;
+BEGIN;
+UPDATE t SET f = 'magenta 2' WHERE f = 'red';
+ERROR HY000: Lock wait timeout exceeded; try restarting transaction
+INSERT INTO t VALUES (5 + (2 * 10),"brown");
+INSERT INTO n VALUES (now(),"brown");
+COMMIT;
+ROLLBACK;
+Warnings:
+Warning	1196	Some non-transactional changed tables couldn't be rolled back
+show binlog events from <binlog_start>;
+Log_name	Pos	Event_type	Server_id	End_log_pos	Info
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; UPDATE t SET f = 'magenta 2' WHERE f = 'red'
+master-bin.000001	#	Query	#	#	ROLLBACK
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; UPDATE t SET f = 'yellow 2' WHERE i = 3
+master-bin.000001	#	Xid	#	#	COMMIT /* XID */
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; INSERT INTO t VALUES (5 + (2 * 10),"brown")
+master-bin.000001	#	Query	#	#	use `test`; INSERT INTO n VALUES (now(),"brown")
+master-bin.000001	#	Query	#	#	ROLLBACK
+SET AUTOCOMMIT = 1;
+BEGIN;
+UPDATE t SET f = 'gray 2' WHERE i = 3;
+SET AUTOCOMMIT = 1;
+BEGIN;
+UPDATE t SET f = 'dark blue 2' WHERE f = 'red';
+ERROR HY000: Lock wait timeout exceeded; try restarting transaction
+INSERT INTO t VALUES (6 + (2 * 10),"brown");
+INSERT INTO n VALUES (now(),"brown");
+COMMIT;
+COMMIT;
+show binlog events from <binlog_start>;
+Log_name	Pos	Event_type	Server_id	End_log_pos	Info
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; UPDATE t SET f = 'dark blue 2' WHERE f = 'red'
+master-bin.000001	#	Query	#	#	ROLLBACK
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; UPDATE t SET f = 'gray 2' WHERE i = 3
+master-bin.000001	#	Xid	#	#	COMMIT /* XID */
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; INSERT INTO t VALUES (6 + (2 * 10),"brown")
+master-bin.000001	#	Query	#	#	use `test`; INSERT INTO n VALUES (now(),"brown")
+master-bin.000001	#	Xid	#	#	COMMIT /* XID */
+SET AUTOCOMMIT = 0;
+UPDATE t SET f = 'yellow 1' WHERE i = 3;
+SET AUTOCOMMIT = 0;
+UPDATE t SET f = 'magenta 1' WHERE f = 'red';
+ERROR HY000: Lock wait timeout exceeded; try restarting transaction
+INSERT INTO t VALUES (5 + (1 * 10),"brown");
+INSERT INTO n VALUES (now(),"brown");
+COMMIT;
+ROLLBACK;
+Warnings:
+Warning	1196	Some non-transactional changed tables couldn't be rolled back
+show binlog events from <binlog_start>;
+Log_name	Pos	Event_type	Server_id	End_log_pos	Info
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; UPDATE t SET f = 'magenta 1' WHERE f = 'red'
+master-bin.000001	#	Query	#	#	ROLLBACK
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; UPDATE t SET f = 'yellow 1' WHERE i = 3
+master-bin.000001	#	Xid	#	#	COMMIT /* XID */
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; INSERT INTO t VALUES (5 + (1 * 10),"brown")
+master-bin.000001	#	Query	#	#	use `test`; INSERT INTO n VALUES (now(),"brown")
+master-bin.000001	#	Query	#	#	ROLLBACK
+SET AUTOCOMMIT = 0;
+UPDATE t SET f = 'gray 1' WHERE i = 3;
+SET AUTOCOMMIT = 0;
+UPDATE t SET f = 'dark blue 1' WHERE f = 'red';
+ERROR HY000: Lock wait timeout exceeded; try restarting transaction
+INSERT INTO t VALUES (6 + (1 * 10),"brown");
+INSERT INTO n VALUES (now(),"brown");
+COMMIT;
+COMMIT;
+show binlog events from <binlog_start>;
+Log_name	Pos	Event_type	Server_id	End_log_pos	Info
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; UPDATE t SET f = 'dark blue 1' WHERE f = 'red'
+master-bin.000001	#	Query	#	#	ROLLBACK
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; UPDATE t SET f = 'gray 1' WHERE i = 3
+master-bin.000001	#	Xid	#	#	COMMIT /* XID */
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; INSERT INTO t VALUES (6 + (1 * 10),"brown")
+master-bin.000001	#	Query	#	#	use `test`; INSERT INTO n VALUES (now(),"brown")
+master-bin.000001	#	Xid	#	#	COMMIT /* XID */
+source include/diff_master_slave.inc;
+source include/diff_master_slave.inc;
+########################################################################
+#                                Cleanup
+########################################################################
+DROP TRIGGER tr;
+DROP TABLE t;
+DROP TABLE n;

=== added file 'mysql-test/suite/rpl/t/rpl_concurrency_error-master.opt'
--- a/mysql-test/suite/rpl/t/rpl_concurrency_error-master.opt	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/t/rpl_concurrency_error-master.opt	2009-07-06 07:42:37 +0000
@@ -0,0 +1 @@
+--innodb-lock-wait-timeout=1

=== added file 'mysql-test/suite/rpl/t/rpl_concurrency_error.test'
--- a/mysql-test/suite/rpl/t/rpl_concurrency_error.test	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/t/rpl_concurrency_error.test	2009-07-06 07:42:37 +0000
@@ -0,0 +1,149 @@
+###############################################################################
+#BUG#44581 Slave stops when transaction with non-transactional table gets
+#lock wait timeout
+#
+# In STMT and MIXED modes, a statement that changes both non-transactional and
+# transactional tables must be written to the binary log whenever there are
+# changes to non-transactional tables. This means that the statement gets into
+# the # binary log even when the changes to the transactional tables fail. In
+# particular, in the presence of a failure such statement is annotated with the
+# error number and wrapped in a begin/rollback. On the slave, while applying
+# the statement, it is expected the same failure and the rollback prevents the
+# transactional changes to be persisted.
+
+# This test aims to verify if a statement that updates both transactional and
+# non-transacitonal tables and fails due to concurrency problems is correctly
+# processed by the slave in the sense that the statements get into the binary
+# log, the error is ignored and only the non-transactional tables are changed.
+###############################################################################
+
+--source include/master-slave.inc
+--source include/have_innodb.inc
+--source include/have_binlog_format_statement.inc
+
+--echo ########################################################################
+--echo #                             Environment
+--echo ########################################################################
+connection master;
+
+CREATE TABLE t (i INT, PRIMARY KEY(i), f CHAR(8)) engine = Innodb;
+CREATE TABLE n (d DATETIME, f CHAR(32)) engine = MyIsam;
+
+DELIMITER |;
+CREATE TRIGGER tr AFTER UPDATE ON t FOR EACH ROW 
+BEGIN 
+  INSERT INTO n VALUES ( now(), concat( 'updated t: ', old.f, ' -> ', new.f ) ); 
+END |
+DELIMITER ;|
+
+INSERT INTO t VALUES (4,'black'), (2,'red'), (3,'yelow'), (1,'cyan');
+
+connect (conn1, 127.0.0.1,root,,);
+connect (conn2, 127.0.0.1,root,,);
+
+--echo ########################################################################
+--echo #                     Testing ER_LOCK_WAIT_TIMEOUT
+--echo ########################################################################
+
+let $type=2;
+
+while ($type)
+{
+  let $binlog_start= query_get_value("SHOW MASTER STATUS", Position, 1);
+  connection conn1;
+  if (`select $type = 2`)
+  {
+    SET AUTOCOMMIT = 1;
+    BEGIN;
+  }
+  if (`select $type = 1`)
+  {
+    SET AUTOCOMMIT = 0;
+  }
+  eval UPDATE t SET f = 'yellow $type' WHERE i = 3;
+  
+  connection conn2;
+  if (`select $type = 2`)
+  {
+    SET AUTOCOMMIT = 1;
+    BEGIN;
+  }
+  if (`select $type = 1`)
+  {
+    SET AUTOCOMMIT = 0;
+  }
+  --error ER_LOCK_WAIT_TIMEOUT
+  eval UPDATE t SET f = 'magenta $type' WHERE f = 'red';
+  eval INSERT INTO t VALUES (5 + ($type * 10),"brown");
+  INSERT INTO n VALUES (now(),"brown");
+  
+  connection conn1;
+  COMMIT;
+  
+  connection conn2;
+  ROLLBACK;
+  --source include/show_binlog_events.inc
+
+  let $binlog_start= query_get_value("SHOW MASTER STATUS", Position, 1);
+  connection conn1;
+  if (`select $type = 2`)
+  {
+    SET AUTOCOMMIT = 1;
+    BEGIN;
+  }
+  if (`select $type = 1`)
+  {
+    SET AUTOCOMMIT = 0;
+  }
+  eval UPDATE t SET f = 'gray $type' WHERE i = 3;
+  
+  connection conn2;
+  if (`select $type = 2`)
+  {
+    SET AUTOCOMMIT = 1;
+    BEGIN;
+  }
+  if (`select $type = 1`)
+  {
+    SET AUTOCOMMIT = 0;
+  }
+  --error ER_LOCK_WAIT_TIMEOUT
+  eval UPDATE t SET f = 'dark blue $type' WHERE f = 'red';
+  eval INSERT INTO t VALUES (6 + ($type * 10),"brown");
+  INSERT INTO n VALUES (now(),"brown");
+  
+  connection conn1;
+  COMMIT;
+  
+  connection conn2;
+  COMMIT;
+  --source include/show_binlog_events.inc
+  
+  dec $type;
+}
+
+connection master;
+sync_slave_with_master;
+
+connection master;
+let $diff_statement= SELECT * FROM t order by i;
+source include/diff_master_slave.inc;
+
+connection master;
+let $diff_statement= SELECT * FROM n order by d, f;
+source include/diff_master_slave.inc;
+
+--echo ########################################################################
+--echo #                                Cleanup
+--echo ########################################################################
+
+connection master;
+DROP TRIGGER tr;
+DROP TABLE t;
+DROP TABLE n;
+
+sync_slave_with_master;
+
+connection master;
+disconnect conn1;
+disconnect conn2;

=== modified file 'sql/log_event.cc'
--- a/sql/log_event.cc	2009-06-29 14:00:47 +0000
+++ b/sql/log_event.cc	2009-07-06 07:42:37 +0000
@@ -369,6 +369,34 @@ int convert_handler_error(int error, THD
   return (actual_error);
 }
 
+inline bool concurrency_error_code(int error)
+{
+  switch (error)
+  {
+  case ER_LOCK_WAIT_TIMEOUT:
+  case ER_LOCK_DEADLOCK:
+  case ER_XA_RBDEADLOCK:
+    return TRUE;
+  default: 
+    return (FALSE);
+  }
+}
+
+inline bool unexpected_error_code(int unexpected_error)
+{
+  switch (unexpected_error) 
+  {
+  case ER_NET_READ_ERROR:
+  case ER_NET_ERROR_ON_WRITE:
+  case ER_QUERY_INTERRUPTED:
+  case ER_SERVER_SHUTDOWN:
+  case ER_NEW_ABORTING_CONNECTION:
+    return(TRUE);
+  default:
+    return(FALSE);
+  }
+}
+
 /*
   pretty_print_str()
 */
@@ -3006,7 +3034,7 @@ int Query_log_event::do_apply_event(Rela
     DBUG_PRINT("query",("%s",thd->query));
 
     if (ignored_error_code((expected_error= error_code)) ||
-	!check_expected_error(thd,rli,expected_error))
+	!unexpected_error_code(expected_error))
     {
       if (flags2_inited)
         /*
@@ -3138,8 +3166,8 @@ compare_errors:
     actual_error= thd->is_error() ? thd->main_da.sql_errno() : 0;
     DBUG_PRINT("info",("expected_error: %d  sql_errno: %d",
  		       expected_error, actual_error));
-    if ((expected_error != actual_error) &&
- 	expected_error &&
+    if ((expected_error && expected_error != actual_error &&
+         !concurrency_error_code(expected_error)) &&
  	!ignored_error_code(actual_error) &&
  	!ignored_error_code(expected_error))
     {
@@ -3158,7 +3186,8 @@ Default database: '%s'. Query: '%s'",
     /*
       If we get the same error code as expected, or they should be ignored. 
     */
-    else if (expected_error == actual_error ||
+    else if ((expected_error == actual_error && 
+              !concurrency_error_code(expected_error)) ||
  	     ignored_error_code(actual_error))
     {
       DBUG_PRINT("info",("error ignored"));

=== modified file 'sql/slave.cc'
--- a/sql/slave.cc	2009-06-29 14:00:47 +0000
+++ b/sql/slave.cc	2009-07-06 07:42:37 +0000
@@ -1884,25 +1884,6 @@ static ulong read_event(MYSQL* mysql, Ma
   DBUG_RETURN(len - 1);
 }
 
-
-int check_expected_error(THD* thd, Relay_log_info const *rli,
-                         int expected_error)
-{
-  DBUG_ENTER("check_expected_error");
-
-  switch (expected_error) {
-  case ER_NET_READ_ERROR:
-  case ER_NET_ERROR_ON_WRITE:
-  case ER_QUERY_INTERRUPTED:
-  case ER_SERVER_SHUTDOWN:
-  case ER_NEW_ABORTING_CONNECTION:
-    DBUG_RETURN(1);
-  default:
-    DBUG_RETURN(0);
-  }
-}
-
-
 /*
   Check if the current error is of temporary nature of not.
   Some errors are temporary in nature, such as

=== modified file 'sql/slave.h'
--- a/sql/slave.h	2009-06-23 09:10:04 +0000
+++ b/sql/slave.h	2009-07-06 07:42:37 +0000
@@ -171,7 +171,6 @@ bool rpl_master_has_bug(const Relay_log_
 bool rpl_master_erroneous_autoinc(THD* thd);
 
 const char *print_slave_db_safe(const char *db);
-int check_expected_error(THD* thd, Relay_log_info const *rli, int error_code);
 void skip_load_data_infile(NET* net);
 
 void end_slave(); /* release slave threads */


Attachment: [text/bzr-bundle]
Thread
bzr commit into mysql-5.1-bugteam branch (alfranio.correia:2999)Bug#44581Alfranio Correia6 Jul