MySQL Bugs: #74145: FLUSH LOGS improperly disables the logging if the log file cannot be accessed

Bug #74145	FLUSH LOGS improperly disables the logging if the log file cannot be accessed
Submitted:	29 Sep 2014 22:05	Modified:	30 Sep 2014 12:00
Reporter:	Jean Weisbuch	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	5.5.39, 5.5.41	OS:	Linux
Assigned to:		CPU Architecture:	Any
Tags:	flush, logging

Description:
The value of slow_query_log/general_log should be set to 0 when the server is disabling the logging after a FLUSH LOGS if the file cannot be accessed at the FLUSH execution.
The server ends-up running with the logging disabled while its configuration variable shows that it is enabled.

How to repeat:
Reproduction of the problematic behavior with the slow query log (the same happens with the general log) :

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

mysql> FLUSH SLOW LOGS;
Query OK, 0 rows affected (0.00 sec)

MariaDB [(none)]> \q
Bye
# lsof -n |grep mysql-slow
#
# tail /var/log/mysql/error.log |tac |grep -m1 mysql-slow\.log
Sep 29 23:42:12 hostname mysqld: 140422 23:42:12 [ERROR] Could not use /var/log/mysql/mysql-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.

Suggested fix:
The slow_query_log (or general_log) is set to 0 when the FLUSH fails and disable the logging.

ps: the error on the error log states that the server should be restarted to enable back the logging which is untrue as setting back the log file variable suffice to do so.

Hello Jean Weisbuch,

Thank you for the report and steps.
Verified as described.

Thanks,
Umesh

//

[ushastry@cluster-repo mysql-5.5.41]$ uname -an
Linux cluster-repo 2.6.32-100.28.5.el6.x86_64 #1 SMP Wed Feb 2 18:40:23 EST 2011 x86_64 x86_64 x86_64 GNU/Linux

mysql> show variables like '%version%';
+-------------------------+------------------------------+
| Variable_name           | Value                        |
+-------------------------+------------------------------+
| innodb_version          | 5.5.41                       |
| protocol_version        | 10                           |
| slave_type_conversions  |                              |
| version                 | 5.5.41-log                   |
| version_comment         | MySQL Community Server (GPL) |
| version_compile_machine | x86_64                       |
| version_compile_os      | Linux                        |
+-------------------------+------------------------------+
7 rows in set (0.00 sec)

//

[ushastry@cluster-repo mysql-5.5.41]$ lsof -n |grep -m1 mysql-slow
mysqld    12408  ushastry   11w      REG               8,17      666   938799 /data/ushastry/server/mysql-5.5.41/data/mysql-slow.log

// 

[ushastry@cluster-repo mysql-5.5.41]$ chmod 000 /data/ushastry/server/mysql-5.5.41/data/mysql-slow.log

//
[ushastry@cluster-repo mysql-5.5.41]$ mysqladmin flush-logs -S ./mysql.sock
mysqladmin: refresh failed; error: 'File './mysql-slow.log' not found (Errcode: 13)'

// Snippet from error log

141002  8:20:28 [Note] /data/ushastry/server/mysql-5.5.41/bin/mysqld: ready for connections.
Version: '5.5.41-log'  socket: '/data/ushastry/server/mysql-5.5.41/mysql.sock'  port: 3306  MySQL Community Server (GPL)
141002  8:21:57 [ERROR] Could not use mysql-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.

// chmod 600
[ushastry@cluster-repo mysql-5.5.41]$ chmod 600 /data/ushastry/server/mysql-5.5.41/data/mysql-slow.log

// flush-logs
[ushastry@cluster-repo mysql-5.5.41]$ mysqladmin flush-logs -S ./mysql.sock

//

//
[ushastry@cluster-repo mysql-5.5.41]$ bin/mysql -uroot -p -S ./mysql.sock
Enter password:
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.5.41-log MySQL Community Server (GPL)

Copyright (c) 2000, 2014, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> SHOW GLOBAL VARIABLES LIKE '%slow_qu%';
+---------------------+----------------+
| Variable_name       | Value          |
+---------------------+----------------+
| log_slow_queries    | ON             |
| slow_query_log      | ON             |
| slow_query_log_file | mysql-slow.log |
+---------------------+----------------+
3 rows in set (0.00 sec)

// change permission, and flush logs

[ushastry@cluster-repo mysql-5.5.41]$ chmod 000 /data/ushastry/server/mysql-5.5.41/data/mysql-slow.log
[ushastry@cluster-repo mysql-5.5.41]$
[ushastry@cluster-repo mysql-5.5.41]$ bin/mysqladmin -uroot -p -S ./mysql.sock flush-logs
Enter password:
bin/mysqladmin: refresh failed; error: 'File './mysql-slow.log' not found (Errcode: 13)'
[ushastry@cluster-repo mysql-5.5.41]$

// Error log

Version: '5.5.41-log'  socket: '/data/ushastry/server/mysql-5.5.41/mysql.sock'  port: 3306  MySQL Community Server (GPL)
141002  8:42:44 [ERROR] Could not use mysql-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.

// Try to confirm if logging is disabled

mysql> SHOW GLOBAL VARIABLES LIKE '%slow_qu%';
+---------------------+----------------+
| Variable_name       | Value          |
+---------------------+----------------+
| log_slow_queries    | ON             |
| slow_query_log      | ON             |
| slow_query_log_file | mysql-slow.log |
+---------------------+----------------+
3 rows in set (0.00 sec)

So, I see two issues here - confusing error message "shutdown the MySQL server and restart it", just resetting the permission resolved the issue, secondly - error message says "turning off logging" even though variable confirms it is still enabled.