概要
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)]