Bug #68488 Slave master_log_file be reset to binlog.000001 automatically
Submitted: 25 Feb 2013 16:47 Modified: 22 Aug 2014 17:19
Reporter: Lixun Peng (OCA) Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.5.20 OS:Any
Assigned to: CPU Architecture:Any
Tags: replication

[25 Feb 2013 16:47] Lixun Peng
Description:
I found a problem when I check slave, the master_log_file and master_log_pos back to from the binlog.000001 again!

I found this in error.log:

130224 23:02:24 [Warning] Slave SQL: Could not execute Update_rows event on table manage.ftp_num; Can't find record in 'ftp_num', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log man-bin.000024, end_log_pos 1066685707, Error_code: 1032
130224 23:02:55 [Warning] Slave SQL: Could not execute Update_rows event on table manage.ftp_num; Can't find record in 'ftp_num', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log man-bin.000024, end_log_pos 1066694121, Error_code: 1032
130224 23:29:57 [Warning] Slave SQL: Could not execute Update_rows event on table manage.ftp_num; Can't find record in 'ftp_num', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log man-bin.000001, end_log_pos 20181, Error_code: 1032
130224 23:29:57 [Warning] Slave SQL: Could not execute Delete_rows event on table manage.inbound_alert_history_new; Can't find record in 'inbound_alert_history_new', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log man-bin.000001, end_log_pos 311908, Error_code: 1032
130224 23:29:57 [Warning] Slave SQL: Could not execute Update_rows event on table manage.ftp_num; Can't find record in 'ftp_num', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log man-bin.000001, end_log_pos 499029, Error_code: 1032

it seems when slave read the event ( master log man-bin.000024, end_log_pos 1066694121), slave back to beginning again.

So I checked the master binlog around man-bin.000024, _pos 1066694121. and this is the result:

[root@webserver mysql]# cat /tmp/1.sql
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#130223  0:05:01 server id 1  end_log_pos 107 	Start: binlog v 4, server v 5.5.20-log created 130223  0:05:01
BINLOG '
/U0oUQ8BAAAAZwAAAGsAAAAAAAQANS41LjIwLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 1066694121
#130224 23:02:54 server id 1  end_log_pos 1066694192 	Query	thread_id=14205227	exec_time=0	error_code=0
SET TIMESTAMP=1361764974/*!*/;
SET @@session.pseudo_thread_id=14205227/*!*/;
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 latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
COMMIT
/*!*/;
# at 1066694192
#130224 23:03:01 server id 1  end_log_pos 1066694262 	Query	thread_id=14205228	exec_time=0	error_code=0
SET TIMESTAMP=1361764981/*!*/;
flush hosts
/*!*/;
# at 1066694262
#130224 23:03:01 server id 1  end_log_pos 1066694332 	Query	thread_id=14205230	exec_time=0	error_code=0
SET TIMESTAMP=1361764981/*!*/;
BEGIN
/*!*/;
# at 1066694332
# at 1066694427
#130224 23:03:01 server id 1  end_log_pos 1066694427 	Table_map: `manage`.`datasource` mapped to number 229
#130224 23:03:01 server id 1  end_log_pos 1066694819 	Update_rows: table id 229 flags: STMT_END_F

BINLOG '
deIqURMBAAAAXwAAABt3lD8AAOUAAAAAAAEABm1hbmFnZQAKZGF0YXNvdXJjZQASDw8P/A8PAw8P
Aw/+DwMBAw8PGQoAHgAeAAL/ABQAGQDIAGQA/gH6ADIAMgD9lwM=
deIqURgBAAAAiAEAAKN4lD8AAOUAAAAAAAEAEv///////wCW/gZhY3RpdmUIUE0xMjc0X00BM0cA
U0VMRUNUICogRlJPTSBwb3B1bGFyLmRhdGFfdGFibGVfbWF0Y2ggV0hFUkUgZV9rZXkgPSAnN25m
dTFzeTNWTVFEd0Y4ZicQN25mdTFzeTNWTVFEd0Y4ZgRMaXZlAQAAABBkYmNvbmZpZ19tYXN0ZXIx
GHBvcHVsYXIuZGF0YV90YWJsZV9tYXRjaAFNAQAAAAAJMTAuMC4zLjIzAJb+BmFjdGl2ZQhQTTEy
NzRfTQEzRwBTRUxFQ1QgKiBGUk9NIHBvcHVsYXIuZGF0YV90YWJsZV9tYXRjaCBXSEVSRSBlX2tl
eSA9ICc3bmZ1MXN5M1ZNUUR3RjhmJxA3bmZ1MXN5M1ZNUUR3RjhmBExpdmUBAAAAEGRiY29uZmln
X21hc3RlcjEYcG9wdWxhci5kYXRhX3RhYmxlX21hdGNoAU0AAAAAAAkxMC4wLjMuMjM=
'/*!*/;
### UPDATE manage.datasource
### WHERE
###   @1='active' /* VARSTRING(10) meta=10 nullable=1 is_null=0 */
###   @2='PM1274_M' /* VARSTRING(30) meta=30 nullable=0 is_null=0 */
###   @3='3' /* VARSTRING(30) meta=30 nullable=1 is_null=0 */
###   @4='SELECT * FROM popular.data_table_match WHERE e_key = '7nfu1sy3VMQDwF8f'' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
###   @5='7nfu1sy3VMQDwF8f' /* VARSTRING(255) meta=255 nullable=1 is_null=0 */
###   @6='Live' /* VARSTRING(20) meta=20 nullable=1 is_null=0 */
###   @7=1 /* INT meta=0 nullable=1 is_null=0 */
###   @8='dbconfig_master1' /* VARSTRING(25) meta=25 nullable=1 is_null=0 */
###   @9='popular.data_table_match' /* VARSTRING(200) meta=200 nullable=1 is_null=0 */
###   @10=NULL /* VARSTRING(200) meta=0 nullable=1 is_null=1 */
###   @11=NULL /* VARSTRING(200) meta=100 nullable=1 is_null=1 */
###   @12='M' /* STRING(1) meta=65025 nullable=0 is_null=0 */
###   @13=NULL /* STRING(1) meta=250 nullable=1 is_null=1 */
###   @14=1 /* INT meta=0 nullable=0 is_null=0 */
###   @15=0 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @16=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @17='10.0.3.23' /* VARSTRING(50) meta=50 nullable=1 is_null=0 */
###   @18=NULL /* VARSTRING(50) meta=50 nullable=1 is_null=1 */
### SET
###   @1='active' /* VARSTRING(10) meta=10 nullable=1 is_null=0 */
###   @2='PM1274_M' /* VARSTRING(30) meta=30 nullable=0 is_null=0 */
###   @3='3' /* VARSTRING(30) meta=30 nullable=1 is_null=0 */
###   @4='SELECT * FROM popular.data_table_match WHERE e_key = '7nfu1sy3VMQDwF8f'' /* BLOB/TEXT meta=2 nullable=1 is_null=0 */
###   @5='7nfu1sy3VMQDwF8f' /* VARSTRING(255) meta=255 nullable=1 is_null=0 */
###   @6='Live' /* VARSTRING(20) meta=20 nullable=1 is_null=0 */
###   @7=1 /* INT meta=0 nullable=1 is_null=0 */
###   @8='dbconfig_master1' /* VARSTRING(25) meta=25 nullable=1 is_null=0 */
###   @9='popular.data_table_match' /* VARSTRING(200) meta=200 nullable=1 is_null=0 */
###   @10=NULL /* VARSTRING(200) meta=0 nullable=1 is_null=1 */
###   @11=NULL /* VARSTRING(200) meta=100 nullable=1 is_null=1 */
###   @12='M' /* STRING(1) meta=65025 nullable=0 is_null=0 */
###   @13=NULL /* STRING(1) meta=250 nullable=1 is_null=1 */
###   @14=0 /* INT meta=0 nullable=0 is_null=0 */
###   @15=0 /* TINYINT meta=0 nullable=0 is_null=0 */
###   @16=NULL /* TINYINT meta=0 nullable=1 is_null=1 */
###   @17='10.0.3.23' /* VARSTRING(50) meta=50 nullable=1 is_null=0 */
###   @18=NULL /* VARSTRING(50) meta=50 nullable=1 is_null=1 */
# at 1066694819
#130224 23:03:01 server id 1  end_log_pos 1066694846 	Xid = 76866364
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

I found a "flush hosts" , but I checked doc:http://dev.mysql.com/doc/refman/5.5/en/flush.html
this command wouldn't cause slave reset. 

This master has 2 slaves, they are reported the same error message.
So it's not accidental, this binlog event will cause all slaves reset.

How to repeat:
I don't know.
[22 Jul 2014 17:19] Sveta Smirnova
Thank you for the report.

I cannot repeat described behavior. Please try with current version 5.5.38 and inform us if the issue still exists in your environment. Make sure nobody run RESET SLAVE on your slave.
[23 Aug 2014 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".