Did your logging stop working after you set up logrotate? Then this post might be for you.
Archive your log files!
Archive your log files!
Some time ago, Peter Boros wrote about Rotating MySQL Slow Logs safely, explaining the steps of a “best practice” log rotate/archive. This post will add more info about the topic.
When running logrotate for MySQL (after proper setting the /etc/logrotate.d/mysql conf file) from anacron, there’s a situation that you might potentially face if the user and password used to execute the “flush logs” command is stored in, for example, /root/.my.cnf file.
The situation:
You might find out that you have a new MySQL log file ready to receive data, but nothing is being written to it.
Why did this happen?
The logrotate script is executed, but the postrotate fails to successfully flush logs. If this happened to you, you might think, “I’ve lost my slow log file!” The good news: You didn’t lose it. What just happened is that your MySQL log file is no longer visible from the filesystem perspective, but the file still exists and is still receiving data.
So where is it? How can I find it again?
Through the file descriptor. If your mysqld still running, you can find your log under /proc/[pid of mysqld process]/fd path:
1 2 3 4 5 6 | [root@hostname]# cd /proc/$(/sbin/pidof mysqld)/fd [root@hostname fd]# ls -lh | grep deleted lrwx------ 1 root root 64 Oct 21 11:39 131 -> /tmp/MLQKbznR (deleted) lrwx------ 1 root root 64 Oct 21 11:39 26 -> /tmp/ib95UPJ8 (deleted) lrwx------ 1 root root 64 Oct 21 11:39 5 -> /tmp/ib9nYywT (deleted) lrwx------ 1 root root 64 Oct 21 11:39 501 -> /var/log/mysql/log-slow-queries.log.1 (deleted) |
And how big is it? lsof can give us the answer with the file descriptor number, which for this example is 501:
1 2 3 | [root@hostname fd]# /usr/sbin/lsof -p $(/sbin/pidof mysqld) -ad 501 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME mysqld 2813 mysql 501u REG 253,0 976746174 70516762 /var/log/mysql/log-slow-queries.log.1 (deleted) |
The output of lsof tell us that this file size is 976746174 bytes, which is 931MB aprox.
Can I recover the file contents?
Yes, you can. You just need to use the “cat” command and knowing the File Descriptor number. In this case, is 501:
1 | cat /proc/$(/sbin/pidof mysqld)/fd/501 > /path/to/new/logfile.log |
Remember that once you execute a success “flush logs” commands on the MySQL client, the old contents will disappear, so do this prior any further log rotation.
How did this happen?
Let’s examine the logrotate script:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 | /var/log/mysql/log-slow-queries.log { create 600 mysql mysql daily rotate 3 missingok compress sharedscripts postrotate if test -x /usr/bin/mysqladmin && /usr/bin/mysqladmin ping &>/dev/null then /usr/bin/mysql -e 'select @@global.long_query_time into @lqt_save; set global long_query_time=2000; set global slow_query_log = 0; select sleep(2); FLUSH LOGS; select sleep(2); set global long_query_time=@lqt_save; set global slow_query_log = 1;' > /var/log/mysqladmin.flush-logs 2>&1 fi endscript } |
Everything seems okay, except for one thing: When executing from cron, the HOME term environment variable will be blank. Meaning: /usr/bin/mysql won’t be able to find the file with the access credentials (user and password) and thus cannot execute the “flush logs” command.
What is the solution?
Add the HOME variable to the postscript line: env HOME=/root/
1 | env HOME=/root/ /usr/bin/mysql -e 'select @@global.long_query_time into @lqt_save; set global long_query_time=2000; set global slow_query_log = 0; select sleep(2); FLUSH LOGS; select sleep(2); set global long_query_time=@lqt_save; set global slow_query_log = 1;' > /var/log/mysqladmin.flush-logs 2>&1 |
Can I get an alert if this happens to me?
Yes! With the Percona Nagios Plugin pmp-check-mysql-deleted-files. The Percona Nagios Plugin, which like all Percona software is free, looks at the files that the mysqld process has open and warns if any of them are deleted that shouldn’t be. For example: a slow MySQL log file that has being deleted by a poorly written logrotate script. (Download the Percona Nagios Plugin here)
In conclusion: Don’t fall into a situation where you suddenly realize, to your horror, that you’ve lost your slow MySQL log file. And if you do, relax: Recover your MySQL log file contents and add the proper monitoring alert. Problem solved!
Instead of mysql -e ‘………’ (which can also fail if credentials are elsewhere or in some other root or few other things), sending a COM_DEBUG (essentially a mysqladmin debug) with SIGHUP (like in other web servers etc.) should also do. Similar thing is done in init scripts and/or packaging post-installs where requirement of credentials to do non-SQL operations (like logrotate) is not required, and cannot be expected to be present at known locations/
Sending SIGHUP involves more things than just flushing logs, as explained here http://bugs.mysql.com/bug.php?id=65481, so if you just want to flush logs, the ideal thing is to use the CLI with the right credentials.
a simpler solution may just be use copytruncate option in logrotate, I use this in a lot of cases where the apps don’t have built in log rotation. slow query log and mysql logs don’t get appended to all that much in a lot of cases(my logs are still small and go back a year). Sure there is some tiny risk of losing a bit of data during the copytruncate but in the past what 12 years of me using this I’ve never had a complaint that someone lost data in any log file.
not everyone’s db is the same of course but for the past year on my main prod database slow query log is 1.6G and error.log is 22k (all of this data feeds into splunk as well, pretty rare to reference the log files directly).
mysqladmin with the wrong credentials will still return true which is why its normally not required to set HOME for it.
If your ~/.my.cnf contains any setting of non-default location of socket or port then mysqladmin will also need HOME=/root/ set.
So if you’re aware of the problem, why is it that Percona rpms still have this faulty logrotate?
Burn:
Logrotate is not a Percona tool nor it comes with Percona rpms. Logrotate is a tool created by RedHat that comes with several Linux distros.
However, Percona Server does it come with a feature to manage Slow Query Log Rotation and Expiration in case you don’t want to/can’t use Logrotate: https://www.percona.com/doc/percona-server/5.6/flexibility/slowlog_rotation.html
golden post!
for the user/password use mysqladmin –defaults-file=/etc/mysql/debian.cnf for ubuntu 14.04 so no need to set HOME
I had same issue on mysql 5.0 when I executed logrotate through crontab (Worked perfectly on mysql5.5 though) and got my script fixed by passing HOME in cron itself.
But even after executing flush-logs successfully, mysql is not able to write into –err-log file and lsof shows the (deleted) files are still there.
Is there a way I can get rid of these (deleted) error file(there are 2 FD for deleted error file) without stopping mysql.
Thanks