Add logging

.gitignore

@@ -12,3 +12,5 @@ stdout
 tags
 tags.*
 *.gem
+.ruby-version
+.ruby-gemset

README.md

@@ -361,6 +361,34 @@ Or you can define the entire key by overriding `redis_retry_key`.
       end
     end
 
+### Debugging
+
+By default, resque-retry doesn't log anything, however if you are having trouble understanding why your jobs
+are, or are not, retrying, you can turn logging on.
+
+1. Ensure that `VERBOSE` or `VVERBOSE` are set in your environment.  This will enable log formatters that generate log output.
+2. Ensure that `RESQUE_RETRY_LOGGING` is set to "true" in your environment.  This will enable log messages within resque-retry to be sent to Resque's logger
+
+This will show what resque-retry is doing, and when, as well as your job args and the exception that initiated the retry process.
+
+Example output:
+
+```
+** [09:09:38 2014-04-24] 86961: got: (Job{fire_item_event} | FireItemEventJob | [-2000, "foobar"])
+** [09:09:38 2014-04-24] 86961: Running before_fork hooks with [(Job{fire_item_event} | FireItemEventJob | [-2000, "foobar"])]
+** [09:09:38 2014-04-24] 87285: Running after_fork hooks with [(Job{fire_item_event} | FireItemEventJob | [-2000, "foobar"])]
+** [09:09:38 2014-04-24] 87285: [-2000, "foobar"]: before_perform_retry
+** [09:09:38 2014-04-24] 87285: [-2000, "foobar"]: Attempt 11 set in Redis
+** [09:09:39 2014-04-24] 87285: [-2000, "foobar"] [ActiveRecord::RecordNotFound/No Foobar with id -2000]: on_failure_retry
+** [09:09:39 2014-04-24] 87285: [-2000, "foobar"] [ActiveRecord::RecordNotFound/No Foobar with id -2000]: Retrying based on exception
+** [09:09:39 2014-04-24] 87285: [-2000, "foobar"] [ActiveRecord::RecordNotFound/No Foobar with id -2000]: NOT Retrying based on criteria
+** [09:09:39 2014-04-24] 87285: [-2000, "foobar"] [ActiveRecord::RecordNotFound/No Foobar with id -2000]: retry criteria valid, trying again
+** [09:09:39 2014-04-24] 87285: [-2000, "foobar"] [ActiveRecord::RecordNotFound/No Foobar with id -2000]: trying again
+** [09:09:39 2014-04-24] 87285: [-2000, "foobar"] [ActiveRecord::RecordNotFound/No Foobar with id -2000]: retry delay: 5 for queue FireItemEventJob
+** [09:09:39 2014-04-24] 87285: (Job{fire_item_event} | FireItemEventJob | [-2000, "foobar"]) failed: #<ActiveRecord::RecordNotFound: No Foobar with id -2000>
+```
+
+
 Contributing/Pull Requests
 --------------------------
 

lib/resque/plugins/retry.rb

@@ -230,17 +230,27 @@ def retry_exceptions
       # @api public
       def retry_criteria_valid?(exception, *args)
         # if the retry limit was reached, dont bother checking anything else.
-        return false if retry_limit_reached?
+        if retry_limit_reached?
+          log 'retry limit reached',args,exception
+          return false 
+        end
 
         # We always want to retry if the exception matches.
-        should_retry = retry_exception?(exception)
+        retry_based_on_exception = retry_exception?(exception)
+
+        log "#{retry_based_on_exception ? 'Retrying' : 'NOT Retrying'} based on exception",args,exception
 
-        # call user retry criteria check blocks.
-        retry_criteria_checks.each do |criteria_check|
-          should_retry ||= !!instance_exec(exception, *args, &criteria_check)
+        retry_based_on_criteria = false
+        unless retry_based_on_exception
+          # call user retry criteria check blocks.
+          retry_criteria_checks.each do |criteria_check|
+            retry_based_on_criteria ||= !!instance_exec(exception, *args, &criteria_check)
+          end
         end
 
-        should_retry
+        log "#{retry_based_on_criteria ? 'Retrying' : 'NOT Retrying'} based on criteria",args,exception
+
+        retry_based_on_exception || retry_based_on_criteria
       end
 
       # Retry criteria checks
@@ -297,11 +307,14 @@ def retry_criteria_check(&block)
       #
       # @api private
       def try_again(exception, *args)
+        log "trying again",args,exception
         # some plugins define retry_delay and have it take no arguments, so rather than break those,
         # we'll just check here to see whether it takes the additional exception class argument or not
         temp_retry_delay = ([-1, 1].include?(method(:retry_delay).arity) ? retry_delay(exception.class) : retry_delay)
 
         retry_in_queue = retry_job_delegate ? retry_job_delegate : self
+        log "retry delay: #{temp_retry_delay} for queue #{retry_in_queue}", args,exception
+
         if temp_retry_delay <= 0
           # If the delay is 0, no point passing it through the scheduler
           Resque.enqueue(retry_in_queue, *args_for_retry(*args))
@@ -322,12 +335,15 @@ def try_again(exception, *args)
       #
       # @api private
       def before_perform_retry(*args)
+        log 'before_perform_retry', args
         @on_failure_retry_hook_already_called = false
 
         # store number of retry attempts.
         retry_key = redis_retry_key(*args)
         Resque.redis.setnx(retry_key, -1)             # default to -1 if not set.
         @retry_attempt = Resque.redis.incr(retry_key) # increment by 1.
+        log "attempt #{@retry_attempt} set in Redis", args
+        @retry_attempt
       end
 
       # Resque after_perform hook
@@ -336,6 +352,7 @@ def before_perform_retry(*args)
       #
       # @api private
       def after_perform_retry(*args)
+        log 'after_perform_retry, clearing retry key', args
         clean_retry_key(*args)
       end
 
@@ -350,11 +367,16 @@ def after_perform_retry(*args)
       #
       # @api private
       def on_failure_retry(exception, *args)
-        return if @on_failure_retry_hook_already_called
+        log "on_failure_retry", args,exception
+        if @on_failure_retry_hook_already_called
+          log 'on_failure_retry_hook_already_called', args, exception
+          return 
+        end
 
         if retry_criteria_valid?(exception, *args)
           try_again(exception, *args)
         else
+          log 'retry criteria not sufficient for retry', args, exception
           clean_retry_key(*args)
         end
 
@@ -381,9 +403,27 @@ class << self; self end.class_eval{ undef_method(mname) } rescue nil
       #
       # @api private
       def clean_retry_key(*args)
+        log "Clearing retry key",args
         Resque.redis.del(redis_retry_key(*args))
       end
 
+      # Log messages through the Resque logger.  Generally not for appication
+      # logging-just for interworkings of Resque and plugins.
+      #
+      # Requires that RESQUE_RETRY_LOGGING be set to the string "true" in the environment.
+      #
+      # message:: message to log
+      # args:: args of the resque job in context
+      # exception:: the exception that might be causing a retry
+      def log(message, args, exception=nil)
+        # Resque::Worker will handle interpeting LOGGER, VERBOSE, and VVERBOSE
+        # since everyone is sharing Resque.logger.
+        if Resque.logger && ENV['RESQUE_RETRY_LOGGING'] == 'true'
+          exception_portion = exception.nil? ? '' : " [#{exception.class}/#{exception}]"
+          message = "#{args.inspect}#{exception_portion}: #{message}"
+          Resque.logger.info message if Resque.logger
+        end
+      end
     end
   end
 end

test/test_helper.rb

@@ -45,6 +45,9 @@
 `redis-server #{dir}/redis-test.conf`
 Resque.redis = '127.0.0.1:9736'
 
+# Ensure that log message code is executed and doesn't blow up.
+ENV['RESQUE_RETRY_LOGGING'] = 'true'
+
 # Test helpers
 class MiniTest::Unit::TestCase
   def perform_next_job(worker, &block)