Bug #71732 Garbage value in output when MASTER_LOG_FILE='' is set
Submitted: 15 Feb 2014 12:50 Modified: 18 Feb 2014 18:20
Reporter: Valeriy Kravchuk Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.5 OS:Any
Assigned to: CPU Architecture:Any
Tags: CHANGE MASTER, missing manual

[15 Feb 2014 12:50] Valeriy Kravchuk
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.
[17 Feb 2014 9:57] MySQL Verification Team
Hello Valeriy,

Thank you for the bug report.

Thanks,
Umesh
[18 Feb 2014 14:23] Jon Stephens
This appears to a problem with the server, not the docs.

If MASTER_LOG_FILE is set to '', this is what should be reported.

Unassigning myself from / Changing category etc of this bug accordingly.