railsログをLTSV形式で出力する

##やりたいこと

普通にLTSV対応するならgemを使うのが簡単。

* [ltsv-logger](https://rubygems.org/gems/ltsv-logger)
* [logger-ltsv](https://rubygems.org/gems/logger-ltsv)

ただし、そのまま[ActiveSupport::TaggedLogging](http://api.rubyonrails.org/classes/ActiveSupport/TaggedLogging.html)のタグ埋め込みに対応すると、message preffixとして出力されてしまう。

```　例：リクエストIDを出力した場合
"[0294a134-a338-11e3-90bc-52540092ec69] hoge"
```

せっかくなので、リクエストID等のタグ埋め込みもLTSV形式で出力可能にしてみる。

```
"uuid:0294a134-a338-11e3-90bc-52540092ec69[TAB]message:hoge"
```

## 対応

```rb:formatter.rb
module LTSV
  class Formatter < ::Logger::Formatter
    def call(severity, time, progname, msg)
      return "" if msg.blank?
      raws = []
      raws << "pid:#{$$}"
      raws << "severity:#{severity}"
      raws << "time:#{format_datetime(time)}"
      raws << "progname:#{progname}" if progname
      case msg
      when Hash
        key = "severity"
        message = msg.stringify_keys
        if message.has_key?(key)
          index = raws.find_index { |v| v =~ /^#{key}:(.*)/ }
          raws[index].gsub!($1, message[key])
          message.delete(key)
        end 
        raws = msg.inject(raws) { |h, (k, v)| h << "#{k}:#{v}"; h }
      else
        raws << "message:#{msg2str(msg)}"
      end
      "#{raws.join("\t")}\n"
    end

    private

    def format_datetime(time)
      if @datetime_format.nil?
        time.strftime("%Y-%m-%dT%H:%M:%S.") << "%06d" % time.usec
      else
        super
      end
    end
  end
end
```

```rb:logger.rb 
require 'logger'

module LTSV
  class Logger < ::Logger
    def initialize(*args)
      super
      @formatter = LTSV::Formatter.new
    end

    def add_ext(severity, message = nil, progname = nil, tags_hash)
      self.add(severity, msg2hash(message, tags_hash), progname)
    end

    private

    def msg2hash(msg, tags_hash)
      return nil if msg.blank?
      hash = tags_hash.clone
      case msg
      when ::Exception
        hash["message"] = "#{msg.message} (#{msg.class})"
        msg.backtrace.each_with_index {|trace, i| hash["trace#{i}"] = trace }
      when ::Hash
        hash.merge!(msg)
      when ::String
        hash["message"] = msg
      else
        hash["message"] = msg.inspect
      end
      hash
    end
  end
end
```

```rb:tagged_logging.rb 
module LTSV
  class TaggedLogging < ActiveSupport::TaggedLogging
    class << self
      # for Rails.configuration.log_tags
      def log_tags
        tags.values
      end

      # for Me
      def log_tag_keys
        tags.keys
      end

      private
      def tags
        {
          request_id: :uuid,
          session:    lambda {|req| req.cookies["_#{APP_NAME}_session"]}
        }
      end
    end

    # Override
    def add(severity, message = nil, progname = nil, &block)
      if message.nil?
        if block_given?
          message = block.call
        else
          message = progname
          progname = nil #No instance variable for this like Logger
        end
      end
      if @logger.respond_to?(:add_ext)
        @logger.add_ext(severity, message, progname, tags_hash)
      else
        @logger.add(severity, "#{tags_text}#{message}", progname)
      end
    end

    private
    def tags_hash
      hash = {}
      self.class.log_tag_keys.each_with_index do |tag, i|
        if tag == :session
          next if current_tags[i].blank?
          session_base64, digest = URI.decode(current_tags[i]).split("--")
          hash.merge!(Marshal.load(Base64.decode64(session_base64)))
        else
          hash[tag.to_s] = current_tags[i]
        end
      end
      hash
    end
  end
end
```