From 5200be320b3414716339ec6934fb480af941699c Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Thu, 24 Apr 2014 08:19:58 -0400 Subject: [PATCH 01/15] ignore rvm/rbenv droppings I like gemsets, but that doesn't mean anyone else should... --- .gitignore | 2 ++ 1 file changed, 2 insertions(+) diff --git a/.gitignore b/.gitignore index 5e4aa59..6aea648 100644 --- a/.gitignore +++ b/.gitignore @@ -12,3 +12,5 @@ stdout tags tags.* *.gem +.ruby-version +.ruby-gemset From 409299a10b1dcf2a68856e21430679779d38e0fa Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Thu, 24 Apr 2014 09:09:57 -0400 Subject: [PATCH 02/15] add logging, in backwards compatible way --- README.md | 28 +++++++++++++++++++ lib/resque/plugins/retry.rb | 54 ++++++++++++++++++++++++++++++++----- test/test_helper.rb | 3 +++ 3 files changed, 78 insertions(+), 7 deletions(-) diff --git a/README.md b/README.md index 0d4ef32..5b52140 100644 --- a/README.md +++ b/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: # +``` + + Contributing/Pull Requests -------------------------- diff --git a/lib/resque/plugins/retry.rb b/lib/resque/plugins/retry.rb index ce12c3e..6ffa473 100644 --- a/lib/resque/plugins/retry.rb +++ b/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 diff --git a/test/test_helper.rb b/test/test_helper.rb index c4fbd57..e1a3aa9 100644 --- a/test/test_helper.rb +++ b/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) From ff3a8362faf7b0ba35aaa1045089e13d9ba22e59 Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Thu, 24 Apr 2014 10:24:18 -0400 Subject: [PATCH 03/15] remove unneeded `if` --- lib/resque/plugins/retry.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/resque/plugins/retry.rb b/lib/resque/plugins/retry.rb index 6ffa473..2d34914 100644 --- a/lib/resque/plugins/retry.rb +++ b/lib/resque/plugins/retry.rb @@ -421,7 +421,7 @@ def log(message, args, exception=nil) 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 + Resque.logger.info message end end end From d65ceea87452723b40f44c162930e34fdab9d0b9 Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Thu, 24 Apr 2014 10:24:28 -0400 Subject: [PATCH 04/15] make invocation style consistent. --- lib/resque/plugins/retry.rb | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/lib/resque/plugins/retry.rb b/lib/resque/plugins/retry.rb index 2d34914..de42977 100644 --- a/lib/resque/plugins/retry.rb +++ b/lib/resque/plugins/retry.rb @@ -231,14 +231,14 @@ def retry_exceptions def retry_criteria_valid?(exception, *args) # if the retry limit was reached, dont bother checking anything else. if retry_limit_reached? - log 'retry limit reached',args,exception + log 'retry limit reached', args, exception return false end # We always want to retry if the exception matches. retry_based_on_exception = retry_exception?(exception) - log "#{retry_based_on_exception ? 'Retrying' : 'NOT Retrying'} based on exception",args,exception + log "#{retry_based_on_exception ? 'Retrying' : 'NOT Retrying'} based on exception", args, exception retry_based_on_criteria = false unless retry_based_on_exception @@ -248,7 +248,7 @@ def retry_criteria_valid?(exception, *args) end end - log "#{retry_based_on_criteria ? 'Retrying' : 'NOT Retrying'} based on criteria",args,exception + log "#{retry_based_on_criteria ? 'Retrying' : 'NOT Retrying'} based on criteria", args, exception retry_based_on_exception || retry_based_on_criteria end @@ -307,13 +307,13 @@ def retry_criteria_check(&block) # # @api private def try_again(exception, *args) - log "trying again",args,exception + 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 + 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 @@ -367,7 +367,7 @@ def after_perform_retry(*args) # # @api private def on_failure_retry(exception, *args) - log "on_failure_retry", args,exception + log "on_failure_retry", args, exception if @on_failure_retry_hook_already_called log 'on_failure_retry_hook_already_called', args, exception return @@ -403,7 +403,7 @@ class << self; self end.class_eval{ undef_method(mname) } rescue nil # # @api private def clean_retry_key(*args) - log "Clearing retry key",args + log "Clearing retry key", args Resque.redis.del(redis_retry_key(*args)) end From 3efb105762b2cf8c7f41a127ec2b7cb021cf3733 Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Thu, 24 Apr 2014 10:28:54 -0400 Subject: [PATCH 05/15] use double-quotes only when interpolating --- lib/resque/plugins/retry.rb | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/lib/resque/plugins/retry.rb b/lib/resque/plugins/retry.rb index de42977..b359070 100644 --- a/lib/resque/plugins/retry.rb +++ b/lib/resque/plugins/retry.rb @@ -45,7 +45,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 +55,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 +81,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 @@ -307,7 +307,7 @@ def retry_criteria_check(&block) # # @api private def try_again(exception, *args) - log "trying again", args, exception + 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) @@ -367,7 +367,7 @@ def after_perform_retry(*args) # # @api private def on_failure_retry(exception, *args) - log "on_failure_retry", args, exception + log 'on_failure_retry', args, exception if @on_failure_retry_hook_already_called log 'on_failure_retry_hook_already_called', args, exception return @@ -403,7 +403,7 @@ class << self; self end.class_eval{ undef_method(mname) } rescue nil # # @api private def clean_retry_key(*args) - log "Clearing retry key", args + log 'Clearing retry key', args Resque.redis.del(redis_retry_key(*args)) end From 404ccb7149a5dc4e0dd507d18659efe69f2974ed Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Thu, 24 Apr 2014 10:30:04 -0400 Subject: [PATCH 06/15] mark as private --- lib/resque/plugins/retry.rb | 2 ++ 1 file changed, 2 insertions(+) diff --git a/lib/resque/plugins/retry.rb b/lib/resque/plugins/retry.rb index b359070..a7a9607 100644 --- a/lib/resque/plugins/retry.rb +++ b/lib/resque/plugins/retry.rb @@ -415,6 +415,8 @@ def clean_retry_key(*args) # 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. From 6500cc64922c19dbaba6740ca8633fb44fa67315 Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Thu, 24 Apr 2014 10:36:02 -0400 Subject: [PATCH 07/15] Fix wrong word/bad spelling in comment --- lib/resque/plugins/retry.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/resque/plugins/retry.rb b/lib/resque/plugins/retry.rb index a7a9607..ac8b5a0 100644 --- a/lib/resque/plugins/retry.rb +++ b/lib/resque/plugins/retry.rb @@ -408,7 +408,7 @@ def clean_retry_key(*args) end # Log messages through the Resque logger. Generally not for appication - # logging-just for interworkings of Resque and plugins. + # logging-just for inner-workings of Resque and plugins. # # Requires that RESQUE_RETRY_LOGGING be set to the string "true" in the environment. # From 6980741e3f8c52a1d4927a65adcef2bd4d469e83 Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Fri, 25 Apr 2014 08:56:24 -0400 Subject: [PATCH 08/15] add logging to failure backend as well --- .../failure/multiple_with_retry_suppression.rb | 17 +++++++++++++++++ lib/resque/plugins/retry.rb | 8 +++----- lib/resque/plugins/retry/logging.rb | 12 ++++++++++++ 3 files changed, 32 insertions(+), 5 deletions(-) create mode 100644 lib/resque/plugins/retry/logging.rb diff --git a/lib/resque/failure/multiple_with_retry_suppression.rb b/lib/resque/failure/multiple_with_retry_suppression.rb index a97165e..7c7ba53 100644 --- a/lib/resque/failure/multiple_with_retry_suppression.rb +++ b/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,7 @@ 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 +27,14 @@ class MultipleWithRetrySuppression < Multiple # # @api private def save + log "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 diff --git a/lib/resque/plugins/retry.rb b/lib/resque/plugins/retry.rb index ac8b5a0..ef15d0f 100644 --- a/lib/resque/plugins/retry.rb +++ b/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 # @@ -420,11 +422,7 @@ def clean_retry_key(*args) 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 - end + Resque.logger.info format_message(message,args,exception) if Resque.logger end end end diff --git a/lib/resque/plugins/retry/logging.rb b/lib/resque/plugins/retry/logging.rb new file mode 100644 index 0000000..5594806 --- /dev/null +++ b/lib/resque/plugins/retry/logging.rb @@ -0,0 +1,12 @@ +module Resque + module Plugins + module Retry + module Logging + 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 From c2689a26c4b06f796fd5c8aa8a0fa75f18e537f4 Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Fri, 25 Apr 2014 08:56:47 -0400 Subject: [PATCH 09/15] default to logging being on --- README.md | 28 ---------------------------- test/test_helper.rb | 3 --- 2 files changed, 31 deletions(-) diff --git a/README.md b/README.md index 5b52140..0d4ef32 100644 --- a/README.md +++ b/README.md @@ -361,34 +361,6 @@ 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: # -``` - - Contributing/Pull Requests -------------------------- diff --git a/test/test_helper.rb b/test/test_helper.rb index e1a3aa9..c4fbd57 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -45,9 +45,6 @@ `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) From 81c16c7227b3b4ec38f444205b804e6f575ea3cf Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Fri, 25 Apr 2014 09:02:34 -0400 Subject: [PATCH 10/15] rename the module --- lib/resque/failure/multiple_with_retry_suppression.rb | 4 ++-- lib/resque/plugins/retry.rb | 4 ++-- lib/resque/plugins/retry/{logging.rb => log_formatting.rb} | 2 +- 3 files changed, 5 insertions(+), 5 deletions(-) rename lib/resque/plugins/retry/{logging.rb => log_formatting.rb} (91%) diff --git a/lib/resque/failure/multiple_with_retry_suppression.rb b/lib/resque/failure/multiple_with_retry_suppression.rb index 7c7ba53..5264205 100644 --- a/lib/resque/failure/multiple_with_retry_suppression.rb +++ b/lib/resque/failure/multiple_with_retry_suppression.rb @@ -1,5 +1,5 @@ require 'resque/failure/multiple' -require 'resque/plugins/retry/logging' +require 'resque/plugins/retry/log_formatting' module Resque module Failure @@ -18,7 +18,7 @@ module Failure # Resque::Failure.backend = Resque::Failure::MultipleWithRetrySuppression # class MultipleWithRetrySuppression < Multiple - include Resque::Plugins::Retry::Logging + include Resque::Plugins::Retry::LogFormatting # Called when the job fails # # If the job will retry, suppress the failure from the other backends. diff --git a/lib/resque/plugins/retry.rb b/lib/resque/plugins/retry.rb index ef15d0f..422e2ce 100644 --- a/lib/resque/plugins/retry.rb +++ b/lib/resque/plugins/retry.rb @@ -1,5 +1,5 @@ require 'digest/sha1' -require 'resque/plugins/retry/logging' +require 'resque/plugins/retry/log_formatting' module Resque module Plugins @@ -36,7 +36,7 @@ module Plugins # end # module Retry - include Resque::Plugins::Retry::Logging + include Resque::Plugins::Retry::LogFormatting # Raised if the retry-strategy cannot be determined or has conflicts # diff --git a/lib/resque/plugins/retry/logging.rb b/lib/resque/plugins/retry/log_formatting.rb similarity index 91% rename from lib/resque/plugins/retry/logging.rb rename to lib/resque/plugins/retry/log_formatting.rb index 5594806..b89938c 100644 --- a/lib/resque/plugins/retry/logging.rb +++ b/lib/resque/plugins/retry/log_formatting.rb @@ -1,7 +1,7 @@ module Resque module Plugins module Retry - module Logging + module LogFormatting def format_message(message,args=nil,exception=nil) exception_portion = exception.nil? ? '' : " [#{exception.class}/#{exception}]" message = "#{args.inspect}#{exception_portion}: #{message}" From 72ac3568d4bade04c77222183b6e2d2d71dbd8a2 Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Fri, 25 Apr 2014 09:02:42 -0400 Subject: [PATCH 11/15] improve log messages based on code review and real use --- .../failure/multiple_with_retry_suppression.rb | 2 +- lib/resque/plugins/retry.rb | 16 ++++++---------- 2 files changed, 7 insertions(+), 11 deletions(-) diff --git a/lib/resque/failure/multiple_with_retry_suppression.rb b/lib/resque/failure/multiple_with_retry_suppression.rb index 5264205..67110a0 100644 --- a/lib/resque/failure/multiple_with_retry_suppression.rb +++ b/lib/resque/failure/multiple_with_retry_suppression.rb @@ -27,7 +27,7 @@ class MultipleWithRetrySuppression < Multiple # # @api private def save - log "save", payload, exception + log 'failure backend save', payload, exception if !(retryable? && retrying?) log "!(#{retryable?} && #{retryable? && retrying?}) - sending failure to superclass", payload, exception diff --git a/lib/resque/plugins/retry.rb b/lib/resque/plugins/retry.rb index 422e2ce..975d0d1 100644 --- a/lib/resque/plugins/retry.rb +++ b/lib/resque/plugins/retry.rb @@ -239,8 +239,7 @@ def retry_criteria_valid?(exception, *args) # We always want to retry if the exception matches. retry_based_on_exception = retry_exception?(exception) - - log "#{retry_based_on_exception ? 'Retrying' : 'NOT Retrying'} based on exception", args, 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 @@ -249,8 +248,7 @@ def retry_criteria_valid?(exception, *args) retry_based_on_criteria ||= !!instance_exec(exception, *args, &criteria_check) end end - - log "#{retry_based_on_criteria ? 'Retrying' : 'NOT Retrying'} based on criteria", args, exception + log "user retry criteria is #{retry_based_on_criteria ? '' : 'not '}sufficient for a retry", args, exception retry_based_on_exception || retry_based_on_criteria end @@ -309,13 +307,13 @@ def retry_criteria_check(&block) # # @api private def try_again(exception, *args) - log 'trying again', args, exception + 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 queue #{retry_in_queue}", args, exception + 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 @@ -344,7 +342,7 @@ def before_perform_retry(*args) 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 + log "attempt: #{@retry_attempt} set in Redis", args @retry_attempt end @@ -405,15 +403,13 @@ class << self; self end.class_eval{ undef_method(mname) } rescue nil # # @api private def clean_retry_key(*args) - log 'Clearing 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. # - # 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 From ff9a16d31b85cfcd6b7e1600619268fe195229dc Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Mon, 28 Apr 2014 09:06:09 -0400 Subject: [PATCH 12/15] module now has all logging code Thisi makes our logging totally independent of whatever logging methods are provided by Resque. We use Resque.logger underneath, but the plugin log statements now go through on interface that we control --- .../multiple_with_retry_suppression.rb | 21 ++++------ lib/resque/plugins/retry.rb | 42 +++++++------------ lib/resque/plugins/retry/log_formatting.rb | 12 ------ lib/resque/plugins/retry/logging.rb | 22 ++++++++++ 4 files changed, 44 insertions(+), 53 deletions(-) delete mode 100644 lib/resque/plugins/retry/log_formatting.rb create mode 100644 lib/resque/plugins/retry/logging.rb diff --git a/lib/resque/failure/multiple_with_retry_suppression.rb b/lib/resque/failure/multiple_with_retry_suppression.rb index 67110a0..4faac2f 100644 --- a/lib/resque/failure/multiple_with_retry_suppression.rb +++ b/lib/resque/failure/multiple_with_retry_suppression.rb @@ -1,5 +1,5 @@ require 'resque/failure/multiple' -require 'resque/plugins/retry/log_formatting' +require 'resque/plugins/retry/logging' module Resque module Failure @@ -18,7 +18,7 @@ module Failure # Resque::Failure.backend = Resque::Failure::MultipleWithRetrySuppression # class MultipleWithRetrySuppression < Multiple - include Resque::Plugins::Retry::LogFormatting + include Resque::Plugins::Retry::Logging # Called when the job fails # # If the job will retry, suppress the failure from the other backends. @@ -27,14 +27,14 @@ class MultipleWithRetrySuppression < Multiple # # @api private def save - log 'failure backend save', payload, exception + log_message 'failure backend save', args_from(payload), exception if !(retryable? && retrying?) - log "!(#{retryable?} && #{retryable? && retrying?}) - sending failure to superclass", payload, exception + log_message "!(#{retryable?} && #{retryable? && retrying?}) - sending failure to superclass", args_from(payload), exception cleanup_retry_failure_log! super elsif retry_delay > 0 - log "retry_delay: #{retry_delay} > 0 - saving details for resque-web", payload, exception + log_message "retry_delay: #{retry_delay} > 0 - saving details for resque-web", args_from(payload), exception data = { :failed_at => Time.now.strftime("%Y/%m/%d %H:%M:%S"), :payload => payload, @@ -47,7 +47,7 @@ def save Resque.redis.setex(failure_key, 2*retry_delay, Resque.encode(data)) else - log "retry_delay: #{retry_delay} <= 0 - ignoring", payload, exception + log_message "retry_delay: #{retry_delay} <= 0 - ignoring", args_from(payload), exception end end @@ -91,13 +91,8 @@ 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 + def args_from(payload) + (payload || {})['args'] end end end diff --git a/lib/resque/plugins/retry.rb b/lib/resque/plugins/retry.rb index 975d0d1..a0a4967 100644 --- a/lib/resque/plugins/retry.rb +++ b/lib/resque/plugins/retry.rb @@ -1,5 +1,5 @@ require 'digest/sha1' -require 'resque/plugins/retry/log_formatting' +require 'resque/plugins/retry/logging' module Resque module Plugins @@ -36,7 +36,7 @@ module Plugins # end # module Retry - include Resque::Plugins::Retry::LogFormatting + include Resque::Plugins::Retry::Logging # Raised if the retry-strategy cannot be determined or has conflicts # @@ -233,13 +233,13 @@ def retry_exceptions def retry_criteria_valid?(exception, *args) # if the retry limit was reached, dont bother checking anything else. if retry_limit_reached? - log 'retry limit reached', args, exception + log_message 'retry limit reached', args, exception return false end # We always want to retry if the exception matches. retry_based_on_exception = retry_exception?(exception) - log "Exception is #{retry_based_on_exception ? '' : 'not '}sufficient for a retry", args, 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 @@ -248,7 +248,7 @@ def retry_criteria_valid?(exception, *args) 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 + log_message "user retry criteria is #{retry_based_on_criteria ? '' : 'not '}sufficient for a retry", args, exception retry_based_on_exception || retry_based_on_criteria end @@ -307,13 +307,13 @@ def retry_criteria_check(&block) # # @api private def try_again(exception, *args) - log 'try_again', args, exception + 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 "retry delay: #{temp_retry_delay} for class: #{retry_in_queue}", args, exception + 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 @@ -335,14 +335,14 @@ def try_again(exception, *args) # # @api private def before_perform_retry(*args) - log '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 "attempt: #{@retry_attempt} set in Redis", args + log_message "attempt: #{@retry_attempt} set in Redis", args @retry_attempt end @@ -352,7 +352,7 @@ def before_perform_retry(*args) # # @api private def after_perform_retry(*args) - log 'after_perform_retry, clearing retry key', args + log_message 'after_perform_retry, clearing retry key', args clean_retry_key(*args) end @@ -367,16 +367,16 @@ def after_perform_retry(*args) # # @api private def on_failure_retry(exception, *args) - log 'on_failure_retry', args, exception + log_message 'on_failure_retry', args, exception if @on_failure_retry_hook_already_called - log 'on_failure_retry_hook_already_called', args, exception + log_message '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 + log_message 'retry criteria not sufficient for retry', args, exception clean_retry_key(*args) end @@ -403,23 +403,9 @@ class << self; self end.class_eval{ undef_method(mname) } rescue nil # # @api private def clean_retry_key(*args) - log 'clean_retry_key', args + log_message '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 diff --git a/lib/resque/plugins/retry/log_formatting.rb b/lib/resque/plugins/retry/log_formatting.rb deleted file mode 100644 index b89938c..0000000 --- a/lib/resque/plugins/retry/log_formatting.rb +++ /dev/null @@ -1,12 +0,0 @@ -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 diff --git a/lib/resque/plugins/retry/logging.rb b/lib/resque/plugins/retry/logging.rb new file mode 100644 index 0000000..36b85ba --- /dev/null +++ b/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 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(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 From de9686bf0a288070c3173eb35cff05f46f3ba29d Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Mon, 28 Apr 2014 09:14:24 -0400 Subject: [PATCH 13/15] ensure we make calls to Redis only once for logging The log message in question needs to distinguish between "job is not retriable" and "job IS retriable, but isn't actually being retried right now". We also don't want to go to Redis more than is required, so intermediate variables to the rescue. Also happens to straighten out that double-negative, DeMorgan's Law-requiring `if` statement expression. --- lib/resque/failure/multiple_with_retry_suppression.rb | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/lib/resque/failure/multiple_with_retry_suppression.rb b/lib/resque/failure/multiple_with_retry_suppression.rb index 4faac2f..0ef5577 100644 --- a/lib/resque/failure/multiple_with_retry_suppression.rb +++ b/lib/resque/failure/multiple_with_retry_suppression.rb @@ -29,12 +29,15 @@ class MultipleWithRetrySuppression < Multiple def save log_message 'failure backend save', args_from(payload), exception - if !(retryable? && retrying?) - log_message "!(#{retryable?} && #{retryable? && retrying?}) - sending failure to superclass", 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 for resque-web", args_from(payload), exception + 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, From ecef752f960bff479d9570518a0345ab8661e3a3 Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Mon, 28 Apr 2014 20:32:08 -0400 Subject: [PATCH 14/15] I can spell. Really. I can. --- lib/resque/plugins/retry/logging.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/resque/plugins/retry/logging.rb b/lib/resque/plugins/retry/logging.rb index 36b85ba..7dce963 100644 --- a/lib/resque/plugins/retry/logging.rb +++ b/lib/resque/plugins/retry/logging.rb @@ -2,7 +2,7 @@ module Resque module Plugins module Retry module Logging - # Log messages through the Resque logger. Generally not for appication + # Log messages through the Resque logger. Generally not for application # logging-just for inner-workings of Resque and plugins. # # message:: message to log From e0fee8a2f030dcc693fef85f56c53db6a14619fa Mon Sep 17 00:00:00 2001 From: Dave Copeland Date: Mon, 28 Apr 2014 20:32:18 -0400 Subject: [PATCH 15/15] formatting --- lib/resque/failure/multiple_with_retry_suppression.rb | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/resque/failure/multiple_with_retry_suppression.rb b/lib/resque/failure/multiple_with_retry_suppression.rb index 0ef5577..ed1c36a 100644 --- a/lib/resque/failure/multiple_with_retry_suppression.rb +++ b/lib/resque/failure/multiple_with_retry_suppression.rb @@ -19,6 +19,7 @@ module Failure # 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.