| 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: | |
| 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 | ||
[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.
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);