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.
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.