MySQL Bugs: #58983: Error replicating with "start slave until" when replicate-same-server-id enabled

Bug #58983	Error replicating with "start slave until" when replicate-same-server-id enabled
Submitted:	16 Dec 2010 19:02	Modified:	4 Jan 2011 23:20
Reporter:	Lior Goikhburg	Email Updates:
Status:	Won't fix	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.0.91, 5.0	OS:	Linux
Assigned to:	Alfranio Tavares Correia Junior	CPU Architecture:	Any

Description:
When replicate-same-server-id is enabled, replicating with start slave until command fails with error message logged:
[ERROR] Slave SQL thread is stopped because UNTIL condition is bad.

When replicate-same-server-id is disabled, everything works as expected.

How to repeat:
install 2 mysql servers version 5.0.91
configure slave with replicate-same-server-id enabled
start servers
provide replication grants on the master

on server1:
# mysql
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 11
Server version: 5.0.91-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> create database testrep1;
Query OK, 1 row affected (0.00 sec)

mysql> use testrep1;
Database changed
mysql> create table testtab1 (comment varchar(64));
Query OK, 0 rows affected (0.00 sec)

mysql> insert into testtab1 values ('insert1');
Query OK, 1 row affected (0.00 sec)

mysql> insert into testtab1 values ('insert2');
Query OK, 1 row affected (0.00 sec)

mysql> insert into testtab1 values ('insert3');
Query OK, 1 row affected (0.00 sec)

mysql> show master status;
+------------------+----------+--------------+------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------------+----------+--------------+------------------+
| mysql-bin.000001 |      954 | testrep1     |                  | 
+------------------+----------+--------------+------------------+
1 row in set (0.00 sec)

mysql> show binlog events in 'mysql-bin.000001';
+------------------+-----+-------------+-----------+-------------+-------------------------------------------------------------+
| Log_name         | Pos | Event_type  | Server_id | End_log_pos | Info                                                        |
+------------------+-----+-------------+-----------+-------------+-------------------------------------------------------------+
| mysql-bin.000001 |   4 | Format_desc |         1 |          98 | Server ver: 5.0.91-log, Binlog ver: 4                       | 
| mysql-bin.000001 |  98 | Query       |         1 |         194 | create database testrep1                                    | 
| mysql-bin.000001 | 194 | Query       |         1 |         309 | use `testrep1`; create table testtab1 (comment varchar(64)) | 
| mysql-bin.000001 | 309 | Query       |         1 |         386 | BEGIN                                                       | 
| mysql-bin.000001 | 386 | Query       |         1 |         497 | use `testrep1`; insert into testtab1 values ('insert1')     | 
| mysql-bin.000001 | 497 | Xid         |         1 |         524 | COMMIT /* xid=183 */                                        | 
| mysql-bin.000001 | 524 | Query       |         1 |         601 | BEGIN                                                       | 
| mysql-bin.000001 | 601 | Query       |         1 |         712 | use `testrep1`; insert into testtab1 values ('insert2')     | 
| mysql-bin.000001 | 712 | Xid         |         1 |         739 | COMMIT /* xid=193 */                                        | 
| mysql-bin.000001 | 739 | Query       |         1 |         816 | BEGIN                                                       | 
| mysql-bin.000001 | 816 | Query       |         1 |         927 | use `testrep1`; insert into testtab1 values ('insert3')     | 
| mysql-bin.000001 | 927 | Xid         |         1 |         954 | COMMIT /* xid=200 */                                        | 
+------------------+-----+-------------+-----------+-------------+-------------------------------------------------------------+
12 rows in set (0.00 sec)

mysql>

on server2:
# mysql
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 86
Server version: 5.0.91-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> change master to master_user='repl', master_password='repl', master_host='10.10.10.102', MASTER_LOG_FILE='mysql-bin.000001', MASTER_LOG_POS=98;
Query OK, 0 rows affected (0.00 sec)

mysql> start slave until MASTER_LOG_FILE='mysql-bin.000001', MASTER_LOG_POS=739;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> show databases;
+--------------------+
| Database           |
+--------------------+
| information_schema | 
| mysql              | 
| test               | 
+--------------------+
3 rows in set (0.00 sec)

mysql> show slave status\G;
*************************** 1. row ***************************
             Slave_IO_State: Waiting for master to send event
                Master_Host: 10.10.10.102
                Master_User: repl
                Master_Port: 3306
              Connect_Retry: 60
            Master_Log_File: mysql-bin.000001
        Read_Master_Log_Pos: 954
             Relay_Log_File: mysql-relay-bin.000002
              Relay_Log_Pos: 4
      Relay_Master_Log_File: mysql-relay-bin.000002
           Slave_IO_Running: Yes
          Slave_SQL_Running: No
            Replicate_Do_DB: testrep1
        Replicate_Ignore_DB: 
         Replicate_Do_Table: 
     Replicate_Ignore_Table: 
    Replicate_Wild_Do_Table: 
Replicate_Wild_Ignore_Table: 
                 Last_Errno: 0
                 Last_Error: 
               Skip_Counter: 0
        Exec_Master_Log_Pos: 4
            Relay_Log_Space: 1091
            Until_Condition: Master
             Until_Log_File: mysql-bin.000001
              Until_Log_Pos: 739
         Master_SSL_Allowed: No
         Master_SSL_CA_File: 
         Master_SSL_CA_Path: 
            Master_SSL_Cert: 
          Master_SSL_Cipher: 
             Master_SSL_Key: 
      Seconds_Behind_Master: NULL
1 row in set (0.00 sec)

mysql> Bye
# tail /var/log/mysqld.log 
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
101216 18:55:41  InnoDB: Started; log sequence number 0 0
101216 18:55:41 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.0.91-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  Source distribution
101216 18:58:42 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000001' at position 98, relay log '/var/lib/mysql/mysql-relay-bin.000001' position: 4
101216 18:58:42 [Note] Slave I/O thread: connected to master 'repl@10.179.113.102:3306',  replication started in log 'mysql-bin.000001' at position 98
101216 18:58:42 [ERROR] Slave SQL thread is stopped because UNTIL condition is bad.
101216 18:58:42 [Note] Slave SQL thread stopped because it reached its UNTIL position 4

Thank you for the report.

Verified as described.

This problem *does not* happen in 5.1, 5.5 and 5.6.

To check the problem, run the test case below and open the logs.

5.0 --> var/log/slave.err
5.1, 5.5, 5.6 --> var/log/mysqld.2.err

------- rpl_test.test -------

--source include/master-slave.inc
--source include/have_innodb.inc

connection slave;
--source include/stop_slave.inc

connection master;

CREATE TABLE t1 (a INT, b INT) ENGINE=MyISAM;
CREATE TABLE t2 (c INT, d INT) ENGINE=MyISAM;
INSERT INTO t1 VALUES (1,1),(2,4),(3,9);
INSERT INTO t2 VALUES (1,1),(2,8),(3,27);
let $master_log_pos= query_get_value(SHOW MASTER STATUS, Position, 1);
UPDATE t1,t2 SET b = d, d = b * 2 WHERE a = c;
source include/show_binlog_events.inc;

SELECT * FROM t1;
SELECT * FROM t2;

connection slave;

eval START SLAVE UNTIL MASTER_LOG_FILE='master-bin.000001', MASTER_LOG_POS=$master_log_pos;
source include/wait_for_slave_sql_to_stop.inc;

--query_vertical SHOW SLAVE STATUS

Problem is fixed in 5.1+ and will not be fixed in 5.0