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.
