Merge pull request #99 from stitchfix/add-logging

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/logging'
 
 module Resque
   module Failure
@@ -17,6 +18,8 @@ module Failure
     #   Resque::Failure.backend = Resque::Failure::MultipleWithRetrySuppression
     #
     class MultipleWithRetrySuppression < Multiple
+      include Resque::Plugins::Retry::Logging
+
       # Called when the job fails
       #
       # If the job will retry, suppress the failure from the other backends.
@@ -25,10 +28,17 @@ class MultipleWithRetrySuppression < Multiple
       #
       # @api private
       def save
-        if !(retryable? && retrying?)
+        log_message 'failure backend save', args_from(payload), exception
+
+        retryable = retryable?
+        job_being_retried = retryable && retrying?
+
+        if !job_being_retried
+          log_message "#{retryable ? '' : 'non-'}retriable job is not being retried - sending failure to superclass", args_from(payload), exception
           cleanup_retry_failure_log!
           super
         elsif retry_delay > 0
+          log_message "retry_delay: #{retry_delay} > 0 - saving details in Redis", args_from(payload), exception
           data = {
             :failed_at => Time.now.strftime("%Y/%m/%d %H:%M:%S"),
             :payload   => payload,
@@ -40,6 +50,8 @@ def save
           }
 
           Resque.redis.setex(failure_key, 2*retry_delay, Resque.encode(data))
+        else
+          log_message "retry_delay: #{retry_delay} <= 0 - ignoring", args_from(payload), exception
         end
       end
 
@@ -82,6 +94,10 @@ def retrying?
       def cleanup_retry_failure_log!
         Resque.redis.del(failure_key) if retryable?
       end
+
+      def args_from(payload)
+        (payload || {})['args']
+      end
     end
   end
 end

lib/resque/plugins/retry.rb

@@ -1,4 +1,5 @@
 require 'digest/sha1'
+require 'resque/plugins/retry/logging'
 
 module Resque
   module Plugins
@@ -35,6 +36,7 @@ module Plugins
     #   end
     #
     module Retry
+      include Resque::Plugins::Retry::Logging
 
       # 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_message '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_message "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_message "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_message '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_message "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,14 @@ def try_again(exception, *args)
       #
       # @api private
       def before_perform_retry(*args)
+        log_message '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_message "attempt: #{@retry_attempt} set in Redis", args
         Resque.redis.expire(retry_key, @retry_delay.to_i + @expire_retry_key_after.to_i) if @expire_retry_key_after
       end
 
@@ -337,6 +352,7 @@ def before_perform_retry(*args)
       #
       # @api private
       def after_perform_retry(*args)
+        log_message 'after_perform_retry, clearing retry key', args
         clean_retry_key(*args)
       end
 
@@ -351,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_message 'on_failure_retry', args, exception
+        if @on_failure_retry_hook_already_called
+          log_message 'on_failure_retry_hook_already_called', args, exception
+          return 
+        end
 
         if retry_criteria_valid?(exception, *args)
           try_again(exception, *args)
         else
+          log_message 'retry criteria not sufficient for retry', args, exception
           clean_retry_key(*args)
         end
 
@@ -382,9 +403,9 @@ class << self; self end.class_eval{ undef_method(mname) } rescue nil
       #
       # @api private
       def clean_retry_key(*args)
+        log_message 'clean_retry_key', args
         Resque.redis.del(redis_retry_key(*args))
       end
-
     end
   end
 end

lib/resque/plugins/retry/logging.rb

@@ -0,0 +1,22 @@
+module Resque
+  module Plugins
+    module Retry
+      module Logging
+        # Log messages through the Resque logger.  Generally not for application
+        # 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(message,args=nil,exception=nil)
+          if Resque.logger
+            exception_portion = exception.nil? ? '' : " [#{exception.class}/#{exception}]"
+            Resque.logger.info "#{args.inspect}#{exception_portion}: #{message}"
+          end
+        end
+      end
+    end
+  end
+end