Description:
When MySQL in rotating its binary log file, it duplicates one of the last transaction of the bin log file to the new bin log file.
Then it generates a "duplicate key" error on slaves that see two insert with the same INSERT_ID.
For instance, let's look at binlog when MySQL is rotating from mysql-bin.002406 to mysql-bin.002407.
mysql-bin.002406 (end of file):
#150316 5:53:53 server id 1 end_log_pos 191183550 CRC32 0x0b7164e3 GTID [commit=yes]
SET @@SESSION.GTID_NEXT= '99db3315-1b28-11e3-b3f4-002590a3f8ba:1030317865'/*!*/;
# at 191183550
#150316 5:53:53 server id 1 end_log_pos 191183651 CRC32 0x478638fa Query thread_id=4416811 exec_time=1 error_code=0
SET TIMESTAMP=1426499633/*!*/;
BEGIN
/*!*/;
# at 191183651
# at 191183683
#150316 5:53:53 server id 1 end_log_pos 191183683 CRC32 0x837bfe73 Intvar
SET INSERT_ID=21714037/*!*/;
#150316 5:53:53 server id 1 end_log_pos 191183995 CRC32 0x478057fb Query thread_id=4416811 exec_time=1 error_code=0
SET TIMESTAMP=1426499633/*!*/;
INSERT INTO ad_impression (field1_id,field2_id,field3_id,field4_id,field5,field6,field7,field8,field9) VALUES ('10881341','13739387','1414098','374252',1,2,'2015-03-16T10:47:18+01:00','255.255.255.255','')
/*!*/;
# at 191183995
#150316 5:53:53 server id 1 end_log_pos 191184026 CRC32 0x1982cfd6 Xid = 16969327
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog *//*!*/;
DELIMITER ;
# End of log file
And the content of the beginning of the newly created mysql-bin.002407:
#150316 5:55:13 server id 1 end_log_pos 103902 CRC32 0x659192a0 GTID [commit=yes]
SET @@SESSION.GTID_NEXT= '99db3315-1b28-11e3-b3f4-002590a3f8ba:1030317893'/*!*/;
# at 103902
#150316 5:55:13 server id 1 end_log_pos 104003 CRC32 0x93bd3875 Query thread_id=65 exec_time=0 error_code=0
SET TIMESTAMP=1426499713/*!*/;
BEGIN
/*!*/;
# at 104003
# at 104035
#150316 5:55:13 server id 1 end_log_pos 104035 CRC32 0xba95cfba Intvar
SET INSERT_ID=21714037/*!*/;
#150316 5:55:13 server id 1 end_log_pos 104344 CRC32 0x70309767 Query thread_id=65 exec_time=0 error_code=0
SET TIMESTAMP=1426499713/*!*/;
INSERT INTO ad_impression (field1_id,field2_id,field3_id,field4_id,field5,field6,field7,field8,field9) VALUES ('10881333','13739427','1443310',NULL,1,2,'2015-03-16T10:48:38+01:00','255.255.255.255','')
/*!*/;
# at 104344
#150316 5:55:13 server id 1 end_log_pos 104375 CRC32 0x1759b562 Xid = 235
COMMIT/*!*/;
# at 104375
#150316 5:55:14 server id 1 end_log_pos 104423 CRC32 0x7d8d24dd GTID [commit=yes]
SET @@SESSION.GTID_NEXT= '99db3315-1b28-11e3-b3f4-002590a3f8ba:1030317894'/*!*/;
Observations:
The row that is inserted is not the same in mysql-bin.002406 and mysql-bin.002407.
But both rows are inserted with the same INSERT_ID !
My code does not insert rows with a specified ID. It's always auto_incremented
It happens ONLY when Mysql rotates bin log. I am sure there is something here.
How to repeat:
It happens some time to time, there is not scenario to repeat it.