| Bug #55704 | incorrect binlogging of savepoints break slaves! | ||
|---|---|---|---|
| Submitted: | 3 Aug 2010 7:13 | Modified: | 29 Nov 2010 22:35 |
| Reporter: | Shane Bester (Platinum Quality Contributor) | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S2 (Serious) |
| Version: | 5.1.49, 5.1.50, 5.5.5 | OS: | Any |
| Assigned to: | Alfranio Tavares Correia Junior | CPU Architecture: | Any |
[3 Aug 2010 7:13]
Shane Bester
[3 Aug 2010 7:27]
MySQL Verification Team
binlog has this: 195 | use `test`; drop table if exists t1,t4 293 | use `test`; create table t1(b int)engine=myisam 391 | use `test`; create table t4(b int)engine=innodb 459 | BEGIN 545 | use `test`; replace into t4 set b=1 572 | COMMIT /* xid=20 */ 640 | BEGIN 726 | use `test`; replace into t4 set b=1 812 | use `test`; replace into t1 set b=1 893 | ROLLBACK TO batch1 962 | COMMIT
[3 Aug 2010 7:39]
Valeriy Kravchuk
Verified with recent mysql-5.1 from bzr on Mac OS X: macbook-pro:mysql-test openxs$ ./mtr bug55704 Logging: ./mtr bug55704 100803 10:35:57 [Warning] Setting lower_case_table_names=2 because file system for /var/folders/dX/dXCzvuSlHX4Op1g-o1jIWk+++TI/-Tmp-/AjxpXMl946/ is case insensitive 100803 10:35:57 [Note] Plugin 'FEDERATED' is disabled. 100803 10:35:57 [Note] Plugin 'ndbcluster' is disabled. MySQL Version 5.1.50 Checking supported features... - using ndbcluster when necessary, mysqld supports it - SSL connections supported - binaries are debug compiled Collecting tests... vardir: /Users/openxs/dbs/5.1/mysql-test/var Checking leftover processes... Removing old var directory... Creating var directory '/Users/openxs/dbs/5.1/mysql-test/var'... Installing system database... Using server port 54461 ============================================================================== TEST RESULT TIME (ms) ------------------------------------------------------------ worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009 main.bug55704 [ fail ] Test ended at 2010-08-03 10:36:06 CURRENT_TEST: main.bug55704 === SHOW MASTER STATUS === ---- 1. ---- File slave-bin.000001 Position 856 Binlog_Do_DB Binlog_Ignore_DB ========================== === SHOW SLAVE STATUS === ---- 1. ---- Slave_IO_State Waiting for master to send event Master_Host 127.0.0.1 Master_User root Master_Port 13000 Connect_Retry 1 Master_Log_File master-bin.000001 Read_Master_Log_Pos 962 Relay_Log_File slave-relay-bin.000003 Relay_Log_Pos 718 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 Last_Errno 1305 Last_Error Error 'SAVEPOINT batch1 does not exist' on query. Default database: 'test'. Query: 'ROLLBACK TO batch1' Skip_Counter 0 Exec_Master_Log_Pos 572 Relay_Log_Space 1263 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 Last_IO_Errno 0 Last_IO_Error Last_SQL_Errno 1305 Last_SQL_Error Error 'SAVEPOINT batch1 does not exist' on query. Default database: 'test'. Query: 'ROLLBACK TO batch1' ========================= === SHOW PROCESSLIST === ---- 1. ---- Id 2 User root Host localhost:54475 db test Command Query Time 0 State Info SHOW PROCESSLIST ---- 2. ---- Id 3 User root Host localhost:54476 db test Command Sleep Time 3 State Info ---- 3. ---- Id 4 User system user Host db Command Connect Time 1 State Waiting for master to send event Info ======================== analyze: sync_with_master mysqltest: At line 19: sync_slave_with_master failed: 'select master_pos_wait('master-bin.000001', 962, 300)' returned NULL indicating slave SQL thread failure The result from queries just before the failure was: < snip > start slave; drop table if exists t1,t4; Warnings: Note 1051 Unknown table 't1' Note 1051 Unknown table 't4' create table t1(b int)engine=myisam; create table t4(b int)engine=innodb; replace into t4 set b=1; rollback; xa start 'xid1'; replace into t4 set b=1; xa end 'xid1'; savepoint batch1; rollback work to savepoint batch1; xa prepare 'xid1'; replace into t1 set b=1; rollback work to savepoint batch1; Warnings: Warning 1196 Some non-transactional changed tables couldn't be rolled back xa commit 'xid1'; More results from queries before failure can be found in /Users/openxs/dbs/5.1/mysql-test/var/log/bug55704.log Warnings from just before the error: Note 1051 Unknown table 't1' Note 1051 Unknown table 't2' Note 1051 Unknown table 't3' Note 1051 Unknown table 't4' Note 1051 Unknown table 't5' Note 1051 Unknown table 't6' Note 1051 Unknown table 't7' Note 1051 Unknown table 't8' == /Users/openxs/dbs/5.1/mysql-test/var/tmp/analyze-sync_with_master-mysqld.1.err == SHOW PROCESSLIST; Id User Host db Command Time State Info 5 root localhost:54477 NULL Binlog Dump 1 Has sent all binlog to slave; waiting for binlog to be updated NULL 6 root localhost NULL Query 0 NULL SHOW PROCESSLIST SHOW BINLOG EVENTS IN 'master-bin.000001'; Log_name Pos Event_type Server_id End_log_pos Info master-bin.000001 4 Format_desc 1 106 Server ver: 5.1.50-debug-log, Binlog ver: 4 master-bin.000001 106 Query 1 195 use `test`; drop table if exists t1,t4 master-bin.000001 195 Query 1 293 use `test`; create table t1(b int)engine=myisam master-bin.000001 293 Query 1 391 use `test`; create table t4(b int)engine=innodb master-bin.000001 391 Query 1 459 BEGIN master-bin.000001 459 Query 1 545 use `test`; replace into t4 set b=1 master-bin.000001 545 Xid 1 572 COMMIT /* xid=23 */ master-bin.000001 572 Query 1 640 BEGIN master-bin.000001 640 Query 1 726 use `test`; replace into t4 set b=1 master-bin.000001 726 Query 1 812 use `test`; replace into t1 set b=1 master-bin.000001 812 Query 1 893 ROLLBACK TO batch1 master-bin.000001 893 Query 1 962 COMMIT == /Users/openxs/dbs/5.1/mysql-test/var/tmp/analyze-sync_with_master-mysqld.2.err == SHOW PROCESSLIST; Id User Host db Command Time State Info 4 system user NULL Connect 1 Waiting for master to send event NULL 6 root localhost NULL Query 0 NULL SHOW PROCESSLIST SHOW BINLOG EVENTS IN 'slave-bin.000001'; Log_name Pos Event_type Server_id End_log_pos Info slave-bin.000001 4 Format_desc 2 106 Server ver: 5.1.50-debug-log, Binlog ver: 4 slave-bin.000001 106 Query 1 195 use `test`; drop table if exists t1,t4 slave-bin.000001 195 Query 1 293 use `test`; create table t1(b int)engine=myisam slave-bin.000001 293 Query 1 391 use `test`; create table t4(b int)engine=innodb slave-bin.000001 391 Query 1 450 BEGIN slave-bin.000001 450 Query 1 536 use `test`; replace into t4 set b=1 slave-bin.000001 536 Xid 1 563 COMMIT /* xid=32 */ slave-bin.000001 563 Query 1 622 BEGIN slave-bin.000001 622 Query 1 708 use `test`; replace into t4 set b=1 slave-bin.000001 708 Query 1 794 use `test`; replace into t1 set b=1 slave-bin.000001 794 Query 1 856 ROLLBACK - saving '/Users/openxs/dbs/5.1/mysql-test/var/log/main.bug55704/' to '/Users/openxs/dbs/5.1/mysql-test/var/log/main.bug55704/' ------------------------------------------------------------ The servers were restarted 0 times Spent 0.000 of 9 seconds executing testcases Completed: Failed 1/1 tests, 0.00% were successful. Failing test(s): main.bug55704 The log files in var/log may give you some hint of what went wrong. If you want to report this error, please read first the documentation at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html mysql-test-run: *** ERROR: there were failing test cases This is the test case: macbook-pro:mysql-test openxs$ cat t/bug55704.test --source include/master-slave.inc --source include/have_innodb.inc connection master; drop table if exists t1,t4; create table t1(b int)engine=myisam; create table t4(b int)engine=innodb; #xa end 'xid1'; replace into t4 set b=1; rollback; xa start 'xid1'; replace into t4 set b=1; xa end 'xid1'; savepoint batch1; rollback work to savepoint batch1; xa prepare 'xid1'; replace into t1 set b=1; rollback work to savepoint batch1; xa commit 'xid1'; sync_slave_with_master; connection slave; select * from t1;
[3 Aug 2010 8:19]
Alfranio Tavares Correia Junior
Hi all, Find below another test case: --source include/master-slave.inc --source include/have_innodb.inc --source include/have_binlog_format_statement.inc connection master; drop table if exists t1,t4; create table t1(b int)engine=myisam; create table t4(b int)engine=innodb; BEGIN; replace into t4 set b=1; savepoint batch1; rollback work to savepoint batch1; replace into t1 set b=1; rollback work to savepoint batch1; COMMIT; --sync_slave_with_master SHOW BINLOG EVENTS; exit;
[5 Aug 2010 14:11]
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/115107 3162 Alfranio Correia 2010-08-05 BUG#55704 incorrect binlogging of savepoints break slaves! The replication was ignoring that a savepoint was valid within a transaction unless it is released, implicit or explicitly, and was removing its occurrence from the binary log when a rollback was issued. To fix the problem, we always keep the savepoint definition in the binary log. @ mysql-test/extra/rpl_tests/rpl_mixing_engines.inc Improve this test case to easily generate savepoint and rollback to savepoint commands. @ mysql-test/extra/rpl_tests/rpl_mixing_engines.test Updated the test case with the new syntax for savepoints. @ mysql-test/suite/binlog/r/binlog_row_mix_innodb_myisam.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/binlog/r/binlog_stm_mix_innodb_myisam.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/rpl/r/rpl_innodb_mixed_dml.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/rpl/r/rpl_mixed_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_mixed_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_row_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_stm_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_row_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_stm_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ sql/log.cc The core of the patch.
[2 Sep 2010 14:03]
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/117424 3257 Alfranio Correia 2010-09-02 BUG#55704 incorrect binlogging of savepoints break slaves! The replication was ignoring that a savepoint was valid within a transaction unless it is released, implicit or explicitly, and was removing its occurrence from the binary log when a rollback was issued. To fix the problem, we always keep the savepoint definition in the binary log. @ mysql-test/extra/rpl_tests/rpl_mixing_engines.inc Improve this test case to easily generate savepoint and rollback to savepoint commands. @ mysql-test/extra/rpl_tests/rpl_mixing_engines.test Updated the test case with the new syntax for savepoints. @ mysql-test/suite/binlog/r/binlog_row_mix_innodb_myisam.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/binlog/r/binlog_stm_mix_innodb_myisam.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/rpl/r/rpl_innodb_mixed_dml.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/rpl/r/rpl_mixed_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_mixed_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_row_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_stm_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_row_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_stm_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints.
[2 Sep 2010 16:44]
Alfranio Tavares Correia Junior
The test case for this patch is in WL#5485.
[2 Sep 2010 17:21]
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/117447 3257 Alfranio Correia 2010-09-02 BUG#55704 incorrect binlogging of savepoints break slaves! The replication was ignoring that a savepoint was valid within a transaction unless it is released, implicit or explicitly, and was removing its occurrence from the binary log when a rollback was issued. To fix the problem, we always keep the savepoint definition in the binary log. @ mysql-test/extra/rpl_tests/rpl_mixing_engines.inc Improve this test case to easily generate savepoint and rollback to savepoint commands. @ mysql-test/extra/rpl_tests/rpl_mixing_engines.test Updated the test case with the new syntax for savepoints. @ mysql-test/suite/binlog/r/binlog_row_mix_innodb_myisam.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/binlog/r/binlog_stm_mix_innodb_myisam.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/rpl/r/rpl_innodb_mixed_dml.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/rpl/r/rpl_mixed_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_mixed_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_row_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_stm_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_row_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_stm_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints.
[24 Sep 2010 11:36]
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/119022 3275 Alfranio Correia 2010-09-24 BUG#55704 incorrect binlogging of savepoints break slaves! The replication was ignoring that a savepoint was valid within a transaction unless it is released, implicit or explicitly, and was removing its occurrence from the binary log when a 'rollback to' was issued. To fix the problem, we always keep the savepoint defintion in the binary log when rolling back to the savepoint. @ mysql-test/extra/rpl_tests/rpl_mixing_engines.inc Improve this test case to easily generate savepoint and rollback to savepoint commands. @ mysql-test/extra/rpl_tests/rpl_mixing_engines.test Updated the test case with the new syntax for savepoints. @ mysql-test/suite/binlog/r/binlog_row_mix_innodb_myisam.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/binlog/r/binlog_stm_mix_innodb_myisam.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/rpl/r/rpl_innodb_mixed_dml.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/rpl/r/rpl_mixed_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_mixed_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_row_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_stm_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_row_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_stm_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints.
[28 Sep 2010 13:30]
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/119280 3275 Alfranio Correia 2010-09-28 [merge] BUG#55704 incorrect binlogging of savepoints break slaves! The replication was ignoring that a savepoint was valid within a transaction unless it is released, implicit or explicitly, and was removing its occurrence from the binary log when a 'rollback to' was issued. To fix the problem, we always keep the savepoint defintion in the binary log when rolling back to the savepoint. @ mysql-test/extra/rpl_tests/rpl_mixing_engines.inc Improve this test case to easily generate savepoint and rollback to savepoint commands. @ mysql-test/extra/rpl_tests/rpl_mixing_engines.test Updated the test case with the new syntax for savepoints. @ mysql-test/suite/binlog/r/binlog_row_mix_innodb_myisam.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/binlog/r/binlog_stm_mix_innodb_myisam.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/rpl/r/rpl_innodb_mixed_dml.result Updated the result file as a savepoint is recorded if the transaction within which it was generated is written to the binary log. @ mysql-test/suite/rpl/r/rpl_mixed_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_mixed_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_row_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_non_direct_stm_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_row_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints. @ mysql-test/suite/rpl/r/rpl_stm_mixing_engines.result Updated the result file due to the following reasons: . a savepoint is recorded if the transaction within which it was generated is written to the binary log. . the new syntax for savepoints.
[10 Oct 2010 22:39]
Alfranio Tavares Correia Junior
Patch queued to mysql-trunk-bugfixing --> mysql-next-mr-bugfixing
[13 Nov 2010 16:15]
Bugs System
Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:jimmy.yang@oracle.com-20100804103744-vbpeghipkz6pyc9z) (merge vers: 5.1.51) (pib:21)
[13 Nov 2010 16:40]
Bugs System
Pushed into mysql-next-mr (revid:alexander.nozdrin@oracle.com-20101113160336-atmtmfb3mzm4pz4i) (version source revid:jimmy.yang@oracle.com-20100804103744-vbpeghipkz6pyc9z) (pib:21)
[29 Nov 2010 22:35]
Jon Stephens
No fix for this in 5.1; doesn't seem to be in 5.5; doesn't appear in a 5.6 release: no changelog entry required. Closed without further action.
