Bug #59338 Inconsistency in binlog for statements that don't change any rows STATEMENT SBR
Submitted: 6 Jan 2011 19:05 Modified: 9 Feb 2011 21:26
Reporter: Leandro Morgado Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.1.50 OS:Any
Assigned to: Alfranio Correia CPU Architecture:Any
Triage: Triaged: D3 (Medium)

[6 Jan 2011 19:05] Leandro Morgado
Description:
When using STATEMENT based replication, an INSERT ON DUPLICATE KEY UPDATE statement that does not change data (Rows .. Changed: 0) will not be recorded in the binary log. 

However, an similar UPDATE statement will. This inconsistent behaviour is not desirable. 

How to repeat:
master [localhost] {msandbox} (test) > SELECT VERSION();
+------------------------------------+
| VERSION()                          |
+------------------------------------+
| 5.1.50-enterprise-gpl-advanced-log |
+------------------------------------+
1 row in set (0.00 sec)

master [localhost] {msandbox} (test) > SHOW VARIABLES LIKE "binlog_format";
+---------------+-----------+
| Variable_name | Value     |
+---------------+-----------+
| binlog_format | STATEMENT |
+---------------+-----------+
1 row in set (0.00 sec)

************************************************************************
============ TEST CASE FOR INSERT ON DUPLICATE KEY UPDATE ==============
CREATE TABLE t1 (
  c1 varchar(15) NOT NULL,
  c2 varchar(20) DEFAULT NULL,
  c3 timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (c1)
) ENGINE=InnoDB DEFAULT CHARSET=latin1;

INSERT INTO t1(c1, c2) VALUES ('a', 'b');

SELECT * FROM  t1;

INSERT INTO t1(c1, c2) VALUES ('a', 'b') ON DUPLICATE KEY UPDATE c1='a', c2='b';

SELECT * FROM t1;

============ RESULT FOR INSERT ON DUPLICATE KEY UPDATE =================
master [localhost] {msandbox} (test) > CREATE TABLE t1 (
    ->   c1 varchar(15) NOT NULL,
    ->   c2 varchar(20) DEFAULT NULL,
    ->   c3 timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
    ->   PRIMARY KEY (c1)
    -> ) ENGINE=InnoDB DEFAULT CHARSET=latin1;
Query OK, 0 rows affected (0.01 sec)

master [localhost] {msandbox} (test) > INSERT INTO t1(c1, c2) VALUES ('a', 'b');
Query OK, 1 row affected (0.01 sec)

master [localhost] {msandbox} (test) > SELECT * FROM t1;
+----+------+---------------------+
| c1 | c2   | c3                  |
+----+------+---------------------+
| a  | b    | 2011-01-06 20:01:26 |
+----+------+---------------------+
1 row in set (0.00 sec)

master [localhost] {msandbox} (test) > INSERT INTO t1(c1, c2) VALUES ('a', 'b') ON DUPLICATE KEY UPDATE c1='a', c2='b';
Query OK, 0 rows affected (0.00 sec)

master [localhost] {msandbox} (test) > SELECT * FROM t1;+----+------+---------------------+
| c1 | c2   | c3                  |
+----+------+---------------------+
| a  | b    | 2011-01-06 20:01:26 |
+----+------+---------------------+
1 row in set (0.00 sec)

master [localhost] {msandbox} (test) > SHOW BINLOG EVENTS\G*************************** 1. row ***************************   Log_name: mysql-bin.000001
        Pos: 4
 Event_type: Format_desc
  Server_id: 1
End_log_pos: 106
       Info: Server ver: 5.1.50-enterprise-gpl-advanced-log, Binlog ver: 4
*************************** 2. row ***************************
   Log_name: mysql-bin.000001
        Pos: 106
 Event_type: Query
  Server_id: 1
End_log_pos: 381
       Info: use `test`; CREATE TABLE t1 (
  c1 varchar(15) NOT NULL,
  c2 varchar(20) DEFAULT NULL,
  c3 timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (c1)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
*************************** 3. row ***************************
   Log_name: mysql-bin.000001
        Pos: 381
 Event_type: Query
  Server_id: 1
End_log_pos: 449
       Info: BEGIN
*************************** 4. row ***************************
   Log_name: mysql-bin.000001
        Pos: 449
 Event_type: Query
  Server_id: 1
End_log_pos: 552
       Info: use `test`; INSERT INTO t1(c1, c2) VALUES ('a', 'b')
*************************** 5. row ***************************
   Log_name: mysql-bin.000001
        Pos: 552
 Event_type: Xid
  Server_id: 1
End_log_pos: 579
       Info: COMMIT /* xid=140 */
5 rows in set (0.00 sec)

CONCLUSION: We never see the INSERT .. ON DUPLICATE KEY UPDATE statement in the binlog.

************************************************************************
====================== TEST CASE FOR UPDATE ============================
CREATE TABLE t1 (
  c1 varchar(15) NOT NULL,
  c2 varchar(20) DEFAULT NULL,
  c3 timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (c1)
) ENGINE=InnoDB DEFAULT CHARSET=latin1;

INSERT INTO t1(c1, c2) VALUES ('a', 'b');

SELECT * FROM  t1;

UPDATE t1 SET c1='a', c2='b' WHERE c1='a' AND c2='b';

SELECT * FROM t1;

====================== RESULT FOR UPDATE ==========================
master [localhost] {msandbox} (test) > CREATE TABLE t1 (
    ->   c1 varchar(15) NOT NULL,
    ->   c2 varchar(20) DEFAULT NULL,
    ->   c3 timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
    ->   PRIMARY KEY (c1)
    -> ) ENGINE=InnoDB DEFAULT CHARSET=latin1;
Query OK, 0 rows affected (0.01 sec)

master [localhost] {msandbox} (test) > INSERT INTO t1(c1, c2) VALUES ('a', 'b');
Query OK, 1 row affected (0.01 sec)

master [localhost] {msandbox} (test) > SELECT * FROM  t1;
+----+------+---------------------+
| c1 | c2   | c3                  |
+----+------+---------------------+
| a  | b    | 2011-01-06 19:58:42 |
+----+------+---------------------+
1 row in set (0.00 sec)

-- notice Changed:0 below
master [localhost] {msandbox} (test) > UPDATE t1 SET c1='a', c2='b' WHERE c1='a' AND c2='b';
Query OK, 0 rows affected (0.00 sec)
Rows matched: 1  Changed: 0  Warnings: 0
 
master [localhost] {msandbox} (test) > SELECT * FROM t1;
+----+------+---------------------+
| c1 | c2   | c3                  |
+----+------+---------------------+
| a  | b    | 2011-01-06 19:58:42 |
+----+------+---------------------+
1 row in set (0.00 sec)

master [localhost] {msandbox} (test) > SHOW BINLOG EVENTS\G
*************************** 1. row ***************************
   Log_name: mysql-bin.000001
        Pos: 4
 Event_type: Format_desc
  Server_id: 1
End_log_pos: 106
       Info: Server ver: 5.1.50-enterprise-gpl-advanced-log, Binlog ver: 4
*************************** 2. row ***************************
   Log_name: mysql-bin.000001
        Pos: 106
 Event_type: Query
  Server_id: 1
End_log_pos: 381
       Info: use `test`; CREATE TABLE t1 (
  c1 varchar(15) NOT NULL,
  c2 varchar(20) DEFAULT NULL,
  c3 timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (c1)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
*************************** 3. row ***************************
   Log_name: mysql-bin.000001
        Pos: 381
 Event_type: Query
  Server_id: 1
End_log_pos: 449
       Info: BEGIN
*************************** 4. row ***************************
   Log_name: mysql-bin.000001
        Pos: 449
 Event_type: Query
  Server_id: 1
End_log_pos: 552
       Info: use `test`; INSERT INTO t1(c1, c2) VALUES ('a', 'b')
*************************** 5. row ***************************
   Log_name: mysql-bin.000001
        Pos: 552
 Event_type: Xid
  Server_id: 1
End_log_pos: 579
       Info: COMMIT /* xid=132 */
*************************** 6. row ***************************
   Log_name: mysql-bin.000001
        Pos: 579
 Event_type: Query
  Server_id: 1
End_log_pos: 647
       Info: BEGIN
*************************** 7. row ***************************
   Log_name: mysql-bin.000001
        Pos: 647
 Event_type: Query
  Server_id: 1
End_log_pos: 762
       Info: use `test`; UPDATE t1 SET c1='a', c2='b' WHERE c1='a' AND c2='b'
*************************** 8. row ***************************
   Log_name: mysql-bin.000001
        Pos: 762
 Event_type: Query
  Server_id: 1
End_log_pos: 831
       Info: COMMIT
8 rows in set (0.00 sec)

CONCLUSION: Row 7 of the binlog events show that the UPDATE was logged.

Suggested fix:
This is inconsistent as no statement changes rows but one is logged and the other one isn't. I think either both are logged or non are.

Binary logging both entries is probably safer to cover edge user cases and hacks like this:

mysql> UPDATE tbl SET col = 1 WHERE @@server_id = 2;
[6 Jan 2011 19:13] Leandro Morgado
Work around: 

master [localhost] {msandbox} (test) > RESET MASTER;
Query OK, 0 rows affected (0.00 sec)

master [localhost] {msandbox} (test) > INSERT INTO t1(c1, c2) VALUES ('a', 'b') ON DUPLICATE KEY UPDATE c1='a', c2='b',c3=NOW();
Query OK, 2 rows affected (0.01 sec)

master [localhost] {msandbox} (test) > SELECT * FROM t1;+----+------+---------------------+
| c1 | c2   | c3                  |
+----+------+---------------------+
| a  | b    | 2011-01-06 20:12:34 |
+----+------+---------------------+
1 row in set (0.00 sec)

master [localhost] {msandbox} (test) > SHOW BINLOG EVENTS\G
*************************** 1. row ***************************
   Log_name: mysql-bin.000001
        Pos: 4
 Event_type: Format_desc
  Server_id: 1
End_log_pos: 106
       Info: Server ver: 5.1.50-enterprise-gpl-advanced-log, Binlog ver: 4
*************************** 2. row ***************************
   Log_name: mysql-bin.000001
        Pos: 106
 Event_type: Query
  Server_id: 1
End_log_pos: 182
       Info: BEGIN
*************************** 3. row ***************************
   Log_name: mysql-bin.000001
        Pos: 182
 Event_type: Query
  Server_id: 1
End_log_pos: 341
       Info: use `test`; INSERT INTO t1(c1, c2) VALUES ('a', 'b') ON DUPLICATE KEY UPDATE c1='a', c2='b',c3=NOW()
*************************** 4. row ***************************
   Log_name: mysql-bin.000001
        Pos: 341
 Event_type: Xid
  Server_id: 1
End_log_pos: 368
       Info: COMMIT /* xid=148 */
4 rows in set (0.00 sec)
[7 Jan 2011 13:48] 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/128170

3535 Alfranio Correia	2011-01-07
      BUG#59338 Inconsistency in binlog for statements that don't change any rows STATEMENT SBR
      
      In SBR, if a statement does not fail, it always written to the binary log, regardless if
      rows are changed or not. If there is a failure, a statement is only written to the
      binary log if a non-transactional engine is updated.
      
      INSERT ON DUPLICATE KEY UPDATE was not following the rule above and was not being written
      to the binary log, if then engine was Innodb.
[7 Jan 2011 16:12] 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/128186

3535 Alfranio Correia	2011-01-07
      BUG#59338 Inconsistency in binlog for statements that don't change any rows STATEMENT SBR
      
      In SBR, if a statement does not fail, it is always written to the binary log, regardless if
      rows are changed or not. If there is a failure, a statement is only written to the binary
      log if a non-transactional (.e.g. MyIsam) engine is updated.
      
      INSERT ON DUPLICATE KEY UPDATE and INSERT IGNORE were not following the rule above and were
      not written to the binary log, if then engine was Innodb.
[19 Jan 2011 11:31] 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/129169

3535 Alfranio Correia	2011-01-19
      BUG#59338 Inconsistency in binlog for statements that don't change any rows STATEMENT SBR
      
      In SBR, if a statement does not fail, it is always written to the binary log, regardless if
      rows are changed or not. If there is a failure, a statement is only written to the binary
      log if a non-transactional (.e.g. MyIsam) engine is updated.
      
      INSERT ON DUPLICATE KEY UPDATE and INSERT IGNORE were not following the rule above and were
      not written to the binary log, if then engine was Innodb.
[21 Jan 2011 12:57] 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/129330

3535 Alfranio Correia	2011-01-21
      BUG#59338 Inconsistency in binlog for statements that don't change any rows STATEMENT SBR
      
      In SBR, if a statement does not fail, it is always written to the binary
      log, regardless if rows are changed or not. If there is a failure, a
      statement is only written to the binary log if a non-transactional (.e.g.
      MyIsam) engine is updated.
      
      INSERT ON DUPLICATE KEY UPDATE and INSERT IGNORE were not following the
      rule above and were not written to the binary log, if then engine was
      Innodb.
     @ mysql-test/extra/rpl_tests/rpl_insert_duplicate.test
        Added test case.
     @ mysql-test/extra/rpl_tests/rpl_insert_ignore.test
        Updated test case.
     @ mysql-test/include/commit.inc
        Updated test case as the calls to the binary log have changed
        for INSERT ON DUPLICATE and INSERT IGNORE.
     @ mysql-test/r/commit_1innodb.result
        Updated result file.
     @ mysql-test/suite/rpl/r/rpl_row_insert_duplicate.result
        Added a test case.
     @ mysql-test/suite/rpl/r/rpl_row_insert_ignore.result
        Added a test case.
     @ mysql-test/suite/rpl/r/rpl_stm_mixed_insert_duplicate.result
        Added a test case.
     @ mysql-test/suite/rpl/r/rpl_stm_mixed_insert_ignore.result
        Added a test case.
     @ mysql-test/suite/rpl/t/rpl_row_insert_duplicate.test
        Added a test case.
     @ mysql-test/suite/rpl/t/rpl_row_insert_ignore.test
        Added a test case.
     @ mysql-test/suite/rpl/t/rpl_stm_mixed_insert_duplicate.test
        Added a test case.
     @ mysql-test/suite/rpl/t/rpl_stm_mixed_insert_ignore.test
        Update the test case, in order to run it only in SBR and MIXED modes.
        Note that another test case was created for the ROW mode.
[27 Jan 2011 15:33] 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/129787

3555 Alfranio Correia	2011-01-27
      BUG#59338 Inconsistency in binlog for statements that don't change any rows STATEMENT SBR
      
      In SBR, if a statement does not fail, it is always written to the binary
      log, regardless if rows are changed or not. If there is a failure, a
      statement is only written to the binary log if a non-transactional (.e.g.
      MyIsam) engine is updated.
      
      INSERT ON DUPLICATE KEY UPDATE and INSERT IGNORE were not following the
      rule above and were not written to the binary log, if then engine was
      Innodb.
     @ mysql-test/extra/rpl_tests/rpl_insert_duplicate.test
        Added test case.
     @ mysql-test/extra/rpl_tests/rpl_insert_ignore.test
        Updated test case.
     @ mysql-test/include/commit.inc
        Updated test case as the calls to the binary log have changed
        for INSERT ON DUPLICATE and INSERT IGNORE.
     @ mysql-test/r/commit_1innodb.result
        Updated result file.
     @ mysql-test/suite/rpl/r/rpl_insert_duplicate.result
        Added test case.
     @ mysql-test/suite/rpl/r/rpl_insert_ignore.result
        Updated result file.
     @ mysql-test/suite/rpl/t/rpl_insert_duplicate.test
        Added test case.
     @ mysql-test/suite/rpl/t/rpl_insert_ignore.test
        Improved test case.
[27 Jan 2011 16:15] 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/129792

3555 Alfranio Correia	2011-01-27
      BUG#59338 Inconsistency in binlog for statements that don't change any rows STATEMENT SBR
      
      In SBR, if a statement does not fail, it is always written to the binary
      log, regardless if rows are changed or not. If there is a failure, a
      statement is only written to the binary log if a non-transactional (.e.g.
      MyIsam) engine is updated.
      
      INSERT ON DUPLICATE KEY UPDATE and INSERT IGNORE were not following the
      rule above and were not written to the binary log, if then engine was
      Innodb.
     @ mysql-test/extra/rpl_tests/rpl_insert_duplicate.test
        Added test case.
     @ mysql-test/extra/rpl_tests/rpl_insert_ignore.test
        Updated test case.
     @ mysql-test/include/commit.inc
        Updated test case as the calls to the binary log have changed
        for INSERT ON DUPLICATE and INSERT IGNORE.
     @ mysql-test/r/commit_1innodb.result
        Updated result file.
     @ mysql-test/suite/rpl/r/rpl_insert_duplicate.result
        Added test case.
     @ mysql-test/suite/rpl/r/rpl_insert_ignore.result
        Updated result file.
     @ mysql-test/suite/rpl/t/rpl_insert_duplicate.test
        Added test case.
     @ mysql-test/suite/rpl/t/rpl_insert_ignore.test
        Improved test case.
[28 Jan 2011 12:10] 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/129851

3555 Alfranio Correia	2011-01-28
      BUG#59338 Inconsistency in binlog for statements that don't change any rows STATEMENT SBR
      
      In SBR, if a statement does not fail, it is always written to the binary
      log, regardless if rows are changed or not. If there is a failure, a
      statement is only written to the binary log if a non-transactional (.e.g.
      MyIsam) engine is updated.
      
      INSERT ON DUPLICATE KEY UPDATE and INSERT IGNORE were not following the
      rule above and were not written to the binary log, if then engine was
      Innodb.
     @ mysql-test/extra/rpl_tests/rpl_insert_duplicate.test
        Added test case.
     @ mysql-test/extra/rpl_tests/rpl_insert_ignore.test
        Updated test case.
     @ mysql-test/include/commit.inc
        Updated test case as the calls to the binary log have changed
        for INSERT ON DUPLICATE and INSERT IGNORE.
     @ mysql-test/r/commit_1innodb.result
        Updated result file.
     @ mysql-test/suite/rpl/r/rpl_insert_duplicate.result
        Added test case.
     @ mysql-test/suite/rpl/r/rpl_insert_ignore.result
        Updated result file.
     @ mysql-test/suite/rpl/t/rpl_insert_duplicate.test
        Added test case.
     @ mysql-test/suite/rpl/t/rpl_insert_ignore.test
        Improved test case.
[31 Jan 2011 14:33] 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/130048

3570 Alfranio Correia	2011-01-31
      Post-fix for BUG#59338.
[31 Jan 2011 14:39] Bugs System
Pushed into mysql-5.1 5.1.56 (revid:alfranio.correia@oracle.com-20110131143133-tbrk92p7b691sy7v) (version source revid:alfranio.correia@oracle.com-20110131143133-tbrk92p7b691sy7v) (merge vers: 5.1.56) (pib:24)
[31 Jan 2011 14:39] Bugs System
Pushed into mysql-5.5 5.5.10 (revid:alfranio.correia@oracle.com-20110131143404-lhpp8lyvdm48z54o) (version source revid:alfranio.correia@oracle.com-20110131143404-lhpp8lyvdm48z54o) (merge vers: 5.5.10) (pib:24)
[31 Jan 2011 14:41] Bugs System
Pushed into mysql-trunk 5.6.2 (revid:alfranio.correia@oracle.com-20110131143645-adjsz57nh921np4f) (version source revid:alfranio.correia@oracle.com-20110131143645-adjsz57nh921np4f) (merge vers: 5.6.2) (pib:24)
[1 Feb 2011 16:21] Jon Stephens
Documented bugfix as follows in the 5.1.56, 5.5.10, and 5.6.2 changelogs:

        When using the statement-based logging format, INSERT ON
        DUPLICATE KEY UPDATE and INSERT IGNORE statements affecting
        transactional tables that did not fail were not written to the
        binary log if they did not insert any rows. (With
        statement-based logging, all successful statements should be
        logged, whether they do or do not they cause any rows to be 
        changed.)

Closed.
[9 Feb 2011 21:26] Jon Stephens
Already documented in the 5.1.56 and 5.5.10 changelogs. Closed.
[23 Sep 2011 19:48] Mark Callaghan
I don't understand the testcase for rpl_insert_ignore. The bug was that INSERT IGNORE didn't write to the binlog for when no rows were modified. But the testcase INSERT IGNORE statement inserts 2 rows from t2 into t1