Bug #69861 LAST_INSERT_ID is replicated incorrectly if replication filters are used
Submitted: 28 Jul 2013 9:37 Modified: 21 Oct 2013 14:55
Reporter: Miguel Angel Nieto Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.5.32, 5.6.12/13 OS:Any
Assigned to:

[28 Jul 2013 9:37] Miguel Angel Nieto
Description:
If you have a replication environment that uses replication filters (replicate-ignore-table in this example), the value of LAST_INSERT_ID could not get correctly replicated.

In the environment described in "how to repeat" this is the LAST_INSERT_ID value that the slave server receives without replicate-ignore-table:

SET LAST_INSERT_ID=1/*!*/;

And the same query with replicate-ignore-table writes the following on slave's relay log:

SET LAST_INSERT_ID=0/*!*/;

How to repeat:
We have the following servers:

A<->B
|
C

Where A and B are in master-master and C replicates from A.

Now run the following on B:

CREATE TABLE `sometable_apps` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`appname` varchar(50) DEFAULT NULL,
`createdate` datetime DEFAULT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB;

CREATE TABLE `sometable` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`rundt` datetime DEFAULT NULL,
`appid` int(11) DEFAULT NULL,
`username` varchar(20) DEFAULT NULL,
`machine` varchar(20) DEFAULT NULL,
`finishdt` datetime DEFAULT NULL,
`pid` int(11) DEFAULT NULL,
PRIMARY KEY (`id`),
KEY `sometable_apps` (`appid`),
CONSTRAINT `sometable_apps` FOREIGN KEY (`appid`) REFERENCES `sometable_apps` (`id`)
) ENGINE=InnoDB;

insert into sometable_apps(appname, createdate) values ('xxxxx', '2013-07-23 15:56:59');
insert into sometable (rundt, appid, username, machine, pid) values ('2013-07-23 15:56:59', LAST_INSERT_ID(), 'xxxxx', 'xxxxxxx', 2736);

The C's replication will fail:

"Error 'Cannot add or update a child row: a foreign key constraint fails".

If you remove the replicate-ignore-table and repeat the process it won't fail and the LAST_INSERT_ID will be correctly logged on slaves relay log.

A SERVER:

[client]
user               = msandbox
password           = msandbox
port               = 22987
socket             = /tmp/mysql_sandbox22987.sock

[mysqld]
user               = root
port               = 22987
socket             = /tmp/mysql_sandbox22987.sock
basedir            = /root/5.5.32
datadir            = /root/sandboxes/rsandbox_mysql-5_5_32/master/data
tmpdir             = /root/sandboxes/rsandbox_mysql-5_5_32/master/tmp
pid-file           = /root/sandboxes/rsandbox_mysql-5_5_32/master/data/mysql_sandbox22987.pid
bind-address       = 127.0.0.1
log-bin=mysql-bin
server-id=1
log-error=msandbox.err

replicate-ignore-table=database.table

log-slave-updates = 1

B SERVER:

[client]
user               = msandbox
password           = msandbox
port               = 22988
socket             = /tmp/mysql_sandbox22988.sock

[mysqld]
user               = root
port               = 22988
socket             = /tmp/mysql_sandbox22988.sock
basedir            = /root/5.5.32
datadir            = /root/sandboxes/rsandbox_mysql-5_5_32/node1/data
tmpdir             = /root/sandboxes/rsandbox_mysql-5_5_32/node1/tmp
pid-file           = /root/sandboxes/rsandbox_mysql-5_5_32/node1/data/mysql_sandbox22988.pid
bind-address       = 127.0.0.1
server-id=101
report-host=SBslave1
report-port=22988
log-bin=mysql-bin
log-error=msandbox.err

replicate-ignore-table=database.table

log-slave-updates = 1

C SERVER:

[client]
user               = msandbox
password           = msandbox
port               = 22989
socket             = /tmp/mysql_sandbox22989.sock

[mysqld]
user               = root
port               = 22989
socket             = /tmp/mysql_sandbox22989.sock
basedir            = /root/5.5.32
datadir            = /root/sandboxes/rsandbox_mysql-5_5_32/node2/data
tmpdir             = /root/sandboxes/rsandbox_mysql-5_5_32/node2/tmp
pid-file           = /root/sandboxes/rsandbox_mysql-5_5_32/node2/data/mysql_sandbox22989.pid
bind-address       = 127.0.0.1

server-id=102
report-host=SBslave2
report-port=22989
log-bin=mysql-bin
log-error=msandbox.err

replicate-ignore-table=database.table
[28 Jul 2013 10:42] Miguel Angel Nieto
Tested in latest 5.5.32.
[29 Jul 2013 10:04] Umesh Shastry
Hello Miguel,

Thank you for the bug report and the test case. 
Verified as described.

Thanks,
Umesh
[29 Jul 2013 10:06] Umesh Shastry
// With the test case and replicate-ignore-table=database.table enabled

                   Last_Error: Error 'Cannot add or update a child row: a foreign key constraint fails (`test`.`sometable`, CONSTRAINT `sometable_apps` FOREIGN KEY (`appid`) REFERENCES `sometable_apps` (`id`))' on query. Default database: 'test'. Query: 'insert into sometable (rundt, appid, username, machine, pid) values ('2013-07-23 15:56:59', LAST_INSERT_ID(), 'xxxxx', 'xxxxxxx', 2736)'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 1645
              Relay_Log_Space: 1724
              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: 1452
               Last_SQL_Error: Error 'Cannot add or update a child row: a foreign key constraint fails (`test`.`sometable`, CONSTRAINT `sometable_apps` FOREIGN KEY (`appid`) REFERENCES `sometable_apps` (`id`))' on query. Default database: 'test'. Query: 'insert into sometable (rundt, appid, username, machine, pid) values ('2013-07-23 15:56:59', LAST_INSERT_ID(), 'xxxxx', 'xxxxxxx', 2736)'
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
1 row in set (0.00 sec)

//
[root@cluster-repo C]# /data/ushastry/server/mysql-5.5.32/bin/mysqlbinlog C-relay-bin.000002 |grep -i "SET LAST_INSERT_ID"
SET LAST_INSERT_ID=0/*!*/;

// With the test case and replicate-ignore-table=database.table disabled

[root@cluster-repo C]# /data/ushastry/server/mysql-5.5.32/bin/mysqlbinlog C-relay-bin.000002 |grep -i "SET LAST_INSERT_ID"
SET LAST_INSERT_ID=1/*!*/;
[29 Jul 2013 12:41] Umesh Shastry
// 5.6.13 too affected

mysql> select version();
+------------+
| version()  |
+------------+
| 5.6.13-log |
+------------+
1 row in set (0.00 sec)

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: localhost
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000003
          Read_Master_Log_Pos: 2226
               Relay_Log_File: C-relay-bin.000002
                Relay_Log_Pos: 1313
        Relay_Master_Log_File: mysql-bin.000003
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table: database.table
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 1452
                   Last_Error: Error 'Cannot add or update a child row: a foreign key constraint fails (`test`.`sometable`, CONSTRAINT `sometable_apps` FOREIGN KEY (`appid`) REFERENCES `sometable_apps` (`id`))' on query. Default database: 'test'. Query: 'insert into sometable (rundt, appid, username, machine, pid) values ('2013-07-23 15:56:59', LAST_INSERT_ID(), 'xxxxx', 'xxxxxxx', 2736)'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 1843
              Relay_Log_Space: 1865
              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: 1452
               Last_SQL_Error: Error 'Cannot add or update a child row: a foreign key constraint fails (`test`.`sometable`, CONSTRAINT `sometable_apps` FOREIGN KEY (`appid`) REFERENCES `sometable_apps` (`id`))' on query. Default database: 'test'. Query: 'insert into sometable (rundt, appid, username, machine, pid) values ('2013-07-23 15:56:59', LAST_INSERT_ID(), 'xxxxx', 'xxxxxxx', 2736)'
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
                  Master_UUID: 7d77c950-f901-11e2-9540-9d1696aea42d
             Master_Info_File: /tmp/C/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State:
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp: 130730 16:17:34
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set:
                Auto_Position: 0
1 row in set (0.00 sec)

//

# /data/ushastry/server/mysql-5.5.32/bin/mysqlbinlog /tmp/C/C-relay-bin.000002 |grep -i "SET LAST_INSERT_ID"
SET LAST_INSERT_ID=0/*!*/;
[29 Jul 2013 15:04] Umesh Shastry
// enabled GTID mode.. and confirmed it still breaks replication on C

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: localhost
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000003
          Read_Master_Log_Pos: 2689
               Relay_Log_File: C-relay-bin.000002
                Relay_Log_Pos: 1488
        Relay_Master_Log_File: mysql-bin.000003
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table: database.table
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 1452
                   Last_Error: Error 'Cannot add or update a child row: a foreign key constraint fails (`test`.`sometable`, CONSTRAINT `sometable_apps` FOREIGN KEY (`appid`) REFERENCES `sometable_apps` (`id`))' on query. Default database: 'test'. Query: 'insert into sometable (rundt, appid, username, machine, pid) values ('2013-07-23 15:56:59', LAST_INSERT_ID(), 'xxxxx', 'xxxxxxx', 2736)'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 2258
              Relay_Log_Space: 2119
              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: 1452
               Last_SQL_Error: Error 'Cannot add or update a child row: a foreign key constraint fails (`test`.`sometable`, CONSTRAINT `sometable_apps` FOREIGN KEY (`appid`) REFERENCES `sometable_apps` (`id`))' on query. Default database: 'test'. Query: 'insert into sometable (rundt, appid, username, machine, pid) values ('2013-07-23 15:56:59', LAST_INSERT_ID(), 'xxxxx', 'xxxxxxx', 2736)'
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
                  Master_UUID: 09b63709-f919-11e2-95da-9c138a7dd2a7
             Master_Info_File: /tmp/C/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State:
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp: 130730 18:42:47
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set: 0cfe5261-f919-11e2-95da-91e5cb490d63:6-9
            Executed_Gtid_Set: 0cfe5261-f919-11e2-95da-91e5cb490d63:6-8
                Auto_Position: 0
1 row in set (0.00 sec)
[21 Oct 2013 14:55] Jon Stephens
Fixed in 5.1+. Documented in the MySQL 5.1.73, 5.5.35, 5.6.15, and 5.7.3 changelogs, as follows:

        The value of LAST_INSERT_ID() was not correctly replicated when
        filtering rules were used on the slave.

Closed.
[5 Dec 2013 6:42] Laurynas Biveinis
5.1$ bzr log -r 4055
------------------------------------------------------------
revno: 4055
committer: Venkatesh Duggirala<venkatesh.duggirala@oracle.com>
branch nick: mysql-5.1
timestamp: Wed 2013-10-16 22:12:23 +0530
message:
  Bug#17234370 LAST_INSERT_ID IS REPLICATED INCORRECTLY IF
  REPLICATION FILTERS ARE USED.
  
  Problem:
  When Filtered-slave applies Int_var_log_event and when it
  tries to write the event to its own binlog, LAST_INSERT_ID
  value is written wrongly.
  
  Analysis:
  THD::stmt_depends_on_first_successful_insert_id_in_prev_stmt
  is a variable which is set when LAST_INSERT_ID() is used by
  a statement. If it is set, first_successful_insert_id_in_
  prev_stmt_for_binlog will be stored in the statement-based
  binlog. This variable is CUMULATIVE along the execution of
  a stored function or trigger: if one substatement sets it
  to 1 it will stay 1 until the function/trigger ends,
  thus making sure that first_successful_insert_id_in_
  prev_stmt_for_binlog does not change anymore and is
  propagated to the caller for binlogging. This is achieved
  using the following code
  if(!stmt_depends_on_first_successful_insert_id_in_prev_stmt)               
  {                                                                           
    /* It's the first time we read it */                                      
    first_successful_insert_id_in_prev_stmt_for_binlog=                       
    first_successful_insert_id_in_prev_stmt;                                
    stmt_depends_on_first_successful_insert_id_in_prev_stmt= 1;               
  }
  
  Slave server, after receiving Int_var_log_event event from
  master, it is setting
  stmt_depends_on_first_successful_insert_id_in_prev_stmt
  to true(*which is wrong*) and not setting
  first_successful_insert_id_in_prev_stmt_for_binlog. Because
  of this problem, when the actual DML statement with
  LAST_INSERT_ID() is parsed by slave SQL thread,
  first_successful_insert_id_in_prev_stmt_for_binlog is not
  set. Hence the value zero (default value) is written to
  slave's binlog.
  
  Why only *Filtered slave* is effected when the code is
  in common place:
  -------------------------------------------------------
  In Query_log_event::do_apply_event,
  THD::stmt_depends_on_first_successful_insert_id_in_prev_stmt
  is reset to zero at the end of the function. In case of
  normal slave (No Filters), this variable will be reset. 
  In Filtered slave, Slave SQL thread defers all IRU events's
  execution until IRU's Query_log event is received. Once it
  receives Query_log_event it executes all pending IRU events
  and then it executes Query_log_event. Hence the variable is
  not getting reset to 0, causing this bug.
  
  Fix: As described above, the root cause was setting 
  THD::stmt_depends_on_first_successful_insert_id_in_prev_stmt
  when Int_var_log_event was executed by a SQL thread. Hence
  removing the problematic line from the code.