Bug #70923 Replication failure on multi-statement INSERT DELAYED queries
Submitted: 15 Nov 2013 16:59 Modified: 18 Nov 2013 19:03
Reporter: Ovais Tariq Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.5.34, 5.6.16 OS:Any
Assigned to: CPU Architecture:Any
Tags: binlog, insert delayed, replication
Triage: Needs Triage: D2 (Serious)

[15 Nov 2013 16:59] Ovais Tariq
Description:
If 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)

How to repeat:
Create the table `log_messages` as shown above and run the PHP script with the below contents:

#!/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);
[15 Nov 2013 17:04] Ovais Tariq
-- Master MySQL configuration:
[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/mysql-server/5.5.34
datadir                         = /work/sandboxes/rsandbox_5_5_34/master/data
tmpdir                          = /work/sandboxes/rsandbox_5_5_34/master/tmp
pid-file                        = /work/sandboxes/rsandbox_5_5_34/master/data/mysql_sandbox23389.pid
#log-slow-queries               = /work/sandboxes/rsandbox_5_5_34/master/data/msandbox-slow.log
#log                            = /work/sandboxes/rsandbox_5_5_34/master/data/msandbox.log
#
# additional options passed through 'my_clause'
#
log-bin=mysql-bin
server-id=1
log-error=msandbox.err

-- Slave MySQL configuration:
[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/mysql-server/5.5.34
datadir                         = /work/sandboxes/rsandbox_5_5_34/node1/data
tmpdir                          = /work/sandboxes/rsandbox_5_5_34/node1/tmp
pid-file                        = /work/sandboxes/rsandbox_5_5_34/node1/data/mysql_sandbox23390.pid
#log-slow-queries               = /work/sandboxes/rsandbox_5_5_34/node1/data/msandbox-slow.log
#log                            = /work/sandboxes/rsandbox_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
[15 Nov 2013 17:06] Ovais Tariq
Binlog generated on master:

# at 2081
#131115 17:53:56 server id 1  end_log_pos 2387  Query   thread_id=3     exec_time=0     error_code=0
use test/*!*/;
SET TIMESTAMP=1384534436/*!*/;
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
/*!*/;
# at 2387
#131115 17:55:13 server id 1  end_log_pos 2463  Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1384534513/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
BEGIN
/*!*/;
# at 2463
#131115 17:55:13 server id 1  end_log_pos 2848  Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1384534513/*!*/;
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 2848
#131115 17:55:13 server id 1  end_log_pos 2925  Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1384534513/*!*/;
COMMIT
/*!*/;
# at 2925
#131115 17:55:13 server id 1  end_log_pos 3001  Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1384534513/*!*/;
BEGIN
/*!*/;
# at 3001
#131115 17:55:13 server id 1  end_log_pos 3225  Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1384534513/*!*/;
INSERT  INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_2', 'test_url_2', 'b6273b589df2dfdbd8fe35b1011e3183')
/*!*/;
# at 3225
#131115 17:55:13 server id 1  end_log_pos 3302  Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1384534513/*!*/;
COMMIT
/*!*/;
# at 3302
#131115 17:55:34 server id 1  end_log_pos 3345  Rotate to mysql-bin.000002  pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
[15 Nov 2013 17:08] Ovais Tariq
Relevant relay log on the slave:

# at 2227
#131115 17:53:56 server id 1  end_log_pos 2387  Query   thread_id=3     exec_time=0     error_code=0
use test/*!*/;
SET TIMESTAMP=1384534436/*!*/;
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
/*!*/;
# at 2533
#131115 17:55:13 server id 1  end_log_pos 2463  Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1384534513/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
BEGIN
/*!*/;
# at 2609
#131115 17:55:13 server id 1  end_log_pos 2848  Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1384534513/*!*/;
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 2994
#131115 17:55:13 server id 1  end_log_pos 2925  Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1384534513/*!*/;
COMMIT
/*!*/;
# at 3071
#131115 17:55:13 server id 1  end_log_pos 3001  Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1384534513/*!*/;
BEGIN
/*!*/;
# at 3147
#131115 17:55:13 server id 1  end_log_pos 3225  Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1384534513/*!*/;
INSERT  INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_2', 'test_url_2', 'b6273b589df2dfdbd8fe35b1011e3183')
/*!*/;
# at 3371
#131115 17:55:13 server id 1  end_log_pos 3302  Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1384534513/*!*/;
COMMIT
/*!*/;
# at 3448
#131115 17:51:49 server id 101  end_log_pos 3510        Rotate to mysql_sandbox23390-relay-bin.000003  pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
[15 Nov 2013 19:00] Sveta Smirnova
Thank you for the report.

Verified as described. Bug is only repeatable if PHP script is used, but I still think this is server bug, because general query log does not show anything wrong was issued by PHP:

| 2013-11-15 21:46:08 | root[root] @ localhost [127.0.0.1] |        11 |         1 | Query        | INSERT DELAYED INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_1', 'test_url_1', '0bee89b07a248e27c83fc3d5951213c1'); |
| 2013-11-15 21:46:08 | root[root] @ localhost [127.0.0.1] |        11 |         1 | Query        | INSERT DELAYED INTO test.log_messages (time_stamp, message, url, hash) VALUES(CURRENT_TIMESTAMP, 'test_msg_2', 'test_url_2', 'b6273b589df2dfdbd8fe35b1011e3183')  |
[15 Nov 2013 19:06] Ovais Tariq
Hi Sveta,

Thank you for the fast verification. Could you tell me how else did you test the queries with, apart from using PHP?
[15 Nov 2013 19:25] Sveta Smirnova
A tried to repeat this behavior using MySQL command-line client.
[18 Nov 2013 19:03] Ovais Tariq
PHP probably sends the queries differently to the server. But still this appears to be a MySQL server bug rather then a client library issue.