ログ管理 | Ruby on Rails | Railsのログをカスタマイズする

概要

Railsのログをカスタマイズする

内容

Railsのログをカスタマイズします

LTSVに変更

※別途記事参照

Railsのコントローラーログの無効化

※下記記事参照
ログ管理 | LTSV | Ruby on RailsのログをLTSV形式に変更Comments
http://d.hatena.ne.jp/tbpg/20130725/1374767548

独自コントローラーログの設定

around_action :logging_filter

def logging_filter
  class_name = "#{params[:controller].capitalize}Controller"
  method_name = params[:action]
  login = current_user.login if current_user

  start_time = Time.now_msec
  trace_start = {type: "controller", se_flg: "start", user: login, class_name: class_name, method_name: method_name, apptime: "", params: params}
  logger.debug trace_start

  ret = yield

  end_time = Time.now_msec
  trace_end = {type: "controller", se_flg: "end", user: login, class_name: class_name, method_name: method_name, apptime: "#{(end_time - start_time).to_s}ms", params: ""}
  logger.debug trace_end
end

renderingログをLTSV形式に分割

def convert_hash_if_rendering_log(msg)
  return msg unless msg =~ /  Rendered .*/
  messages = {}
  messages[:type] = "rendering"
  msg =~ /  (Rendered) (.*) (.*)/
  messages[:uri] = $2
  messages[:apptime] = $3.gsub(/[\(\)]/, "")
  messages
end

Request GET、POSTのログをLTSV形式に分割

def convert_hash_if_request_log(msg)
  return msg unless msg =~ /Started (GET|POST) .*/
  messages = {}

  msg =~ /(Started) (.*) (.*) (.*) (.*) (.*) (.*) (.*) (.*).*/
  messages[:type] = $2
  messages[:uri] = $3
  messages[:host] = $5
  messages
end

CompletedログをLTSV形式に分割

def convert_hash_if_complete_log(msg)
  return msg unless msg =~ /Completed .*/
  messages = {}
  messages[:type] = "completed"

  msg =~ /(Completed) (.*) (.*) (.*) (.*) (.*) (.*) (.*) (.*) (.*)/
  messages[:status] = $2
  messages[:success] = $3
  messages[:apptime] = $5
  messages[:apptime_view] = $7
  messages[:apptime_active_record] = $10.chop!
  messages
end

カスタムロガー全体のコード

config/environment.rb

# Load the Rails application.
require File.expand_path('../application', __FILE__)

# Initialize the Rails application.
Project::Application.initialize!

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
    msg = convert_hash_if_rendering_log msg
    msg = convert_hash_if_request_log msg
    msg = convert_hash_if_complete_log msg
    if (msg.instance_of?(Hash))
      msg.each {|k, v|ret << "#{k}:[#{v}]"}
    else
      ret << "msg:[#{msg}]"
    end
    ret.join("\t") + "\n"
  end

  def convert_hash_if_rendering_log(msg)
    return msg unless msg =~ /  Rendered .*/
    messages = {}
    messages[:type] = "rendering"
    msg =~ /  (Rendered) (.*) (.*)/
    messages[:uri] = $2
    messages[:apptime] = $3.gsub(/[\(\)]/, "")
    messages
  end

  def convert_hash_if_request_log(msg)
    return msg unless msg =~ /Started (GET|POST) .*/
    messages = {}

    msg =~ /(Started) (.*) (.*) (.*) (.*) (.*) (.*) (.*) (.*).*/
    messages[:type] = $2
    messages[:uri] = $3
    messages[:host] = $5
    messages
  end

  def convert_hash_if_complete_log(msg)
    return msg unless msg =~ /Completed .*/
    messages = {}
    messages[:type] = "completed"

    msg =~ /(Completed) (.*) (.*) (.*) (.*) (.*) (.*) (.*) (.*) (.*)/
    messages[:status] = $2
    messages[:success] = $3
    messages[:apptime] = $5
    messages[:apptime_view] = $7
    app_time_active_record = $10.nil? ? "" : $10.chop! 
    messages[:apptime_active_record] = app_time_active_record
    messages
  end
end

module ActionController
  class LogSubscriber < ActiveSupport::LogSubscriber
    # 標準のControllerトレースログを無効化
    # application_controller.rbで独自定義したログを利用する。
    def start_processing(event)
    end
  end
end

各種ログ出力サンプル

time:[2013/07/26 23:54:53.656]  level:[INFO]  type:[POST] uri:["/user/create"]  host:[192.168.xxx.xxx]
time:[2013/07/26 23:54:53.708]  level:[INFO]  type:[GET]  uri:["/user/new"] host:[192.168.xxx.xxx]
time:[2013/07/26 23:54:53.711]  level:[DEBUG] se_flg:[start]  user:[admin]  class_name:[UserController] method_name:[new] total_time:[] params:[{"controller"=>"user", "action"=>"new"}]
time:[2013/07/26 23:54:53.716]  level:[INFO]  type:[rendering]  uri:[user/new.html.haml within layouts/application] apptime:[3.6ms]
time:[2013/07/26 23:54:53.722]  level:[INFO]  type:[rendering]  uri:[application/_menu.html.haml] apptime:[0.8ms]
time:[2013/07/26 23:54:53.724]  level:[INFO]  type:[rendering]  uri:[application/_message.html.haml]  apptime:[1.1ms]
time:[2013/07/26 23:54:53.724]  level:[DEBUG] se_flg:[end]  user:[admin]  class_name:[UserController] method_name:[new] total_time:[13 msec]  params:[]
time:[2013/07/26 23:54:53.724]  level:[INFO]  type:[completed]  status:[200]  success:[OK]  apptime:[15ms]  apptime_view:[12.6ms] apptime_active_record:[0.1ms]