MySQL Bugs: #40116: Uncommited changes are replicated and stay on slave after rollback on master

Bug #40116	Uncommited changes are replicated and stay on slave after rollback on master
Submitted:	17 Oct 2008 16:57	Modified:	12 Nov 2009 12:18
Reporter:	Elena Stepanova	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.0.70, 5.0.74, 5.1.26, 5.1.29	OS:	Any
Assigned to:	Mats Kindahl	CPU Architecture:	Any
Tags:	regression

Description:
If there is a trigger on an InnoDB table which updates a non-transactional (e.g. MyISAM) table, changes performed on the InnoDB table get replicated and are visible on slave even before a commit on master, and are not rolled back on slave after successful rollback on master.

Actions not affected by the trigger work all right, e.g. if the trigger is 'after insert' then there is a problem with insert, but update works fine.

If there is no trigger or the trigger uses another InnoDB table, the problem does not show up.

The result is the same for RBR, MBR, and SBR.
Also checked 5.1.26 -- happens there as well.

It works all right in 5.0.70.

How to repeat:
on master:
----------

create table t ( f int ) engine = innodb;
create table log ( r int ) engine = myisam; 
create trigger tr after insert on t for each row insert into log values ( new.f );
set autocommit = 0;
insert into t values ( 1 );

select * from t;
+------+
| f    |
+------+
|    1 |
+------+
1 row in set (0.03 sec)

on slave:
---------

select * from t;
+------+
| f    |
+------+
|    1 |
+------+
1 row in set (0.01 sec)

on master:
----------

rollback;

select * from t;
Empty set (0.01 sec)

on slave:
---------

select * from t;
+------+
| f    |
+------+
|    1 |
+------+
1 row in set (0.00 sec)

Thank you for a bug report. Verifed just as described. In the binary log on master one may find the following:

# at 106
#081017 20:26:21 server id 1  end_log_pos 204   Query   thread_id=1     exec_tim
e=0     error_code=0
use test/*!*/;
SET TIMESTAMP=1224264381/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.uniq
ue_checks=1/*!*/;
SET @@session.sql_mode=1344274432/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/
;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@sessio
n.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table t(f int) engine=InnoDB
/*!*/;
# at 204
#081017 20:26:36 server id 1  end_log_pos 304   Query   thread_id=1     exec_tim
e=0     error_code=0
SET TIMESTAMP=1224264396/*!*/;
create table log(r int) engine=MyISAM
/*!*/;
# at 304
#081017 20:27:06 server id 1  end_log_pos 472   Query   thread_id=1     exec_tim
e=0     error_code=0
SET TIMESTAMP=1224264426/*!*/;
CREATE DEFINER=`root`@`localhost` trigger tr after insert on t for each row inse
rt into log values(new.f)
/*!*/;
# at 472
#081017 20:27:24 server id 1  end_log_pos 540   Query   thread_id=1     exec_tim
e=0     error_code=0
SET TIMESTAMP=1224264444/*!*/;
SET /*!*/;
BEGIN
/*!*/;
# at 540
#081017 20:27:24 server id 1  end_log_pos 626   Query   thread_id=1     exec_tim
e=0     error_code=0
SET TIMESTAMP=1224264444/*!*/;
insert into t values(1)
/*!*/;
# at 626
#081017 20:27:24 server id 1  end_log_pos 695   Query   thread_id=1     exec_tim
e=0     error_code=0
SET TIMESTAMP=1224264444/*!*/;
COMMIT
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

It works in 5.0.x. Look:

C:\Program Files\MySQL\MySQL Server 5.0\bin>mysql -uroot -proot -P3308 test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.0.66a-enterprise-gpl-nt-log MySQL Enterprise Server (GPL)

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> drop table t;
Query OK, 0 rows affected (0.25 sec)

mysql> drop table log;
ERROR 1051 (42S02): Unknown table 'log'
mysql> create table t ( f int ) engine = innodb;
Query OK, 0 rows affected (0.19 sec)

mysql> create table log ( r int ) engine = myisam;
Query OK, 0 rows affected (0.08 sec)

mysql> create trigger tr after insert on t for each row insert into log values (
 new.f );
Query OK, 0 rows affected (0.03 sec)

mysql> set autocommit = 0;
Query OK, 0 rows affected (0.02 sec)

mysql> insert into t values ( 1 );
Query OK, 1 row affected (0.08 sec)

mysql> rollback;
Query OK, 0 rows affected, 1 warning (0.05 sec)

mysql> show warnings\G
*************************** 1. row ***************************
  Level: Warning
   Code: 1196
Message: Some non-transactional changed tables couldn't be rolled back
1 row in set (0.00 sec)

mysql> select * from t;
Empty set (0.00 sec)

mysql> show master status;
+-------------------------+----------+--------------+------------------+
| File                    | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+-------------------------+----------+--------------+------------------+
| toshiba-user-bin.000008 |      780 |              |                  |
+-------------------------+----------+--------------+------------------+
1 row in set (0.00 sec)

mysql> exit
Bye

C:\Program Files\MySQL\MySQL Server 5.0\bin>mysqlbinlog ..\data\toshiba-user-bin
.000008
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#081022 16:33:05 server id 1  end_log_pos 98    Start: binlog v 4, server v 5.0.
66a-enterprise-gpl-nt-log created 081022 16:33:05 at startup
# Warning: this binlog was not closed properly. Most probably mysqld crashed wri
ting it.
ROLLBACK/*!*/;
# at 98
#081022 16:33:18 server id 1  end_log_pos 173   Query   thread_id=3     exec_tim
e=0     error_code=0
use test/*!*/;
SET TIMESTAMP=1224682398/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.uniq
ue_checks=1/*!*/;
SET @@session.sql_mode=1344274432/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@sessio
n.collation_server=33/*!*/;
drop table t
/*!*/;
# at 173
#081022 16:33:32 server id 1  end_log_pos 276   Query   thread_id=3     exec_tim
e=0     error_code=0
SET TIMESTAMP=1224682412/*!*/;
create table t ( f int ) engine = innodb
/*!*/;
# at 276
#081022 16:33:32 server id 1  end_log_pos 381   Query   thread_id=3     exec_tim
e=1     error_code=0
SET TIMESTAMP=1224682412/*!*/;
create table log ( r int ) engine = myisam
/*!*/;
# at 381
#081022 16:33:33 server id 1  end_log_pos 552   Query   thread_id=3     exec_tim
e=0     error_code=0
SET TIMESTAMP=1224682413/*!*/;
CREATE DEFINER=`root`@`localhost` trigger tr after insert on t for each row inse
rt into log values ( new.f )
/*!*/;
# at 552
#081022 16:33:40 server id 1  end_log_pos 620   Query   thread_id=3     exec_tim
e=0     error_code=0
SET TIMESTAMP=1224682420/*!*/;
BEGIN
/*!*/;
# at 620
#081022 16:33:33 server id 1  end_log_pos 709   Query   thread_id=3     exec_tim
e=0     error_code=0
SET TIMESTAMP=1224682413/*!*/;
insert into t values ( 1 )
/*!*/;
# at 709
#081022 16:33:40 server id 1  end_log_pos 780   Query   thread_id=3     exec_tim
e=0     error_code=0
SET TIMESTAMP=1224682420/*!*/;
ROLLBACK
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

Note ROLLBACK instead of 5.1's COMMIT in the binary log.

Further information:
1) The above described 'mismatch' between naster and slave can also cause the 
   slave to have 'less' rows if the trigger is a delete trigger and rows are 
   deleted from table 't and rolled back.

2) If the above tables are defined with auto_increment columns, re-issuing the 
   rolled back delete query (described in #1) a second time will cause replication 
   to abort with ERROR: 1032 Could not execute Delete_rows event on table .

Scenarios described before do not affect 5.0 versions, but the following one makes slave SQL thread to abort both in 5.0 and 5.1. Please consider whether it should be treated as a variation of the same bug, or extracted into a new one.

Similarity:
A mix of transactional and non-transactional tables causes a failure in replication

Differences:
- different error messages/codes produced;
- 5.0 is also affected;
- the new scenario requires PK and other special conditions related to the PK (described below after test case).

Test case:

Connection #1:
--------------

drop database if exists rpl_failure_test;
create database rpl_failure_test;
use rpl_failure_test;

create table t ( i int, primary key(i), f char(8) ) engine = innodb;
create table l ( d datetime, f char(32) ) engine = myisam;

delimiter |
create trigger tr after update on t for each row begin insert into l values ( no
w(), concat( 'updated t: ', old.f, ' -> ', new.f ) ); end |
delimiter ;

insert into t values (4,'black'), (2,'red'), (3,'yelow'), (1,'cyan');

commit;

set autocommit = 0;

update t set f = 'yellow' where i = 3;

Connection #2:
--------------

update t set f = 'magenta' where f = 'red';

# Note: if the 2nd connection also has autocommit=0, 
# the problem happens after an explicit commit or rollback of the transaction.

#end of test case

After wait timeout is exceeded on connection #2, the following records appear in the slave.err log:

[ERROR] Slave: Query caused different errors on master and slave
. Error on master: 'Lock wait timeout exceeded; try restarting transaction' (1205), Error on slave: 'no error' (0). Default database: 'rpl_failure_test'. Query:
 'update t set f = 'magenta' where f = 'red'', Error_code: 0
[ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log '
master-bin.000001' position 2531

The last record in slave.log is the update.

Specific requirements:

The first connection should use PK as a criteria in WHERE clause (although PK itself does not have to be updated); the second connection does not use PK, however it should update a specific row -- in my experiments only updates of rows with PK value less than the one updated by the first connection caused slave abort -- e.g. in the test case above, if the 1st connection updates the row with PK=3, than the second connection has to update rows 'cyan' or 'magenta' to produce slave abort, while updates on 'black' or 'yellow' rows do not cause the problem.

Here is an explanation of the bug and what causes it.

- Traditionally, if one writes non-transactional changes at the beginning of a
transaction, they are written to the binary log ahead of the transaction since
the changes are not part of the transaction.

- In 5.1, a statement is non-transactional if it contain changes to a
non-transactional table. In 5.0, a statement is non-transactional if a table
in the top-level statement (not counting triggers) is non-transactional.

- When the statement is committed in the test case, it includes a change to a
non-transactional table, hence it is considered non-transactional and is
therefore written to the binary log. This both for 5.0 and 5.1.

- For 5.1, the statement is surrounded by BEGIN-COMMIT events which is part of
the resolution for BUG#22540.

- In 5.0, the statement is just written as it is.

The dual of this bug for 5.0 can be triggered with the following code:

create table t1 ( f int ) engine = myisam;
create table log ( r int ) engine = innodb;
create trigger tr
after insert on t1
for each row insert into log values ( new.f );

set autocommit = 0;
insert into t1 values ( 1 );
commit;

Which does not replicate correctly since the 'log' table will have a mismatch (nothing will be written to the table on the slave).

The main problem is the "write-ahead" approach used in 5.0, which causes problems with 5.1 since the semantics are slightly different. The sensible solution is to not write non-transactional statement to the binary log ahead of a transaction when the statement is inside a transaction. This is a low-risk fix.

The other approach would be to try to give a "priority" to the "non-transactionality" of tables in a statement by, for example, ignoring tables in the trigger, but this will just complicate the logic and is likely to introduce subtle bugs.

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/60546

2776 Mats Kindahl	2008-12-03
      Bug #40116: Uncommited changes are replicated and stay on slave
      after rollback on master
      
      When starting a transaction with a statement containing changes
      to both transactional tables and non-transactional tables, the
      statement is considered as non-transactional and is therefore
      written directly to the binary log. This behaviour was present
      in 5.0, and has propagated to 5.1.
      
      If a trigger containing a change of a non-transactional table is
      added to a transactional table, any changes to the transactional
      table is "tainted" as non-transactional.
      
      This patch solves the problem by removing the existing "hack" that
      allows non-transactional statements appearing first in a transaction
      to be written directly to the binary log. Instead, anything inside
      a transaction is treaded as part of the transaction and not written
      to the binary log until the transaction is committed.

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/60728

2777 Mats Kindahl	2008-12-05
      Bug #40116:
      Uncommited changes are replicated and stay on slave after
      rollback on master
      
      Making test slightly more generic and robust.

With this patch, the semantics have changed when mixing non-transactional and transactional tables in a transaction in the first statement of a transaction.

In the logic preceding this patch, the rule was that if the first statement in a transaction contained non-transactional changes, the statement was written directly to the binary log in an attempt to mimic the non-transactional behavior of the statement. For 5.1, a statement is non-transactional if it changes a non-transactional table. For 5.0, triggers were not taken into account when deciding if the statement is non-transactional.

This "write-ahead" behavior have subtle consequences:

- For statements containing only non-transactional changes, these were written
  immediately to the binary log.

- For statements containing only transactional changes, these were always
  cached awaiting the commit.

- For statement containing a mix of transactional and non-transactional
  changes, the result could always lead to mismatching tables.

With this patch, statement appearing after a BEGIN (or just after a COMMIT if AUTOCOMMIT=0) are always considered part of the transaction and cached. This means that non-transactional changes will not propagate to the slave until the transaction is committed and hence written to the binary log.

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/63177

2966 Mats Kindahl	2009-01-13
      Bug #40116: Uncommited changes are replicated and stay on slave
      after rollback on master
      
      Test case fixes after merging patch to 6.0.

Pushed into 5.1.31 (revid:joro@sun.com-20090115053147-tx1oapthnzgvs1ro) (version source revid:azundris@mysql.com-20081230114838-cn52tu180wcrvh0h) (merge vers: 5.1.31) (pib:6)

Documented in the 5.1.31 changelog as follows:

        If a trigger was defined on an InnoDB table and this trigger
        updated a non-transactional table, changes performed on the
        InnoDB table were replicated and were visible on the slave
        before they were committed on the master, and were not rolled
        back on the slave after a successful rollback of those changes
        on the master.

        As a result of the fix for this issue, the semantics of mixing
        non-transactional and transactional tables in a transaction in
        the first statement of a transaction have changed. Previously,
        if the first statement in a transaction contained
        non-transactional changes, the statement was written directly to
        the binary log. Now, any statement appearing after a BEGIN (or
        immediately following a COMMIT if AUTOCOMMIT = 0) is always
        considered part of the transaction and cached. This means that
        non-transactional changes do not propagate to the slave until
        the transaction is committed and thus written to the binary log.

Also updated http://dev.mysql.com/doc/refman/5.1/en/replication-features-transactions.html and http://dev.mysql.com/doc/refman/5.1/en/replication-features-triggers.html with information from this bug report.

Set bug status to NDI pending 5.0 fix/6.0 merge.

Pushed into 5.1.31-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090119095303-uwwvxiibtr38djii) (version source revid:tomas.ulin@sun.com-20090115073240-1wanl85vlvw2she1) (merge vers: 5.1.31-ndb-6.2.17) (pib:6)

Pushed into 5.1.31-ndb-6.3.21 (revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (version source revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (merge vers: 5.1.31-ndb-6.3.21) (pib:6)

Set status back to NDI pending merge to 6.0 tree.

Pushed into 5.1.31-ndb-6.4.1 (revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (version source revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (merge vers: 5.1.31-ndb-6.4.1) (pib:6)

Set back to NDI pending merge to 6.0.

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/63576

2969 Mats Kindahl	2009-01-19
      BUG#40116: Uncommited changes are replicated and stay on
      slave after rollback on master
      
      Post-merge fixes to disable part of a test that is not
      relevant any more.
      
      When replicating from MyISAM to any transactional table
      with AUTOCOMMIT=0 and not using a COMMIT to terminate
      the transaction, the changes will not be applied to the
      slave since they are not committed to the transactional
      engine.

Pushed into 6.0.10-alpha (revid:joro@sun.com-20090119171328-2hemf2ndc1dxl0et) (version source revid:timothy.smith@sun.com-20090114143745-x2dvnmix6gjlt6z6) (merge vers: 6.0.10-alpha) (pib:6)

Fix also documented in 6.0.10 changelog, relevant portions of 6.0 Replication chapter also updated; closed.

Pushed into 6.0.10-alpha (revid:kostja@sun.com-20090204104420-mw1i2u9lum4bxjo6) (version source revid:mats@sun.com-20090119212828-3jqla408udt2d5p4) (merge vers: 6.0.10-alpha) (pib:6)

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/84831

3111 Mats Kindahl	2009-09-28
      Disabling tests that are not relevant after BUG#40116, these will be enabled
      when WL#2867 or associated fixes for 5.1 is added to solve the problem.

Pushed into 6.0.14-alpha (revid:alik@sun.com-20091027094604-9p7kplu1vd2cvcju) (version source revid:zhenxing.he@sun.com-20091026140226-uhnqejkyqx1aeilc) (merge vers: 6.0.14-alpha) (pib:13)

Already documented in 6.0.10; closed.

Pushed into 5.5.0-beta (revid:alik@sun.com-20091110093229-0bh5hix780cyeicl) (version source revid:alik@sun.com-20091027095744-rf45u3x3q5d1f5y0) (merge vers: 5.5.0-beta) (pib:13)

Already documented in the 5.5.0 changelog; re-closing.