2

Ruby 2.2.2、Rails 4.2.1 にて以下のやり方でログを出力しています。

config/development.rb

config.logger = Logger.new('log/my.log', 'daily')
config.log_formatter = Logger::Formatter.new

ログ出力コード

Rails.logger.info "hogehoge"

ログは出力されるのですが、日をまたいでも初めのmy.logに追記されていき、ローテーションされません。開発しながらなので、サーバーは常時起動ではなく、止めたり、起動したりしています。

バッチ的な処理をrailsで書いていて、cronで定期的にURLにアクセスして、処理をして終わるということをしています。

処理は複数スレッドで内部で並列化しています。(常駐スレッドはなし)

テスト環境の別サーバーは常時稼働していますが、同様に初めのファイルに追記されローテーションされません。

ためしに、 dailyをやめて、

config.logger = Logger.new('log/my.log', 5, 1 * 1024)

のようにサイズ指定にしてみましたが、やはりローテーションされず、かつ今度はログ出力がとても遅くなり、全体的に処理が重くなっているように見えます。

できれば、dailyでログを回したいのですが、どなたか参考情報などありますでしょうか?

Logger自体スレッドセーフだと思ったのですが、マルチスレッド処理が弊害を起こしていますかね?

2 件の回答 2

3

dailyを指定するとローテートしないのは、Ruby 2.2以降のLoggerのバグだったようです。
修正パッチが登録されていました。

https://github.com/ruby/ruby/commit/f6e77b9d3555c1fbaa8aab1cdc0bd6bde95f62c6

bugs.ruby-lang.org の Bug #12948 と、リビジョン 56815 の変更です。

私の手元の環境(ruby 2.2.1p85, Rails 4.2.1)で同様の現象が起きていましたが、
上記の修正を行った所、dailyでローテートするようになりました。

1
  • なるほど、ありがとうございます! 2016年12月4日 4:25
2

サーバーは常時起動ではなく、止めたり、起動したりしています。

に関しては、サーバの起動時に次回のローテーション時刻を設定しているため、
サーバを止めると無効になると考えます。

Logger.new の際に、
LogDevice.new され、
@next_rotate_time に更新日が記憶され、
write の度に、check_shift_log を行い、
next_rotate_time に達していたら、shift_log_period で今のファイルをローテーションする、
という動作のようです。

ruby/logger.rb at trunk · ruby/ruby

class LogDevice
  def initialize(log = nil, opt = {})
      # ...
    @dev = open_logfile(log)
    # ...
    @shift_age = opt[:shift_age] || 7
    # ...
    @next_rotate_time = next_rotate_time(Time.now, @shift_age) unless @shift_age.is_a?(Integer)
  end

  def write(message)
    begin
      @mutex.synchronize do
        if @shift_age and @dev.respond_to?(:stat)
          begin
            check_shift_log
    ...

  def check_shift_log
    if @shift_age.is_a?(Integer)
      # Note: always returns false if '0'.
      if @filename && (@shift_age > 0) && (@dev.stat.size > @shift_size)
        lock_shift_log { shift_log_age }
      end
    else
      now = Time.now
      if now >= @next_rotate_time
        @next_rotate_time = next_rotate_time(now, @shift_age)
        lock_shift_log { shift_log_period(previous_period_end(now, @shift_age)) }
      end
    end
  end

テスト環境の別サーバーは常時稼働して

ということですが、例えば Rails.env が異なる、などといったことは無いでしょうか?

追記

daily=24時間ってことですかね? 自分はカレンダ情報だと思っていたのですが、24時間だと、24時間いないに毎回サーバー落としていたらローテーションされない仕組みですよね?

参照が不足していたようで、スミマセン。
daily など文字列で指定した場合は特殊処理をしており、24時間ではなく、日が変わるまでです。

 SiD = 24 * 60 * 60

    def next_rotate_time(now, shift_age)
      case shift_age
      when /^daily$/
        t = Time.mktime(now.year, now.month, now.mday) + SiD

例えば、2015-07-03 の 9:00 にサーバを起動しても、23:00 に起動しても、
同じく 2015-07-04 には切り替わります。

Rails.loggerとlogger(コントローラ以外だとRailsをつけないと呼べないってどこかで見ましたが)って、参照してるメソッド(実体)は同じですよね‌​?

environment.rb で下記のように設定されていることと思います。
これは、Rails の logger に、Logger クラスを代入しているので、同じものと考えました。

config.logger = Logger.new('log/my.log', 'daily')

別の logger を使っていれば、そちらの挙動になると考えます。

# environment.rb の sample に記載の例
config.logger = ActiveSupport::TaggedLogging.new(SyslogLogger.new)
3
  • ご回答ありがとうございます! 上記をみて自分はちょっと勘違いしていたかもしれません。。 daily=24時間ってことですかね? 自分はカレンダ情報だと思っていたのですが、24時間だと、24時間いないに毎回サーバー落としていたらローテーションされない仕組みですよね? テスト環境もenviroinmentはdevelopemntを使っていますが、プログラム入れ替え時に停止していることもあるので、もうすこしみてみます。 それとついでにお聞きしたいのですが、 Rails.loggerとlogger(コントローラ以外だとRailsをつけないと呼べないってどこかで見ましたが)って、参照してるメソッド(実体)は同じですよね? 2015年7月2日 2:26
  • 追記ありがとうございます! 結局なんでローテートしないかわからない感じですが、 あやしいところだと -Loggerを設定しているのが、environment.rbではなくdevelopment.rb(通常見かけるのは各環境ごとにLoggerの設定をしているコードですが)であること、 -LoggerでなくてActiveLoggerにしてみる? -常駐ではないが、長いバッチ処理をスレッドで行っていてその中でloggerを参照している(loggerがスレッドセーフでないとか?) ぐらいかなと思います。 上記試してみるので、またアップデートします! 2015年7月6日 7:29
  • 1
    結局、いろいろやってみてダメだったので、ローテーションを自作して解決しました。今回、マルチスレッドなど使っていたので、別のシンプルなアプリを作った時にまた試してみます。ありがとうございました! 2015年7月23日 2:18

この質問に回答するには、ログインする必要があります。

求めていた回答ではありませんか? のタグが付いた他の質問を参照する。