[Ruby] 例えば、Rails の標準ログを止める

rack-ltsv_logger とか strftime_logger とかを使って自分が出したいアクセスログやアプリケーションログ(エラーログ)は自分で１行で出せるようにしたので、もう rails が標準で出すログを止めてしまいたい。ただし、Rails の Controller で例外を rescue しないでしまった時に出るあのログだけ、error.log に出したい。

TL; DR

~~config/initializers/tweak_logger.rb あたりに~~ config/application.rb に

require 'logger'
require 'rack-config_env'

module MyAppName
  class Application < RailsApplication
    null_logger = Logger.new(nil).tap {|log| def log.write(msg); end }
    error_logger = Logger.new('error.log')

    config.logger = null_logger
    config.middleware.delete Rails::Rack::Logger # 必須ではないが無駄になるので消す
    config.middleware.insert_after(0, Rack::ConfigEnv, {
      'rack.errors' => null_logger,
      'action_dispatch.logger' => error_logger,
    }) 
  end
end

のように書く。rack-config_env はこちら。

Rails.logger を挿げ替える

Rails.logger を挿げ替えるには

config.logger = null_logger

とすればよい。

補足：config/initiailizers/* 以下は、Rails.logger が初期化されてから呼ばれるため(at railties/lib/rails/application/bootstrap.rb)、その時点では config.logger= を使っても挿げ替えることができないようだ。 config/application.rb もしくは config/environments/[env].rb のような早めに呼ばれる箇所で挿げ替える必要がある。

捕捉２：config/application.rb で Rails.logger のログレベルを変更するには config.log_level = 'WARN' のようにする必要がある。config.logger.level = Logger::WARN ではダメなので注意。railties/lib/rails/application/bootstrap.rb で config.logger.level を config.log_level の値(デフォルト debug) で上書きしているのでかき消されてしまう。

Rails::Rack::Logger を消す

デフォルトの rails 設定では Rails::Rack::Logger ミドルウェアを使うようになっており、内部で Rails.logger を使ってごにょごにょ出力するようになっているが、 Rails.logger を null_logger に挿げ替えたのだからもはや意味がない。

残しておいてもなにも出力されないので、止めてしまってよさそう

cf. https://github.com/rails/rails/blob/master/railties/lib/rails/rack/logger.rb

env['action_dispatch.logger'] をすげ変える

controller で例外をおこした時に出るログを別のファイルに出すには、env['action_dispatch.logger'] を挿げかえる。

FYI: 追った際のログはこちら https://gist.github.com/sonots/0270cb58f14e75362c9b

任意の rack env を挿げ替えるには、拙作の rack-config_env を利用できるので、それを使ってすげかえる（というか今回作った）。

使い方はこんなかんじ。

config.middleware.insert_after(0, Rack::ConfigEnv, {
  'action_dispatch.logger' => error_logger
})

env['rack.errors'] をすげ変える

rack env の中身を見てみると env['rack.errors'] が IO オブジェクトを握っていたので、念のためすげかえておく。 #write メソッドが必要なようなので、てきとうに生やしてすげかえるようにしてみた(本来は IO オブジェクトを渡せばよさそう)

null_logger = Logger.new('/dev/null').tap {|log| def log.write(msg); end }
config.middleware.insert_after(0, Rack::ConfigEnv, {
  'rack.errors' => null_logger,
})

LogSubscriber も消す

Rails.logger が null_logger になったので何も出ないはずだが、無駄処理になるので消したほうがよさそう。

LogSubscriber というのは、rails の ActiveSupport::Notifications および ActiveSupport::Subscriber が提供する instrumentation の仕組み。この辺の記事を読むと良い。

subscriber を削除するには、

ActiveSupport::Notifications.unsubscribe "start_processing.action_controller"

のようにする。削除する対象を探すために subscriber 一覧を取得するには

irb>
notifier = ActiveSupport::Notifications.notifier
notifier.instance_variable_get("@subscribers").each {|s|
  klass = s.instance_variable_get(:@delegate).class
  pattern = s.instance_variable_get(:@pattern)
  p "#{klass} #{pattern}"
}
"ActiveRecord::LogSubscriber render_bind.active_record"
"ActiveRecord::LogSubscriber sql.active_record"
"ActiveRecord::LogSubscriber odd?.active_record"
...

のようにすればなんとかできる。※ instance_variable_get だらけでちょっと辛みある。

ただ、ちょっと注意点があって、rails は lazy loading するので、 ActionController::LogSubscriber なんかは controller の処理が入るまで require されていなかったりして、 rails c とか config/initializers/*.rb あたりではまだ登録されていなくて一覧にでてこなかったりする。

subscribe される前に unsubscribe しても当然意味がないので、

require 'actionpack/lib/action_controller/log_subscriber.rb'
ActiveSupport::Notifications.unsubscribe "start_processing.action_controller"

のように明示的に require してから unsubscribe する流れになる。 cf. https://gist.github.com/sonots/f46b2d1b1fb7ca6f5513

ちょっと辛みあるし、Rails.logger を null_logger に置き換えてなにも出なくはなっているので、自分はやらないことにしてしまった。

まだ出る

これでも rails s すると

I, [2014-07-02T02:47:26.090849 #12430]  INFO -- :   Rendered books/_form.html.erb (35.9ms)
I, [2014-07-02T02:47:26.091497 #12430]  INFO -- :   Rendered books/new.html.erb within layouts/application (49.5ms)
I, [2014-07-02T02:47:26.168202 #12430]  INFO -- : Completed 200 OK in 203ms (Views: 134.3ms | ActiveRecord: 1.3ms)

のようなログが性懲りもなく出て来る。が、結論としては気にしなくて良かった。

railties/lib/rails/commands/server.rb#L141-L143 において、rails s で起動した場合に、

      def log_to_stdout
        wrapped_app # touch the app so the logger is set up

        console = ActiveSupport::Logger.new($stdout)
        console.formatter = Rails.logger.formatter
        console.level = Rails.logger.level

        Rails.logger.extend(ActiveSupport::Logger.broadcast(console))
      end

のように $stdout 決め打ちで ActiveSupport::Logger を起動しているために表示されてしまうので、すげかえることが出来ないのだが、この log_to_stdout メソッドは L43 の条件が示すように、

43:        options[:log_stdout] = options[:daemonize].blank? && (options[:environment] || Rails.env) == "development"

daemon じゃない && development の時にのみ呼ばれるもので、production 環境では表示されない。よって、気にしなくてよかった。

なお、ActiveSupport::Logger は $stdout と Rails.logger 両方に出力するためのラッパー。どうしても気になる場合はモンキーパッチして止めるしかなさそう。

まとめ

めんどくさい。いちおう最後まで調べたが、ここまでする価値なさそう感ある。

追記：

似たようなことをして、rails の logger を挿げ替えて１行にしたりいらないログを削ったりしているプロジェクトを見つけた https://github.com/roidrage/lograge 参考になりそうだけど、仕組み的には同じなのでつらみありそう

追記:

自分用メモ。結局 config/application.rb にこんな感じに書いてる。rails のログはいちおう出してるけど、基本見てない。rack-ltsv_logger と strftime_logger を使ってる。

  require_relative '../app/models/settings' # settingslogic

  access_logger = StrftimeLogger.new('/var/log/access_log.%Y%m%d')
  config.middleware.insert_after(0, Rack::LtsvLogger, access_logger)

  $logger = StrftimeLogger.new('/var/log/application_log.%Y%m%d')
  $logger.log_level = Settings.application_log_level

  rails_logger = StrftimeLogger.new('/var/log/rails_log.%Y%m%d')

  config.logger = rails_logger # this line must be at config/application.rb
  config.log_level = Settings.rails_log_level
  config.middleware.insert_after(0, Rack::ConfigEnv, {
    # switch log path for non-rescued exceptions on controller
    'action_dispatch.logger' => $logger,
  })

sonots:blog