CODEWITHSUNDEEP
ruby-on-railsruby-on-rails-3
mahemoff
mahemoff

Reputation: 46399

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

Upvotes: 14

Views: 3896

Answers (4)

Jared Beck
Jared Beck

Reputation: 17528

I just wrote a gem for this.

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

Upvotes: 13

Gary S. Weaver
Gary S. Weaver

Reputation: 8096

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

Upvotes: 0

xtoddx
xtoddx

Reputation: 541

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

Upvotes: 6

felipeclopes
felipeclopes

Reputation: 4070

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")}")

Upvotes: 0

Related Questions