MySQL Bugs: #34641: "Query partially completed on master" problem with InnoDB INSERT + SUBSELECT

Bug #34641	"Query partially completed on master" problem with InnoDB INSERT + SUBSELECT
Submitted:	18 Feb 2008 16:09	Modified:	7 Oct 2008 12:32
Reporter:	Guillaume Lefranc	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.0.50sp1a	OS:	Linux (Ubuntu 6.06 LTS x86_64)
Assigned to:		CPU Architecture:	Any
Tags:	replication 1053 error innodb subselect

Description:
In a master-slave system, I get this error while killing a specific query:

Query partially completed on the master (error on master: 1053) and was aborted. There is a chance that your master is inconsistent at this point. If you are sure that your master is ok, run this query manually on the slave and then restart the slave with SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; START SLAVE; . Query: (INSERT vhc (v_id, vc_id) SELECT 7421594, vc_id FROM vc WHERE label='st' AND value='re')

The problem is that both tables are InnoDB, IMHO this should not be a problem since the transaction implied by the INSERT + SUB-SELECT should be rollbacked.

How to repeat:
Use the following schema + example data:

CREATE TABLE vhc (v_id int unsigned NOT NULL, vc_id int unsigned NOT NULL, primary key(v_id,vc_id)) ENGINE=InnoDB

CREATE TABLE vc (v_id int unsigned NOT NULL auto_increment, label varchar(50) NOT NULL, value varchar(50) NOT NULL, PRIMARY KEY(v_id), UNIQUE KEY(label,value)) ENGINE=InnoDB

INSERT INTO vc (label, value) VALUES('st','re') 

Run this query and attempt to kill it;

INSERT vhc (v_id, vc_id) SELECT 7421594, vc_id FROM vc WHERE label='st' AND value='re'

Many thanks for writing a bug report.

To reproduce this, we need to know the exact version you use.

Please make a:
mysql> select version()

Also we need to know the operating system. There are hundreds of Linux distrubution. Please, let us know, which distribution you are using and if it is 32 or 64 bit.

Hello,

Sorry, was not sure if that was relevant.

Version is same as tagged above:

mysql> select version();
+-------------------------------+
| version()                     |
+-------------------------------+
| 5.0.50sp1a-enterprise-gpl-log | 
+-------------------------------+

Distribution is Ubuntu 6.06 x86_64, kernel 2.6.20-5-server SMP.

added distribution to ticket header.

Please, send the results of:

show variables like 'sync_binlog';

Value is at 1.

mysql> select @@sync_binlog;
+---------------+
| @@sync_binlog |
+---------------+
|             1 | 
+---------------+

Thank you for the feedback.

Please also send us output of SELECT @@autocommit;

Value is at 0 (application default)

Thank you for the feedback.

I can not repeat described behavior. Please provide output of SELECT * FROM VHC WHERE v_id=7421594 run on master.

+---------+-------+
| v_id    | vc_id |
+---------+-------+
| 7421594 |     1 | 
| 7421594 |    50 | 
| 7421594 |    51 | 
| 7421594 |    53 | 
| 7421594 |   402 | 
+---------+-------+
5 rows in set (0.00 sec)

Thank you for the feedback.

Please also check output of SELECT vc_id FROM vc WHERE label='st' AND value='re': I want to be sure query on master was rolled back.

+-------+
| vc_id |
+-------+
|   402 | 
+-------+
1 row in set (0.91 sec)

It's possible that the query has been replayed later and completed, so I can't really tell if it has been rolled back or not.

I can't repeat this behaviour by using MySQL 5.0.72.

It seems already be fixed in source repository.

According to the description this only hit SBR (statement based replication) this should not hit RBR (row based replication) at all.

If you still will have this problem with newer version of MySQL 5.0 just upgrade to MySQL 5.1 and use row based or mixed mode replication.

HI, I can repeat by following step.
1. create table info1(id int, name varchar(30)) engine=myisam;
2. create table info2(id int, name varchar(30)) engine=myisam;
3. insert into  info1 values
4. insert into  info2 select id, name form info1;
5. kill query generated by step 4
then you can have the binlog like this:
#130602 16:25:32 server id 1  end_log_pos 207   Query   thread_id=32    exec_time=6     error_code=1053
use test/*!*/;
SET TIMESTAMP=1370161532/*!*/;
SET @@session.pseudo_thread_id=32/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C gbk *//*!*/;
SET @@session.character_set_client=28,@@session.collation_connection=28,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
insert info2 select id,name from info1
/*!*/;

the stack went like this:
#0  Query_log_event::write (this=0x7f74916cd0f0, file=0xe89610) at log_event.cc:2404
#1  0x00000000006d3069 in MYSQL_BIN_LOG::write (this=0xe89300, thd=0xae5d4a0, cache=0x7f7344007a70, commit_event=0x7f74916cd0f0, incident=false)
    at log.cc:4945
#2  0x00000000006cbdcc in binlog_end_trans (thd=0xae5d4a0, trx_data=0x7f7344007a70, end_ev=0x7f74916cd0f0, all=false) at log.cc:1440
#3  0x00000000006cc27e in binlog_rollback (hton=0x1ee1b40, thd=0xae5d4a0, all=false) at log.cc:1616
#4  0x00000000007276f8 in ha_rollback_trans (thd=0xae5d4a0, all=false) at handler.cc:1311
#5  0x00000000007278e0 in ha_autocommit_or_rollback (thd=0xae5d4a0, error=1) at handler.cc:1376
#6  0x000000000061c9f8 in dispatch_command (command=COM_QUERY, thd=0xae5d4a0, packet=0xae64c51 "insert info2 select id,name from info1", 
    packet_length=38) at sql_parse.cc:1709
#7  0x000000000061aaf5 in do_command (thd=0xae5d4a0) at sql_parse.cc:913
#8  0x000000000061922c in handle_one_connection (arg=0xae5d4a0) at sql_connect.cc:1465
#9  0x0000003659e077e1 in start_thread () from /lib64/libpthread.so.0
#10 0x0000003659ae68ed in clone () from /lib64/libc.so.6

by the way , the binlog_format=statement

Thank you for the feedback.

But your scenario is not a bug. MyISAM is non-transactional table and statements which change information in it don't get written into binary log transaction cache, but go into binary log straight. If you want to avoid such issues in future either use binlog_format=row or transactional storage engine InnoDB: in this case statement would be simply rolled back and won't occur in the binary log.