Rails2.3のログフォーマット

Rails2.3のログフォーマットの変更は、Railscasts - The Logger を見て
Logger!!!（ログにタイムスタンプを追加する方法） - うんたらかんたら日記
としていましたが、改めてソースを見ると

#activesupport-2.3.11/lib/active_support/core_ext/logger.rb
This logger is deprecated in favor of ActiveSupport::BufferedLogger

と書かれていました。
Loggerでのフォーマット変更は結構柔軟（ミリ秒、プロセス、ログレベルなど）に書けたので
特に困ってないし、理由もわかんないのですが、deprecatedと言われると不安なので
ActiveSupport::BufferedLoggerでのフォーマット変更を試してみました。

結論

#config/environment.rb
ActiveSupport::BufferedLogger.class_eval do
  SEVERITIES = self::Severity.constants.inject({}){ |val, con| val[eval("self::#{con}")] = con; val }
    def add_with_format(severity, message = nil, progname = nil, &block)
      time = Time.now
      format = "[%s #%d] %s -- %s: %s\n"
      formatted_message = format % ["#{time.strftime('%Y-%m-%d %H:%M:%S')}.#{'%06d' % time.usec.to_s}",
                          $$, SEVERITIES[severity], progname, message]
      add_without_format(severity, nil) { formatted_message }
    end
  alias_method_chain :add, :format
end

これでOK。

[2011-05-01 14:09:07.723610 #9165] INFO -- :   Parameters: {"id"=>"1"}
[2011-05-01 14:09:07.730061 #9165] WARN -- :   Article Load (0.3ms)   SELECT * FROM "articles" WHERE ("articles"."id" = 1) 
[2011-05-01 14:09:07.745981 #9165] INFO -- : Rendering template within layouts/articles
[2011-05-01 14:09:07.746250 #9165] INFO -- : Rendering articles/edit
[2011-05-01 14:09:07.756997 #9165] INFO -- : Completed in 32ms (View: 25, DB: 0) | 200 OK [http://localhost/articles/1/edit]

まずは

ActiveSupport::BufferedLoggerがどこで使用されるかを見ていきます。
#rails/lib/initializer.rb

initializer

RAILS_ENV = (ENV['RAILS_ENV'] || 'development').dup unless defined?(RAILS_ENV)

module Rails
  class Initializer
    def self.run(command = :process, configuration = Configuration.new)
      yield configuration if block_given?
      initializer = new configuration
      initializer.send(command)
      initializer
    end

関係ないけど、最初にRAILS_ENVの設定をしてるんですね。
initializer = new configuration が謎ですが
configurationをnewして、processメソッドをsendするという流れ。

Configurationを見てみると

module Rails
  class Configuration
    def initialize
      set_root_path!

      self.frameworks                   = default_frameworks
      self.autoload_paths               = default_autoload_paths
      self.autoload_once_paths          = default_autoload_once_paths
      self.eager_load_paths             = default_eager_load_paths
      self.log_path                     = default_log_path
      self.log_level                    = default_log_level
      self.view_path                    = default_view_path
      self.controller_paths             = default_controller_paths
      self.preload_frameworks           = default_preload_frameworks
      self.cache_classes                = default_cache_classes
      self.dependency_loading           = default_dependency_loading
      self.whiny_nils                   = default_whiny_nils
      self.plugins                      = default_plugins
      self.plugin_paths                 = default_plugin_paths
      self.plugin_locators              = default_plugin_locators
      self.plugin_loader                = default_plugin_loader
      self.database_configuration_file  = default_database_configuration_file
      self.routes_configuration_file    = default_routes_configuration_file
      self.gems                         = default_gems
      self.i18n                         = default_i18n

      for framework in default_frameworks
        self.send("#{framework}=", Rails::OrderedOptions.new)
      end
      self.active_support = Rails::OrderedOptions.new
    end

いろいろやってますが、log_levelの設定もここでやってます。

module Rails
  class Configuration
    private
      def default_log_level
        environment == 'production' ? :info : :debug
      end

process

module Rails
  class Initializer
    def process
      Rails.configuration = configuration

      check_ruby_version
      install_gem_spec_stubs
      set_load_path
      add_gem_load_paths

      require_frameworks
      set_autoload_paths
      add_plugin_load_paths
      load_environment
      preload_frameworks

      initialize_encoding
      initialize_database

      initialize_cache
      initialize_framework_caches

      initialize_logger
      initialize_framework_logging

ここもいろいろやってます。

initialize_logger

Rails.loggerやconfiguration.logger（つまりenvironment.rbでLogger.new(config.log_path)とかしてる）が設定されていない場合
ActiveSupport::BufferedLoggerをnewしています。
最後にRAILS_DEFAULT_LOGGERも設定してますね。ほぅ。

module Rails
  class Initializer
    def initialize_logger
      # if the environment has explicitly defined a logger, use it
      return if Rails.logger

      unless logger = configuration.logger
        begin
          logger = ActiveSupport::BufferedLogger.new(configuration.log_path)
          logger.level = ActiveSupport::BufferedLogger.const_get(configuration.log_level.to_s.upcase)
          if configuration.environment == "production"
            logger.auto_flushing = false
          end
        rescue StandardError => e
          logger = ActiveSupport::BufferedLogger.new(STDERR)
          logger.level = ActiveSupport::BufferedLogger::WARN
          logger.warn(
            "Rails Error: Unable to access log file. Please ensure that #{configuration.log_path} exists and is chmod 0666. " +
            "The log level has been raised to WARN and the output directed to STDERR until the problem is fixed."
          )
        end
      end

      silence_warnings { Object.const_set "RAILS_DEFAULT_LOGGER", logger }
    end

では、activesupportを見てみましょう

#activesupport-2.3.11/lib/active_support/core_ext

initialize

最後のforでaddメソッドが作成されています。

module ActiveSupport
  class BufferedLogger
    module Severity
      DEBUG   = 0
      INFO    = 1
      WARN    = 2
      ERROR   = 3
      FATAL   = 4
      UNKNOWN = 5
    end
    include Severity

    def initialize(log, level = DEBUG)
      @level         = level
      @buffer        = {}
      @auto_flushing = 1
      @guard = Mutex.new

      if log.respond_to?(:write)
        @log = log
      elsif File.exist?(log)
        @log = open(log, (File::WRONLY | File::APPEND))
        @log.sync = true
      else
        FileUtils.mkdir_p(File.dirname(log))
        @log = open(log, (File::WRONLY | File::APPEND | File::CREAT))
        @log.sync = true
        @log.write("# Logfile created on %s" % [Time.now.to_s])
      end
    end


    for severity in Severity.constants
      class_eval <<-EOT, __FILE__, __LINE__ + 1
        def #{severity.downcase}(message = nil, progname = nil, &block)  
          add(#{severity}, message, progname, &block)                    
        end                                                              
                                                                         
        def #{severity.downcase}?                                        
          #{severity} >= @level                                          
        end                                                              
      EOT
    end
    # def debug(message = nil, progname = nil, &block)
    #   add(DEBUG, message, progname, &block)
    # end
    #
    # def debug?
    #   DEBUG >= @level
    # end

add

ありました、ここですね。

    def add(severity, message = nil, progname = nil, &block)
      return if @level > severity
      message = (message || (block && block.call) || progname).to_s
      # If a newline is necessary then create a new message ending with a newline.
      # Ensures that the original message is not mutated.
      message = "#{message}\n" unless message[-1] == ?\n
      buffer << message
      auto_flush
      message
    end

改行付与のついでに、フォーマット変更してみましょう。

修正してみた

module ActiveSupport
  class BufferedLogger
    module Severity
      DEBUG   = 0
      INFO    = 1
      WARN    = 2
      ERROR   = 3
      FATAL   = 4
      UNKNOWN = 5
    end
    include Severity

    def add(severity, message = nil, progname = nil, &block)
      return if @level > severity
      message = (message || (block && block.call) || progname).to_s
      # If a newline is necessary then create a new message ending with a newline.
      # Ensures that the original message is not mutated.
      time = Time.now
      format = "[%s #%d] %s -- %s: %s\n"
      severity = Severity.constants.find{ |c| Severity.const_get(c) == severity }
      # severity_initial = Severity.constants.find{ |c| Severity.const_get(c) == severity }[0..0]
      message = "#{message}\n" unless message[-1] == ?\n
      message = format % ["#{time.strftime('%Y-%m-%d %H:%M:%S')}.#{'%06d' % time.usec.to_s}",
                  $$, severity, progname, message]
      buffer << message
      auto_flush
      message
    end
  end
end

severityが数値で渡ってくるので、DEBUGとかINFOとか文字列を出力するために
Severityも書いています。

さらに改変

ググってみると下記のようなやり方が紹介されていました。
Railsのログに関する覚書き - Ruby Study Go

ActiveSupport::BufferedLogger.class_eval do
  SEVERITIES = self::Severity.constants.inject({}){ |val, con| val[eval("self::#{con}")] = con; val }
  def add_with_format(severity, message = nil, progname = nil, &block)
    add_without_format(severity, nil) { "%s [%5s] %s" % [Time.now.strftime("%Y/%m/%d %H:%M:%S"), SEVERITIES[severity], message] }
  end
  alias_method_chain :add, :format
end

これはcool。なるほど元メソッドを呼ぶ形であればclas_evalした上で
alias_method_chainしてあげればこんなに短く書ける。

感想

ということで、冒頭のソースになりました。
Rails側は、LoggerやLog4Rなどのloggerオブジェクトに柔軟に対応した作りになっていますが
ActiveSupport::BufferedLoggerのフォーマット変更は、ちょっと面倒。
もう少し書きやすい構造にしてくれると有り難いですね。

おまけ

loggerオブジェクトの中身です。

Loggerの場合

#<Logger:0x101609350
 @default_formatter=#<Logger::Formatter:0x101608ec8 @datetime_format=nil>,
 @formatter=#<Logger::Formatter:0x101609198 @datetime_format=nil>,
 @level=0,
 @logdev=
  #<Logger::LogDevice:0x101608ce8
   @dev=#<File:/Users/rochefort/work/rails/bloga/log/production.log>,
   @filename="/Users/rochefort/work/rails/bloga/log/production.log",
   @mutex=
    #<Logger::LogDevice::LogDeviceMutex:0x101608b80
     @mon_count=0,
     @mon_entering_queue=[],
     @mon_owner=nil,
     @mon_waiting_queue=[]>,
   @shift_age=0,
   @shift_size=1048576>,
 @progname=nil>

ActiveSupport::BufferedLoggerの場合

#<ActiveSupport::BufferedLogger:0x102d76650
 @auto_flushing=1000,
 @buffer=
  {#<Thread:0x102d7cbb8 run>=>
    ["\n\nProcessing ArticlesController#show (for 127.0.0.1 at 2011-04-30 06:17:06) [GET]\n",
     "  Parameters: {\"id\"=>\"2\"}\n"]},
 @guard=#<Mutex:0x102d6ba70>,
 @level=1,
 @log=#<File:/Users/rochefort/work/rails/bloga/log/production.log>>