Bug #76333 duplicate transaction in binary log
Submitted: 16 Mar 2015 10:55 Modified: 21 Nov 17:27
Reporter: Romain Moyne Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.6.23 OS:Linux
Assigned to: Bogdan Kecman CPU Architecture:Any
Tags: bin log, binary log, binlog, duplicate

[16 Mar 2015 10:55] Romain Moyne
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.
[8 Apr 2015 12:50] Vaclav Bilek
what kind of binlog do you use? ROW/STATEMENT/MIXED

see https://bugs.mysql.com/bug.php?id=76587
[21 Oct 17:27] Bogdan Kecman
I can't reproduce this. Can you share your full config.

thanks
[22 Nov 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".