Hi Alfranio,
Nice work, patch approved!
Just one minor issue, the test result file is not updated after modified
the rpl_concurrency_error.test.
Alfranio Correia wrote:
> #At
> file:///home/acorreia/workspace.sun/repository.mysql/bzrwork/bug-44581/mysql-5.1-bugteam/
> based on revid:staale.smedseng@stripped
>
> 2988 Alfranio Correia 2009-07-01
> 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.
> @ sql/slave.cc
> Moved the validation to the log_event.cc as any other error checking is done
> there.
> @ sql/slave.h
> Moved the validation to the log_event.cc as any other error checking is done
> there.
>
> 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-01 06:03:17 +0000
> @@ -0,0 +1,92 @@
> +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 t1 (i INT, PRIMARY KEY(i), f CHAR(8)) engine = Innodb;
> +CREATE TABLE t2 (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 t1 FOR EACH ROW
> +BEGIN
> +INSERT INTO n VALUES ( now(), concat( 'updated t: ', old.f, ' -> ', new.f ) );
> +END |
> +INSERT INTO t1 VALUES (4,'black'), (2,'red'), (3,'yelow'), (1,'cyan');
> +INSERT INTO t2 VALUES (4,'black'), (2,'red'), (3,'yelow'), (1,'cyan');
> +########################################################################
> +# Testing ER_LOCK_WAIT_TIMEOUT
> +########################################################################
> +BEGIN;
> +UPDATE t1 SET f = 'yellow' WHERE i = 3;
> +BEGIN;
> +UPDATE t1 SET f = 'magenta' WHERE f = 'red';
> +ERROR HY000: Lock wait timeout exceeded; try restarting transaction
> +INSERT INTO t1 VALUES (5,"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 t1 SET f = 'magenta' WHERE f =
> 'red'
> +master-bin.000001 # Query # # ROLLBACK
> +master-bin.000001 # Query # # BEGIN
> +master-bin.000001 # Query # # use `test`; UPDATE t1 SET f = 'yellow' WHERE i = 3
> +master-bin.000001 # Xid # # COMMIT /* XID */
> +master-bin.000001 # Query # # BEGIN
> +master-bin.000001 # Query # # use `test`; INSERT INTO t1 VALUES (5,"brown")
> +master-bin.000001 # Query # # use `test`; INSERT INTO n VALUES (now(),"brown")
> +master-bin.000001 # Query # # ROLLBACK
> +########
> +BEGIN;
> +UPDATE t1 SET f = 'brown' WHERE i = 3;
> +BEGIN;
> +UPDATE t1 SET f = 'green' WHERE f = 'red';
> +ERROR HY000: Lock wait timeout exceeded; try restarting transaction
> +INSERT INTO t1 VALUES (6,"sea blue");
> +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 t1 SET f = 'green' WHERE f = 'red'
> +master-bin.000001 # Query # # ROLLBACK
> +master-bin.000001 # Query # # BEGIN
> +master-bin.000001 # Query # # use `test`; UPDATE t1 SET f = 'brown' WHERE i = 3
> +master-bin.000001 # Xid # # COMMIT /* XID */
> +master-bin.000001 # Query # # BEGIN
> +master-bin.000001 # Query # # use `test`; INSERT INTO t1 VALUES (6,"sea blue")
> +master-bin.000001 # Query # # use `test`; INSERT INTO n VALUES (now(),"brown")
> +master-bin.000001 # Xid # # COMMIT /* XID */
> +########
> +BEGIN;
> +UPDATE t2 SET f = 'yellow' WHERE i = 3;
> +BEGIN;
> +UPDATE t2 SET f = 'magenta' WHERE f = 'red';
> +ERROR HY000: Lock wait timeout exceeded; try restarting transaction
> +INSERT INTO n VALUES ( now(), 'manual insert' );
> +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 # # use `test`; INSERT INTO n VALUES ( now(), 'manual
> insert' )
> +master-bin.000001 # Query # # BEGIN
> +master-bin.000001 # Query # # use `test`; UPDATE t2 SET f = 'yellow' WHERE i = 3
> +master-bin.000001 # Xid # # COMMIT /* XID */
> +source include/diff_master_slave.inc;
> +source include/diff_master_slave.inc;
> +########################################################################
> +# Cleanup
> +########################################################################
> +DROP TRIGGER tr;
> +DROP TABLE t1;
> +DROP TABLE t2;
> +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-01 06:03:17
> +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-01 06:03:17 +0000
> @@ -0,0 +1,112 @@
> +###############################################################################
> +#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 $binlog_start= query_get_value("SHOW MASTER STATUS", Position, 1);
> +connection conn1;
> +BEGIN;
> +UPDATE t SET f = 'yellow' WHERE i = 3;
> +
> +connection conn2;
> +BEGIN;
> +--error ER_LOCK_WAIT_TIMEOUT
> +UPDATE t SET f = 'magenta' WHERE f = 'red';
> +INSERT INTO t VALUES (5,"brown");
> +INSERT INTO n VALUES (now(),"brown");
> +
> +connection conn1;
> +COMMIT;
> +
> +connection conn2;
> +ROLLBACK;
> +--source include/show_binlog_events.inc
> +
> +--echo ########
> +
> +let $binlog_start= query_get_value("SHOW MASTER STATUS", Position, 1);
> +connection conn1;
> +BEGIN;
> +UPDATE t SET f = 'brown' WHERE i = 3;
> +
> +connection conn2;
> +BEGIN;
> +--error ER_LOCK_WAIT_TIMEOUT
> +UPDATE t SET f = 'green' WHERE f = 'red';
> +INSERT INTO t VALUES (6,"sea blue");
> +INSERT INTO n VALUES (now(),"brown");
> +
> +connection conn1;
> +COMMIT;
> +
> +connection conn2;
> +COMMIT;
> +--source include/show_binlog_events.inc
> +
> +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 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-01 06:03:17 +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 check_expected_error(int 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:
> + 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))
> + !check_expected_error(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-01 06:03:17 +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-01 06:03:17 +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 */
>
