Description:
Manual for CHANGE MASTER (http://dev.mysql.com/doc/refman/5.5/en/change-master-to.html) says:
"If you specify the MASTER_HOST or MASTER_PORT option, the slave assumes that the master server is different from before (even if the option value is the same as its current value.) In this case, the old values for the master binary log file name and position are considered no longer applicable, so if you do not specify MASTER_LOG_FILE and MASTER_LOG_POS in the statement, MASTER_LOG_FILE='' and MASTER_LOG_POS=4 are silently appended to it."
But it does NOT say what binary log will actually be used on master to start replication from: current one, oldest available one? All we can see is messages like this:
" New state master_host='hostname', master_port='3306', master_log_file='', master_log_pos='4'."
and then:
"140214 15:22:40 [Note] Slave SQL thread initialized, starting replication in log 'FIRST' at position 0, relay log '/some_path/mysql-relay-bin.000001' position: 4"
on slave and:
"140214 15:22:38 [Note] Start binlog_dump to slave_server(#####), pos(, 4)"
on master.
It would be nice to see some clear statements in the manual (at least) on what this "FIRST" means and what binary log is actually read from master.
How to repeat:
Set up replication, do some changes and flush logs to move "past" the first binary log, then with several long in place, on slave:
slave1 [localhost] {msandbox} ((none)) > show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 127.0.0.1
Master_User: rsandbox
Master_Port: 23791
Connect_Retry: 60
Master_Log_File: mysql-bin.000003
Read_Master_Log_Pos: 107
Relay_Log_File: mysql_sandbox23792-relay-bin.000006
Relay_Log_Pos: 253
Relay_Master_Log_File: mysql-bin.000003
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:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 107
Relay_Log_Space: 465
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: 0
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 1
1 row in set (0.00 sec)
slave1 [localhost] {msandbox} ((none)) > stop slave;
Query OK, 0 rows affected (0.08 sec)
slave1 [localhost] {msandbox} ((none)) > change master to master_host='127.0.0.1', master_port=23791;
Query OK, 0 rows affected (0.16 sec)
slave1 [localhost] {msandbox} ((none)) > show slave status\G *************************** 1. row ***************************
Slave_IO_State:
Master_Host: 127.0.0.1
Master_User: rsandbox
Master_Port: 23791
Connect_Retry: 60
Master_Log_File:
Read_Master_Log_Pos: 4
Relay_Log_File: mysql_sandbox23792-relay-bin.000001
Relay_Log_Pos: 4
Relay_Master_Log_File:
Slave_IO_Running: No
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: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 0
Relay_Log_Space: 107
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: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 1
1 row in set (0.00 sec)
Find this in slave's error log:
140215 14:24:51 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='23791', master_log_file='', master_log_pos='4'.
140215 14:24:51 [Note] Slave I/O thread: connected to master 'rsandbox@127.0.0.1:23791',replication started in log 'FIRST' at position 4
140215 14:24:51 [Note] Slave SQL thread initialized, starting replication in log 'FIRST' at position 0, relay log './mysql_sandbox23792-relay-bin.000001' position: 4
140215 14:36:36 [Note] Error reading relay log event: slave SQL thread was killed
140215 14:36:36 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
140215 14:36:36 [Note] Slave I/O thread killed while reading event
140215 14:36:36 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.000003', position 107
140215 14:36:39 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='23791', master_log_file='mysql-bin.000003', master_log_pos='107'. New state master_host='127.0.0.1', master_port='23791', master_log_file='', master_log_pos='4'.
Go back to master:
master [localhost] {msandbox} ((none)) > show master status;
+------------------+----------+--------------+------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------------+----------+--------------+------------------+
| mysql-bin.000003 | 107 | | |
+------------------+----------+--------------+------------------+
1 row in set (0.00 sec)
master [localhost] {msandbox} ((none)) > use test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A
Database changed
master [localhost] {msandbox} (test) > insert into t values(2);
ERROR 1146 (42S02): Table 'test.t' doesn't exist
master [localhost] {msandbox} (test) > insert into t1 values(2);
Query OK, 1 row affected (0.09 sec)
master [localhost] {msandbox} (test) > flush logs;
Query OK, 0 rows affected (0.21 sec)
Then go back to slave and start slave and find how nice it breaks:
slave1 [localhost] {msandbox} (test) > start slave;
Query OK, 0 rows affected (0.00 sec)
slave1 [localhost] {msandbox} (test) > show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 127.0.0.1
Master_User: rsandbox
Master_Port: 23791
Connect_Retry: 60
Master_Log_File: mysql-bin.000004
Read_Master_Log_Pos: 107
Relay_Log_File: mysql_sandbox23792-relay-bin.000002
Relay_Log_Pos: 2227
Relay_Master_Log_File: mysql-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: 1050
Last_Error: Error 'Table 't1' already exists' on query. Default database: 'test'. Query: 'create table t1(c1 int)'
Skip_Counter: 0
Exec_Master_Log_Pos: 2081
Relay_Log_Space: 4427
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: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 1050
Last_SQL_Error: Error 'Table 't1' already exists' on query. Default database: 'test'. Query: 'create table t1(c1 int)'
Replicate_Ignore_Server_Ids:
Master_Server_Id: 1
1 row in set (0.00 sec)
That's because it really reads from the first binary log available and replays everything. Now, try to find explanation of the above in the manual.
Suggested fix:
Explain what binary log is really read when you see messages like these in the slave's error log:
140215 14:24:51 [Note] Slave I/O thread: connected to master 'rsandbox@127.0.0.1:23791',replication started in log 'FIRST' at position 4
140215 14:24:51 [Note] Slave SQL thread initialized, starting replication in log 'FIRST' at position 0, relay log './mysql_sandbox23792-relay-bin.000001' position: 4
or when you set MASTER_LOG_FILE='' explicitly in CHANGE MASTER.
