Bug #69185 Replication breaks during concurrent INSERTs and LOAD DATA in a auto_inc table
Submitted: 9 May 2013 15:23 Modified: 24 Feb 2014 12:33
Reporter: Ovais Tariq Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.1.69 OS:Any
Assigned to: CPU Architecture:Any
Triage: Needs Triage: D2 (Serious)

[9 May 2013 15:23] Ovais Tariq
Description:
Under certain conditions concurrent execution of INSERTs and LOAD DATA in an auto_increment table will cause replication to break on the slave with a duplicate key error. For this condition to be met the table involved in the INSERTs will not have an auto_incrementing column on the master but will have a auto_incrementing column on the slave. This is caused by the INSERT being logged within the LOAD DATA INFILE block of events. Following is what the binary log contents look like in this case:

# at 961
#130509 17:15:59 server id 1  end_log_pos 989   Intvar
SET INSERT_ID=1/*!*/;
# at 989
#130509 17:15:59 server id 1  end_log_pos 1032
#Begin_load_query: file_id: 12  block_len: 20
# at 1032
#130509 17:15:59 server id 1  end_log_pos 1203  Query   thread_id=182   exec_time=0     error_code=0
SET TIMESTAMP=1368112559/*!*/;
INSERT INTO tbl_auto_col_only_on_slave SET col1 = 23211, col2 = 'foo', col3 = 'bar', col4 = 1, col5 = 242122
/*!*/;
# at 1203
#130509 17:15:59 server id 1  end_log_pos 1231  Intvar
SET INSERT_ID=1/*!*/;
# at 1231
#130509 17:15:59 server id 1  end_log_pos 1512  Execute_load_query      thread_id=181   exec_time=0     error_code=0
SET TIMESTAMP=1368112559/*!*/;
LOAD DATA LOCAL INFILE '/tmp/SQL_LOAD_MB-c-0' INTO TABLE `tbl_auto_col` FIELDS TERMINATED BY ',' ENCLOSED BY '"' ESCAPED BY '\\' LINES TERMINATED BY '\n' (`c`)
/*!*/;
# file_id: 12 

As you can see that there is an INSERT logged in the binary log within the group of events belonging to the LOAD DATA, which means the INSERT on the slave will use the auto_increment value of 1 because of "SET INSERT_ID=1" being present before the INSERT.

And the slave fails as follows:
slave1 [localhost] {msandbox} (test) > show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: rsandbox
                  Master_Port: 29984
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000014
          Read_Master_Log_Pos: 2196
               Relay_Log_File: mysql_sandbox29985-relay-bin.000026
                Relay_Log_Pos: 1177
        Relay_Master_Log_File: mysql-bin.000014
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 1062
                   Last_Error: Error 'Duplicate entry '1' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'INSERT INTO tbl_auto_col_only_on_slave SET col1 = 23211, col2 = 'foo', col3 = 'bar', col4 = 1, col5 = 242122'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 1032
              Relay_Log_Space: 2552
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 1062
               Last_SQL_Error: Error 'Duplicate entry '1' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'INSERT INTO tbl_auto_col_only_on_slave SET col1 = 23211, col2 = 'foo', col3 = 'bar', col4 = 1, col5 = 242122'
1 row in set (0.00 sec)

How to repeat:
Create the following MyISAM tables:
CREATE TABLE `tbl_auto_col` (
  `id` int(11) NOT NULL auto_increment,
  `c` char(3) default NULL,
  PRIMARY KEY  (`id`)
) ENGINE=MyISAM DEFAULT CHARSET=latin1;

CREATE TABLE `tbl_auto_col_only_on_slave` (
  `col1` int(11) DEFAULT NULL,
  `col2` varchar(100) DEFAULT NULL,
  `col3` varchar(100) DEFAULT NULL,
  `col4` int(11) DEFAULT NULL,
  `col5` int(11) DEFAULT NULL
) ENGINE=MyISAM DEFAULT CHARSET=latin1;

Alter the table tbl_auto_col_only_on_slave on the slave to add an auto_increment column:
-- on slave:
alter table tbl_auto_col_only_on_slave add column id bigint(20) NOT NULL AUTO_INCREMENT PRIMARY KEY;

Create a file to be loaded by LOAD DATA INFILE:
[root@ovaistariq-test master]# cat /tmp/SQL_LOAD_MB-17a99f5-3 
17d
c44
019
69b
9c5

Run the script attached to this bug report:
./test_insert.sh

The script would need to be executed multiple times before the condition can be produced, I was able to produce the bug by executing the script test_insert.sh 7 times.
[9 May 2013 15:27] Ovais Tariq
Test script to execute INSERT and LOAD DATA concurrently

Attachment: test_insert.sh (application/octet-stream, text), 913 bytes.

[9 May 2013 15:28] Ovais Tariq
MySQL binlog that caused replication failure

Attachment: mysql-bin.000014 (application/octet-stream, text), 2.14 KiB.

[9 May 2013 15:31] Ovais Tariq
file used in the LOAD DATA INFILE

Attachment: SQL_LOAD_MB-17a99f5-3 (application/octet-stream, text), 20 bytes.

[9 May 2013 18:53] Umesh Shastry
Hello Ovais,

Thank you for the report.
Verified as described.

Thanks,
Umesh
[9 May 2013 19:01] Umesh Shastry
- Had to run load file some 18+ times to hit this error

## Duplicate error on slave

slave1 [localhost] {msandbox} (test) > show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: rsandbox
                  Master_Port: 29984
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000024
          Read_Master_Log_Pos: 2163
               Relay_Log_File: mysql_sandbox29985-relay-bin.000038
                Relay_Log_Pos: 1177
        Relay_Master_Log_File: mysql-bin.000019
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 1062
                   Last_Error: Error 'Duplicate entry '1' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'INSERT INTO tbl_auto_col_only_on_slave SET col1 = 23211, col2 = 'foo', col3 = 'bar', col4 = 1, col5 = 242122'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 1032
              Relay_Log_Space: 16394
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 1062
               Last_SQL_Error: Error 'Duplicate entry '1' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'INSERT INTO tbl_auto_col_only_on_slave SET col1 = 23211, col2 = 'foo', col3 = 'bar', col4 = 1, col5 = 242122'
1 row in set (0.00 sec)
[9 May 2013 19:02] Umesh Shastry
Test case...

Attachment: 69185.txt (text/plain), 2.71 KiB.

[9 Jan 2014 22:55] Roel Van de Paar
Ovais, Umesh,

Is InnoDB also affected? Is 5.5/5.6 also affected?
[24 Feb 2014 12:16] Ovais Tariq
Hello Roel,

I haven't been able to reproduce it on 5.5 or 5.6
[24 Feb 2014 12:33] Ovais Tariq
I have also not been able to reproduce it on 5.1 with InnoDB. So this appears to be a MyISAM only bug.