[MXS-3559] Access denied error from backend with MySQL 5.7 Created: 2021-05-20  Updated: 2021-06-16  Resolved: 2021-06-16

Status: Closed
Project: MariaDB MaxScale
Component/s: Authenticator
Affects Version/s: 2.5.11
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Ivan Assignee: markus makela
Resolution: Not a Bug Votes: 0
Labels: None
Environment:

Oracle Linux Server 7.9
Server version: 5.7.32-35-log Percona Server


Sprint: MXS-SPRINT-133

 Description   

Invalid authentication message from backend 'db-master1'. Error code: 1045, Msg : #28000: Access denied for user 'user'@'...' (using password: NO)

mysql> show global variables like '%default_authentication_plugin%';
+-------------------------------+-----------------------+
| Variable_name                 | Value                 |
+-------------------------------+-----------------------+
| default_authentication_plugin | mysql_native_password |
+-------------------------------+-----------------------+

# Global parameters
[maxscale]
threads=auto
admin_host = 0.0.0.0
admin_gui=true
admin_auth=1
admin_secure_gui=false
log_debug=1
 
# Server definitions
[db-master1]
type=server
address=1.1.1.1
port=3306
protocol=MariaDBBackend
rank=primary
 
[db-slave1]
type=server
address=1.1.1.2
port=3306
protocol=MariaDBBackend
rank=secondary
 
[Service-for-cluster_service]
user = maxscale
password = ********
filters = Hint
max_slave_replication_lag=300
disable_sescmd_history=false
prune_sescmd_history=true
lazy_connect= true
type = service
router = readwritesplit
servers = db-master1, db-slave1
master_accept_reads = true
 
[MariaDB-Monitor-for-cluster_service]
type = monitor
module = mariadbmon
user = maxscale
password = ********
monitor_interval = 5000
failover_timeout = 10
auto_failover = false
detect_replication_lag = true
handle_events = false
servers = db-master1, db-slave1
 
[Listener-for-cluster_service]
address = 0.0.0.0
type = listener
service = Service-for-cluster_service
protocol = MariaDBClient
port = 3307
authenticator_options=skip_authentication=true



 Comments   
Comment by markus makela [ 2021-05-20 ]

Have you confirmed that you can access the database with those credentials from both the client server as well as the MaxScale server?

Comment by Ivan [ 2021-05-20 ]

Yes that's right. With these credentials I can connect directly to the mysql server from maxscale host.
I get an error through the maxscale connect.

Comment by Ivan [ 2021-05-21 ]

@markus makela Think I have the same problem https://jira.mariadb.org/browse/MXS-2355.
But I don't understand how to change the authorization plugin

Comment by markus makela [ 2021-05-21 ]

You can fix that by adding default-authentication-plugin=mysql_native_password to the server configuration.

Comment by Ivan [ 2021-05-21 ]

@markus makela Thx, runtime configuration show at all mysql servers.
but this is not in the config file , is it necessary to add this parameter in the configuration file?

mysql> show global variables like '%default_authentication_plugin%';
----------------------------------------------------+

Variable_name Value

----------------------------------------------------+

default_authentication_plugin mysql_native_password

----------------------------------------------------+
1 row in set (0.00 sec)

Comment by markus makela [ 2021-05-21 ]

If it's already set to mysql_native_password then you aren't running into the same problem as in MXS-2355.

Comment by Ivan [ 2021-05-21 ]

Yes, maybe this is another problem . tell me how to solve it?

Comment by markus makela [ 2021-05-21 ]

Without more information it is hard to say what the problem is. If you can create an example that reproduces the problem, we'd be able to verify it in our environment.

Comment by Ivan [ 2021-05-21 ]

ОК, what i have...
System Oracle Linux Server 7.9
Server backend Server version: 5.7.32-35-log Percona Server (GPL), Release 35, Revision 5688520
Mysql default configured with default-authentication-plugin=mysql_native_password
All work normal with Maxscale 2.4.17 with same maxscale config and same mysql backend.

**After upgrade to version Maxscale 2.5.11 , i get error in log **

error  : (2) Invalid authentication message from backend 'db-master1'. Error code: 1045, Msg : #28000: Access denied for user 'user'@'*.*.*.*' (using password: NO)

My maxscale config

[root@lbsql-1 ~]# cat /etc/maxscale.cnf
# Global parameters
[maxscale]
threads=auto
admin_host = 0.0.0.0
 
# Server definitions
[db-master1]
type=server
address=172.16.2.1
port=3306
protocol=MariaDBBackend
 
[db-master2]
type=server
address=172.16.2.2
port=3306
protocol=MariaDBBackend
 
[db-slave1]
type=server
address=172.16.2.3
port=3306
protocol=MariaDBBackend
 
[db-slave2]
type=server
address=172.16.2.4
port=3306
protocol=MariaDBBackend
 
[db-slave3]
type=server
address=172.16.2.5
port=3306
protocol=MariaDBBackend
 
[db-slave4]
type=server
address=172.16.2.6
port=3306
protocol=MariaDBBackend
 
[db-slave5]
type=server
address=172.16.2.7
port=3306
protocol=MariaDBBackend
 
[db-slave6]
type=server
address=172.16.2.8
port=3306
protocol=MariaDBBackend
 
 
[Service-for-cluster_service]
user = maxscale
password = maxscale_passwd
filters = Hint
max_slave_replication_lag=300
disable_sescmd_history=false
prune_sescmd_history=true
lazy_connect= true
type = service
router = readwritesplit
servers = db-master1
master_accept_reads = true
 
[Read-Only-Service]
user = maxscale
password = maxscale_passwd
filters = Hint
max_slave_replication_lag=300
disable_sescmd_history=false
prune_sescmd_history=true
lazy_connect= true
type = service
router = readwritesplit
servers = db-master1, db-master2, db-slave1, db-slave2, db-slave3, db-slave4, db-slave5, db-slave6
master_accept_reads = false
 
 
# Monitor for the servers
[MariaDB-Monitor-for-cluster_service]
type = monitor
module = mariadbmon
user = maxscale
password = maxscale_passwd
monitor_interval = 5000
failover_timeout = 10
auto_failover = false
detect_replication_lag = true
handle_events = false
servers = db-master1, db-master2, db-slave1, db-slave2, db-slave3, db-slave4, db-slave5, db-slave6
 
# Listener definitions for the services
[Listener-for-cluster_service]
address = 0.0.0.0
type = listener
service = Service-for-cluster_service
port = 3307
protocol = MariaDBClient
authenticator_options=skip_authentication=true
 
[Listener-for-Read-Only-Service]
address = 0.0.0.0
type = listener
service = Read-Only-Service
protocol = MariaDBClient
port = 3308
authenticator_options=skip_authentication=true
 
 
[Hint]
type = filter
module = hintfilter

What information i cat present for solve this problem?
Thx!

Comment by markus makela [ 2021-05-21 ]

OK, if it works with 2.4 but not with 2.5 then it sounds like a bug in MaxScale.

  • What sort of a connector or client program are you testing this with?
  • Can you check if the command line client works from both the client and the MaxScale server?
  • Does the problem happen with some specific user or all users? If you can, please test if a newly created user works correctly.
Comment by Ivan [ 2021-05-21 ]

* What sort of a connector or client program are you testing this with?

I'm try to use
[root@lbsql-1 ~]# mysql -V
mysql Ver 15.1 Distrib 5.5.68-MariaDB, for Linux (x86_64) using readline 5.1
and php/php-fpm v.74 , same situation .

Can you check if the command line client works from both the client and the MaxScale server?

Yes, i'm try to connect from others servers and from MaxScale server, same situation .

Does the problem happen with some specific user or all users? If you can, please test if a newly created user works correctly.

Yes, this problem for all users, i'm try 3 different user.

Comment by markus makela [ 2021-05-21 ]

I think this might be caused by some interaction with the Percona 5.7 server. I think we'll have to set up our own environment and investigate this issue more closely.

Have you tried if the MySQL 5.7 server works?

Comment by Ivan [ 2021-05-21 ]

only with Percona server 5.7. (Server version: 5.7.32-35-log Percona Server (GPL), Release 35, Revision 5688520)
i'm can try install Mysql 5.7 from Оracle and try again reproduces the problem, if this necessary

Comment by Ivan [ 2021-06-02 ]

hi Markus! May be you have any UPD?

Comment by markus makela [ 2021-06-02 ]

We haven't taken a look at this yet. Have you tried if MySQL 5.7 behaves the same way?

Comment by Ivan [ 2021-06-02 ]

Yes, i'm try ... same problem

Server version: 5.7.34 MySQL Community Server (GPL)

// Try connect through Maxscale
[root@lbsql-1 ~]# mysql -h172.16.225.40 -P 3309 -ujdoe -p
Enter password:
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.7.34
 
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
MySQL [(none)]> show databases;
ERROR 2006 (HY000): MySQL server has gone away

2021-06-02 17:37:04 error : (2) Invalid authentication message from backend '172.16.225.43'. Error code: 1045, Msg : #28000: Access denied for user 'jdoe'@'172.16.225.40' (using password: NO)

// Try direct connect to mysql backend
[root@lbsql-1 ~]# mysql -h172.16.225.43 -P 3306 -ujdoe -p
Enter password:
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MySQL connection id is 7
Server version: 5.7.34 MySQL Community Server (GPL)
 
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
MySQL [(none)]> show databases;
+--------------------+
| Database           |
+--------------------+
| information_schema |
| mysql              |
| performance_schema |
| sys                |
| test1              |
+--------------------+
5 rows in set (0.00 sec)

Comment by Ivan [ 2021-06-03 ]

Markus,
today i installed mariadb
MariaDB [(none)]> SELECT VERSION ();
-----------------

VERSION ()

-----------------

10.3.29-MariaDB

-----------------
and the problem remained. I do not understand what is wrong, why 2.4 works and 2.5 does not !
How i can debug this problem?
Today i can try with tcpdump.

Comment by markus makela [ 2021-06-03 ]

Hmm, that is curious. Can you give us the output of SHOW CREATE USER for one of the users that has the problem? Please make sure there's no sensitive data in it before you post it.

Comment by Ivan [ 2021-06-03 ]

no sensitive data .

MariaDB [(none)]> SHOW CREATE USER;
+-------------------------------------------------------------------------------------------+
| CREATE USER for jdoe@%                                                                    |
+-------------------------------------------------------------------------------------------+
| CREATE USER `jdoe`@`%` IDENTIFIED BY PASSWORD '*0FE61236E2442B4C345B593A0AFD64D69E77D5A8' |
+-------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

Comment by markus makela [ 2021-06-03 ]

That is quite unexpected as there's nothing special about that. Does Maxscale log any errors or warnings in its log after startup?

Comment by Ivan [ 2021-06-03 ]

log

config
maxscale host = 172.16.225.40

# Global parameters
[maxscale]
threads=auto
admin_host = 0.0.0.0
admin_gui=true
admin_auth=1
admin_secure_gui=false
log_debug=1
log_info=true
 
 
# Server definitions
[172.16.225.43]
type=server
address=172.16.225.43
port=3306
protocol=MySQLBackend
authenticator=MySQLBackendAuth
rank=primary
 
### SERVICE
[us_service]
user = maxscale
password = **********
filters = Hint
max_slave_replication_lag=1s
disable_sescmd_history=false
prune_sescmd_history=true
lazy_connect= true
type = service
router = readwritesplit
servers = 172.16.225.43
master_accept_reads = true
 
# Monitor for the servers
[Monitor-for-cluster_service]
type = monitor
module = mariadbmon
user = maxscale
password = ********
monitor_interval = 5000ms
failover_timeout = 10
auto_failover = false
detect_replication_lag = true
handle_events = false
servers = 172.16.225.43
 
[Listener-for]
address = 0.0.0.0
type = listener
service = us_service
protocol = mariadbclient
port = 3309
authenticator=mariadbauth
authenticator_options=skip_authentication=true
 
[Hint]
type = filter
module = hintfilter

MariaDB MaxScale  /var/log/maxscale/maxscale.log  Thu Jun  3 10:19:12 2021
----------------------------------------------------------------------------
2021-06-03 10:19:12   notice : The collection of SQLite memory allocation statistics turned off.
2021-06-03 10:19:12   notice : Threading mode of SQLite set to Multi-thread.
2021-06-03 10:19:12   notice : The systemd watchdog is Enabled. Internal timeout = 30s
2021-06-03 10:19:12   notice : Worker message queue size: 1MiB
2021-06-03 10:19:12   warning: The 'log_debug' option has no effect in release mode.
2021-06-03 10:19:12   notice : The logging of debug messages has been enabled.
2021-06-03 10:19:12   notice : The logging of informational messages has been enabled.
2021-06-03 10:19:12   notice : Using up to 1.12GiB of memory for query classifier cache
2021-06-03 10:19:12   notice : syslog logging is enabled.
2021-06-03 10:19:12   notice : maxlog logging is enabled.
2021-06-03 10:19:12   notice : Running OS: Linux@5.4.17-2102.201.3.el7uek.x86_64, #2 SMP Fri Apr 23 09:05:55 PDT 2021, x86_64 with 6 processor cores.
2021-06-03 10:19:12   notice : Total usable main memory: 7.47GiB.
2021-06-03 10:19:12   notice : MariaDB MaxScale 2.5.11 started (Commit: 9024df3abfa30ab81785ed25acc578e9d9a028b3)
2021-06-03 10:19:12   notice : MaxScale is running in process 62234
2021-06-03 10:19:12   notice : Configuration file: /etc/maxscale.cnf
2021-06-03 10:19:12   notice : Log directory: /var/log/maxscale
2021-06-03 10:19:12   notice : Data directory: /var/lib/maxscale
2021-06-03 10:19:12   notice : Module directory: /usr/lib64/maxscale
2021-06-03 10:19:12   notice : Service cache: /var/cache/maxscale
2021-06-03 10:19:12   notice : Working directory: /var/log/maxscale
2021-06-03 10:19:12   notice : Loaded module qc_sqlite: V1.0.0 from /usr/lib64/maxscale/libqc_sqlite.so
2021-06-03 10:19:12   info   : qc_sqlite loaded.
2021-06-03 10:19:12   notice : Query classification results are cached and reused. Memory used per thread: 191.14MiB
2021-06-03 10:19:12   notice : Password encryption key file '/var/lib/maxscale/.secrets' not found, using configured passwords as plaintext.
2021-06-03 10:19:12   info   : Epoll instance for listening sockets added to worker epoll instance.
2021-06-03 10:19:12   info   : Epoll instance for listening sockets added to worker epoll instance.
2021-06-03 10:19:12   info   : Epoll instance for listening sockets added to worker epoll instance.
2021-06-03 10:19:12   info   : Epoll instance for listening sockets added to worker epoll instance.
2021-06-03 10:19:12   info   : Epoll instance for listening sockets added to worker epoll instance.
2021-06-03 10:19:12   info   : Epoll instance for listening sockets added to worker epoll instance.
2021-06-03 10:19:12   info   : [qc_sqlite] In-memory sqlite database successfully opened for thread 140361234806528.
2021-06-03 10:19:12   info   : [qc_sqlite] In-memory sqlite database successfully opened for thread 140361226413824.
2021-06-03 10:19:12   info   : [qc_sqlite] In-memory sqlite database successfully opened for thread 140361218021120.
2021-06-03 10:19:12   info   : [qc_sqlite] In-memory sqlite database successfully opened for thread 140361007625984.
2021-06-03 10:19:12   info   : [qc_sqlite] In-memory sqlite database successfully opened for thread 140360999233280.
2021-06-03 10:19:12   info   : [qc_sqlite] In-memory sqlite database successfully opened for thread 140360990840576.
2021-06-03 10:19:12   notice : MaxScale started with 6 worker threads, each with a stack size of 8388608 bytes.
2021-06-03 10:19:12   info   : [qc_sqlite] In-memory sqlite database successfully opened for thread 140361451060992.
2021-06-03 10:19:12   notice : Loading /etc/maxscale.cnf.
2021-06-03 10:19:12   notice : /etc/maxscale.cnf.d does not exist, not reading.
2021-06-03 10:19:12   notice : Loaded module hintfilter: V1.0.0 from /usr/lib64/maxscale/libhintfilter.so
2021-06-03 10:19:12   notice : Loaded module mariadbclient: V1.1.0 from /usr/lib64/maxscale/libmariadbclient.so
2021-06-03 10:19:12   notice : Loaded module mariadbmon: V1.5.0 from /usr/lib64/maxscale/libmariadbmon.so
2021-06-03 10:19:12   warning: Parameter 'detect_replication_lag' for module 'Monitor-for-cluster_service' is deprecated and will be ignored.
2021-06-03 10:19:12   info   : Specifying durations without a suffix denoting the unit is strongly discouraged as it will be deprecated in the future: failover_timeout=10. Use the suffixes 'h' (hour), 'm' (minute), 's' (second) or 'ms' (milliseconds).
2021-06-03 10:19:12   notice : Loaded module readwritesplit: V1.1.0 from /usr/lib64/maxscale/libreadwritesplit.so
2021-06-03 10:19:12   notice : (Listener-for) Loaded module mariadbauth: V2.1.0 from /usr/lib64/maxscale/libmariadbauth.so
2021-06-03 10:19:12   notice : Started REST API on [0.0.0.0]:8989
2021-06-03 10:19:12   info   : Loaded server states from journal file: /var/lib/maxscale/Monitor-for-cluster_service/monitor.dat
2021-06-03 10:19:12   notice : '172.16.225.43' sent version string '10.3.29-MariaDB'. Detected type: 'MariaDB', version: 10.3.29.
2021-06-03 10:19:12   notice : Server '172.16.225.43' charset: latin1
2021-06-03 10:19:12   info   : Server variables loaded from '172.16.225.43', next update in 600 seconds.
2021-06-03 10:19:12   notice : Starting a total of 1 services...
2021-06-03 10:19:12   notice : (Listener-for Listening for connections at [0.0.0.0]:3309
2021-06-03 10:19:12   notice : Service 'us_service' started (1/1)
2021-06-03 10:19:13   notice : Read 6 user@host entries from '172.16.225.43' for service 'us_service'.
2021-06-03 10:20:01   info   : (1) Found matching user 'jdoe'@'%' for client 'jdoe'@'172.16.225.40' with sufficient privileges.
2021-06-03 10:20:01   info   : (1) Started us_service client session [1] for 'jdoe' from 172.16.225.40
2021-06-03 10:20:01   info   : (1) (us_service) > Autocommit: [enabled], trx is [not open], cmd: (0x03) COM_QUERY, plen: 37, type: QUERY_TYPE_READ|QUERY_TYPE_SYSVAR_READ, stmt: select @@version_comment limit 1
2021-06-03 10:20:01   info   : (1) [readwritesplit] (us_service) Replacing old master '<no previous master>' with new master '172.16.225.43'
2021-06-03 10:20:01   info   : (1) [readwritesplit] (us_service) Connected to '172.16.225.43'
2021-06-03 10:20:01   info   : (1) [readwritesplit] (us_service) Route query to master: 172.16.225.43 <
2021-06-03 10:20:01   info   : (1) Connected to '172.16.225.43' with thread id 13
2021-06-03 10:20:01   error  : (1) Invalid authentication message from backend '172.16.225.43'. Error code: 1045, Msg : #28000: Access denied for user 'jdoe'@'172.16.225.40' (using password: NO)
2021-06-03 10:20:01   info   : (1) [readwritesplit] (us_service) Master '172.16.225.43' failed: #HY000: Lost connection to backend server: connection closed by peer (172.16.225.43)
2021-06-03 10:20:01   error  : (1) [readwritesplit] (us_service) Lost connection to the master server, closing session. Lost connection to master server while waiting for a result. Connection has been idle for 0 seconds. Error caused by: #HY000: Lost co$
2021-06-03 10:20:01   info   : Stopped us_service client session [1]
2021-06-03 10:20:06   info   : (2) Found matching user 'jdoe'@'%' for client 'jdoe'@'172.16.225.40' with sufficient privileges.
2021-06-03 10:20:06   info   : (2) Started us_service client session [2] for 'jdoe' from 172.16.225.40
2021-06-03 10:20:06   info   : (2) (us_service) > Autocommit: [enabled], trx is [not open], cmd: (0x03) COM_QUERY, plen: 19, type: QUERY_TYPE_SHOW_DATABASES, stmt: show databases
2021-06-03 10:20:06   info   : (2) [readwritesplit] (us_service) Replacing old master '<no previous master>' with new master '172.16.225.43'
2021-06-03 10:20:06   info   : (2) [readwritesplit] (us_service) Connected to '172.16.225.43'
2021-06-03 10:20:06   info   : (2) [readwritesplit] (us_service) Route query to master: 172.16.225.43 <
2021-06-03 10:20:06   info   : (2) Connected to '172.16.225.43' with thread id 14
2021-06-03 10:20:06   error  : (2) Invalid authentication message from backend '172.16.225.43'. Error code: 1045, Msg : #28000: Access denied for user 'jdoe'@'172.16.225.40' (using password: NO)
2021-06-03 10:20:06   info   : (2) [readwritesplit] (us_service) Master '172.16.225.43' failed: #HY000: Lost connection to backend server: connection closed by peer (172.16.225.43)
2021-06-03 10:20:06   error  : (2) [readwritesplit] (us_service) Lost connection to the master server, closing session. Lost connection to master server while waiting for a result. Connection has been idle for 0 seconds. Error caused by: #HY000: Lost co$
2021-06-03 10:20:06   info   : Stopped us_service client session [2]

I do not understand , why* (using password: NO)*

Comment by markus makela [ 2021-06-03 ]

I didn't spot the authenticator_options=skip_authentication=true parameter, does removing that affect it?

Comment by Ivan [ 2021-06-03 ]

Yes, after removing authenticator_options=skip_authentication=true parameter,

i have next affect
ERROR 1045 (28000): Access denied for user 'jdoe'@'172.16.225.40' (using password: YES)

and log

2021-06-03 12:25:47   info   : (2) Found matching user 'jdoe'@'%' for client 'jdoe'@'172.16.225.40' with sufficient privileges.
2021-06-03 12:25:47   warning: (2) [mariadbclient] Authentication failed for user 'jdoe'@[172.16.225.40] to service 'us_service'. Originating listener: 'Listener-for'. MariaDB error: 'Access denied for user 'jdoe'@'172.16.225.40' (using password: YES)'.

Comment by markus makela [ 2021-06-03 ]

OK, that suggests the password for the user is either not correct or MaxScale somehow does't manage to read it correctly from the database.

Comment by Ivan [ 2021-06-07 ]

Hi Markus!
Yes, after removing authenticator_options=skip_authentication=true parameter, authentication works correctly!
but I don’t understand why this option doesn’t work in version 2.5 .

Comment by markus makela [ 2021-06-07 ]

Do you mean it works correctly in 2.4 or it also works correctly in 2.5 without that parameter?

Comment by Ivan [ 2021-06-07 ]

Authorization is working now, I need to test it. I can not say it is working correctly or not.

Comment by markus makela [ 2021-06-16 ]

I tested this with a MySQL 5.7 docker image and it seems to work. The documentation mentions that skip_authentication does not work with the default authentication mechanism: https://mariadb.com/kb/en/mariadb-maxscale-25-authentication-modules/#skip_authentication

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