デフォルトのRailsロガーを使用して、TomcatにデプロイされたJRuby on Rails 2アプリケーションがあります。DST の境界を越えてしばらくすると、ログに次のエラー メッセージが表示され、アプリケーションが停止していることがわかりました。
org.jruby.rack.RackInitializationException: Shifting failed. '/tc_instance/applogs/search.log.20111106' already exists.
通常、ログは深夜にローテーションされます。前日のログの最終タイムスタンプは常に 23:59 ですが、 11 月 6 日のログのタイムスタンプは 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
そのため、真夜中ではなく午後 11 時にログのロールオーバーが試行されました。次に、新しい日のログを作成しようとしたときに、同じ日付を使用していました。
構成に問題があるか、ログ ローテーションのタイミング ロジックにバグがあるようです。
以下は、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
「UTC」の config.time_zone 設定は ActiveRecord 用だと思いますが、それが原因なのかなと思います。
私の質問は次のとおりです。何が問題なのですか? また、ログ ローテーションのタイミング ロジックはどこにありますか? それは Rails、Jruby-Rack、または基礎となるロギング メカニズムにありますか?