Bug #64139 Duplicate INSERTs in binary log for NDB tables when binlog_format=STATEMENT
Submitted: 26 Jan 2012 22:20 Modified: 26 Jan 2012 23:00
Reporter: Kolbe Kegel Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Cluster: Replication Severity:S3 (Non-critical)
Version:mysql-cluster-gpl-7.2.2 OS:Any
Assigned to: Matthew Montgomery CPU Architecture:Any
Tags: BINARY, binlog, cluster, duplicate, RBL, RBR, SBL, sbr
Triage: Needs Triage: D2 (Serious)

[26 Jan 2012 22:20] Kolbe Kegel
Description:
If mysqld is started with binlog_format=STATEMENT (the default!), and binlog_format is changed to ROW (or MIXED) after mysqld is started, either globally or for a session, and then rows are inserted into an NDB table, the [results of the] insert appears *twice* in the binary log on the master.

Even if binlog_format is changed to ROW or MIXED *globally* and the client-reconnects, this problem persists. The only way to avoid this problem is to start mysqld with binlog_format=ROW. (That's surely a good idea, even required, but just because someone starts mysqld with the default value of binlog_format doesn't mean they deserve duplicate data and nonsensical binary logs.)

This, of course, causes all kinds of serious problems, such as either duplicate data or duplicate key errors on a slave.

This bug may be caused in part by NDB and in part by MySQL.

How to repeat:
1) Start mysqld with binlog_format=STATMENT (the default)
2) Create an NDB table
3) Insert some rows
   - Note that this INSERT shows up as a STATEMENT-based log entry! That is probably a separate bug...
4) SET binlog_format=ROW
5) Insert some more rows
6) Use SHOW BINLOG EVENTS to see that there are *two* write events for the table, presumably one written by mysqld (why?) and one injected by the Cluster:

master> show binlog events in 'master72.000002';
+-----------------+-----+-------------+-----------+-------------+-----------------------------------------------------+
| Log_name        | Pos | Event_type  | Server_id | End_log_pos | Info                                                |
+-----------------+-----+-------------+-----------+-------------+-----------------------------------------------------+
| master72.000002 |   4 | Format_desc |         1 |         112 | Server ver: 5.5.16-ndb-7.2.2-gpl-log, Binlog ver: 4 |
| master72.000002 | 112 | Query       |         1 |         180 | BEGIN                                               |
| master72.000002 | 180 | Intvar      |         1 |         208 | INSERT_ID=1                                         |
| master72.000002 | 208 | Query       |         1 |         304 | use `test`; insert into c1 () values (),(),()       |
| master72.000002 | 304 | Query       |         1 |         373 | COMMIT                                              |
| master72.000002 | 373 | Query       |         1 |         441 | BEGIN                                               |
| master72.000002 | 441 | Table_map   |         1 |         482 | table_id: 41 (test.c1)                              |
| master72.000002 | 482 | Write_rows  |         1 |         528 | table_id: 41 flags: STMT_END_F                      |
| master72.000002 | 528 | Query       |         1 |         597 | COMMIT                                              |
| master72.000002 | 597 | Query       |         1 |         661 | BEGIN                                               |
| master72.000002 | 661 | Table_map   |         1 |         702 | table_id: 39 (test.c1)                              |
| master72.000002 | 702 | Table_map   |         1 |         764 | table_id: 34 (mysql.ndb_apply_status)               |
| master72.000002 | 764 | Write_rows  |         1 |         825 | table_id: 34                                        |
| master72.000002 | 825 | Write_rows  |         1 |         871 | table_id: 39 flags: STMT_END_F                      |
| master72.000002 | 871 | Query       |         1 |         936 | COMMIT                                              |
+-----------------+-----+-------------+-----------+-------------+-----------------------------------------------------+
15 rows in set (0.00 sec)

Or, use mysqldump to see that:

#120126 17:01:00 server id 1  end_log_pos 441   Query   thread_id=3     exec_time=0     error_code=0
SET TIMESTAMP=1327615260/*!*/;
BEGIN
/*!*/;
# at 441
# at 482
#120126 17:01:00 server id 1  end_log_pos 482   Table_map: `test`.`c1` mapped to number 41
#120126 17:01:00 server id 1  end_log_pos 528   Write_rows: table id 41 flags: STMT_END_F

BINLOG '
HM0hTxMBAAAAKQAAAOIBAACAACkAAAAAAAEABHRlc3QAAmMxAAEDAAA=
HM0hTx4BAAAALgAAABACAAAAACkAAAAAAAEAAgAB//4EAAAA/gUAAAD+BgAAAA==
'/*!*/;
### INSERT INTO test.c1
### SET
###   @1=4
### INSERT INTO test.c1
### SET
###   @1=5
### INSERT INTO test.c1
### SET
###   @1=6
# at 528
#120126 17:01:00 server id 1  end_log_pos 597   Query   thread_id=3     exec_time=0     error_code=0
SET TIMESTAMP=1327615260/*!*/;
COMMIT
/*!*/;
# at 597
#120126 17:01:00 server id 1  end_log_pos 661   Query   thread_id=0     exec_time=0     error_code=0
SET TIMESTAMP=1327615260/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
BEGIN
/*!*/;
# at 661
# at 702
# at 764
# at 825
#120126 17:01:00 server id 1  end_log_pos 702   Table_map: `test`.`c1` mapped to number 39
#120126 17:01:00 server id 1  end_log_pos 764   Table_map: `mysql`.`ndb_apply_status` mapped to number 34
#120126 17:01:00 server id 1  end_log_pos 825   Write_rows: table id 34
#120126 17:01:00 server id 1  end_log_pos 871   Write_rows: table id 39 flags: STMT_END_F

BINLOG '
HM0hTxMBAAAAKQAAAL4CAACAACcAAAAAAAEABHRlc3QAAmMxAAEDAAA=
HM0hTxMBAAAAPgAAAPwCAACAACIAAAAAAAEABW15c3FsABBuZGJfYXBwbHlfc3RhdHVzAAUDCA8I
CAL/AAA=
HM0hTx4BAAAAPQAAADkDAAAAACIAAAAAAAAAAgAF/+ABAAAADgAAAGECAAAAAAAAAAAAAAAAAAAA
AAAAAA==
### INSERT INTO mysql.ndb_apply_status
### SET
###   @1=1
###   @2=2615635083278
###   @3=''
###   @4=0
###   @5=0
HM0hTx4BAAAALgAAAGcDAAAAACcAAAAAAAEAAgAB//4GAAAA/gQAAAD+BQAAAA==
'/*!*/;
### INSERT INTO test.c1
### SET
###   @1=6
### INSERT INTO test.c1
### SET
###   @1=4
### INSERT INTO test.c1
### SET
###   @1=5
# at 871

This, of course, causes trouble on a replication slave, too:

Last_Error: Could not execute Write_rows event on table test.c1; Duplicate entry '6' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log master72.000002, end_log_pos 871

Here is a test case that can be pasted, assuming of course that you have started the server with binlog_format set to the default, you have set up and connected to a functional Cluster, etc:

use test;
create table c1 (id int not null auto_increment primary key) engine=ndbcluster;
insert into c1 () values (),(),();
set binlog_format=row;
insert into c1 () values (),(),();
show binlog events; #may need to give a log name here

Suggested fix:
The default binlog_format for NDB packages surely should *not* be STATEMENT! In fact, binlog_format=STATEMENT should not even be allowed for NDB; see bug #46172. Indeed, it looks like this has already been brought up in the past; see bug #40586.

Regardless, when mysqld is started with binlog_format=STATEMENT, and binlog_format is later changed to ROW or MIXED, that should not cause, under any circumstance, two copies of an INSERT to be written to the binary log.
[26 Jan 2012 23:00] Matthew Montgomery
Thank you for your detailed bug report. This behavior is verified as described on 5.5.17-7.2.3 also. 

For clarity, duplicate events are only seen after starting mysqld with binlog_format=STATEMENT and later changing it to ROW/MIXED.  For inserts that occur while binlog_format=STATEMENT a single statement based event is logged.
[29 Apr 2015 7:58] kamal sharma
I am facing similar issue,We are getting duplicate delete query in binary log,which is creating problem in replication.

MySQL version :- 5.6
Engine :- InnoDB

### DELETE FROM `oauth_db`.`Token_scopes`
### WHERE
###   @1=1040103520
###   @2='pocket'
### DELETE FROM `oauth_db`.`Token_scopes`
### WHERE
###   @1=1040103520
###   @2='pocket'