Add logging

.gitignore

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

lib/resque/failure/multiple_with_retry_suppression.rb

@@ -1,4 +1,5 @@
 require 'resque/failure/multiple'
+require 'resque/plugins/retry/log_formatting'
 
 module Resque
   module Failure
@@ -17,6 +18,7 @@ module Failure
     #   Resque::Failure.backend = Resque::Failure::MultipleWithRetrySuppression
     #
     class MultipleWithRetrySuppression < Multiple
+      include Resque::Plugins::Retry::LogFormatting
       # Called when the job fails
       #
       # If the job will retry, suppress the failure from the other backends.
@@ -25,10 +27,14 @@ class MultipleWithRetrySuppression < Multiple
       #
       # @api private
       def save
+        log 'failure backend save', payload, exception
+
         if !(retryable? && retrying?)
+          log "!(#{retryable?} && #{retryable? && retrying?}) - sending failure to superclass", payload, exception
           cleanup_retry_failure_log!
           super
         elsif retry_delay > 0
+          log "retry_delay: #{retry_delay} > 0 - saving details for resque-web", payload, exception
           data = {
             :failed_at => Time.now.strftime("%Y/%m/%d %H:%M:%S"),
             :payload   => payload,
@@ -40,6 +46,8 @@ def save
           }
 
           Resque.redis.setex(failure_key, 2*retry_delay, Resque.encode(data))
+        else
+          log "retry_delay: #{retry_delay} <= 0 - ignoring", payload, exception
         end
       end
 
@@ -82,6 +90,15 @@ def retrying?
       def cleanup_retry_failure_log!
         Resque.redis.del(failure_key) if retryable?
       end
+
+      def log(message,payload=nil,exception=nil)
+        if Resque.logger
+          args = (payload || {})['args']
+          Resque.logger.info format_message(message,args,exception)
+        else
+          super(message)
+        end
+      end
     end
   end
 end

lib/resque/plugins/retry.rb

@@ -1,4 +1,5 @@
 require 'digest/sha1'
+require 'resque/plugins/retry/log_formatting'
 
 module Resque
   module Plugins
@@ -35,6 +36,7 @@ module Plugins
     #   end
     #
     module Retry
+      include Resque::Plugins::Retry::LogFormatting
 
       # Raised if the retry-strategy cannot be determined or has conflicts
       #
@@ -45,7 +47,7 @@ class AmbiguousRetryStrategyException < StandardError; end
       #
       # @api private
       def self.extended(receiver)
-        if receiver.instance_variable_get("@fatal_exceptions") && receiver.instance_variable_get("@retry_exceptions")
+        if receiver.instance_variable_get('@fatal_exceptions') && receiver.instance_variable_get('@retry_exceptions')
           raise AmbiguousRetryStrategyException.new(%{You can't define both "@fatal_exceptions" and "@retry_exceptions"})
         end
       end
@@ -55,7 +57,7 @@ def self.extended(receiver)
       # @api private
       def inherited(subclass)
         super(subclass)
-        subclass.instance_variable_set("@retry_criteria_checks", retry_criteria_checks.dup)
+        subclass.instance_variable_set('@retry_criteria_checks', retry_criteria_checks.dup)
       end
 
       # @abstract You may override to implement a custom retry identifier,
@@ -81,7 +83,7 @@ def retry_identifier(*args)
       #
       # @api public
       def redis_retry_key(*args)
-        ['resque-retry', name, retry_identifier(*args)].compact.join(":").gsub(/\s/, '')
+        ['resque-retry', name, retry_identifier(*args)].compact.join(':').gsub(/\s/, '')
       end
 
       # Maximum number of retrys we can attempt to successfully perform the job
@@ -230,17 +232,25 @@ 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)
-
-        # call user retry criteria check blocks.
-        retry_criteria_checks.each do |criteria_check|
-          should_retry ||= !!instance_exec(exception, *args, &criteria_check)
+        retry_based_on_exception = retry_exception?(exception)
+        log "Exception is #{retry_based_on_exception ? '' : 'not '}sufficient for a retry", args, exception
+
+        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
+        log "user retry criteria is #{retry_based_on_criteria ? '' : 'not '}sufficient for a retry", args, exception
 
-        should_retry
+        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 'try_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 class: #{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,23 @@ class << self; self end.class_eval{ undef_method(mname) } rescue nil
       #
       # @api private
       def clean_retry_key(*args)
+        log 'clean_retry_key', args
         Resque.redis.del(redis_retry_key(*args))
       end
 
+      # Log messages through the Resque logger.  Generally not for appication
+      # logging-just for inner-workings of Resque and plugins.
+      #
+      # message:: message to log
+      # args:: args of the resque job in context
+      # exception:: the exception that might be causing a retry
+      #
+      # @api private
+      def log(message, args, exception=nil)
+        # Resque::Worker will handle interpeting LOGGER, VERBOSE, and VVERBOSE
+        # since everyone is sharing Resque.logger.
+        Resque.logger.info format_message(message,args,exception) if Resque.logger
+      end
     end
   end
 end

lib/resque/plugins/retry/log_formatting.rb

@@ -0,0 +1,12 @@
+module Resque
+  module Plugins
+    module Retry
+      module LogFormatting
+        def format_message(message,args=nil,exception=nil)
+          exception_portion = exception.nil? ? '' : " [#{exception.class}/#{exception}]"
+          message = "#{args.inspect}#{exception_portion}: #{message}"
+        end
+      end
+    end
+  end
+end