[MXS-781] binlog router does not give proper error when authentication with master fails Created: 2016-06-23  Updated: 2017-12-01  Resolved: 2016-07-06

Status: Closed
Project: MariaDB MaxScale
Component/s: binlogrouter
Affects Version/s: 1.4.3
Fix Version/s: 2.1.0

Type: New Feature Priority: Minor
Reporter: Geoff Montee (Inactive) Assignee: Massimiliano Pinto (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Sprint: 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.



 Comments   
Comment by Massimiliano Pinto (Inactive) [ 2016-07-01 ]

The error message reports the Authentication failure.
The authentication failure message is not reported via SHOW SLAVE STATUS

Currently SHOW SLAVE STATUS can only report errors that could happen after authentication.

Comment by Massimiliano Pinto (Inactive) [ 2016-07-06 ]

Now binlog server handles the Auth failure in errorReply and proper message will be available via SHOW SLAVE STATUS

When there is failed authentication (i.e: wrong password):

Slave_IO_Running: No
Slave_SQL_Running: No
....
Last_Errno: 1045
Last_Error: #28000 Authentication with master server failed

... Slave_SQL_Running_State: Slave stopped

Replication status is STOPPED: it doesn't make sense to continue in this well known case.

User action: check logs, fix user/password values and issue START SLAVE to start replication from the master

Comment by Massimiliano Pinto (Inactive) [ 2016-07-06 ]

Committed to develop branch

Generated at Thu Feb 08 04:01:53 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.