Rails log shifting is keeping old log open and filling it up

Question

I help to maintain a Rails website. It's running JRuby 1.5.5, Rails 2.3.10, on a Solaris Sparc machine. I have a problem related to logging.

To stop our logfiles growing too large and filling the disk, we're using the log-shifting that's built in to the Logger class. In config/environments/production.rb we have:

config.logger = Logger.new(config.log_path, 10, 100.megabyte)

Which should rotate the logfiles when they reach 100 megabytes, and only keep 10 files.

The problem is two-fold: Rails is not rotating the logs properly, and it is keeping open the old log file to write to it -- but what it is writing is just repeated content of a few requests. So if I do ls -l log I see something like this:

-rw-r--r-- 83040892 Oct  4 15:07 production.log
-rw-r--r-- 3303158664 Oct  4 15:07 production.log.0
-rw-r--r-- 104857616 Oct  2 23:13 production.log.1
-rw-r--r-- 104857618 Oct  1 17:12 production.log.2

Note how the most recently cycled log is still open and still being written to (running pfiles confirms that it the Rails server still has three file handles to the log). Note also that it has reached 3 gigabytes in two days, where usually we do 100MB a day. This is because it is full of repeated requests. I can't easily paste it in here, but the log is full of the same 1000 line chunk of requests from 18:50 on Oct 3 (which I believe is the point at which the logs rotated), printed over and over again. From past experience, the log file will keep filling with this repeated content until the disk fills up.

Is log shifting/Rails logging just plain broken? (There's nothing odd about our logfile usage: we don't do any direct logging, it all just comes from the Rails framework.) The obvious next step is to try something like logrotate, but if Rails is refusing to close old log files and is writing junk to them forever, I suspect it won't solve my problem (because the log will never be closed, and thus the disk space never recovered).

Answer 1

The symptom seems to be that one old logfile still keeps getting used, although you successfully rotated the logs.

The cause is most likely that one or more of your Rails instances or threads is still using the old file handle.

The solution is to make sure that all the Rails instances restart completely after logs are rotated, so they all use the new file handle / name.

Use logrotate instead of config.logger to rotate your logs!

I'd suggest to use the UNIX logrotate to rotate your logs, instead of config.logger. IMHO that's a better solution, more reliable, you have more control over the log rotation, and you can provide some post-rotation commands to restart your Rails processes. (either via logrotate's postrotate or endscript option)

See:

http://www.opencsw.org/packages/logrotate/ (logrotate Package for Solaris)

http://www.thegeekstuff.com/2010/07/logrotate-examples/ (logrotate tutorial with examples)

http://linux.die.net/man/8/logrotate

Can you use Unicorn? - Unicorn is has built-in support for re-opening all log files in your application via USR1 signal - this allows logrotate to rotate files atomically... - Unicorn keeps track of and restarts it's workers! You can kill the workers after log rotation and Unicorn will restart them, making sure they use the new log file.

See: https://github.com/blog/517-unicorn (many advantages for Unicorn over Mongrel)

If you're using Mongrel and can't switch to Unicorn:

use logrotate, and restart your Mongrels via the postrotate option.

hope this helps..

Answer 2

I've always used the platform's log rotation mechanism when dealing with the Rails log files. Following the advice from http://www.nullislove.com/2007/09/10/rotating-rails-log-files/ and because I run Passenger from http://overstimulate.com/articles/logrotate-rails-passenger as well.

The first method uses the logrotate copytruncate method of creating the new log file, so processes that still have a handle to it will always write to the current log file.

Other things to check on the server are:

• Make sure that none of the gems or plugins have a handle to the Logger inside the ruby context.
• Since you're using JRuby ensure that there isn't a stuck/runaway thread somewhere that's trying to fulfill a request but getting stuck logging.
• Just like with Passenger, consider restarting the Rails server processes every now and again. I know this is effectively a hack but it might work.