Bug #12691 Exec_master_log_pos corrupted with SQL_SLAVE_SKIP_COUNTER
| Submitted: | 19 Aug 2005 21:21 | Modified: | 31 Jan 2008 13:32 |
|---|---|---|---|
| Reporter: | Dean Ellis | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S2 (Serious) |
| Version: | 5.0/4.1/4.0 | OS: | Linux (Linux) |
| Assigned to: | Mats Kindahl | CPU Architecture: | Any |
[19 Aug 2005 21:21]
Dean Ellis
[19 Aug 2005 21:21]
Dean Ellis
Verified on 5.0; should be verified on 4.0 and 4.1 however, so I am leaving it Open
[23 Oct 2005 4:06]
Alexander Pachev
I have tested BK-4.1.16 and could not verify it with the following test case: Test case for BUG #12691 --source include/master-slave.inc connection master; CREATE TABLE t1 ( a INT ) ENGINE=InnoDB; commit; sync_slave_with_master; connection slave; DROP TABLE t1; connection master; BEGIN; INSERT INTO t1 VALUES (1); INSERT INTO t1 VALUES (2); INSERT INTO t1 VALUES (3); COMMIT; sleep 3; connection slave; --vertical_results SHOW SLAVE STATUS; SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; START SLAVE; sleep 3; SHOW SLAVE STATUS; #cleanup connection master; drop table if exists t1; commit; connection slave; drop table if exists t1; commit; Exec_master_pos advances 40 bytes after SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; START SLAVE; and 3 seconds of sleep just like you would expect it. I will now try this again in 5.0.
[23 Oct 2005 4:17]
Alexander Pachev
Tried it on 5.0. Again Exec_master_pos advanced by 68 bytes just like it was supposed to. Note that Read_master_pos does not advance because it does not have to. SQL_SLAVE_SKIP_COUNTER tells the SQL thread to skip the next N events. However, the I/O thread will keep reading events regardless and will move at its own pace.
[28 Sep 2006 17:24]
Andrei Elkin
I claim this is not a bug, but a feature requiring explanation in docs. Exec_master_log_pos is not getting corrupted although the couter indeed behaves sometimes non-monotonically (that is contra-intuitive). That happens exclusively in SBR when master executes a multi-statement transaction which sequence of queries causes slave to stop e.g because of replication rules. In the current setup slave stops for the first time having Exec_master_log_pos mapping to CREATE TABLE t1, whereas Last_Error shows the first offending statement of the transaction. The first sequence of 'set SQL_SLAVE_SKIP_COUNTER = 1; start slave; show slave status' shifted "the slider" to the BEGIN, which Exec counter still increases. But in all sequent iterations the reporter must have observed values less than the pre-transactional statement. And those numbers, associated with INSERTs, are just offsets from the BEGIN statement. One can check this with mysqlbinlog binlog, the numbers are values at end_log_pos. After 4 interations with SQL_SLAVE_SKIP_COUNTER = 4 the whole transaction is skipped, and the Exec_master_log_pos increases from the value corresponding to the pre-transactional query by the size of the whole transaction event.
[2 Oct 2006 7:43]
Andrei Elkin
It's not a bug. I left lines most probably explaining what made our customer wondering.
[12 Oct 2006 15:58]
Lars Thalmann
See also BUG#23171
[20 Feb 2007 18:00]
Jonathan Miller
Per Lars request I have added a test case file to the bug. This show issues with skip and triggers when using MyISAM. /Jeb
[20 Feb 2007 18:01]
Jonathan Miller
Test file
Attachment: rpl_test.test (application/octet-stream, text), 4.19 KiB.
[20 Feb 2007 18:01]
Jonathan Miller
innodb reject file
Attachment: rpl_test_innodb.reject (application/octet-stream, text), 7.57 KiB.
[20 Feb 2007 18:02]
Jonathan Miller
MyISAM Reject
Attachment: rpl_test_myisam.reject (application/octet-stream, text), 7.36 KiB.
[13 Apr 2007 18:41]
Jonathan Miller
Hi, I am not sure that this is patched. replicate-wild-ignore-table=mysql.% does not seem to change the results anymore, but by adding extra skip counters, it seems that you can still get an Exec_master_log_pos that is not correct. The first time the slave bombs out the Exec_master_log_pos = 299 After the first SQL_SLAVE_SKIP_COUNTER=1 the Exec_master_log_pos = 367 Then if you set SQL_SLAVE_SKIP_COUNTER=2 the Exec_master_log_pos = 73, this seems to be a bug to me. Then if you continue and set SQL_SLAVE_SKIP_COUNTER=3, the the Exec_master_log_pos = 613 and the slave continues to run. + stop slave; + drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9; + reset master; + reset slave; + drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9; + start slave; + DROP TABLE IF EXISTS test.t1; + + **** Create Table for Test 1 **** + + CREATE TABLE t1 ( a INT ) ENGINE=innodb; + commit; + + **** Drop Table on slave for Test 1 **** + + DROP TABLE t1; + + **** Insert data on master for Test 1 **** + + BEGIN; + INSERT INTO t1 VALUES (1); + INSERT INTO t1 VALUES (2); + INSERT INTO t1 VALUES (3); + COMMIT; + + **** Connect to slave and show status Test 1 **** + + SHOW SLAVE STATUS; + Slave_IO_State # + Master_Host 127.0.0.1 + Master_User root + Master_Port MASTER_MYPORT + Connect_Retry 1 + Master_Log_File master-bin.000001 + Read_Master_Log_Pos 613 + Relay_Log_File slave-relay-bin.000003 + Relay_Log_Pos 445 + Relay_Master_Log_File master-bin.000001 + 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 mysql.% + Last_Errno 1146 + Last_Error Error 'Table 'test.t1' doesn't exist' on opening table `test`.`t1` + Skip_Counter 0 + Exec_Master_Log_Pos 299 + Relay_Log_Space # + 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 # + Master_SSL_Verify_Server_Cert No + + **** Stop slave and set skip for Test 1 **** + + STOP SLAVE; + SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; + + **** Start slave and show status for Test 1 **** + + START SLAVE; + SHOW SLAVE STATUS; + Slave_IO_State # + Master_Host 127.0.0.1 + Master_User root + Master_Port MASTER_MYPORT + Connect_Retry 1 + Master_Log_File master-bin.000001 + Read_Master_Log_Pos 613 + Relay_Log_File slave-relay-bin.000003 + Relay_Log_Pos 513 + Relay_Master_Log_File master-bin.000001 + 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 mysql.% + Last_Errno 1146 + Last_Error Error 'Table 'test.t1' doesn't exist' on opening table `test`.`t1` + Skip_Counter 0 + Exec_Master_Log_Pos 367 + Relay_Log_Space # + 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 # + Master_SSL_Verify_Server_Cert No + + **** Stop slave and set skip for Test 1 **** + + STOP SLAVE; + SET GLOBAL SQL_SLAVE_SKIP_COUNTER=2; + + **** Start slave and show status for Test 1 **** + + START SLAVE; + SHOW SLAVE STATUS; + Slave_IO_State # + Master_Host 127.0.0.1 + Master_User root + Master_Port MASTER_MYPORT + Connect_Retry 1 + Master_Log_File master-bin.000001 + Read_Master_Log_Pos 613 + Relay_Log_File slave-relay-bin.000003 + Relay_Log_Pos 586 + Relay_Master_Log_File master-bin.000001 + 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 mysql.% + Last_Errno 1146 + Last_Error Error 'Table 'test.t1' doesn't exist' on opening table `test`.`t1` + Skip_Counter 0 + Exec_Master_Log_Pos 73 + Relay_Log_Space # + 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 # + Master_SSL_Verify_Server_Cert No + + **** Stop slave and set skip for Test 1 **** + + STOP SLAVE; + SET GLOBAL SQL_SLAVE_SKIP_COUNTER=3; + + **** Start slave and show status for Test 1 **** + + START SLAVE; + SHOW SLAVE STATUS; + Slave_IO_State # + Master_Host 127.0.0.1 + Master_User root + Master_Port MASTER_MYPORT + Connect_Retry 1 + Master_Log_File master-bin.000001 + Read_Master_Log_Pos 613 + Relay_Log_File slave-relay-bin.000006 + Relay_Log_Pos 252 + Relay_Master_Log_File master-bin.000001 + Slave_IO_Running Yes + Slave_SQL_Running Yes + Replicate_Do_DB + Replicate_Ignore_DB + Replicate_Do_Table + Replicate_Ignore_Table + Replicate_Wild_Do_Table + Replicate_Wild_Ignore_Table mysql.% + Last_Errno 0 + Last_Error + Skip_Counter 0 + Exec_Master_Log_Pos 613 + Relay_Log_Space # + 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 # + Master_SSL_Verify_Server_Cert No + + **** cleanup for Test 1 **** + + drop table if exists t1; + commit; + drop table if exists t1; + commit; + RESET MASTER; + STOP SLAVE; + RESET SLAVE; + START SLAVE; connection master; --disable_warnings DROP TABLE IF EXISTS test.t1; --enable_warnings --echo --echo **** Create Table for Test 1 **** --echo eval CREATE TABLE t1 ( a INT ) ENGINE=$engine_type; commit; sync_slave_with_master; --echo --echo **** Drop Table on slave for Test 1 **** --echo connection slave; DROP TABLE t1; --echo --echo **** Insert data on master for Test 1 **** --echo connection master; BEGIN; INSERT INTO t1 VALUES (1); INSERT INTO t1 VALUES (2); INSERT INTO t1 VALUES (3); COMMIT; sleep 3; --echo --echo **** Connect to slave and show status Test 1 **** --echo connection slave; --replace_result $MASTER_MYPORT MASTER_MYPORT --replace_column 1 # 23 # 33 # --vertical_results SHOW SLAVE STATUS; --echo --echo **** Stop slave and set skip for Test 1 **** --echo STOP SLAVE; SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; --echo --echo **** Start slave and show status for Test 1 **** --echo START SLAVE; sleep 3; --replace_result $MASTER_MYPORT MASTER_MYPORT --replace_column 1 # 23 # 33 # SHOW SLAVE STATUS; --echo --echo **** Stop slave and set skip for Test 1 **** --echo STOP SLAVE; SET GLOBAL SQL_SLAVE_SKIP_COUNTER=2; --echo --echo **** Start slave and show status for Test 1 **** --echo START SLAVE; sleep 3; --replace_result $MASTER_MYPORT MASTER_MYPORT --replace_column 1 # 23 # 33 # SHOW SLAVE STATUS; --echo --echo **** Stop slave and set skip for Test 1 **** --echo STOP SLAVE; SET GLOBAL SQL_SLAVE_SKIP_COUNTER=3; --echo --echo **** Start slave and show status for Test 1 **** --echo START SLAVE; sleep 3; --replace_result $MASTER_MYPORT MASTER_MYPORT --replace_column 1 # 23 # 33 # SHOW SLAVE STATUS; #cleanup --echo --echo **** cleanup for Test 1 **** --echo --disable_warnings connection master; drop table if exists t1; commit; connection slave; drop table if exists t1; commit; --enable_warnings
[13 Apr 2007 18:50]
Jonathan Miller
Hi, Just my thoughts. But it seems like the following makes one full groups of transactions: BEGIN; INSERT INTO t1 VALUES (1); INSERT INTO t1 VALUES (2); INSERT INTO t1 VALUES (3); COMMIT; Seems like when SQL_SLAVE_SKIP_COUNTER=1 it should skip the entire set of statements that belong to the transaction.
[13 Apr 2007 21:39]
Jonathan Miller
Updated test file for safe keeping
Attachment: rpl_skip_events_innodb.test (application/octet-stream, text), 602 bytes.
[13 Apr 2007 21:39]
Jonathan Miller
Updated test file for safe keeping
Attachment: rpl_skip_events_myisam.test (application/octet-stream, text), 568 bytes.
[13 Apr 2007 21:40]
Jonathan Miller
option file
Attachment: rpl_skip_events_innodb-master.opt (application/octet-stream, text), 10 bytes.
[13 Apr 2007 21:40]
Jonathan Miller
option file
Attachment: rpl_skip_events_innodb-slave.opt (application/octet-stream, text), 48 bytes.
[13 Apr 2007 21:41]
Jonathan Miller
Updated test file for safe keeping
Attachment: rpl_skip_events.test (application/octet-stream, text), 5.07 KiB.
[13 Apr 2007 21:41]
Jonathan Miller
reject file
Attachment: rpl_skip_events_innodb.reject (application/octet-stream, text), 9.62 KiB.
[23 May 2007 12:32]
Mats Kindahl
BUG#28618 was created to track the status of the 5.1 version of this bug. This bug is strictly focused on pre-5.1 since the code is significantly different.
[22 Oct 2007 14:27]
Lars Thalmann
This is fixed in 5.1 and it won't be fixed in 5.0 or below.
[23 Oct 2007 20:12]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/36200 ChangeSet@1.2544, 2007-10-23 22:10:23+02:00, mats@kindahl-laptop.dnsalias.net +1 -0 BUG#12691 (Exec_master_log_pos corrupted with SQL_SLAVE_SKIP_COUNTER): Adding code to keep skipping events while inside a transaction. Execution will start just after the transaction has been skipped.
[25 Oct 2007 12:48]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/36342 ChangeSet@1.2544, 2007-10-25 14:48:31+02:00, mats@kindahl-laptop.dnsalias.net +3 -0 BUG#12691 (Exec_master_log_pos corrupted with SQL_SLAVE_SKIP_COUNTER): Adding code to keep skipping events while inside a transaction. Execution will start just after the transaction has been skipped.
[25 Oct 2007 12:50]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/36343 ChangeSet@1.2544, 2007-10-25 14:50:07+02:00, mats@kindahl-laptop.dnsalias.net +4 -0 BUG#12691 (Exec_master_log_pos corrupted with SQL_SLAVE_SKIP_COUNTER): Adding code to keep skipping events while inside a transaction. Execution will start just after the transaction has been skipped.
[26 Oct 2007 7:43]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/36408 ChangeSet@1.2544, 2007-10-26 09:41:59+02:00, mats@kindahl-laptop.dnsalias.net +4 -0 BUG#12691 (Exec_master_log_pos corrupted with SQL_SLAVE_SKIP_COUNTER): Adding code to keep skipping events while inside a transaction. Execution will start just after the transaction has been skipped.
[26 Oct 2007 7:59]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/36409 ChangeSet@1.2544, 2007-10-26 09:09:42+02:00, mats@kindahl-laptop.dnsalias.net +4 -0 BUG#12691 (Exec_master_log_pos corrupted with SQL_SLAVE_SKIP_COUNTER): Adding code to keep skipping events while inside a transaction. Execution will start just after the transaction has been skipped.
[26 Oct 2007 8:58]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/36415 ChangeSet@1.2544, 2007-10-26 09:04:24+02:00, mats@kindahl-laptop.dnsalias.net +4 -0 BUG#12691 (Exec_master_log_pos corrupted with SQL_SLAVE_SKIP_COUNTER): Adding code to keep skipping events while inside a transaction. Execution will start just after the transaction has been skipped.
[26 Oct 2007 16:53]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/36447 ChangeSet@1.2544, 2007-10-26 18:52:58+02:00, mats@kindahl-laptop.dnsalias.net +4 -0 BUG#12691 (Exec_master_log_pos corrupted with SQL_SLAVE_SKIP_COUNTER): Adding code to keep skipping events while inside a transaction. Execution will start just after the transaction has been skipped.
[30 Oct 2007 11:50]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/36637 ChangeSet@1.2603, 2007-10-30 13:49:42+02:00, aelkin@koti.dsl.inet.fi +6 -0 Manual merge 5.0-rpl -> 5.1-rpl. involved bug#12691, bug#27571
[25 Nov 2007 18:26]
Serge Kozlov
The bug still exists for LOAD DATA INFILE statement because it contains 2 events. -- source include/master-slave.inc -- connection master CREATE TABLE t1(b CHAR(10)); --echo **** On Slave **** -- sync_slave_with_master STOP SLAVE; source include/wait_for_slave_to_stop.inc; -- connection master --exec cp ./suite/bugs/data/rpl_bug12691.dat $MYSQLTEST_VARDIR/tmp/ LOAD DATA INFILE '../tmp/rpl_bug12691.dat' INTO TABLE t1 FIELDS TERMINATED BY '|' ; --remove_file $MYSQLTEST_VARDIR/tmp/rpl_bug12691.dat SELECT COUNT(*) FROM t1; --replace_column 2 # 5 # --replace_regex /Server ver: .+/Server ver: #/ /table_id: [0-9]+/table_id: #/ /COMMIT.+xid=[0-9]+.+/#/ /file_id=[0-9]+/file_id=#/ /block_len=[0-9]+/block_len=#/ SHOW BINLOG EVENTS; -- save_master_pos -- connection slave SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; START SLAVE; source include/wait_for_slave_to_start.inc; -- sync_with_master SELECT COUNT(*) FROM t1; Log_name Pos Event_type Server_id End_log_pos Info master-bin.000001 # Format_desc 1 # Server ver: # master-bin.000001 # Query 1 # use `test`; CREATE TABLE t1(b CHAR(10)) master-bin.000001 # Begin_load_query 1 # ;file_id=#;block_len=# master-bin.000001 # Execute_load_query 1 # use `test`; LOAD DATA INFILE '../tmp/rpl_bug12691.dat' INTO TABLE t1 FIELDS TERMINATED BY '|' ;file_id=# Slave.err: 071125 21:10:00 [ERROR] Slave: Error 'Can't get stat of '/home/user/builds/rpl50/mysql-test/var/tmp/SQL_LOAD-2-1-1.data' (Errcode: 2)' on query. Default database: 'test'. Query: 'LOAD DATA INFILE '../tmp/SQL_LOAD-2-1-1.data' INTO TABLE t1 FIELDS TERMINATED BY '|'', Error_code: 13
[27 Nov 2007 10:48]
Bugs System
Pushed into 5.0.54
[27 Nov 2007 10:51]
Bugs System
Pushed into 5.1.23-rc
[27 Nov 2007 10:53]
Bugs System
Pushed into 6.0.4-alpha
[30 Dec 2007 13:43]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/40464 ChangeSet@1.2557, 2007-12-20 15:24:27+01:00, mats@capulet.kindahl.net +3 -0 BUG#12691 (Exec_master_log_pos corrupted with SQL_SLAVE_SKIP_COUNTER): Complementary patch since LOAD DATA INFILE was not covered in the previous patch. This patch adds a check so that the slave skip counter is not decreased to zero if seeing a BEGIN_LOAD_QUERY_EVENT, APPEND_BLOCK_EVENT, or CREATE_FILE_EVENT since these cannot end a group. The group is terminated by an EXECUTE_LOAD_QUERY_ EVENT or DELETE_FILE_EVENT.
[30 Dec 2007 13:43]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/40465 ChangeSet@1.2557, 2007-12-20 16:07:54+01:00, mats@capulet.kindahl.net +3 -0 BUG#12691 (Exec_master_log_pos corrupted with SQL_SLAVE_SKIP_COUNTER): Complementary patch since LOAD DATA INFILE was not covered in the previous patch. This patch adds a check so that the slave skip counter is not decreased to zero if seeing a BEGIN_LOAD_QUERY_EVENT, APPEND_BLOCK_EVENT, or CREATE_FILE_EVENT since these cannot end a group. The group is terminated by an EXECUTE_LOAD_QUERY_ EVENT or DELETE_FILE_EVENT.
[23 Jan 2008 18:30]
Andrei Elkin
There is Bug #31190, a possible dup, that could not be reproduced. I think that's because of this bug fixes were pushed.
[23 Jan 2008 18:30]
Andrei Elkin
There is Bug #31190, a possible dup, that could not be reproduced. I think that's because of this bug fixes have been pushed.
[5 Feb 2008 12:45]
Bugs System
Pushed into 5.0.56
[5 Feb 2008 13:03]
Bugs System
Pushed into 5.1.24-rc
[5 Feb 2008 13:07]
Bugs System
Pushed into 6.0.5-alpha
[15 Feb 2008 13:40]
Bugs System
Pushed into 5.1.24-rc
[15 Feb 2008 13:42]
Bugs System
Pushed into 6.0.5-alpha
Portions of this website are copyright © 2001, 2002 The PHP Group
Page generated in 0.068 sec. using MySQL 8.4.7-u6-cloud
Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the
respective copyright holders.
It is not reviewed in advance
by Oracle and does not necessarily represent the opinion of
Oracle or any other party.