require 'timeout' require 'active_support' require 'active_support/core_ext/hash' require "#{File.dirname(__FILE__)}/exception_handling_mailer" EXCEPTION_HANDLING_MAILER_SEND_MAIL = true unless defined?(EXCEPTION_HANDLING_MAILER_SEND_MAIL) _ = ActiveSupport::HashWithIndifferentAccess if defined?(EVENTMACHINE_EXCEPTION_HANDLING) && EVENTMACHINE_EXCEPTION_HANDLING require 'em/protocols/smtpclient' end module ExceptionHandling # never included class Warning < StandardError; end class MailerTimeout < Timeout::Error; end class ClientLoggingError < StandardError; end SUMMARY_THRESHOLD = 5 SUMMARY_PERIOD = 60*60 # 1.hour SECTIONS = [:request, :session, :environment, :backtrace, :event_response] EXCEPTION_FILTER_LIST_PATH = "#{defined?(Rails) ? Rails.root : '.'}/config/exception_filters.yml" ENVIRONMENT_WHITELIST = [ /^HTTP_/, /^QUERY_/, /^REQUEST_/, /^SERVER_/ ] ENVIRONMENT_OMIT =( < ex data.merge!(:environment => "Exception in yield: #{ex.class}:#{ex}") end elsif controller # most of the time though, this method will not get passed a block # and additional hash data is extracted from the controller extract_and_merge_controller_data(controller, data) end log_error_email(data, ex) end rescue Exception => ex $stderr.puts("ExceptionHandling.log_error rescued exception while logging #{exception_context}: #{exception_or_string}:\n#{ex.class}: #{ex}\n#{ex.backtrace.join("\n")}") write_exception_to_log(ex, "ExceptionHandling.log_error rescued exception while logging #{exception_context}: #{exception_or_string}", timestamp) end end # # Write an exception out to the log file using our own custom format. # def write_exception_to_log(ex, exception_context, timestamp) ActiveSupport::Deprecation.silence do ExceptionHandling.logger.fatal( if ActionView::TemplateError === ex "#{ex} Error:#{timestamp}" else "\n(Error:#{timestamp}) #{ex.class} #{exception_context} (#{ex.message}):\n " + clean_backtrace(ex).join("\n ") + "\n\n" end ) end end # # Pull certain fields out of the controller and add to the data hash. # def extract_and_merge_controller_data(controller, data) data[:request] = { :params => controller.request.parameters.to_hash, :rails_root => Rails.root, :url => controller.complete_request_uri } data[:environment].merge!(controller.request.env.to_hash) controller.session[:fault_in_session] data[:session] = { :key => controller.request.session_options[:id], :data => controller.session.dup } end def log_warning( message ) log_error( Warning.new(message) ) end def log_info( message ) ExceptionHandling.logger.info( message ) end def log_debug( message ) ExceptionHandling.logger.debug( message ) end def ensure_safe( exception_context = "" ) yield rescue => ex log_error ex, exception_context return nil end def ensure_completely_safe( exception_context = "" ) yield rescue SystemExit, SystemStackError, NoMemoryError, SecurityError, SignalException raise rescue Exception => ex log_error ex, exception_context end def ensure_escalation( email_subject ) begin yield rescue => ex log_error ex escalate(email_subject, ex, ExceptionHandling.last_exception_timestamp) nil end end def set_log_error_timestamp ExceptionHandling.last_exception_timestamp = Time.now.to_i end def should_send_email? defined?( EXCEPTION_HANDLING_MAILER_SEND_MAIL ) && EXCEPTION_HANDLING_MAILER_SEND_MAIL end def trace_timing(description) result = nil time = Benchmark.measure do result = yield end log_info "#{description} %.4fs " % time.real result end def log_periodically(exception_key, interval, message) self.periodic_exception_intervals ||= {} last_logged = self.periodic_exception_intervals[exception_key] if !last_logged || ( (last_logged + interval) < Time.now ) log_error( message ) self.periodic_exception_intervals[exception_key] = Time.now end end # TODO: fix test to not use this. def enhance_exception_data(data) end private def log_error_email( data, exc ) enhance_exception_data( data ) normalize_exception_data( data ) clean_exception_data( data ) SECTIONS.each { |section| add_to_s( data[section] ) if data[section].is_a? Hash } if exception_filters.filtered?( data ) return end if summarize_exception( data ) == :Summarized return end deliver(ExceptionHandling::Mailer.exception_notification(data)) if defined?(Errplane) Errplane.transmit(exc, :custom_data => data) unless exc.is_a?(Warning) end nil end def escalate( email_subject, ex, timestamp ) data = exception_to_data( ex, nil, timestamp ) deliver(ExceptionHandling::Mailer.escalation_notification(email_subject, data)) end def deliver(mail_object) if defined?(EVENTMACHINE_EXCEPTION_HANDLING) && EVENTMACHINE_EXCEPTION_HANDLING EventMachine.schedule do # in case we're running outside the reactor async_send_method = EVENTMACHINE_EXCEPTION_HANDLING == :Synchrony ? :asend : :send smtp_settings = ActionMailer::Base.smtp_settings send_deferrable = EventMachine::Protocols::SmtpClient.__send__( async_send_method, { :host => smtp_settings[:address], :port => smtp_settings[:port], :domain => smtp_settings[:domain], :auth => {:type=>:plain, :username=>smtp_settings[:user_name], :password=>smtp_settings[:password]}, :from => mail_object['from'].to_s, :to => mail_object['to'].to_s, :body => mail_object.body.to_s } ) send_deferrable.errback { |err| ExceptionHandling.logger.fatal("Failed to email by SMTP: #{err.inspect}") } end else safe_email_deliver do mail_object.deliver end end end def safe_email_deliver Timeout::timeout 30, MailerTimeout do yield end rescue StandardError, MailerTimeout => ex $stderr.puts("ExceptionHandling::safe_email_deliver rescued: #{ex.class}: #{ex}\n#{ex.backtrace.join("\n")}") log_error( ex, "ExceptionHandling::safe_email_deliver", nil, true ) end def clean_exception_data( data ) if (as_array = data[:backtrace].to_a).size == 1 data[:backtrace] = as_array.first.to_s.split(/\n\s*/) end if data[:request].is_a?(Hash) && data[:request][:params].is_a?(Hash) data[:request][:params] = clean_params(data[:request][:params]) end if data[:environment].is_a?(Hash) data[:environment] = clean_environment(data[:environment]) end end def normalize_exception_data( data ) if data[:location].nil? data[:location] = {} if data[:request] && data[:request].key?( :params ) data[:location][:controller] = data[:request][:params]['controller'] data[:location][:action] = "fake action" end end if data[:backtrace] && data[:backtrace].first first_line = data[:backtrace].first # template exceptions have the line number and filename as the first element in backtrace if matched = first_line.match( /on line #(\d*) of (.*)/i ) backtrace_hash = {} backtrace_hash[:line] = matched[1] backtrace_hash[:file] = matched[2] else backtrace_hash = Hash[* [:file, :line].zip( first_line.split( ':' )[0..1]).flatten ] end data[:location].merge!( backtrace_hash ) end end def clean_params params params.each do |k, v| params[k] = "[FILTERED]" if k =~ /password/ end end def clean_environment env Hash[ env.map do |k, v| [k, v] if !"#{k}: #{v}".in?(ENVIRONMENT_OMIT) && ENVIRONMENT_WHITELIST.any? { |regex| k =~ regex } end.compact ] end def exception_filters @exception_filters ||= ExceptionFilters.new( EXCEPTION_FILTER_LIST_PATH ) end def clean_backtrace(exception) if exception.backtrace.nil? [''] elsif exception.is_a?(ClientLoggingError) exception.backtrace elsif defined?(Rails) Rails.backtrace_cleaner.clean(exception.backtrace) else exception.backtrace end end def clear_exception_summary @last_exception = nil end # Returns :Summarized iff exception has been added to summary and therefore should not be sent. def summarize_exception( data ) if @last_exception same_signature = @last_exception[:backtrace] == data[:backtrace] case @last_exception[:state] when :NotSummarized if same_signature @last_exception[:count] += 1 if @last_exception[:count] >= SUMMARY_THRESHOLD @last_exception.merge! :state => :Summarized, :first_seen => Time.now, :count => 0 end return nil end when :Summarized if same_signature @last_exception[:count] += 1 if Time.now - @last_exception[:first_seen] > SUMMARY_PERIOD send_exception_summary(data, @last_exception[:first_seen], @last_exception[:count]) @last_exception.merge! :first_seen => Time.now, :count => 0 end return :Summarized elsif @last_exception[:count] > 0 # send the left-over, if any send_exception_summary(@last_exception[:data], @last_exception[:first_seen], @last_exception[:count]) end else raise "Unknown state #{@last_exception[:state]}" end end # New signature we haven't seen before. Not summarized yet--we're just starting the count. @last_exception = { :data => data, :count => 1, :first_seen => Time.now, :backtrace => data[:backtrace], :state => :NotSummarized } nil end def send_exception_summary( exception_data, first_seen, occurrences ) Timeout::timeout 30, MailerTimeout do deliver(ExceptionHandling::Mailer.exception_notification(exception_data, first_seen, occurrences)) end rescue StandardError, MailerTimeout => ex $stderr.puts("ExceptionHandling.log_error_email rescued exception while logging #{exception_context}: #{exception_or_string}:\n#{ex.class}: #{ex}\n#{ex.backtrace.join("\n")}") log_error(ex, "ExceptionHandling::log_error_email rescued exception while logging #{exception_context}: #{exception_or_string}", nil, true) end def add_to_s( data_section ) data_section[:to_s] = dump_hash( data_section ) end def exception_to_data( exception, exception_context, timestamp ) data = ActiveSupport::HashWithIndifferentAccess.new data[:error_class] = exception.class.name data[:error_string]= "#{data[:error_class]}: #{exception.message}" data[:timestamp] = timestamp data[:backtrace] = clean_backtrace(exception) if exception_context && exception_context.is_a?(Hash) # if we are a hash, then we got called from the DebugExceptions rack middleware filter # and we need to do some things different to get the info we want data[:error] = "#{data[:error_class]}: #{exception.message}" data[:session] = exception_context['rack.session'] data[:environment] = exception_context else data[:error] = "#{data[:error_string]}#{': ' + exception_context unless exception_context.blank?}" data[:environment] = { :message => exception_context } end data end def make_exception(exception_or_string) if exception_or_string.is_a?(Exception) exception_or_string else begin # raise to capture a backtrace raise StandardError, exception_or_string rescue => ex ex end end end def dump_hash( h, indent_level = 0 ) result = "" h.sort { |a, b| a.to_s <=> b.to_s }.each do |key, value| result << ' ' * (2 * indent_level) result << "#{key}:" case value when Hash result << "\n" << dump_hash( value, indent_level + 1 ) else result << " #{value}\n" end end unless h.nil? result end end class ExceptionFilters class Filter def initialize filter_name, regexes @regexes = Hash[ regexes.map do |section, regex| section = section.to_sym raise "Unknown section: #{section}" unless section == :error || section.in?( ExceptionHandling::SECTIONS ) [section, (Regexp.new(regex, 'i') unless regex.blank?)] end ] raise "Filter #{filter_name} has all blank regexes: #{regexes.inspect}" if @regexes.all? { |section, regex| regex.nil? } end def match?(exception_data) @regexes.all? do |section, regex| regex.nil? || case exception_data[section] when String regex =~ exception_data[section] when Array exception_data[section].any? { |row| row =~ regex } when Hash exception_data[section] && exception_data[section][:to_s] =~ regex when NilClass false else raise "Unexpected class #{exception_data[section].class.name}" end end end end def initialize( filter_path ) @filter_path = filter_path @filters = { } @filters_last_modified_time = nil end def filtered?( exception_data ) refresh_filters @filters.any? do |name, filter| if ( match = filter.match?( exception_data ) ) ExceptionHandling.logger.warn( "Filtered exception using '#{name}'; not sending email to notify" ) end match end end private def refresh_filters mtime = last_modified_time if @filters_last_modified_time.nil? || mtime != @filters_last_modified_time ExceptionHandling.logger.info( "Reloading filter list from: #{@filter_path}. Last loaded time: #{@filters_last_modified_time}. Last modified time: #{mtime}" ) @filters_last_modified_time = mtime # make race condition fall on the side of reloading unnecessarily next time rather than missing a set of changes @filters = load_file end rescue => ex # any exceptions ExceptionHandling::log_error( ex, "ExceptionRegexes::refresh_filters: #{@filter_path}", nil, true) end def load_file # store all strings from YAML file into regex's on initial load, instead of converting to regex on every exception that is logged filters = YAML::load_file( @filter_path ) Hash[ filters.map do |filter_name, regexes| [filter_name, Filter.new( filter_name, regexes )] end ] end def last_modified_time File.mtime( @filter_path ) end end public module Methods # included on models and controllers protected def log_error(exception_or_string, exception_context = '') controller = self if respond_to?(:request) && respond_to?(:session) ExceptionHandling.log_error(exception_or_string, exception_context, controller) end def log_error_rack(exception_or_string, exception_context = '', rack_filter = '') ExceptionHandling.log_error_rack(exception_or_string, exception_context, controller) end def log_warning(message) log_error(Warning.new(message)) end def log_info(message) ExceptionHandling.logger.info( message ) end def log_debug(message) ExceptionHandling.logger.debug( message ) end def ensure_safe(exception_context = "") begin yield rescue => ex log_error ex, exception_context nil end end def ensure_escalation(*args) ExceptionHandling.ensure_escalation(*args) do yield end end # Store aside the current controller when included LONG_REQUEST_SECONDS = (defined?(Rails) && Rails.env == 'test' ? 300 : 30) def set_current_controller ExceptionHandling.current_controller = self result = nil time = Benchmark.measure do result = yield end name = " in #{controller_name}::#{action_name}" rescue " " log_error( "Long controller action detected#{name} %.4fs " % time.real ) if time.real > LONG_REQUEST_SECONDS && !['development', 'test'].include?(Rails.env) result ensure ExceptionHandling.current_controller = nil end def self.included( controller ) controller.around_filter :set_current_controller if controller.respond_to? :around_filter end end end