ログにタイムスタンプを追加する

Rails のログ(development.log / test.log / production.log) は使いやすいが、なぜかログにタイムスタンプが吐き出されない。どうしてだろうと、つらつらと Rails のソースコードを眺めてみた。やはり ActiveSupport の clean_logger.rb でわざわざ時刻もなにも出力されないようにメソッドが上書きされていた。

そこで、タイムスタンプをログに出力するための hack。

# lib/logger_with_timestamp.rb
class Logger
  private
    if method_defined?(:formatter=)
      def format_message_with_datetime(severity, timestamp, progname, msg)
        app_format_message(msg)
      end
    else
      def format_message_with_datetime(severity, timestamp, msg, progname)
        app_format_message(msg)
      end
    end
    
    def app_format_message(msg)
      time = Time.now
      time_str = time.strftime("%Y-%m-%d %H:%M:%S.") << "%06d " % time.usec
      msg.split(/\n/).collect { |line| line =~ /^\s*$/ ? line : time_str + line }.join("\n") + "\n"
    end
    
    alias_method :format_message_without_datetime, :format_message
    alias_method :format_message, :format_message_with_datetime
end

上のコードを lib/logger_with_timestamp.rb として保存し、config/environment.rb の末尾で、

require File.dirname(__FILE__) + "/../lib/logger_with_timestamp"

とする。こうすると、ログ出力がこんな感じになる。

2007-05-06 19:17:26.539325 Processing TestController#index (for 192.168.133.1 at 2007-05-06 19:17:26) [GET]
2007-05-06 19:17:26.539490   Session ID: 797435c7a5b4431a7e19b8363da82fc7
2007-05-06 19:17:26.539588   Parameters: {"action"=>"index", "controller"=>"test"}
2007-05-06 19:17:26.541183 Rendering  within layouts/application
2007-05-06 19:17:26.541493 Rendering test/index
2007-05-06 19:17:26.545923 Completed in 0.00599 (166 reqs/sec) | Rendering: 0.00313 (52%) | 200 OK [http://server1.softculture.com/]