Tbpgr Blog

Employee Experience Engineer tbpgr(てぃーびー) のブログ

ログ管理 | LTSV | Ruby on RailsのログをLTSV形式に変更

概要

Ruby on RailsのログをLTSV形式に変更

詳細

Ruby on RailsのログをLTSV形式に変更します。

サンプル

ロガーをオープンクラスで拡張してinitializersに保存します。
/config/initializers/logger.rb

class Logger
  def format_message(level, time, progname, msg)
    ret = []
    ret << "time:[#{time.strftime("%Y/%m/%d %H:%M:%S.%L")}]"
    ret << "level:[#{level}]"
    ret << "progname:[#{progname}]" if progname
    if (msg.instance_of?(Hash))
      msg.each {|k, v|ret << "#{k}:[#{v}]"}
    else
      ret << "msg:[#{msg}]"
    end
    ret.join("\t") + "\n"
  end
end

config/environments/test.rb
config/environments/development.rb
config/environments/production.rb

config.logger = Logger.new("log/development.log", 10, 10.megabytes)
config.logger = Logger.new("log/test.log", 10, 10.megabytes)
config.logger = Logger.new("log/production.log", 10, 10.megabytes)

Controllerのトレースログを設定

app/controller/application_controller.rb

around_action :logging_filter

def logging_filter
  class_name = "#{params[:controller].capitalize}Controller"
  method_name = params[:action]
  start_time = Time.now_msec
  trace_start = {se_flg: "start", class_name: class_name, method_name: method_name, total_time: "", params: params}
  logger.debug trace_start
  ret = yield
  end_time = Time.now_msec
  trace_end = {se_flg: "end", class_name: class_name, method_name: method_name, total_time: "#{(end_time - start_time).to_s} msec", params: ""}
  logger.debug trace_end
end

トレースログに使用するTimeのオープンクラス

/config/initializers/time.rb

class Time
  # get current time(msec
  # @return current time(msec)
  def self.now_msec
    self.now.instance_eval { self.to_i * 1000 + (usec/1000) }
  end

  # get msec format string "%Y/%m/%d %H:%M:%S.%L"
  # @return msec format string "%Y/%m/%d %H:%M:%S.%L"
  def self.now_msec_format
    self.now.strftime("%Y/%m/%d %H:%M:%S.%L")
  end
end

出力例

time:[2013/07/26 00:43:06.399]  level:[INFO]  msg:[Started GET "/user/new" for 192.168.xxx.xxx at 2013-07-26 00:43:06 +0900]
time:[2013/07/26 00:43:06.405]  level:[INFO]  msg:[Processing by UserController#new as HTML]
time:[2013/07/26 00:43:06.406]  level:[DEBUG] se_flg:[start]  class_name:[UserController] method_name:[new] total_time:[] params:[{"controller"=>"user", "action"=>"new"}]
time:[2013/07/26 00:43:06.408]  level:[INFO]  msg:[  Rendered user/new.html.haml within layouts/application (1.2ms)]
time:[2013/07/26 00:43:06.414]  level:[DEBUG] msg:[  User Load (0.1ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 5 LIMIT 1]
time:[2013/07/26 00:43:06.415]  level:[INFO]  msg:[  Rendered application/_menu.html.haml (0.1ms)]
time:[2013/07/26 00:43:06.415]  level:[INFO]  msg:[  Rendered application/_message.html.haml (0.0ms)]
time:[2013/07/26 00:43:06.416]  level:[DEBUG] se_flg:[end]  class_name:[UserController] method_name:[new] total_time:[10 msec]  params:[]
time:[2013/07/26 00:43:06.416]  level:[INFO]  msg:[Completed 200 OK in 11ms (Views: 9.5ms | ActiveRecord: 0.1ms)]
time:[2013/07/26 00:43:06.399]  level:[INFO]  msg:[Started GET "/user/new" for 192.168.xxx.xxx at 2013-07-26 00:43:06 +0900]
time:[2013/07/26 00:43:06.405]  level:[INFO]  msg:[Processing by UserController#new as HTML]
time:[2013/07/26 00:43:06.406]  level:[DEBUG] se_flg:[start]  class_name:[UserController] method_name:[new] total_time:[] params:[{"controller"=>"user", "action"=>"new"}]
time:[2013/07/26 00:43:06.408]  level:[INFO]  msg:[  Rendered user/new.html.haml within layouts/application (1.2ms)]
time:[2013/07/26 00:43:06.414]  level:[DEBUG] msg:[  User Load (0.1ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 5 LIMIT 1]
time:[2013/07/26 00:43:06.415]  level:[INFO]  msg:[  Rendered application/_menu.html.haml (0.1ms)]
time:[2013/07/26 00:43:06.415]  level:[INFO]  msg:[  Rendered application/_message.html.haml (0.0ms)]
time:[2013/07/26 00:43:06.416]  level:[DEBUG] se_flg:[end]  class_name:[UserController] method_name:[new] total_time:[10 msec]  params:[]
time:[2013/07/26 00:43:06.416]  level:[INFO]  msg:[Completed 200 OK in 11ms (Views: 9.5ms | ActiveRecord: 0.1ms)]