Bug #53079 due to a trigger, replication fails with DUPLICATE KEY error for an UPDATE
Submitted: 22 Apr 2010 19:04 Modified: 3 Nov 2010 13:07
Reporter: Devananda van der Veen Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.1.45, 5.1, 5.6.99 OS:Any
Assigned to: Assigned Account CPU Architecture:Any
Tags: regression, replication, sbr, triggers

[22 Apr 2010 19:04] Devananda van der Veen
Description:
When there is an UPDATE and an INSERT trigger on same table, and both triggers perform an INSERT into a second table which has an auto_inc column, replication fails with a DUP KEY error on the UPDATE statement if the transactions are committed in a different order than the statements are executed. This is because the binary log contains a SET INSERT_ID statement before the UPDATE, and that ID is used by the trigger (not by the UPDATE statement itself).

How to repeat:
Create the following two tables and two triggers in a replicated environment, using InnoDB engine and 5.1.45 distribution.

master [localhost] {msandbox} (test) > CREATE TABLE `a` (
    ->   `id` int(10) unsigned NOT NULL auto_increment,
    ->   `c1` varchar(255) NOT NULL,
    ->   PRIMARY KEY  (`id`)
    -> ) ENGINE=InnoDB ;
Query OK, 0 rows affected (0.00 sec)

master [localhost] {msandbox} (test) > CREATE TABLE `b` (
    ->   `id` int(10) unsigned NOT NULL auto_increment,
    ->   `a_id` int(10) unsigned NOT NULL,
    ->   `op` enum('i','u','d') default 'i',
    ->   `t` timestamp NOT NULL default CURRENT_TIMESTAMP,
    ->   PRIMARY KEY  (`id`)
    -> ) ENGINE=InnoDB ;
Query OK, 0 rows affected (0.00 sec)

master [localhost] {msandbox} (test) > delimiter ;;
master [localhost] {msandbox} (test) > create trigger a_ai after insert on a for each row begin insert into b (a_id, op) values (NEW.id, 'i'); end;;
Query OK, 0 rows affected (0.01 sec)

master [localhost] {msandbox} (test) > create trigger a_au after update on a for each row begin insert into b (a_id, op) values (NEW.id, 'u'); end;;
Query OK, 0 rows affected (0.00 sec)

I will upload the full log of reproducing the bug in a file, but the gist of it is:

On master, open 2 connections and run insert and update on table `a` in the following order:

1: INSERT
1: COMMIT
2:     BEGIN
2:     UPDATE
1: BEGIN
1: INSERT
1: COMMIT
2:     COMMIT

The interleaving of statements causes the order of statements in the binary log to differ from the order in which the TRIGGERs executed on the master (the master executes IUI but the slave executes IIU), and therefor the UPDATE fails with a DUPKEY error because the binary log included a SET INSERT_ID before the UPDATE statement.

The slave will execute both inserts into the `a` table, and the fail when it executes the update, claiming a duplicate key error for primary key value "2".

Suggested fix:
Do not include SET INSERT_ID before an UPDATE, even if that UPDATE fires a TRIGGER which generates a new auto_inc value. That was the behavior in 5.0.87, and replication did not break (though the master and slave did get out of sync).
[22 Apr 2010 19:05] Devananda van der Veen
full log of reproduction of this bug in mysql sandbox, including binary log dump

Attachment: dup-key-bug-report.txt (text/plain), 11.61 KiB.

[23 Apr 2010 19:52] Sveta Smirnova
Thank you for the report.

Verified as described with binlog_format='statement'. With version 5.1 SET binlog_format='row'; helps.
[2 Nov 2010 4:05] Roel Van de Paar
See bug #50440 | bug #48608 | bug #45677 | bug #42415
[3 Nov 2010 13:07] Andrei Elkin
Analysis reveal this is a dup of Bug #45827.

Indeed two connections contribute to the binary log with the same INSERT_ID:
                                  
| master-bin.000001 | 1074 | Query       |         1 |        1142 | BEGIN
| master-bin.000001 | 1142 | Intvar      |         1 |        1170 | INSERT_ID=1
| master-bin.000001 | 1170 | Query       |         1 |        1272 | use `test`; insert into a (c1) values ('first row')
| master-bin.000001 | 1272 | Xid         |         1 |        1299 | COMMIT /* xid=20 */
| master-bin.000001 | 1299 | Query       |         1 |        1367 | BEGIN
| master-bin.000001 | 1367 | Intvar      |         1 |        1395 | INSERT_ID=2
| master-bin.000001 | 1395 | Query       |         1 |        1498 | use `test`; insert into a (c1) values ('second row')
| master-bin.000001 | 1498 | Xid         |         1 |        1525 | COMMIT /* xid=33 */
| master-bin.000001 | 1525 | Query       |         1 |        1593 | BEGIN
| master-bin.000001 | 1593 | Intvar      |         1 |        1621 | INSERT_ID=2

| master-bin.000001 | 1621 | Query       |         1 |        1723 | use `test`; update a set c1='first row+' where id=1
| master-bin.000001 | 1723 | Xid         |         1 |        1750 | COMMIT /* xid=30 */

However, the INSERT connection #1th value is used on the slave to insert into two tables. That's why the dup key error.
Notice, there is no warning for the unsafe binlogging in 5.1 but there is one
in 5.5+:

mysql> update a set c1='first row+' where id=1;
Query OK, 1 row affected, 1 warning (0.00 sec)

mysql> show warnings;
| Note  | 1592 | Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it invokes a trigger or a stored function that inserts into an AUTO_INCREMENT column. Inserted values cannot be logged correctly.

Finally, set binlog_format=MIXED is a solution for the master-slave consistency issue in this case of two auto-inc tables involved in a query.
5.1 logs the row-based events in that case.