Created
January 3, 2015 22:08
-
-
Save noahsw/bb104ca1253436c55a19 to your computer and use it in GitHub Desktop.
Log4r logger initializer that auto-reloads config and subscribes to Rails notifications
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| # Uncomment these lines to debug Log4r | |
| # trouble = Log4r::Logger.new('log4r') | |
| # trouble.add Log4r::Outputter.stdout | |
| # assign log4r's logger as rails' logger. | |
| log4r_config = YAML.load_file(File.join(File.dirname(__FILE__), "..", "log4r_#{Rails.env}.yml")) | |
| log_cfg = Log4r::YamlConfigurator | |
| log_cfg["ENV"] = Rails.env | |
| log_cfg["HOST"] = `hostname`.to_s.gsub(/\n$/, "") | |
| log_cfg["APPNAME"] = Rails.application.class.parent_name | |
| log_cfg.decode_yaml( log4r_config['log4r_config'] ) | |
| Rails.logger = Log4r::Logger['rails'] | |
| Rails.logger.level = 0 | |
| ActiveRecord::Base.logger = Log4r::Logger['mysql'] | |
| def time_in_ms(start, finish) | |
| ((finish - start).to_f * 100000).round / 100.0 | |
| end | |
| $last_log_check_time = Time.zone.now | |
| def log_time_check | |
| if Time.zone.now - $last_log_check_time > 20.seconds | |
| update_log_levels | |
| $last_log_check_time = Time.zone.now | |
| end | |
| end | |
| def update_log_levels | |
| begin | |
| yaml = YAML::load_file(File.join(Rails.root, "config", "log4r_#{Rails.env}.yml")) | |
| outputters = yaml['log4r_config']['outputters'] | |
| outputters.each do |outputter| | |
| eval("Log4r::Outputter['#{outputter['name']}'].level = Log4r::#{outputter['level']}") if outputter['level'] | |
| end | |
| rescue => e | |
| Rails.logger.error { "Setting the logging level failed: #{e.message}" } | |
| end | |
| end | |
| ActiveSupport::Notifications.subscribe("process_action.action_controller") do |_name, start, finish, _id, payload| | |
| log_time_check | |
| controller_format = "@method @status @path @durationms" | |
| if payload[:exception] || payload[:status] == 500 | |
| #["process_action.action_controller", 0.033505, "b4ebe16ef3da4c5eb902", {:controller=>"MongotestController", :action=>"index", :params=>{"action"=>"index", "controller"=>"mongotest"}, :format=>:html, :method=>"GET", :path=>"/mongotest", :exception=>["Mongoid::Errors::DocumentNotFound", "\nPro ... "]} | |
| Rails.logger.error { | |
| message = controller_format.clone | |
| message.sub!(/@status/, payload[:status].to_s) | |
| message.sub!(/@method/, payload[:method]) | |
| message.sub!(/@path/, payload[:path]) | |
| message.sub!(/@duration/, time_in_ms(start,finish).to_s) | |
| message += " EXCEPTION: #{payload[:exception]}" | |
| message | |
| } | |
| end | |
| if payload[:status] != 200 && payload[:status] != 500 && payload[:exception] | |
| Rails.logger.warn { | |
| message = controller_format.clone | |
| message.sub!(/@status/, payload[:status].to_s) | |
| message.sub!(/@method/, payload[:method]) | |
| message.sub!(/@path/, payload[:path]) | |
| message.sub!(/@duration/, time_in_ms(start,finish).to_s) | |
| message += " EXCEPTION: #{payload[:exception]}" | |
| message | |
| } | |
| end | |
| if payload[:status] == 200 && time_in_ms(start, finish) >= 500 | |
| Rails.logger.warn { | |
| message = controller_format.clone | |
| message.sub!(/@status/, payload[:status].to_s) | |
| message.sub!(/@method/, payload[:method]) | |
| message.sub!(/@path/, payload[:path]) | |
| message.sub!(/@duration/, time_in_ms(start,finish).to_s) | |
| message | |
| } | |
| end | |
| if payload[:status] == 200 && time_in_ms(start, finish) < 500 | |
| Rails.logger.debug { | |
| message = controller_format.clone | |
| message.sub!(/@status/, payload[:status].to_s) | |
| message.sub!(/@method/, payload[:method]) | |
| message.sub!(/@path/, payload[:path]) | |
| message.sub!(/@duration/, time_in_ms(start,finish).to_s) | |
| message | |
| } | |
| end | |
| Rails.logger.debug { | |
| db = (payload[:db_runtime] * 100).round/100.0 rescue "-" | |
| view = (payload[:view_runtime] * 100).round/100.0 rescue "-" | |
| message = "PARAMS: #{payload[:params].to_json } " | |
| message += "TIMING[ms]: sum:#{time_in_ms(start,finish)} db:#{db} view:#{view}" | |
| message | |
| } | |
| end | |
| ActiveSupport::Notifications.subscribe "sql.active_record" do |_name, start, finish, _id, payload| | |
| logger = Log4r::Logger["mysql"] | |
| logger.debug { "(#{time_in_ms(start,finish)}) #{payload[:sql]}" } | |
| end | |
| ActiveSupport::Notifications.subscribe "exception.action_controller" do |_name, _start, _finish, _id, payload| | |
| Rails.logger.error { "msg:#{payload[:message]} - inspect:#{payload[:inspect]} - backtrace:#{payload[:backtrace].to_json}" } | |
| end | |
| ActiveSupport::Notifications.subscribe("factory_girl.run_factory") do |_name, start, finish, _id, payload| | |
| Rails.logger.debug { "Factory: #{payload[:name]} using strategy #{payload[:strategy]}" } | |
| execution_time_in_seconds = finish - start | |
| if execution_time_in_seconds >= 0.5 | |
| Rails.logger.warn { "Slow factory: #{payload[:name]} using strategy #{payload[:strategy]}" } | |
| end | |
| end |
Author
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
This is my
/config/initializers/logger.rbfile. I have my Log4r configs in/config/log4r_production.yml,/config/log4r_staging.yml, etc.