[MDEV-6767] mysqladmin returns success and doesnt output an error message when a logs flushing query fails Created: 2014-09-23  Updated: 2022-09-08

Status: Open
Project: MariaDB Server
Component/s: None
Affects Version/s: 5.5.39, 10.0.13
Fix Version/s: 5.5

Type: Bug Priority: Minor
Reporter: Jean Weisbuch Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: logging, mysqladmin, upstream
Environment:

Debian Wheezy amd64


 Description   

The logs flushing commands of mysqladmin are issuing queries on the server such as "FLUSH LOGS;" but only display an error message on STDOUT/STDERR and return an error code if the query cannot be issued, not if the query itself returns an error.

The problem could also be present for other commands of mysqladmin.

–
Trying to run "FLUSH SLOW LOGS;" from the CLI returns an error telling that the file is not found :

# mysql -e 'SET GLOBAL slow_query_log_file = "/var/log/mysql/mariadb-slow.log";'
 
# lsof -n |grep -m1 mariadb-slow\.log
 
mysqld    26457            mysql  534w      REG              254,0       2467    8636193 /var/log/mysql/mariadb-slow.log
 
# chmod 000 /var/log/mysql/mariadb-slow.log
 
# mysql -e 'FLUSH SLOW LOGS;'
 
ERROR 29 (HY000) at line 1: File '/var/log/mysql/mariadb-slow.log' not found (Errcode: 13)
 
# echo $?
 
1
 
# tail /var/log/syslog |tac |grep -m1 mariadb-slow\.log
 
Sep 22 22:24:54 hostname mysqld: 140422 22:24:54 [ERROR] Could not use /var/log/mysql/mariadb-slow.log for logging (error 13). Turning logging off for the whole duration of the MySQL server process. To turn it on again: fix the cause, shutdown the MySQL server and restart it.

Running "mysqladmin flush-slow-log" doesnt return an error code and no error message on STDOUT or STDERR, the only way to know that something went wrong is to check what mysqld logged :

# chmod 600 /var/log/mysql/mariadb-slow.log
 
# mysql -e 'SET GLOBAL slow_query_log_file = "/var/log/mysql/mariadb-slow.log";'
 
# lsof -n |grep -m1 mariadb-slow\.log
 
mysqld    26457            mysql  534w      REG              254,0        205    8636193 /var/log/mysql/mariadb-slow.log
 
# chmod 000 /var/log/mysql/mariadb-slow.log
 
# mysqladmin flush-slow-log
 
# echo $?
 
0
 
# tail /var/log/syslog |tac |grep -m1 mariadb-slow\.log
 
Sep 22 22:40:32 hostname mysqld: 140422 22:40:32 [ERROR] Could not use /var/log/mysql/mariadb-slow.log for logging (error 13). Turning logging off for the whole duration of the MySQL server process. To turn it on again: fix the cause, shutdown the MySQL server and restart it.

Expected result :
When mysqladmin has an error returned on one of the query it executed, print the error message on STDERR and issue a return code <> 0 so the user or script that ran mysqladmin can be aware that something didnt work as expected without having to manually check the error_log.

nb: the error log is set to syslog on the example server.

 Comments   
Comment by Elena Stepanova [ 2014-09-23 ]

It prints the error just fine to me: 

elenst@wheezy-64:~/bzr/10.0.13$ client/mysqladmin -uroot --protocol=tcp --port=3306 flush-slow-log 
client/mysqladmin: flush failed; error: 'File './slow.log' not found (Errcode: 13 "Permission denied")'
 
elenst@wheezy-64:~/bzr/10.0.13$ echo $?
 
255

Did you run a "clean" test – that is, after trying FLUSH SLOW LOGS via the client, did you made the log file writable, enabled slow_query_log again, and only then tried mysqladmin?
if you didn't, the test is irrelevant – as the error message you quoted says, after you attempted to flush logs for the first time, slow query log was turned off, so subsequent attempts to flush it, be it via the client or mysqladmin, won't fail.

Comment by Jean Weisbuch [ 2014-09-23 ]

You are right, i must have forgot to re-set slow_query_log_file or slow_query_log at the right time.

Anyway, the value of slow_query_log should be set to 0 when the server is disabling it as it looks like the logging is active when it is not and make the FLUSH LOGS check again if it could open the file because the query will return success while it wont start to log again even if it could :

# lsof -n |grep -m1 mariadb-slow
 
mysqld    26457            mysql   36w      REG              254,0     4312    8636193 /var/log/mysql/mariadb-slow.log
 
# chmod 000 /var/log/mysql/mariadb-slow.log
 
# mysqladmin flush-slow-log
 
mysqladmin: flush failed; error: 'File '/var/log/mysql/mariadb-slow.log' not found (Errcode: 13)'
 
# chmod 600 /var/log/mysql/mariadb-slow.log
 
# mysqladmin flush-slow-log
 
# mysql
 
[...]
 
MariaDB [(none)]> SHOW GLOBAL VARIABLES LIKE '%slow_qu%';
 
+---------------------+---------------------------------+
 
| Variable_name       | Value                           |
 
+---------------------+---------------------------------+
 
| log_slow_queries    | ON                              |
 
| slow_query_log      | ON                              |
 
| slow_query_log_file | /var/log/mysql/mariadb-slow.log |
 
+---------------------+---------------------------------+
 
3 rows in set (0.01 sec)
 
 
 
MariaDB [(none)]> FLUSH SLOW LOGS;
 
Query OK, 0 rows affected (0.00 sec)
 
 
 
MariaDB [(none)]> \q
 
Bye
 
# lsof -n |grep mariadb-slow
 
#

Comment by Elena Stepanova [ 2014-09-23 ]

I agree the whole thing is rather confusing. On top of slow_query_log=1 when it's in fact disabled, the error message that the server prints into the log is not true. It says:

Could not use slow.log for logging (error 13). Turning logging off for the whole duration of the MySQL server process. To turn it on again: fix the cause, shutdown the MySQL server and restart it.

But it is not so. If we fix the problem with the log, in this case permissions, and run SET GLOBAL slow_query_log=1 (yes, even though it is already 1), the slow logging gets enabled again.

It's an upstream issue, do you want to report it at bugs.mysql.com?

Comment by Jean Weisbuch [ 2014-09-30 ]

I created the bug report on the MySQL tracker : http://bugs.mysql.com/bug.php?id=74145

Generated at Thu Feb 08 07:14:25 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.