In this blog post, we will look at how to do MongoDB® log rotation in the right—and simplest—way.

Log writing is important for any application to track history. But when the log file size grows larger, it can cause disk space issues. For database servers especially, it may cause performance issues as the database needs to write to a large file continuously. By scheduling regular log rotation, we can avoid such situations proactively and keep the log file size below a predetermined threshold.

MongoDB Log File

In MongoDB, the log is not rotated automatically so we need to rotate it manually. Usually, the log size of the MongoDB server depends on the level of information configured and the slow log configured. By default, commands taking more than 100ms, or whatever the value set for the slowOpThresholdMs parameter, are written into the MongoDB log file. Let’s see how to automate log rotation on Linux based servers.

Rotate MongoDB Log Methods

The following two methods could be used to rotate the log in MongoDB. The first uses the command shown below from within mongo shell:

> use admin
> db.adminCommand( { logRotate : 1 } )

The alternative is to use SIGUSR1 signal to rotate the logs for a single process in Linux/Unix-based systems:

# kill -SIGUSR1 ${pidof mongod)

The behaviour of log rotation in MongoDB differs according to the value of the parameter logRotate which was introduced in version 3.0 (note that this should not be confused with the logRotate command that we’ve seen above). The two values are:

• rename – renames the log file and creates a new file specified by the logpath parameter to write further logs
• reopen – closes and reopens the log file following the typical Linux/Unix log rotation behavior. You also need to enable logAppend if you choose reopen. You should use reopen when using the Linux/Unix log rotate utility to avoid log loss.

In versions 2.6 and earlier, the default behavior when issuing the logRotate command is the same as when using rename, i.e. it renames the original log file from mongod.log to mongod.log.xxxx-xx-xxTxx-xx-xx format where x is filled with the rotation date time, and creates a new log file mongod.log to continue to write logs. You can see an example of this below:

mongodb-osx-x86_64-3.2.19/bin/mongod --fork \
  --dbpath=/usr/local/opt/mongo/data6 \
  --logpath=/usr/local/opt/mongo/data6/mongod.log \
  --logappend --logRotate rename
about to fork child process, waiting until server is ready for connections.
forked process: 59324
child process started successfully, parent exiting
ls -ltrh data6/mongod.log*
-rw-r--r-- 1 vinodhkrish admin 4.9K Sep 14 16:57 mongod.log
mongo
MongoDB shell version: 3.2.19
connecting to: test
>
> db.adminCommand( { logRotate : 1 } )
{ "ok" : 1 }
> exit
bye
ls -ltrh data6/mongod.log*
-rw-r--r-- 1 vinodhkrish admin 4.9K Sep 14 16:57 mongod.log.2018-09-14T11-29-54
-rw-r--r-- 1 vinodhkrish admin 1.0K Sep 14 16:59 mongod.log

Using the above method, we need to compress and move the rotated log file manually. You can of course write a script to automate this. But when using the logrotate=reopen option, the mongod.log is just closed and opened again. In this case, you need to use the command alongside with Linux’s logrotate utility to avoid the loss of log writing in the course of the log rotation operation. We will see more about this in the next section.

Automating MongoDB logRotate using the logrotate utility

I wasn’t a fan of this second method for long time! But MongoDB log rotation seems to work well when using Linux/Unix’s logrotate tool. Now I prefer this approach, since it doesn’t need the complex script writing that’s needed for the first log rotation method described above. Let’s see in detail how to configure log rotation with Linux/Unix’s logrotate utility.

MongoDB 3.x versions

Start MongoDB with the following options:

systemLog:
  destination: file
  logAppend: true
  path: /var/log/mongodb/mongod.log
  logRotate: reopen
processManagement:
  pidFilePath: /var/run/mongodb/mongod.pid

As mentioned in the section about Linux’s logrotation utility, you need to create a separate config file /etc/logrotate.d/mongod.conf for MongoDB’s log file rotation. Add the content shown below into that config file:

/var/log/mongodb/mongod.log {
  daily
  size 100M
  rotate 10
  missingok
  compress
  delaycompress
  notifempty
  create 640 mongod mongod
  sharedscripts
  postrotate
    /bin/kill -SIGUSR1 `cat /var/run/mongodb/mongod.pid 2>/dev/null` >/dev/null 2>&1
  endscript
}

In this config file, we assume that log path is set as /var/log/mongodb/mongod.log in /etc/mongod.conf file, and instruct Linux’s logrotation  utility to do the following:

• Check the size, and start rotation if the log file is greater than 100M
• Move the mongod.log file to mongod.log.1
• Create a new mongod.log file with mongod permissions
• Compress the files from mongod.log.2 but retain up to mongod.log.10 as per delaycompress and rotate 10
• MongoDB continues to write to the old file mongod.log.1 (based on Linux’s inode) – remember that now there is no mongod.log file
• In postrotate, it sends the kill -SIGUSR1 signal to mongod mentioned with the pid file, and thus mongod creates the mongod.log and starts writing to it. So make sure you have the pid file path set to the same as pidFilepath from the /etc/mongod.conf file

Please test the logrotate manually using the created /etc/logrotate.d/mongod.conf file to make sure it is working as expected. Here’s how:

cd /var/log/mongodb/
ls -ltrh
total 4.0K
-rw-r-----. 1 mongod mongod 1.3K Sep 14 12:45 mongod.log
logrotate -f /etc/logrotate.d/mongod
ls -ltrh
total 8.0K
-rw-r-----. 1 mongod mongod 1.4K Sep 14 12:58 mongod.log.1
-rw-r-----. 1 mongod mongod 1.3K Sep 14 12:58 mongod.log
logrotate -f /etc/logrotate.d/mongod
ls -ltrh
total 12K
-rw-r-----. 1 mongod mongod 491 Sep 14 12:58 mongod.log.2.gz
-rw-r-----. 1 mongod mongod 1.4K Sep 14 12:58 mongod.log.1
-rw-r-----. 1 mongod mongod 1.3K Sep 14 12:58 mongod.log

 

Adaptations for MongoDB 2.x and earlier, or when using logRotate=rename

Since the introduction of logRotate parameter in MongoDB 3.0, the log rotate script needs an extra step when you are using logRotate=rename or when using <=2.x versions.

Start the MongoDB with the following options (for 2.4 and earlier, ) :

logAppend=true
logpath=/var/log/mongodb/mongod.log
pidfilePath=/var/run/mongodb/mongod.pid

Start MongoDB with the following options YAML format (YAML config introduced from version 2.6) :

systemLog:
  destination: file
  logAppend: true
  path: /var/log/mongodb/mongod.log
processManagement:
  pidFilePath: /var/run/mongodb/mongod.pid

The config file /etc/logrotate.d/mongod.conf for MongoDB’s log file rotation should be set up like this:

/var/log/mongodb/mongod.log {
  daily
  size 100M
  rotate 10
  missingok
  compress
  delaycompress
  notifempty
  create 640 mongod mongod
  sharedscripts
  postrotate
    /bin/kill -SIGUSR1 `cat /var/run/mongodb/mongod.pid 2>/dev/null` >/dev/null 2>&1
    find /var/log/mongodb -type f -size 0 -regextype posix-awk \
-regex "^\/var\/log\/mongodb\/mongod\.log\.[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}-[0-9]{2}-[0-9]{2}$" \
-execdir rm {} \; >/dev/null 2>&1
  endscript
}

In this case, the logrotate utility behaves as follows:

• Check for the size, and start rotation if the log file size exceeds 100M
• Move mongod.log file to mongod.log.1
• Create a new mongod.log file with mongod permissions
• MongoDB continues to write to the old file, mongod.log.1
• In postrotate, when the SIGUSR1 signal is sent, mongod rotates the log file. This includes renaming the new mongod.log file (0 bytes) created by logrotate to mongod.log.xxxx-xx-xxTxx-xx-xx format and creating a new mongod.log file to which, now, mongod starts writing the logs.
• the Linux command

  find

    identifies mongod.log.xxxx-xx-xxTxx-xx-xx file formats that are sized at 0 bytes, and these are removed

If you enjoyed this blog…

You might also benefit from this recorded webinar led by my colleague Tim Vaillancourt MongoDB Backup and Recovery Field Guide or perhaps the Percona Solution Brief Security for MongoDB.

References:

https://jira.mongodb.org/browse/SERVER-11087
https://jira.mongodb.org/browse/SERVER-14053
https://jira.mongodb.org/browse/SERVER-16821
https://docs.mongodb.com/v2.6/reference/configuration-options/
https://docs.mongodb.com/v2.4/reference/configuration-options/
https://docs.mongodb.com/manual/reference/configuration-options/

The post Automating MongoDB Log Rotation appeared first on Percona Database Performance Blog.

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

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.

This blog post is part two of two. Like part one, published Wednesday, this is a cross-post from Groupon’s engineering blog. Thanks again to Kyle Oppenheim at Groupon. And one more reminder that I’ll be at the Percona Live MySQL Conference and Expo next week in Santa Clara, California so look for me there. You can checkout the sessions I’ll be leading here.

In my last post, I described a solution for keeping the caches of a MySQL standby server hot using MySQL slow logs with long_query_time set to 0. Here are a some lessons we learned when logging a high volume of queries to the slow log.

Do not use copytruncate

Logrotate offers two techniques for log rotation (your log rotation scheme likely offers similar options with a different name):

1. copytruncate – Copies the file to a new name, and then truncates the original file.
2. no copytruncate – Uses the rename() system call to move the file to a new name, and then expects the daemon to be signaled to reopen its log file.

MySQL has a mutex for slow log writes. Truncation can block MySQL because the OS serializes access to the inode during the truncate operation. This problem is particularly evident when using the ext3 file system (instead of xfs).

Use FLUSH LOGS instead of sending SIGHUP

When copytruncate is disabled, MySQL must be told to reopen the slow log file. There are two options for signaling:

1. Send a HUP signal to the mysqld process.
2. Use the mysql console or mysqladmin utility to FLUSH LOGS;

These options should be equivalent, but MySQL bug 65481 explains that the HUP signal also flushes tables in addition to logs. Flushing tables can impact running queries.

Disable MySQL slow logs during rotation

Flushing logs takes time. Meanwhile, queries are still being executed. To prevent MySQL from filling the slow log buffer, we disable the MySQL slow logs temporarily during log rotation.

Putting it all together

Here is a logrotate configuration file for a slow log that illustrates these best practices:

/var/mysql/slow_query.log {
    nocompress
    create 660 mysql mysql
    size 1G
    dateext
    missingok
    notifempty
    sharedscripts
    postrotate
       /usr/local/bin/mysql -e 'select @@global.long_query_time into @lqt_save; set global long_query_time=2000; select sleep(2); FLUSH LOGS; select sleep(2); set global long_query_time=@lqt_save;'
    endscript
    rotate 150

The post Rotating MySQL slow logs safely appeared first on MySQL Performance Blog.