30785


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

config/development.rb

[code]

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

ログ出力コード

[code]

    Rails.logger.info "hogehoge"
    
[/code]

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

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

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

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

ためしに、 dailyをやめて、

[code]

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

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

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

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


CC BY-SA 3.0
2015-07-01T08:34:56.267
11929
2016-11-30T02:03:37.343
2015-07-06T07:34:39.787
9260
9260
question
ruby-on-rails
Rails loggerがローテーションしない


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

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

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

[ruby/logger.rb at trunk ·
ruby/ruby](https://github.com/ruby/ruby/blob/trunk/lib/logger.rb#L589)

[code]

    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
    
[/code]

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

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

# 追記

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

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

[code]

     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
    
[/code]

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

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

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

[code]

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

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

[code]

    # environment.rb の sample に記載の例
    config.logger = ActiveSupport::TaggedLogging.new(SyslogLogger.new)
    
[/code]


CC BY-SA 3.0
2015-07-01T14:04:56.917
11934
2015-07-03T14:51:41.707
2015-07-03T14:51:41.707
7471
7471
11929
answer


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でローテートするようになりました。


CC BY-SA 3.0
2016-11-30T02:03:37.343
30785
2016-11-30T02:03:37.343
19776
11929
answer