RailsでもLTSVを出力したい！

railsのlog/production.logでは主に以下のようなログが吐かれる

'Started GET "/" for 127.0.0.1 at 2014-01-20 20:46:30 +0900'というような感じのアクセスログっぽい奴
Rails.loggerを自分でアプリ内から叩いて出したログ

後者は前に書いたように、Rails.loggerのフォーマッターを変えればLTSV形式で出力できそうだ。じゃあ前者はどうしたらLTSV形式で出力できるのだろうか？
環境はRails4.0.0, ruby2.0.0-p247

Rails::Rack::Logger

railsのrackミドルウェアを調べてみると、どうも前者はRails::Rack::Loggerというやつが出力しているようだ。コードを見ると、started_request_messageというメソッドの中とか見慣れた形式のログを出力している。
https://github.com/rails/rails/blob/master/railties/lib/rails/rack/logger.rb

さらに読み進めると、loggerというプライベートメソッドの中でRails.loggerをそのまま返しているメソッドがある。このクラス内でログを出力していると思われる部分は全部このloggerメソッドを呼んでいる。つまり、Rails::Rack::LoggerはRails.loggerを内部的に使っている。なのでRails.loggerのフォーマッターだけ変えればproduction環境でのrailsのログは全てLTSVに変えることが出来る。

Rails.loggerのフォーマッター改造

ということでRails.loggerのフォーマッターを変えてみる。以下のコードをconfig/initializer/custom_log_formatter.rbという名前で設置。

class Logger::FormatWithTime < Logger::Formatter

  include  ActiveSupport::TaggedLogging::Formatter

  def call(severity, timestamp, progname, msg)
    [].tap do |arr|
      arr << "time:#{timestamp.strftime("%Y/%m/%d %H:%M:%S" )}"
      arr << "severity:#{severity}"
      arr << "progname:#{progname}" if progname
      arr << "message:#{String === msg ? msg : msg.inspect}"
    end.join("\t") + "\n"
  end
end

Rails.logger.formatter = Logger::FormatWithTime.new

前に書いたブログのように、Rails.logger.formatterにcallメソッドを持つオブジェクトを渡せばそれをフォーマッターとして使ってくれる。フォーマッターに渡されるseverity(ログレベル)、時刻、infoやdebugなどのログメソッドに渡したメッセージをそれぞれkey-value形式にして返すようにした。これでログ出力もLTSVになるはず。

以下はrails consoleでの出力。

[1] 2.0.0-p247(main)> Rails.logger.info "Sugoi info"
# => time:2014/01/20 21:05:16     severity:INFO       message:Sugoi info

Rails::Rack::Loggerの改造

このままprodution環境でアクセスログを出力すると以下の様な形式で出力される

time:2014/01/20 21:07:32      severity:INFO      message:Started GET "/" for 127.0.0.1 at 2014-01-20 21:07:32 +0900

エラーの場合はしょうがないにせよ、Started以降のリクエストメソッド、リクエストパス、リクエスト元のホストくらいは決まりきっているのでこの部分もkey-value形式にできそうだ。ということで、ここらへんを出力している部分を改造してさらにイケてるLTSVにしてみる。

class Logger::FormatWithTime < Logger::Formatter

  include  ActiveSupport::TaggedLogging::Formatter

  def call(severity, timestamp, progname, msg)
    [].tap do |arr|
      arr << "time:#{timestamp.strftime("%Y/%m/%d %H:%M:%S" )}"
      arr << "severity:#{severity}"
      arr << "progname:#{progname}" if progname
      if String === msg
        arr << msg
      else
        arr << "message:#{msg.inspect}"
      end
    end.join("\t") + "\n"
  end
end

module Rails
  module Rack
    class Logger < ActiveSupport::LogSubscriber
      def started_request_message(request)
        [
          "method:#{request.request_method}",
          "path:#{request.filtered_path}",
          "host:#{request.ip}"
        ].join("\t")
      end
    end
  end
end

Rails.logger.formatter = Logger::FormatWithTime.new

先ほどのconfig/initializer/custom_log_formatter.rbに置き換える。
Rails::Rack::Loggerのstarted_request_messageというメソッドが問題のリクエストメソッドなどを出力している部分なので、そのまま直接LTSVに入れ替える。これはalias_method_chainとか使ったほうが良かったかも。あとはそのstarted_request_messageを使ってる部分から出力した場合は"messages:"という文字列が邪魔なのでそれも出力しないようにする。

time:2014/01/20 21:25:47        severity:INFO       method:GET      path:/      host:127.0.0.1

これですべてLTSV形式で出力できた！