Replication failure on multi-statement INSERT DELAYED queries

[Ovais Tariq]

Percona Server version 5.5.34-rel32.0 on both master and slave.

I a multi-statement INSERT DELAYED query is executed then the master is not able to parse it correctly and writes both the queries together in the same statement binlog event. Then when the slave thread reads the event, it parses it incorrectly and the replication breaks.

Structure of the table:
CREATE TABLE `log_messages` (
  `time_stamp` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `message` text NOT NULL,
  `url` text NOT NULL,
  `hash` char(32) NOT NULL DEFAULT ''
) ENGINE=MyISAM DEFAULT CHARSET=utf8;

Test query:
INSERT DELAYED INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_1', 'test_url_1', '0bee89b07a248e27c83fc3d5951213c1');INSERT DELAYED INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_2', 'test_url_2', 'b6273b589df2dfdbd8fe35b1011e3183')

When executed together through PHP using mysqli_multi_query, the query executes fine on the master:
[root@ovaistariq-test master]# ./test.php
mysqli Object
(
    [affected_rows] => 1
    [client_info] => 5.1.69
    [client_version] => 50169
    [connect_errno] => 0
    [connect_error] =>
    [errno] => 0
    [error] =>
    [field_count] => 0
    [host_info] => 127.0.0.1 via TCP/IP
    [info] =>
    [insert_id] => 0
    [server_info] => 5.5.34-rel32.0-log
    [server_version] => 50534
    [sqlstate] => 00000
    [protocol_version] => 10
    [thread_id] => 3
    [warning_count] => 0
)

master [localhost] {msandbox} (test) > select * from log_messages;
+---------------------+------------+------------+----------------------------------+
| time_stamp | message | url | hash |
+---------------------+------------+------------+----------------------------------+
| 2013-11-15 17:39:29 | test_msg_1 | test_url_1 | 0bee89b07a248e27c83fc3d5951213c1 |
| 2013-11-15 17:39:29 | test_msg_2 | test_url_2 | b6273b589df2dfdbd8fe35b1011e3183 |
+---------------------+------------+------------+----------------------------------+
2 rows in set (0.00 sec)

But replication on slave gets broken:
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: 23389
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000004
          Read_Master_Log_Pos: 1112
               Relay_Log_File: mysql_sandbox23390-relay-bin.000008
                Relay_Log_Pos: 343
        Relay_Master_Log_File: mysql-bin.000004
             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: 1064
                   Last_Error: Error 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'INSERT DELAYED INTO test.log_messages (time_stamp, message, url, hash) VALUES(CU' at line 1' on query. Default database: 'test'. Query: 'INSERT INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_1', 'test_url_1', '0bee89b07a248e27c83fc3d5951213c1');INSERT DELAYED INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_2', 'test_url_2', 'b6273b589df2dfdbd8fe35b1011e3183')'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 197
              Relay_Log_Space: 1573
              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: 1064
               Last_SQL_Error: Error 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'INSERT DELAYED INTO test.log_messages (time_stamp, message, url, hash) VALUES(CU' at line 1' on query. Default database: 'test'. Query: 'INSERT INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_1', 'test_url_1', '0bee89b07a248e27c83fc3d5951213c1');INSERT DELAYED INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_2', 'test_url_2', 'b6273b589df2dfdbd8fe35b1011e3183')'
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
1 row in set (0.00 sec)

[Ovais Tariq (ovais-tariq)]

MySQL configuration on master:

[root@ovaistariq-test master]# cat my.sandbox.cnf
# The MySQL Sandbox
# Copyright (C) 2006-2012 Giuseppe Maxia
# Contacts: http://datacharmer.org
#
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation; version 2 of the License
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA

[mysql]
prompt='master [\h] {\u} (\d) > '
#

[client]
user = msandbox
password = msandbox
port = 23389
socket = /tmp/mysql_sandbox23389.sock

[mysqld]
user = root
port = 23389
socket = /tmp/mysql_sandbox23389.sock
basedir = /work/binaries/percona-server/5.5.34
datadir = /work/sandboxes/rsandbox_ps_5_5_34/master/data
tmpdir = /work/sandboxes/rsandbox_ps_5_5_34/master/tmp
pid-file = /work/sandboxes/rsandbox_ps_5_5_34/master/data/mysql_sandbox23389.pid
#log-slow-queries = /work/sandboxes/rsandbox_ps_5_5_34/master/data/msandbox-slow.log
#log = /work/sandboxes/rsandbox_ps_5_5_34/master/data/msandbox.log
#
# additional options passed through 'my_clause'
#
log-bin=mysql-bin
server-id=1
log-error=msandbox.err

[Ovais Tariq (ovais-tariq)]

MySQL configuration on slave:

[root@ovaistariq-test node1]# cat my.sandbox.cnf
# The MySQL Sandbox
# Copyright (C) 2006-2012 Giuseppe Maxia
# Contacts: http://datacharmer.org
#
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation; version 2 of the License
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA

[mysql]
prompt='slave1 [\h] {\u} (\d) > '
#

[client]
user = msandbox
password = msandbox
port = 23390
socket = /tmp/mysql_sandbox23390.sock

[mysqld]
user = root
port = 23390
socket = /tmp/mysql_sandbox23390.sock
basedir = /work/binaries/percona-server/5.5.34
datadir = /work/sandboxes/rsandbox_ps_5_5_34/node1/data
tmpdir = /work/sandboxes/rsandbox_ps_5_5_34/node1/tmp
pid-file = /work/sandboxes/rsandbox_ps_5_5_34/node1/data/mysql_sandbox23390.pid
#log-slow-queries = /work/sandboxes/rsandbox_ps_5_5_34/node1/data/msandbox-slow.log
#log = /work/sandboxes/rsandbox_ps_5_5_34/node1/data/msandbox.log
#
# additional options passed through 'my_clause'
#
server-id=101
report-host=SBslave1
report-port=23390
log-bin=mysql-bin
log-error=msandbox.err

[Ovais Tariq (ovais-tariq)]

Sample PHP code to run the test:

[root@ovaistariq-test master]# cat test.php
#!/usr/bin/php
<?php
$m=new mysqli('127.0.0.1', 'msandbox', 'msandbox', 'test', 23389);
$m->multi_query("INSERT DELAYED INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_1', 'test_url_1', '0bee89b07a248e27c83fc3d5951213c1');INSERT DELAYED INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_2', 'test_url_2', 'b6273b589df2dfdbd8fe35b1011e3183')");
print_r($m);

[Ovais Tariq (ovais-tariq)]

Binlog generated on the master:

[root@ovaistariq-test master]# mysqlbinlog data/mysql-bin.000004
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#131115 17:37:14 server id 1 end_log_pos 107 Start: binlog v 4, server v 5.5.34-rel32.0-log created 131115 17:37:14 at startupROLLBACK/*!*/;
BINLOG '
uk2GUg8BAAAAZwAAAGsAAAAAAAQANS41LjM0LXJlbDMyLjAtbG9nAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAC6TYZSEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 107
#131115 17:37:40 server id 1 end_log_pos 197 Query thread_id=2 exec_time=0 error_code=0
use test/*!*/;
SET TIMESTAMP=1384533460/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
truncate table log_messages
/*!*/;
# at 197
#131115 17:39:29 server id 1 end_log_pos 273 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1384533569/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
BEGIN
/*!*/;
# at 273
#131115 17:39:29 server id 1 end_log_pos 658 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1384533569/*!*/;
INSERT INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_1', 'test_url_1', '0bee89b07a248e27c83fc3d5951213c1');INSERT DELAYED INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_2', 'test_url_2', 'b6273b589df2dfdbd8fe35b1011e3183')
/*!*/;
# at 658
#131115 17:39:29 server id 1 end_log_pos 735 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1384533569/*!*/;
COMMIT
/*!*/;
# at 735
#131115 17:39:29 server id 1 end_log_pos 811 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1384533569/*!*/;
BEGIN
/*!*/;
# at 811
#131115 17:39:29 server id 1 end_log_pos 1035 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1384533569/*!*/;
INSERT INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_2', 'test_url_2', 'b6273b589df2dfdbd8fe35b1011e3183')
/*!*/;
# at 1035
#131115 17:39:29 server id 1 end_log_pos 1112 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1384533569/*!*/;
COMMIT
/*!*/;
# at 1112
#131115 17:44:57 server id 1 end_log_pos 1131 Stop
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

[Ovais Tariq (ovais-tariq)]

Relay log generated on the slave:

[root@ovaistariq-test node1]# mysqlbinlog data/mysql_sandbox23390-relay-bin.000008
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#131115 10:42:18 server id 101 end_log_pos 107 Start: binlog v 4, server v 5.5.34-rel32.0-log created 131115 10:42:18
BINLOG '
euyFUg9lAAAAZwAAAGsAAAAAAAQANS41LjM0LXJlbDMyLjAtbG9nAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 107
#700101 1:00:00 server id 1 end_log_pos 0 Rotate to mysql-bin.000004 pos: 4
# at 150
#131115 17:37:14 server id 1 end_log_pos 107 Start: binlog v 4, server v 5.5.34-rel32.0-log created 131115 17:37:14 at startup
ROLLBACK/*!*/;
BINLOG '
uk2GUg8BAAAAZwAAAGsAAAAAAAQANS41LjM0LXJlbDMyLjAtbG9nAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAC6TYZSEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 253
#131115 17:37:40 server id 1 end_log_pos 197 Query thread_id=2 exec_time=0 error_code=0
use test/*!*/;
SET TIMESTAMP=1384533460/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
truncate table log_messages
/*!*/;
# at 343
#131115 17:39:29 server id 1 end_log_pos 273 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1384533569/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
BEGIN
/*!*/;
# at 419
#131115 17:39:29 server id 1 end_log_pos 658 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1384533569/*!*/;
INSERT INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_1', 'test_url_1', '0bee89b07a248e27c83fc3d5951213c1');INSERT DELAYED INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_2', 'test_url_2', 'b6273b589df2dfdbd8fe35b1011e3183')
/*!*/;
# at 804
#131115 17:39:29 server id 1 end_log_pos 735 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1384533569/*!*/;
COMMIT
/*!*/;
# at 881
#131115 17:39:29 server id 1 end_log_pos 811 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1384533569/*!*/;
BEGIN
/*!*/;
# at 957
#131115 17:39:29 server id 1 end_log_pos 1035 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1384533569/*!*/;
INSERT INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_2', 'test_url_2', 'b6273b589df2dfdbd8fe35b1011e3183')
/*!*/;
# at 1181
#131115 17:39:29 server id 1 end_log_pos 1112 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1384533569/*!*/;
COMMIT
/*!*/;
# at 1258
#131...

[Ovais Tariq (ovais-tariq)]

The workaround is to not use INSERT DELAYED, but use plain INSERT

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1448