合同会社nemn-d

Ruby on RailsのロガーをActiveSupport::Loggerに変更したときに形式が変わる問題の原因と対処方法

Ruby on Rails

概要

Ruby on RailsのロガーをRuby標準の Logger クラスから、 ActiveSupport::Logger に変更すると形式が変わってしまったので、原因と対処方法を調査しました。

従来のログ
I, [2021-09-23T21:56:45.043019 #1103]  INFO -- : Started GET "/" for XXX.XXX.XXX.XXX at 2021-09-23 21:57:22 +0900
I, [2021-09-23T21:56:45.043019 #1103]  INFO -- : Processing by ExampleController#show as HTML
I, [2021-09-23T21:56:45.043019 #1103]  INFO -- :   Parameters: {"id"=>"1234"}
I, [2021-09-23T21:56:45.043019 #1103]  INFO -- : Completed 200 OK in 341ms (Views: 152.1ms | ActiveRecord: 123.6ms)
I, [2021-09-23T21:56:45.043019 #1103]  INFO -- : Started GET "/" for XXX.XXX.XXX.XXX at 2021-09-23 21:57:22 +0900
形式が変わってしまったログ
Started GET "/" for XXX.XXX.XXX.XXX at 2021-09-23 21:57:22 +0900
Processing by ExampleController#show as HTML
  Parameters: {"id"=>"1234"}
Completed 200 OK in 341ms (Views: 152.1ms | ActiveRecord: 123.6ms)

先頭についていた I, [2021-09-23T21:56:45.043019 #1103] INFO -- : のような表記がなくなってしまっています。

環境

  • Ruby 2.2.3
  • Ruby on Rails 4.2.4

対応方法

  • config/application.rb （もしくは config/environments/{環境名}.rb ）で以下のように設定する。

    config/application.rb
    - config.logger    = ActiveSupport::Logger.new('log/application.log')

+ logger           = ActiveSupport::Logger.new('log/application.log')
+ logger.formatter = ::Logger::Formatter.new
+ config.logger    = logger

原因

関連コード

  • Rubyの Logger クラスでは、ログのフォーマットは format_message メソッドにて行われる。

    https://github.com/ruby/ruby/blob/v2_2_3/lib/logger.rb#L490-L492

    lib/logger.rb#L490-L492
    def format_message(severity, datetime, progname, msg)
  (@formatter || @default_formatter).call(severity, datetime, progname, msg)
end

    実際のログのフォーマットは @formatter にセットされているフォーマッタクラスによって行われる。

  • Logger クラスのインスタンスの formatter をセットしない場合、デフォルトでは同じファイルで定義されている Formatter クラスが利用される。

    https://github.com/ruby/ruby/blob/v2_2_3/lib/logger.rb#L314

    lib/logger.rb#L314
    @default_formatter = Formatter.new
@formatter = nil

  • Rubyの Logger クラスを継承した ActiveSupport::Logger クラスでは、 formatter の値を上書きして SimpleFormatter クラスにしている。

    https://github.com/rails/rails/blob/v4.2.4/activesupport/lib/active_support/logger.rb#L46

    activesupport/lib/active_support/logger.rb#L46
    def initialize(*args)
  super
  @formatter = SimpleFormatter.new
end

  • SimpleFormatter クラスは以下のような実装となっている。

    https://github.com/rails/rails/blob/v4.2.4/activesupport/lib/active_support/logger.rb#L50-L55

    activesupport/lib/active_support/logger.rb#L50-L55
    class SimpleFormatter < ::Logger::Formatter
  # This method is invoked when a log event occurs
  def call(severity, timestamp, progname, msg)
    "#{String === msg ? msg : msg.inspect}\n"
  end
end

解説

  • Railsの config/application.rb で config.logger に Logger クラスを設定するとフォーマッタにはRubyの Formatter クラスが利用され、 ActiveSupport::Logger クラスを設定するとフォーマッタにはRailsの SimpleFormatter クラスが利用される。
  • logger.formatter に任意のフォーマッタクラスをセットすることでログを好きなフォーマットに変更することができる。

備考

ActiveSupport::TaggedLoggingを使いたい場合の設定方法

config/application.rb
logger           = ActiveSupport::Logger.new('log/application.log')
logger.formatter = ::Logger::Formatter.new
config.logger    = ActiveSupport::TaggedLogging.new(logger)

config.log_formatterにフォーマッタを設定しても意図通りの結果にならない理由

config.log_formatter の値が Logger クラスの formatter にセットされるのは、 config.logger が未設定の場合のみ。

https://github.com/rails/rails/blob/v4.2.4/railties/lib/rails/application/bootstrap.rb#L33-L56

railties/lib/rails/application/bootstrap.rb#L43-L46
logger = ActiveSupport::Logger.new f
logger.formatter = config.log_formatter
logger = ActiveSupport::TaggedLogging.new(logger)
logger

よって、 config.log_formatter = ::Logger::Formatter.new としたとしても、 config.logger = ActiveSupport::Logger.new('log/application.log') としていると意味がなくなってしまう。

そのため、 config.log_formatter を使わずに以下のように設定する。

config/application.rb
logger           = ActiveSupport::Logger.new('log/application.log')
logger.formatter = ::Logger::Formatter.new
config.logger    = logger

背景

RailsアプリでELBからのヘルスチェックのアクセスをログに残さないようにする は ActiveSupport::Logger を継承したクラスを利用していないと行えなかったのでロガークラスを変更したところ、ログの形式が変わってしまったために本対応を行いました。

感想

config.log_formatter を変更しても適用されずしばらくハマりました。今回RailsやRubyのソースコードをじっくり追いながら実装を把握することができて明確になりました。フルタイムで働いていた頃は何かと忙しくてついこういった細部は「動けばいいや」でやってしまっていたことも多かったですが、しっかり調べることで足元を掬われにくくなるのでやはり急がば回れできちんと調べることが重要だと思いました。

参考にさせていただいたサイト