JRuby on Rails log rotation failure

Question

We have a JRuby on Rails 2 application deployed on Tomcat, using the default Rails logger. Some time after we crossed the DST boundary, we found the application was dead with the following error messages in the logs:

org.jruby.rack.RackInitializationException: Shifting failed. '/tc_instance/applogs/search.log.20111106' already exists.

Normally the logs are rotated at midnight. The previous day's logs always have a final timestamp of 23:59, except the Nov 6 log, which had a timestamp of 22:59.

-rw-rw-rw-  300683179 Nov  3 23:59 search.log.20111103
-rw-rw-rw-  226082012 Nov  4 23:59 search.log.20111104
-rw-rw-rw-  79789353 Nov  5 23:59 search.log.20111105
-rw-rw-rw-  109080879 Nov  6 22:59 search.log.20111106

So what happened was the logs attempted to roll over at 11pm instead of midnight. Then when it tried to create the new day's logs it was using the same date.

It would appear there is either a problem with our configuration or a bug in the log rotation timing logic.

Here is the relevant section of the environment.rb:

  # Set Time.zone default to the specified zone and make Active Record auto-convert to this zone.
  # Run "rake -D time" for a list of tasks for finding time zone names.
  config.time_zone = 'UTC'

  if defined?($servlet_context)
    include_class java.lang.System
    app_logs_path = System.getProperty("appLogsPath")
    if app_logs_path.nil?
      Rails.logger.error("***System Property 'appLogsPath' was not set.  Please contact the system administrator immediately!")
    else
      config.logger = Logger.new("#{app_logs_path}/search.log", "daily")
      config.logger.formatter = Logger::Formatter.new
      config.logger.datetime_format = "%Y-%m-%d %H:%M:%S"
      config.logger.level = Logger::Severity::WARN
      def config.format_message(severity, timestamp, progname, msg)
        "[#{timestamp.to_formatted_s(:db)} #{severity}] #{msg}\n"
      end

    end
  end

I assume the config.time_zone setting of 'UTC' is for ActiveRecord, but I wonder if that is a cause here.

My question is: What could be the problem? Also, where is the log rotation timing logic? Is it in Rails, Jruby-Rack, or the underlying logging mechanism?

Answer 1

It would appear that it is a bug in JRuby (http://jira.codehaus.org/browse/JRUBY-6191) that affects 1.8 mode. Workarounds are to use 1.9 mode or use the 'logger' gem.

Update: the JRuby team pointed out that it is actually the logger in MRI Ruby 1.8.7 that exhibits this bug. For compatibility, they will not change this behavior. The above workarounds apply (and seem to work properly).

Answer 2

Tomcat usually uses log4j, which often require finishing touches to get going smoothly.

Check out some best practices:

• http://juliusdavies.ca/logging.html#rotate

• http://jedschneider.posterous.com/rails-application-specific-logging-on-tomcat *

• Logging with log4j on tomcat jruby-rack for a Rails 3 application *

* Obviously a bit different, untested however looks useful. This may kill your dog and eat your children so please deploy any changes with care.