MySQL Bugs: #68657: "mysqlrpladmin start" fails to start slave SQL thread

Bug #68657	"mysqlrpladmin start" fails to start slave SQL thread
Submitted:	12 Mar 2013 22:43	Modified:	11 Jul 2013 3:27
Reporter:	Thorn Roby	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Utilities	Severity:	S2 (Serious)
Version:	1.2.0	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	mysqlrpladmin, replication

Description:
I'm testing replication on a fresh installation of MySQL 5.6GA and MySQL Utilities 1.2.0. After successfully configuring a master and 2 slaves I tried stopping and starting the slaves from the master using "mysqlrpladmin start". The I/O thread starts up OK but the SQL thread does not. Executing "start slave" on the slave directly succeeds. There is no other activity on the servers during this procedure.

How to repeat:
Start slave on slave: 
2013-02-08 16:04:03 11525 [Note] Slave SQL thread initialized, starting replication in log 
'MASTER-bin.000003' at position 1272, 
relay log './SLAVE-relay-bin.000004' position: 363 

Check from master: 
mysqlrpladmin --master=user:pass@localhost --slaves=user:pass@'SLAVE' health 
# Checking privileges. 
# 
# Replication Topology Health: 
+-----------------------------+-------+---------+--------+------------+------------------------------------------+ 
| host | port | role | state | gtid_mode | health | 
+-----------------------------+-------+---------+--------+------------+------------------------------------------+ 
| localhost | 3306 | MASTER | UP | ON | OK | 
| SLAVE | 3306 | SLAVE | UP | ON | Slave has 1 transactions behind master. | 
+-----------------------------+-------+---------+--------+------------+------------------------------------------+ 
# ...done. 

Stop slave from master: 
mysqlrpladmin --master=user:pass@localhost --slaves=user:pass@'SLAVE' stop 
# Checking privileges. 
# Performing STOP on all slaves. 
# Executing stop on slave SLAVE:3306 Ok 
# ...done. 
# mysqlrpladmin --master=user:pass@localhost --slaves=user:pass@'SLAVE' health 
# Checking privileges. 
# 
# Replication Topology Health: 
+-----------------------------+-------+---------+--------+------------+-------------------------------------------------------------------------------------------------+ 
| host | port | role | state | gtid_mode | health | 
+-----------------------------+-------+---------+--------+------------+-------------------------------------------------------------------------------------------------+ 
| localhost | 3306 | MASTER | UP | ON | OK | 
| SLAVE | 3306 | SLAVE | UP | ON | IO thread is not running., SQL thread is not running., Slave has 1 transactions behind master. | 
+-----------------------------+-------+---------+--------+------------+-------------------------------------------------------------------------------------------------+ 
# ...done. 

Start slave from master: 
mysqlrpladmin --master=user:pass@localhost --slaves=user:pass@'SLAVE' start 
# Checking privileges. 
# Performing START on all slaves. 
# Executing start on slave SLAVE:3306 Ok 
# ...done. 
# mysqlrpladmin --master=user:pass@localhost --slaves=user:pass@'SLAVE' health 
# Checking privileges. 
# 
# Replication Topology Health: 
+-----------------------------+-------+---------+--------+------------+----------------------------------------------------------------------+ 
| host | port | role | state | gtid_mode | health | 
+-----------------------------+-------+---------+--------+------------+----------------------------------------------------------------------+ 
| localhost | 3306 | MASTER | UP | ON | OK | 
| SLAVE | 3306 | SLAVE | UP | ON | SQL thread is not running., Slave has 1 transactions behind master. | 
+-----------------------------+-------+---------+--------+------------+----------------------------------------------------------------------+ 
# ...done. 

Log on slave: 
2013-02-08 16:09:05 11525 [Note] Slave I/O thread: connected to master 'root@MASTER:3306',replication started in log 'MASTER-bin.000003' at position 1272 
2013-02-08 16:09:56 11525 [ERROR] Error writing relay log configuration. 
2013-02-08 16:09:56 11525 [ERROR] Slave SQL: Failed during slave workers initialization, Error_code: 1593 

Start slave on slave: 
2013-02-08 16:11:51 11525 [Note] Slave SQL thread initialized, starting replication in log 'MASTER-bin.000003' at position 1272, relay log './SLAVE-relay-bin.000005' position: 363 

Check status from master: 
mysqlrpladmin --master=user:pass@localhost --slaves=user:pass@'SLAVE' health 
# Checking privileges. 

# Replication Topology Health: 
+-----------------------------+-------+---------+--------+------------+------------------------------------------+ 
| host | port | role | state | gtid_mode | health | 
+-----------------------------+-------+---------+--------+------------+------------------------------------------+ 
| localhost | 3306 | MASTER | UP | ON | OK | 
| SLAVE | 3306 | SLAVE | UP | ON | Slave has 1 transactions behind master. | 
+-----------------------------+-------+---------+--------+------------+------------------------------------------+ 

slave_relay_log_info table on slave: 

select * from slave_relay_log_info\G 
*************************** 1. row *************************** 
Number_of_lines: 7 
Relay_log_name: ./SLAVE-relay-bin.000005 
Relay_log_pos: 363 
Master_log_name: MASTER-bin.000003 
Master_log_pos: 1272 
Sql_delay: 0 
Number_of_workers: 0 
Id: 1 

Relevant my.cnf: 
master-info-repository=TABLE 
relay-log-info-repository=TABLE

The issue was identified and it is related to a server bug.

Can we get a link to (or number of, at least) server bug that leads to this?

Hello Thornton,

Thank you for the report.
Verified as described.

Thanks,
Umesh

## 

D:\ushastry\MySQL Workbench 5.2.47 CE\utilities>mysqlrpladmin --master=root@localhost:3333 --slaves=root@localhost:3399 health
# Checking privileges.
#
# Replication Topology Health:
+------------+-------+---------+--------+------------+---------+
| host       | port  | role    | state  | gtid_mode  | health  |
+------------+-------+---------+--------+------------+---------+
| localhost  | 3333  | MASTER  | UP     | OFF        | OK      |
| localhost  | 3399  | SLAVE   | UP     | OFF        | OK      |
+------------+-------+---------+--------+------------+---------+
# ...done.

D:\ushastry\MySQL Workbench 5.2.47 CE\utilities>mysqlrpladmin --master=root@localhost:3333 --slaves=root@localhost:3399 stop
# Checking privileges.
# Performing STOP on all slaves.
#   Executing stop on slave localhost:3399 Ok
# ...done.

D:\ushastry\MySQL Workbench 5.2.47 CE\utilities>
D:\ushastry\MySQL Workbench 5.2.47 CE\utilities>
D:\ushastry\MySQL Workbench 5.2.47 CE\utilities>mysqlrpladmin --master=root@localhost:3333 --slaves=root@localhost:3399 health
# Checking privileges.
#
# Replication Topology Health:
+------------+-------+---------+--------+------------+--------------------------------------------------------+
| host       | port  | role    | state  | gtid_mode  | health                                                 |
+------------+-------+---------+--------+------------+--------------------------------------------------------+
| localhost  | 3333  | MASTER  | UP     | OFF        | OK                                                     |
| localhost  | 3399  | SLAVE   | UP     | OFF        | IO thread is not running., SQL thread is not running.  |
+------------+-------+---------+--------+------------+--------------------------------------------------------+
# ...done.

D:\ushastry\MySQL Workbench 5.2.47 CE\utilities>mysqlrpladmin --master=root@localhost:3333 --slaves=root@localhost:3399 start
# Checking privileges.
# Performing START on all slaves.
#   Executing start on slave localhost:3399 Ok
# ...done.

D:\ushastry\MySQL Workbench 5.2.47 CE\utilities>
D:\ushastry\MySQL Workbench 5.2.47 CE\utilities>mysqlrpladmin --master=root@localhost:3333 --slaves=root@localhost:3399 health
# Checking privileges.
#
# Replication Topology Health:
+------------+-------+---------+--------+------------+-----------------------------+
| host       | port  | role    | state  | gtid_mode  | health                      |
+------------+-------+---------+--------+------------+-----------------------------+
| localhost  | 3333  | MASTER  | UP     | OFF        | OK                          |
| localhost  | 3399  | SLAVE   | UP     | OFF        | SQL thread is not running.  |
+------------+-------+---------+--------+------------+-----------------------------+
# ...done.

D:\ushastry\MySQL Workbench 5.2.47 CE\utilities>

### From slave

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: localhost
                  Master_User: repl
                  Master_Port: 3333
                Connect_Retry: 60
              Master_Log_File: mysqlsup3-bin.000003
          Read_Master_Log_Pos: 120
               Relay_Log_File: mysqlsup3-relay-bin.000009
                Relay_Log_Pos: 287
        Relay_Master_Log_File: mysqlsup3-bin.000003
             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: 1593
                   Last_Error: Failed during slave workers initialization
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 120
              Relay_Log_Space: 975
              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: 1593
               Last_SQL_Error: Failed during slave workers initialization
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 100
                  Master_UUID: d33c38b7-7411-11e2-b265-bc305bc8d894
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State:
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp: 130430 22:31:35
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set:
                Auto_Position: 0
1 row in set (0.00 sec)

mysql> select * from mysql.slave_relay_log_info\G
*************************** 1. row ***************************
  Number_of_lines: 7
   Relay_log_name: .\mysqlsup3-relay-bin.000009
    Relay_log_pos: 287
  Master_log_name: mysqlsup3-bin.000003
   Master_log_pos: 120
        Sql_delay: 0
Number_of_workers: 0
               Id: 1
1 row in set (0.00 sec)

mysql>

Fixed as of MySQL Utilities 1.2.4/1.3.3, and here's the changelog entry:

The "START SLAVE" statement failed when a MySQL server was started with
the "--master-info-repository=TABLE" and
"--relay-log-info-repository=TABLE" options, and with autocommit mode
disabled. This fix provides a workaround by enabling autocommit ("SET
autocommit=1") before executing a "START SLAVE" statement. This allows 
the utility to function with past and future versions of MySQL server.

Thank you for the bug report.