Nov
12
2014
--

Log rotate and the (deleted) MySQL log file mystery

Did your logging stop working after you set up logrotate? Then this post might be for you.

Archive

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:

[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:

[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:

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:

/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/

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!

The post Log rotate and the (deleted) MySQL log file mystery appeared first on MySQL Performance Blog.

Powered by WordPress | Theme: Aeros 2.0 by TheBuckmaker.com