Details
-
New Feature
-
Status: Closed (View Workflow)
-
Minor
-
Resolution: Fixed
-
1.4.3
-
None
-
2016-13
Description
Let's say that I have a binlog router instance with the following configuration:
[maxscale]
|
threads=4
|
log_debug=1
|
log_trace=1
|
|
|
[Replication]
|
type=service
|
router=binlogrouter
|
version_string=10.0.25-log
|
user=maxscale
|
passwd=password
|
router_options=server_id=2,mariadb10-compatibility=1,binlogdir=/var/log/binlogs
|
|
|
[Replication Listener]
|
type=listener
|
service=Replication
|
protocol=MySQLClient
|
port=3306
|
And then I create a replication user on the master:
GRANT ALL PRIVILEGES ON *.* TO 'repl'@'%' IDENTIFIED BY 'password';
|
Now let's say that I execute CHANGE MASTER TO on the binlog router instance, but I supply the wrong password for master_password:
CHANGE MASTER TO master_host='172.31.32.117',master_port=3306,master_user='repl',master_password='password1', MASTER_LOG_FILE='mysqld-bin.000002',MASTER_LOG_POS=4;
|
START SLAVE;
|
This will fail to connect due to the incorrect password, but MaxScale seems to ignore this in SHOW SLAVE STATUS. Instead, it suggests that Slave_IO_State is "Timestamp retrieval" and Last_Errno is 0.
MySQL [(none)]> SHOW SLAVE STATUS\G
|
*************************** 1. row ***************************
|
Slave_IO_State: Timestamp retrieval
|
Master_Host: 172.31.32.117
|
Master_User: repl
|
Master_Port: 3306
|
Connect_Retry: 60
|
Master_Log_File: mysqld-bin.000002
|
Read_Master_Log_Pos: 4
|
Relay_Log_File: mysqld-bin.000002
|
Relay_Log_Pos: 4
|
Relay_Master_Log_File: mysqld-bin.000002
|
Slave_IO_Running: Connecting
|
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: 4
|
Relay_Log_Space: 4
|
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: 0
|
Master_UUID: 57e87f43-3975-11e6-9925-06916daa38f7
|
Master_Info_File:
|
SQL_Delay: 0
|
SQL_Remaining_Delay: NULL
|
Slave_SQL_Running_State: Slave running
|
Master_Retry_Count: 1000
|
Master_Bind:
|
Last_IO_Error_TimeStamp:
|
Last_SQL_Error_Timestamp:
|
Master_SSL_Crl:
|
Master_SSL_Crlpath:
|
Retrieved_Gtid_Set:
|
Executed_Gtid_Set:
|
Auto_Position:
|
1 row in set (0.00 sec)
|
The log does seem to contain an error message when this happens, so it seems that MaxScale is aware of the failure:
2016-06-23 15:06:31 [2] info : Execute statement (truncated, it contains password) from the slave 'change master to master_host='172.31.32.117',master_port=3306,master_user='repl',master_...'
|
2016-06-23 15:06:31 [2] info : Replication: New MASTER_USER is [repl]
|
2016-06-23 15:06:31 [2] info : Replication: New MASTER_HOST is [172.31.32.117]
|
2016-06-23 15:06:31 [2] info : Replication: New MASTER_PORT is [3306]
|
2016-06-23 15:06:31 [2] info : Replication: New MASTER_LOG_FILE is [mysqld-bin.000002]
|
2016-06-23 15:06:31 [2] info : Replication: New MASTER_LOG_POS is [4]
|
2016-06-23 15:06:31 notice : Replication: 'CHANGE MASTER TO executed'. Previous state MASTER_HOST='_none_', MASTER_PORT=3306, MASTER_LOG_FILE='', MASTER_LOG_POS=0, MASTER_USER='maxscale'. New state is MASTER_HOST='172.31.32.117', MASTER_PORT=3306, MASTER_LOG_FILE='mysqld-bin.000002', MASTER_LOG_POS=4, MASTER_USER='repl'
|
2016-06-23 15:06:31 debug : 140013012002560 [dcb_write] Append to writequeue. 4 writes buffered for dcb 0x7f574c000a40 in state DCB_STATE_POLLING fd 4
|
2016-06-23 15:06:31 debug : 140013012002560 [dcb_drain_writeq] Wrote 11 Bytes to dcb 0x7f574c000a40 in state DCB_STATE_POLLING fd 4
|
...snip...
|
2016-06-23 15:06:49 [2] info : Execute statement from the slave 'start slave'
|
2016-06-23 15:06:49 [2] info : Started session [0] for Replication service
|
2016-06-23 15:06:49 notice : Loaded module MySQLBackend: V2.0.0 from /usr/lib64/maxscale/libMySQLBackend.so
|
2016-06-23 15:06:49 debug : 140013001512704 [gw_do_connect_to_backend] Connected to backend server 172.31.32.117:3306, fd 13.
|
2016-06-23 15:06:49 debug : 140013001512704 [gw_create_backend_connection] Connection pending to 172.31.32.117:3306, protocol fd 13 client fd -1.
|
2016-06-23 15:06:49 debug : 140013001512704 [dcb_connect] Connected to server 172.31.32.117:3306, from backend dcb 0x7f5744000ee0, client dcp 0x7f5744000b00 fd -1.
|
2016-06-23 15:06:49 debug : 140013001512704 [poll_add_dcb] Added dcb 0x7f5744000ee0 in state DCB_STATE_POLLING to poll set.
|
2016-06-23 15:06:49 notice : Replication: attempting to connect to master server 172.31.32.117:3306, binlog mysqld-bin.000002, pos 4
|
2016-06-23 15:06:49 debug : 140013001512704 [gw_MySQLWrite_backend] delayed write to dcb 0x7f5744000ee0 fd 13 protocol state MYSQL_PENDING_CONNECT.
|
2016-06-23 15:06:49 notice : Replication: START SLAVE executed by maxscale@127.0.0.1. Trying connection to master 172.31.32.117:3306, binlog mysqld-bin.000002, pos 4, transaction safe pos 4
|
2016-06-23 15:06:49 debug : 140013442922464 [poll_waitevents] epoll_wait found 1 fds
|
2016-06-23 15:06:49 debug : 140013012002560 [poll_waitevents] epoll_wait found 1 fds
|
2016-06-23 15:06:49 debug : Loading data from backend database [172.31.32.117:3306] for service [Replication]
|
2016-06-23 15:06:49 debug : Replication: Adding database db1 to the resouce hash.
|
2016-06-23 15:06:49 debug : Replication: Adding database information_schema to the resouce hash.
|
2016-06-23 15:06:49 debug : Replication: Adding database mysql to the resouce hash.
|
2016-06-23 15:06:49 debug : Replication: Adding database performance_schema to the resouce hash.
|
2016-06-23 15:06:49 debug : Replication: Adding database test to the resouce hash.
|
2016-06-23 15:06:49 debug : Loaded 5 MySQL Database Names for service [Replication]
|
2016-06-23 15:06:49 [2] info : Replication: User appuser@localhost for database no db added to service user table.
|
2016-06-23 15:06:49 [2] info : Replication: User appuser@% for database no db added to service user table.
|
2016-06-23 15:06:49 warning: Duplicate MySQL user found for service [Replication]: maxscale@% for database: (null)
|
2016-06-23 15:06:49 [2] info : Replication: User repl@% for database no db added to service user table.
|
2016-06-23 15:06:49 [2] info : Replication: User sst@% for database no db added to service user table.
|
2016-06-23 15:06:49 debug : 140013001512704 [dcb_write] Append to writequeue. 121 writes buffered for dcb 0x7f574c000a40 in state DCB_STATE_POLLING fd 4
|
2016-06-23 15:06:49 debug : 140013001512704 [dcb_drain_writeq] Wrote 11 Bytes to dcb 0x7f574c000a40 in state DCB_STATE_POLLING fd 4
|
2016-06-23 15:06:49 debug : 140013001512704 [poll_waitevents] event 5 dcb 0x7f5744000ee0 role DCB_ROLE_REQUEST_HANDLER
|
2016-06-23 15:06:49 debug : 140013001512704 [gw_write_backend_event] wrote to dcb 0x7f5744000ee0 fd 13, return 1
|
2016-06-23 15:06:49 debug : 140013001512704 [poll_waitevents] Read in dcb 0x7f5744000ee0 fd 13
|
2016-06-23 15:06:49 debug : 140013001512704 [gw_read_backend_event] Read dcb 0x7f5744000ee0 fd 13 protocol state 2, MYSQL_CONNECTED.
|
2016-06-23 15:06:49 debug : 140013001512704 [dcb_read] Read 99 bytes from dcb 0x7f5744000ee0 in state DCB_STATE_POLLING fd 13.
|
2016-06-23 15:06:49 debug : 140013001512704 [dcb_write] Append to writequeue. 1 writes buffered for dcb 0x7f5744000ee0 in state DCB_STATE_POLLING fd 13
|
2016-06-23 15:06:49 debug : 140013001512704 [dcb_drain_writeq] Wrote 84 Bytes to dcb 0x7f5744000ee0 in state DCB_STATE_POLLING fd 13
|
2016-06-23 15:06:49 debug : 140013001512704 [gw_receive_backend_auth] Read zero bytes from backend dcb 0x7f5744000ee0 fd 13 in state DCB_STATE_POLLING. n 0, head (nil), len 0
|
2016-06-23 15:06:49 debug : 140013001512704 [gw_read_backend_event] gw_receive_backend_auth read successfully nothing. dcb 0x7f5744000ee0 fd 13, user repl.
|
2016-06-23 15:06:49 debug : 140013001512704 [poll_waitevents] epoll_wait found 1 fds
|
2016-06-23 15:06:49 debug : 140013001512704 [poll_waitevents] event 8197 dcb 0x7f5744000ee0 role DCB_ROLE_REQUEST_HANDLER
|
2016-06-23 15:06:49 debug : 140013001512704 [gw_write_backend_event] wrote to dcb 0x7f5744000ee0 fd 13, return 1
|
2016-06-23 15:06:49 debug : 140013001512704 [poll_waitevents] Read in dcb 0x7f5744000ee0 fd 13
|
2016-06-23 15:06:49 debug : 140013001512704 [gw_read_backend_event] Read dcb 0x7f5744000ee0 fd 13 protocol state 4, MYSQL_AUTH_RECV.
|
2016-06-23 15:06:49 debug : 140013001512704 [dcb_read] Read 110 bytes from dcb 0x7f5744000ee0 in state DCB_STATE_POLLING fd 13.
|
2016-06-23 15:06:49 debug : 140013001512704 [gw_receive_backend_auth] Invalid authentication message from backend dcb 0x7f5744000ee0 fd 13, ptr[4] = 255, error 28000, msg Access denied for user 'repl'@'ip-172-31-47-243.us-west-2.compute.internal' (using password: YES).
|
2016-06-23 15:06:49 error : Invalid authentication message from backend. Error : 28000, Msg : Access denied for user 'repl'@'ip-172-31-47-243.us-west-2.compute.internal' (using password: YES)
|
2016-06-23 15:06:49 debug : 140013001512704 [gw_read_backend_event] after gw_receive_backend_authentication fd 13, state = MYSQL_AUTH_FAILED.
|
2016-06-23 15:06:49 error : Backend server didn't accept authentication for user repl.
|