[MDEV-19276] If login fails when selecting a database, no warning is printed to the log with log_warnings=2 Created: 2019-04-17  Updated: 2020-08-25  Resolved: 2019-04-28

Status: Closed
Project: MariaDB Server
Component/s: Authentication and Privilege System
Affects Version/s: 10.1.38, 10.2.23, 10.3.14
Fix Version/s: 10.2.24, 10.1.39, 10.3.15, 10.4.5

Type: Bug Priority: Major
Reporter: Geoff Montee (Inactive) Assignee: Vladislav Vaintroub
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-19277 Add status variable that gets increme... Closed
relates to MDEV-19282 Log more specific warning with log_wa... Closed

 Description   

When log_warnings is set to 2 or greater, most login failures are logged to the error log.

One exception currently seems to be the case where, if a database is selected during the login and if the user can't actually select that database, then their login will fail, but no warning will be printed to the log.

To reproduce, simply create a user account with no privileges:

CREATE USER 'bob'@'localhost' IDENTIFIED BY 'password';

And ensure that log_warnings is set to 2 or above:

SET GLOBAL log_warnings=2;

Then try to login as this user while selecting a database that they can't use:

$ mysql -u bob -ppassword db1
ERROR 1044 (42000): Access denied for user 'bob'@'localhost' to database 'db1'

No warning will be printed to the log.

The root cause seems to be that if this section of code encounters an error:

https://github.com/MariaDB/server/blob/mariadb-10.1.38/sql/sql_acl.cc#L12687

Then it does not call the login_failed_error function:

https://github.com/MariaDB/server/blob/mariadb-10.1.38/sql/sql_acl.cc#L11272

This case actually has its own error code:

  • Error code, 1044, error ID: ER_DBACCESS_DENIED_ERROR, error message: Access denied for user '%s'@'%s' to database '%s'

https://mariadb.com/kb/en/library/mariadb-error-codes/

We might need to update the login_failed_error and access_denied_error_code functions to support this error code as well.

https://github.com/MariaDB/server/blob/mariadb-10.1.38/sql/sql_acl.h#L190

The only way to currently see a warning in the error log in this case is to set log_warnings=4. At that point, you'll see a warning like this:

2019-04-18 18:25:03 140535201905408 [Warning] Aborted connection 334 to db: 'unconnected' user: 'bob' host: 'localhost' (CLOSE_CONNECTION)

But I think it should actually log a warning like this when log_warnings=2 is set instead:

2019-04-18 18:25:03 140535201905408 [Warning] Access denied for user 'bob'@'localhost' to database 'db1' (using password: YES)



 Comments   
Comment by Vladislav Vaintroub [ 2019-04-24 ]

There can be several reasons why selecting database may fail (non-existing database name for example). I think only ER_DBACCESS_DENIED_ERROR would fit into "access denied" category, and thus should be handled as other access-denieds

Comment by Geoff Montee (Inactive) [ 2019-04-24 ]

Good point. Currently, MariaDB does raise ER_DBACCESS_DENIED_ERROR if the named database doesn't exist. Would you consider that a bug too? For example:

[ec2-user@ip-172-30-0-198 ~]$ sudo mysql -u root --execute="SHOW DATABASES"
+--------------------+
| Database           |
+--------------------+
| db1                |
| information_schema |
| mysql              |
| performance_schema |
| test               |
+--------------------+
[ec2-user@ip-172-30-0-198 ~]$ mysql -u bob -ppassword --execute="SHOW GRANTS"
+------------------------------------------------------------------------------------------------------------+
| Grants for bob@localhost                                                                                   |
+------------------------------------------------------------------------------------------------------------+
| GRANT USAGE ON *.* TO 'bob'@'localhost' IDENTIFIED BY PASSWORD '*2470C0C06DEE42FD1618BB99005ADCA2EC9D1E19' |
| GRANT PROXY ON 'dba'@'localhost' TO 'bob'@'localhost'                                                      |
| GRANT PROXY ON 'app1_dba'@'localhost' TO 'bob'@'localhost'                                                 |
+------------------------------------------------------------------------------------------------------------+
[ec2-user@ip-172-30-0-198 ~]$ mysql -u bob -ppassword doesnotexist
ERROR 1044 (42000): Access denied for user 'bob'@'localhost' to database 'doesnotexist'
[ec2-user@ip-172-30-0-198 ~]$ mysql -u bob -ppassword db1
ERROR 1044 (42000): Access denied for user 'bob'@'localhost' to database 'db1'

Comment by Vladislav Vaintroub [ 2019-04-24 ]

I only read code, I did not try it According to code, ER_WRONG_DB_NAME, ER_BAD_DB_ERROR may also be thrown, as well as some kind of "out of memory" inside my_strndup() in mysql_change_db() in sql_db.cc
I think ER_BAD_DB_ERROR would show up, if permissions are ok, but database directory does not exist, which is quite likely rare occasion.

Generated at Thu Feb 08 08:50:23 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.