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

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).

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

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.

Neil,

I don't know if this works for your particular situation, but I was having a similar problem and I think I just solved it. In my case, I had two symptoms. The first was the same issue as you -- my log rotation was screwy...in particular, the production.log.1 file was kept open and continued logging to is was happening while production.log was also getting logged to. The second symptom was that the log files ownerships and group memberships would keep changing to root. My Rails app is deployed via Capistrano, using a 'deployer' user, so I'd get all sorts of neat errors whenever the app tried to write to a log file that was no longer owned by deployer.

I'm embarrassed to say how long it took me to realize what the cause of both problems was. Somewhere along the way, I updated cron with the app's crontab as root. This must have been when I messing around at the command prompt...if I had just stayed with my deployment recipe via Capistrano, I wouldn't have inadvertently done that. In any case, I finally looked in /var/spool/cron/crontabs and I found two copies of my crontab file...one for deployer and one for root. So, the processes that cron fired off for my app were getting duplicated -- one was run under deployer and a second under root. It was that second one that was screwing things up. Once I deleted root's crontab, all was better.

Some caveats: on my setup, there were no non-app-related tasks in root's crontab, i.e. it was an exact duplicate of deployer's crontab...so deleting it had no side effects for me. Also, my server is running Ubuntu...the path to your crontabs may be different.

Hope that helps.

• David

I think you forgot the 's' in megabytes or instead use something like this

config.logger = Logger.new(config.log_path, 10, 102400)

also check this link it's very helpful

http://railsillustrated.com/logger-tricks.html