| 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
