Bug #46864 Incorrect update of InnoDB table on slave when using trigger with myisam table
Submitted: 22 Aug 2009 7:05 Modified: 16 Sep 2009 9:57
Reporter: Victor Kirkebo Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.1.38, 5.0, 5.1, next bzr OS:Any
Assigned to: Alfranio Tavares Correia Junior CPU Architecture:Any
Tags: auto_increment, autoinc, innodb, myisam, primary key, replication, trigger, UPDATE

[22 Aug 2009 7:05] Victor Kirkebo
Description:
This has been tested on the pre-release version of 5.1.38 for row/statement/mixed based replication.
The error doesn't happen with version 5.1.37.

When doing a multi-row update of the autoincrement column of an innodb table we can get an inconsistency between master and slave. This happens if we are using transactions (autocommit=0/commit or start transaction/commit) and there is a trigger present that updates a non-transactional table. If the update fails on the master with e.g. error Duplicate entry 'x' for key 'PRIMARY' then no rows will be updated. However, on the slave some rows might get updated.
E.g. if we attempt to update two rows r1 and r2 in that order and the update fails because the update of r2 would have caused a primary key violation then the master will neither update r1 nor r2. The slave on the other hand will incorrectly update r1 but not r2.

How to repeat:
# t/rpl_failure.test

source include/have_innodb.inc;
source include/master-slave.inc;

connection master;

--disable_warnings
drop database if exists tst;
--enable_warnings
create database tst;
use tst;

create table tb1(
  i1 int NOT NULL auto_increment, primary key (i1),
  f1 char (15)
) engine=innodb;

insert into tb1 values
(1,'init'),
(2,'init'),
(3,'init'),
(4,'init');

create table log (
  entry_dsc char(100)
) engine=myisam;

delimiter //;
Create trigger tb1_upd after update on tb1 for each row
begin
  insert into log (entry_dsc)
  values (concat('Update row ', old.i1,' ', old.f1, '->', new.f1));
end//
delimiter ;//

set autocommit = 0;

--disable_abort_on_error
UPDATE tb1
SET i1=i1 + ((i1-1) DIV 2),
    f1 = 'UPDATE';
--enable_abort_on_error

commit;

select * from tb1;
select * from log;

connection slave;
use tst;
select sleep(2);
select * from tb1;
select * from log;

# end of t/rpl_failure.test

Running the test above with binlog_format=row,statement or mixed and any
innodb_autoinc_lock_mode e.g :
./mysql-test-run.pl  --mysqld=--binlog_format=mixed --mysqld=--innodb_autoinc_lock_mode=0 --do-test=rpl_failure

will produce this output:

# master:

set autocommit = 0;
UPDATE tb1
SET i1=i1 + ((i1-1) DIV 2),
f1 = 'UPDATE';
ERROR 23000: Duplicate entry '4' for key 'PRIMARY'
commit;
select * from tb1;
i1      f1
1       init
2       init
3       init
4       init
select * from log;
entry_dsc
Update row 1 init->UPDATE
Update row 2 init->UPDATE

# slave:

use tst;
select sleep(2);
sleep(2)
0
select * from tb1;
i1      f1
1       UPDATE
2       UPDATE
3       init
4       init
select * from log;
entry_dsc
Update row 1 init->UPDATE
Update row 2 init->UPDATE
[23 Aug 2009 22:15] Victor Kirkebo
Here's another test case with an insert statement and insert trigger:
---------------------------------------------------------------------
# t/rpl_failure2.test

source include/have_innodb.inc;
source include/master-slave.inc;

connection master;

--disable_warnings
drop database if exists tst;
--enable_warnings
create database tst;
use tst;

create table tb1(
  i1 int NOT NULL auto_increment, primary key (i1),
  f1 char (15)
) engine=innodb;

insert into tb1 values
(1,'init'),
(2,'init'),
(3,'init'),
(4,'init');

create table log (
  entry_dsc char(100)
) engine=myisam;

delimiter //;
Create trigger tb1_ins after insert on tb1 for each row
begin
  insert into log (entry_dsc)
  values (concat('insert row ', new.i1,' ', new.f1));
end//
delimiter ;//

create table tb1_aux(i1 int, f1 char (15));
insert into tb1_aux values(5,'INSERT'),(6,'INSERT'),(4,'INSERT'),(8,'INSERT');

set autocommit = 0;

--disable_abort_on_error
INSERT INTO tb1 SELECT * FROM tb1_aux;
--enable_abort_on_error

commit;

--echo master:
select * from tb1;
select * from log;

--echo slave:
connection slave;
connection slave;
use tst;
select sleep(2);
select * from tb1;
select * from log;

# end of t/rpl_failure2.test

Output:
-------

set autocommit = 0;
INSERT INTO tb1 SELECT * FROM tb1_aux;
ERROR 23000: Duplicate entry '4' for key 'PRIMARY'
commit;
master:
select * from tb1;
i1      f1
1       init
2       init
3       init
4       init
select * from log;
entry_dsc
insert row 5 INSERT
insert row 6 INSERT

slave:
use tst;
select sleep(2);
sleep(2)
0
select * from tb1;
i1      f1
1       init
2       init
3       init
4       init
5       INSERT
6       INSERT
select * from log;
entry_dsc
insert row 5 INSERT
insert row 6 INSERT
[24 Aug 2009 5:48] Sveta Smirnova
Thank you for the report.

Verified as described. Slave started with option --innodb. With binlog_format='row' I get same wrong results.
[26 Aug 2009 12:05] Alfranio Tavares Correia Junior
Hi all,

I think the old behavior was a regression bug introduced by BUG#43929 and
the patch in BUG#46129 fixed the behavior. Reasoning:

We cannot automatically rollback a transaction because a statement
failed in its context.
The decision of rolling it back is delegated to the user.

----------------------------------

ANALYSIS

See a brief analysis in what follows. Let's assume for now SBR:

1 -

STATEMENT:

 INSERT .... ; /* this will cause error */

BINLOG:

BEGIN
  
INSERT .... ; TAGGED WITH ERROR

ROLLBACK;

2 -

STATEMENT:

BEGIN;

 INSERT .... ; /* this will cause error */

ROLLBACK;

BINLOG:

BEGIN
  
INSERT .... ; TAGGED WITH ERROR

ROLLBACK;

3 -
STATEMENT:

BEGIN;

 INSERT .... ; /* this will cause error */

COMMIT;

BINLOG:

BEGIN
  
INSERT .... ; TAGGED WITH ERROR

COMMIT;

All the three cases above should work perfectly but
only the first two seem to be ok. Please, check
the CONCLUSIONS for an explanation.

----------------------------------
ADDITIONAL INFORMATION:

1 - This is not supposed to work on ROW mode in 5.1.

The reason stems from the fact that we cannot truncate the cache
to get rid of the changes on transactional tables (Innodb) since 
there are also changes on non-transactional tables (MyISAM).

2 - It may work in MIXED if statements are written to the
binary log.

3 - This will be fixed after WL#2687.

----------------------------------
CONCLUSIONS:

1 - There is a bug on the slave side as statements tagged
with an error should be automatically rolled back.
Notice that the statement should be rolled back but not the
transaction.

I thought I had fixed this in the context of BUG#46130 but apparently
I missed something. 

Cheers.
[26 Aug 2009 12:21] Alfranio Tavares Correia Junior
Proposed fix:

--- sql/log_event.cc    2009-08-24 09:24:52 +0000
+++ sql/log_event.cc    2009-08-26 12:17:14 +0000
@@ -3202,6 +3202,15 @@
       DBUG_PRINT("info",("error ignored"));
       clear_all_errors(thd, const_cast<Relay_log_info*>(rli));
       thd->killed= THD::NOT_KILLED;
+      /*
+        When an error is expected and matches the actual error the
+        slave does not report any error and by consequence changes
+        on transactional tables are not rolled back in the function
+        close_thread_tables(). For that reason, we explicitly roll
+        them back here.
+      */
+      if (expected_error)
+        ha_autocommit_or_rollback(thd, TRUE);
     }
     /*
       If we expected a non-zero error code and get nothing and, it is a concurrency
[27 Aug 2009 0:09] 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/81651

3083 Alfranio Correia	2009-08-27
      BUG#46864 Incorrect update of InnoDB table on slave when using trigger with myisam table
      
      Slave does not correctly handle "expected errors" leading to inconsistencies
      between the mater and slave. Specifically, when a statement changes both
      transactional and non-transactional tables, the transactional changes are
      automatically rolled back on the master but the slave ignores the error and
      does not rollback them thus leading to inconsistencies.
            
      To fix the problem, we automatically rollback a statement that fails on
      the slave but note that the transaction is not rolled back unless a "rollback"
      command is in the relay log file.
     @ mysql-test/extra/rpl_tests/rpl_mixing_engines.test
        Enabled item 13.e which was disabled because of the bug fixed by the
        current and removed item 14 which was introduced by mistake.
[27 Aug 2009 12:46] 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/81726

3086 Alfranio Correia	2009-08-27
      BUG#46864 Incorrect update of InnoDB table on slave when using trigger with myisam table
      
      Slave does not correctly handle "expected errors" leading to inconsistencies
      between the mater and slave. Specifically, when a statement changes both
      transactional and non-transactional tables, the transactional changes are
      automatically rolled back on the master but the slave ignores the error and
      does not roll them back thus leading to inconsistencies.
            
      To fix the problem, we automatically roll back a statement that fails on
      the slave but note that the transaction is not rolled back unless a "rollback"
      command is in the relay log file.
     @ mysql-test/extra/rpl_tests/rpl_mixing_engines.test
        Enabled item 13.e which was disabled because of the bug fixed by the
        current and removed item 14 which was introduced by mistake.
[27 Aug 2009 13:27] Alfranio Tavares Correia Junior
Pushed to mysql-5.1-bugteam and mysql-pe.
[2 Sep 2009 16:41] Bugs System
Pushed into 5.1.39 (revid:joro@sun.com-20090902154533-8actmfcsjfqovgsb) (version source revid:alfranio.correia@sun.com-20090827124629-rmhwqvq6x962clwz) (merge vers: 5.1.39) (pib:11)
[9 Sep 2009 9:48] Jon Stephens
Documented bugfix in the 5.1.39 changelog as follows:

        Performing a multi-row update of the AUTO_INCREMENT column of a
        transactional table could result in an inconsistency between
        master and slave when there was a trigger on the transactional
        table that updated a non-transactional table. When such an
        update failed on the master, no rows were updated on the master,
        but some rows could (erroneously) be updated on the slave.

Set status = NDI, waiting for pushes to additional trees.
[10 Sep 2009 22:12] Elena Stepanova
In pre-release 5.1.39 the problem still exists for the same test cases with the only addition: log table has an auto_increment column, e.g.

create table log (
  i int not null auto_increment, key (i),
  entry_dsc char(100)
) engine=myisam;
[11 Sep 2009 10:21] Lars Thalmann
HISTORY:

1. BUG#43929 Fixed that too large transactions can corrupt the binlog.

   This fix unfortunately introduced a regression (for all binlog
   formats) into 5.1.37.

2. BUG#46129 Report about the regression caused by BUG#43929 (for all
   all binlog format).  The bug is that a failing statement is logged
   too early in the binlog.

   This bug was fixed in 5.1.38 restoring the original behaviour of
   5.1.36.

3. BUG#46864 is not a regression bug with respect to 5.1.36.  The
   system works (after the fix for BUG#46129) as it did in 5.1.36.

   (BUG#43929 temporarily made InnoDB transactions with MyISAM
   triggers to work in some circumstances, but the problem in
   BUG#46129 is worse than the problem in BUG#46864, so we can not
   keep the 5.1.37 behaviour.)

   However, there is still a bug (that was also there in 5.1.36) in
   that a multi-row update of the autoinc column of an InnoDB table
   can cause inconsistency between the slave and the master (when
   there is a trigger affecting a myisam table).

   The patch for this bug fixes this bug for statement binlog format
   only.  

   Fixing this bug for mixed and row binlog format will be done in
   WL#2687 (which will most likely not be pushed to 5.1).

DECISION:

Provided that the system works at least as good as 5.1.36 (no
regression with respect to that version), it is ok to close this bug
report.

The idea is that we should have a version which is like 5.1.36, but
that now also handles MyISAM triggers with InnoDB tables correctly
provided that one is using statement binlog format.

ACTION:

Elena, can you verify that it works as it did in 5.1.36?
[11 Sep 2009 11:06] Elena Stepanova
> Elena, can you verify that it works as it did in 5.1.36?

But it does not. I'll put it in a form of a table, maybe it will be clearer this way.

Lets take Victor's original scenario first, without any alterations (the first one, with update).

In the table below, by 'OK' i mean that master and slave have the same contents after the update, by 'FAIL' that they differ as Victor described.

             SBR   RBR
5.1.34sp1    OK    OK
5.1.36       OK    OK
5.1.37       OK    OK
5.1.38       FAIL  FAIL
5.1.39       OK    FAIL

Note: Starting from 5.1.38 binlog contains COMMIT at the end of the transaction with the update statement, while up to 5.1.37 it was ROLLBACK.

My alteration of the scenario (adding an auto-increment into the log table) is only important for MBR, apparently because it makes server switch to RBR while executing the statement.
[14 Sep 2009 16:05] Bugs System
Pushed into 5.4.4-alpha (revid:alik@sun.com-20090914155317-m1g9wodmndzdj4l1) (version source revid:alik@sun.com-20090914155317-m1g9wodmndzdj4l1) (merge vers: 5.4.4-alpha) (pib:11)
[16 Sep 2009 9:57] Jon Stephens
Also documented the current fix in the 5.4.4 changelog. Closed.
[1 Oct 2009 5:59] Bugs System
Pushed into 5.1.39-ndb-6.3.28 (revid:jonas@mysql.com-20091001055605-ap2kiaarr7p40mmv) (version source revid:jonas@mysql.com-20091001055605-ap2kiaarr7p40mmv) (merge vers: 5.1.39-ndb-6.3.28) (pib:11)
[1 Oct 2009 7:25] Bugs System
Pushed into 5.1.39-ndb-7.0.9 (revid:jonas@mysql.com-20091001072547-kv17uu06hfjhgjay) (version source revid:jonas@mysql.com-20091001071652-irejtnumzbpsbgk2) (merge vers: 5.1.39-ndb-7.0.9) (pib:11)
[1 Oct 2009 13:25] Bugs System
Pushed into 5.1.39-ndb-7.1.0 (revid:jonas@mysql.com-20091001123013-g9ob2tsyctpw6zs0) (version source revid:jonas@mysql.com-20091001123013-g9ob2tsyctpw6zs0) (merge vers: 5.1.39-ndb-7.1.0) (pib:11)
[5 Oct 2009 10:50] Bugs System
Pushed into 5.1.39-ndb-6.2.19 (revid:jonas@mysql.com-20091005103850-dwij2dojwpvf5hi6) (version source revid:jonas@mysql.com-20090930185117-bhud4ek1y0hsj1nv) (merge vers: 5.1.39-ndb-6.2.19) (pib:11)
[7 Oct 2009 1:44] Paul DuBois
The 5.4 fix has been pushed into 5.4.3.