Tracking/Logging ActiveRecord Callbacks

问题:

Is there any way to automatically log everytime an ActiveRecord callback happens? It would help to trace through why certain things are happened when a record has several callbacks in place.

I'd like to see automated log message that indicate which messages are being called in response to which callbacks, e.g.: before_validation: calling update_capitalization

回答1:

For google and posterity (on Rails 3):

module CallbackTrace
  def self.included kls
    kls.send :alias_method_chain, :_compile_filter, :trace
  end

  def _compile_filter_with_trace filter
    generated_code = _compile_filter_without_trace(filter)
    return generated_code if filter.is_a?(Array)
    method_name = generated_code.to_s.split(%r{\(|\s}).first
    _klass = @klass
    prelogger = ->{
        Rails.logger.info("START [#{filter.class}](#{generated_code})")
        Rails.logger.info("#{_klass} #{Time.now}")
        if imethod=(_klass.instance_method(method_name) rescue nil)
          begin
            Rails.logger.info(imethod.source)
          rescue MethodSource::SourceNotFoundError
            Rails.logger.info("NO SOURCE FOR #{generated_code}")
          end
        else
          Rails.logger.info("NO METHOD: #{method_name} for #{@klass}")
        end
    }
    postlogger = ->{
      Rails.logger.info("ENDED #{generated_code} #{Time.now}")
    }
    @klass.send :define_method, "prelogger_#{method_name}", &prelogger
    @klass.send :define_method, "postlogger_#{method_name}", &postlogger
    "(prelogger_#{method_name}; retval = retval = #{generated_code}; " +
        "postlogger_#{method_name}; retval)"
  end
end
ActiveSupport::Callbacks::Callback.send :include, CallbackTrace

回答2:

I just wrote a gem for this.

# Gemfile
gem "rails-callback_log", group: [:development, :test]

• https://github.com/jaredbeck/rails-callback_log
• https://rubygems.org/gems/rails-callback_log

回答3:

The easier way is to use the rails native logger methods:

Debugging Rails Applications

Using it like this:

logger.debug "Person attributes hash: #{@person.attributes.inspect}"
logger.info "Processing the request..."
logger.fatal "Terminating application, raised unrecoverable error!!!"

Edit:

To check what was called when an exception ocurred is also interesting to use

logger.error("trace: #{ex.backtrace().join("\n")}")

回答4:

Another way to do it is to define callbacks on all of your models to log. To avoid loading everything, you can just load the models. For simplicity, this tries to load a class corresponding to all files in app/models/*.rb. I'll also use puts, but you could use Rails.logger.info or whatever. For temporary debugging, you could put this into an initializer, e.g. config/initializers/001_log_callbacks.rb:

# Log all callbacks
Dir[Rails.root.join('app/models/*.rb').to_s].each do |filename|
  name = File.basename(filename, '.rb')
  begin
    model = name.camelize.constantize
    ActiveRecord::Callbacks::CALLBACKS.each do |callback|
      if callback.to_s.start_with?('around_')
        model.class_eval "#{callback} do |*args, &prc|; puts \"#{model}(\#{id}).#{callback} start\"; prc.call(*args) if prc; puts \"#{model}(\#{id}).#{callback} end\" end"
      else
        model.class_eval "#{callback} do; puts \"#{model}(\#{id}).#{callback}\" end"
      end
    end
  rescue
  end
end