Bug #47175 failing INSERT, transaction, replication out of sync
Submitted: 7 Sep 2009 13:25 Modified: 7 Mar 2010 1:53
Reporter: Matthias Leich Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Row Based Replication ( RBR ) Severity:S3 (Non-critical)
Version:5.1,5.4 OS:Any
Assigned to: Alfranio Correia CPU Architecture:Any
Triage: Triaged: D2 (Serious) / R4 (High) / E2 (Low)

[7 Sep 2009 13:25] Matthias Leich
Description:
My script:
==========
--source include/master-slave.inc

--disable_warnings
DROP TABLE IF EXISTS t1,t2;
--enable_warnings

connection master;
CREATE TABLE `t1` ( f1 INTEGER, f2 INT, PRIMARY KEY (f1));
INSERT INTO t1 VALUES (1, NULL) ,  (2, 1);
SET AUTOCOMMIT = 0;
CREATE TABLE t2 ( f2 INT, f1 INTEGER , PRIMARY KEY (f1)) ENGINE = MyISAM;
INSERT INTO t2 VALUES (NULL, 1);
COMMIT;
SHOW CREATE TABLE t2;
SELECT * FROM t2;
--sync_slave_with_master
--echo # Switch to slave  ----------------------------------
connection slave;
SHOW CREATE TABLE t2;
SELECT * FROM t2;
--echo # Switch to master ----------------------------------
connection master;
--error ER_DUP_ENTRY
INSERT INTO t2 SELECT * FROM t1;
SELECT * FROM t2;
--sync_slave_with_master
--echo # Switch to slave  ----------------------------------
connection slave;
SELECT * FROM t2;
--echo # Switch to master ----------------------------------
connection master;
ROLLBACK;
SELECT * FROM t2;
--sync_slave_with_master
--echo # Switch to slave  ----------------------------------
connection slave;
SELECT * FROM t2;
--echo # Switch to master ----------------------------------
connection master;

UPDATE t2  SET f2 = 8 ;
COMMIT WORK;
--sync_slave_with_master

DROP TABLE t1,t2;
--sync_slave_with_master

The outcome (a bit edited):
===========================
...
DROP TABLE IF EXISTS t1,t2;
CREATE TABLE `t1` ( f1 INTEGER, f2 INT, PRIMARY KEY (f1));
INSERT INTO t1 VALUES (1, NULL) ,  (2, 1);
SET AUTOCOMMIT = 0;
CREATE TABLE t2 ( f2 INT, f1 INTEGER , PRIMARY KEY (f1)) ENGINE = MyISAM;
INSERT INTO t2 VALUES (NULL, 1);
COMMIT;
SHOW CREATE TABLE t2;
Table Create Table
t2 CREATE TABLE `t2` (
  `f2` int(11) DEFAULT NULL,
  `f1` int(11) NOT NULL DEFAULT '0',
  PRIMARY KEY (`f1`)
) ENGINE=MyISAM DEFAULT CHARSET=latin1
SELECT * FROM t2;
f2 f1
NULL  1
# Switch to slave  ----------------------------------
SHOW CREATE TABLE t2;
Table Create Table
t2 CREATE TABLE `t2` (
  `f2` int(11) DEFAULT NULL,
  `f1` int(11) NOT NULL DEFAULT '0',
  PRIMARY KEY (`f1`)
) ENGINE=MyISAM DEFAULT CHARSET=latin1
SELECT * FROM t2;
f2 f1
NULL  1
      <--- Ok, table definition and content is in sync
# Switch to master ----------------------------------
INSERT INTO t2 SELECT * FROM t1;
ERROR 23000: Duplicate entry '1' for key 'PRIMARY'
SELECT * FROM t2;
f2 f1
NULL  1
1  0
# Switch to slave  ----------------------------------
SELECT * FROM t2;
f2 f1
NULL  1
      <--- This is ok in case we get the row after
           *whatever* transaction end.
# Switch to master ----------------------------------
ROLLBACK;
SELECT * FROM t2;
f2 f1
NULL  1
1  0
      <--- Ok, t1 uses MyISAM -> row not removed
# Switch to slave  ----------------------------------
SELECT * FROM t2;
f2 f1
NULL  1
      <--- !!! Replication out of sync !!!
# Switch to master ----------------------------------
UPDATE t2  SET f2 = 8 ;
<--- Here the slave stops with
     Last_SQL_Errno  1032
     Last_SQL_Error  Could not execute Update_rows
          event on table test.t2; Can't find record
                                  in 't2', 
          Error_code: 1032; handler error
          HA_ERR_KEY_NOT_FOUND; ...

SHOW BINLOG EVENTS IN 'master-bin.000001';
==========================================
Log_name        Pos     Event_type      Server_id       End_log_pos     Info
master-bin.000001       4       Format_desc     1       107     Server ver: 5.4.4-alpha-debug-log, Binlog ver: 4
Query   1       196     use `test`; DROP TABLE IF EXISTS t1,t2
Query   1       316     use `test`; CREATE TABLE `t1` ( f1 INTEGER, f2 INT, PRIMARY KEY (f1))
Query   1       384     BEGIN
Table_map       1       426     table_id: 16 (test.t1)
Write_rows      1       469     table_id: 16 flags: STMT_END_F
Query   1       538     COMMIT
Query   1       673     use `test`; CREATE TABLE t2 ( f2 INT, f1 INTEGER , PRIMARY KEY (f1)) ENGINE = MyISAM
Query   1       741     BEGIN
Table_map       1       783     table_id: 17 (test.t2)
Write_rows      1       817     table_id: 17 flags: STMT_END_F
Query   1       886     COMMIT
<----- Here is something missing.
       There was the failing INSERT t2 (but inserted one row
       becasue of MyISAM use) followed by ROLLBACK.
Query   1       954     BEGIN
Table_map       1       996     table_id: 17 (test.t2)
Update_rows     1       1036    table_id: 17
Update_rows     1       1076    table_id: 17 flags: STMT_END_F
Query   1       1145    COMMIT

Interesting observation:
========================
If I replace the
   INSERT INTO t2 SELECT * FROM t1
by
   INSERT INTO t2 VALUES (1, NULL) ,  (2, 1);
than
- t1 on master has finally the same content
- the ROLLBACK gets a
  Warnings:
  Warning 1196 Some non-transactional changed tables
               couldn't be rolled back
  Ok, correct but why not also in case of INSERT SELECT
- replication stays in sync 

My environment:
---------------
- mysql-next-bugfixing 2009-09-05
- mysql-5.1-bugteam    2009-08-28
- ./BUILD/compile-pentium64-debug-max
- Linux OpenSuSE 11.0 (64 Bit)
- Intel Core2Duo

How to repeat:
See above
./mysql-test-run --mysqld=--binlog-format=row \
    --no-check-testcases <script>
[23 Sep 2009 2:47] Alfranio Correia
See also BUG#47287.
[23 Sep 2009 3:47] Alfranio Correia
The problem in this bug stems from the fact that the failing statement,
which has changed a non-transactional table, does not get through the
binary log even after calling ROLLBACK to finish the transaction.

This problem will be partially fixed in BUG#47287 as an early statement
that fails and has changed non-transactional tables will be automatically
written to the binary log as follows:

COMMANDS:

CREATE TABLE `tt_1_innodb` ( f1 INTEGER, f2 INT, PRIMARY KEY (f1)) ENGINE = Innodb;
CREATE TABLE `nt_1_myisam` ( f1 INTEGER, f2 INT, PRIMARY KEY (f1)) ENGINE = MyISAM;
INSERT INTO nt_1_myisam VALUES (1, NULL) ,  (2, 1);
SET AUTOCOMMIT = 0;
CREATE TABLE nt_2_myisam ( f2 INT, f1 INTEGER , PRIMARY KEY (f1)) ENGINE = MyISAM;
INSERT INTO nt_2_myisam VALUES (NULL, 1);
COMMIT;

--error ER_DUP_ENTRY
INSERT INTO nt_2_myisam SELECT * FROM nt_1_myisam;
ROLLBACK;

BINLOG:

Log_name        Pos     Event_type      Server_id       End_log_pos     Info
master-bin.000001       4       Format_desc     1       106     Server ver: 5.1.39-debug-log, Binlog ver: 4
master-bin.000001       106     Query   1       251     use `test`; CREATE TABLE `tt_1_innodb` ( f1 INTEGER, f2 INT, PRIMARY KEY (f1)) ENGINE = Innodb
master-bin.000001       251     Query   1       396     use `test`; CREATE TABLE `nt_1_myisam` ( f1 INTEGER, f2 INT, PRIMARY KEY (f1)) ENGINE = MyISAM
master-bin.000001       396     Query   1       464     BEGIN
master-bin.000001       464     Table_map       1       515     table_id: 23 (test.nt_1_myisam)
master-bin.000001       515     Write_rows      1       558     table_id: 23 flags: STMT_END_F
master-bin.000001       558     Query   1       627     COMMIT
master-bin.000001       627     Query   1       771     use `test`; CREATE TABLE nt_2_myisam ( f2 INT, f1 INTEGER , PRIMARY KEY (f1)) ENGINE = MyISAM
master-bin.000001       771     Query   1       839     BEGIN
master-bin.000001       839     Table_map       1       890     table_id: 24 (test.nt_2_myisam)
master-bin.000001       890     Write_rows      1       924     table_id: 24 flags: STMT_END_F
master-bin.000001       924     Query   1       993     COMMIT
master-bin.000001       993     Query   1       1061    BEGIN
master-bin.000001       1061    Table_map       1       1112    table_id: 24 (test.nt_2_myisam)
master-bin.000001       1112    Write_rows      1       1150    table_id: 24 flags: STMT_END_F
master-bin.000001       1150    Query   1       1221    ROLLBACK

However, there is another problem not fixed by BUG#47287 and that would pop up if we slightly change the statements:

INSERT INTO tt_1_innodb SELECT * FROM nt_1_myisam;
--error ER_DUP_ENTRY
INSERT INTO nt_2_myisam SELECT * FROM nt_1_myisam;
ROLLBACK;

In this case, nothing is written to the binary log although a non-transactional table was updated. 
This happen because in row mode: thd->transaction.all.modified_non_trans_table is not set to true and the following code in the log.cc is not executed:

    if ((all && thd->transaction.all.modified_non_trans_table) ||
        (!all && thd->transaction.stmt.modified_non_trans_table &&
         !(thd->options & (OPTION_BEGIN | OPTION_NOT_AUTOCOMMIT))) ||
        (!all && thd->transaction.stmt.modified_non_trans_table &&
         !trx_data->at_least_one_stmt &&
         thd->current_stmt_binlog_row_based) ||
        ((thd->options & OPTION_KEEP_LOG)))
    {
      Query_log_event qev(thd, STRING_WITH_LEN("ROLLBACK"), TRUE, TRUE, 0);
      error= binlog_end_trans(thd, trx_data, &qev, all);
    }
[23 Sep 2009 5:14] 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/84236

3118 Alfranio Correia	2009-09-23
      BUG#47175 failing INSERT, transaction, replication out of sync
      
      In the RBR mode, a failing INSERT...SELECT statement was not corretly setting
      the variable THD::transaction.all.modified_non_trans_table and as such if a
      rollback was requested and no other non-transactional table updated, nothing
      was written to the binary log.
      
      To fix the bug, we set the variable regardless the replication mode.
[29 Sep 2009 10:10] Luis Soares
Will be fixed after WL#2687 is pushed in future release.
[4 Nov 2009 1:33] Alfranio Correia
Pushed to mysql-5.1-rep+3

revision-id: alfranio.correia@sun.com-20091103190256-637o8qxlveikrt3i
[12 Nov 2009 23:56] 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/90290

3120 Alfranio Correia	2009-11-12
      Post-fix for WL#2687 WL#5072 BUG#40278 BUG#47175
      
      Create a set of test cases to see if some DDL statements implicitly commit
      a transaction on the NDB and are written directly to the binary log without
      going through either the Statement- or Transactional-Cache.
[13 Nov 2009 0:18] 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/90291

3120 Alfranio Correia	2009-11-13
      Post-fix for WL#2687 WL#5072 BUG#40278 BUG#47175
      
      Create a set of test cases to see if some DDL statements implicitly commit
      a transaction on the NDB and are written directly to the binary log without
      going through either the Statement- or Transactional-Cache.
[18 Jan 2010 12:06] Bugs System
Pushed into 6.0.14-alpha (revid:alik@ibmvm-20100118120357-hnzhgadkpzqfnvsc) (version source revid:alik@ibmvm-20100118115413-kd3klpine09yyktw) (merge vers: 6.0.14-alpha) (pib:16)
[18 Jan 2010 12:07] Bugs System
Pushed into mysql-next-mr (revid:alik@ibmvm-20100118120111-73dulkgc893it4r9) (version source revid:alik@ibmvm-20100118115335-0stecyzftqm7bqx6) (pib:16)
[19 Jan 2010 8:45] Jon Stephens
Documented bugfix in the 5.6.0 and 6.0.14 changelogs.

Set NDI state, waiting for further merges.
[15 Feb 2010 10:17] Jon Stephens
Discussed with Alfranio; no further merges expected. Closed.
[6 Mar 2010 11:06] Bugs System
Pushed into 5.5.3-m3 (revid:alik@sun.com-20100306103849-hha31z2enhh7jwt3) (version source revid:vvaintroub@linux-rbsx-20100118220048-5vnyqi5ghsbgmdsd) (merge vers: 5.5.99-m3) (pib:16)
[7 Mar 2010 1:53] Paul Dubois
Moved 5.6.0 changelog entry to 5.5.3.