Merge branch '1-x-stable'

forwardport Resque.logging from 1.x

Conflicts:
	.gitignore
	Gemfile
	HISTORY.md
	lib/resque/version.rb
	lib/resque/worker.rb
	test/resque_failure_redis_test.rb
	test/test_helper.rb
	test/worker_test.rb

Author: hone

HISTORY.md

@@ -2,6 +2,13 @@
 
 * Changed failures retry process to requeue. (@KensoDev #703)
 
+## 1.23.0 (2012-10-01)
+
+* don't run `before_fork` hook if Resque can't fork (@kjwierenga, @tarcieri, #672, #697)
+* don't run `after_fork` hook if Resque can't fork (@kjwierenga, @tarcieri, #672, #697)
+* retry connecting to redis up to 3 times (@trevorturk, #693)
+* pass exceptions raised by the worker into the Failure backend (@trevorturk, #693)
+
 ## 1.22.0 (2012-08-21)
 
 * unregister signal handlers in child process when ENV["TERM_CHILD"] is set (@dylanasmith, #621)

lib/resque.rb

@@ -1,3 +1,4 @@
+require 'logger'
 require 'redis/namespace'
 
 require 'resque/version'
@@ -9,6 +10,10 @@
 
 require 'resque/helpers'
 require 'resque/stat'
+require 'resque/logging'
+require 'resque/log_formatters/quiet_formatter'
+require 'resque/log_formatters/verbose_formatter'
+require 'resque/log_formatters/very_verbose_formatter'
 require 'resque/job'
 require 'resque/worker'
 require 'resque/plugin'
@@ -80,6 +85,9 @@ def redis_id
     end
   end
 
+  # Set or retrieve the current logger object
+  attr_accessor :logger
+
   # The `before_first_fork` hook will be run in the **parent** process
   # only once, before forking to run the first job. Be careful- any
   # changes you make will be permanent for the lifespan of the
@@ -444,3 +452,6 @@ def hooks(name)
   end
 end
 
+# Log to STDOUT by default
+Resque.logger           = Logger.new(STDOUT)
+Resque.logger.formatter = Resque::QuietFormatter.new

lib/resque/log_formatters/quiet_formatter.rb

@@ -0,0 +1,7 @@
+module Resque
+  class QuietFormatter
+    def call(serverity, datetime, progname, msg)
+      ""
+    end
+  end
+end

lib/resque/log_formatters/verbose_formatter.rb

@@ -0,0 +1,7 @@
+module Resque
+  class VerboseFormatter
+    def call(serverity, datetime, progname, msg)
+      "*** #{msg}"
+    end
+  end
+end

lib/resque/log_formatters/very_verbose_formatter.rb

@@ -0,0 +1,8 @@
+module Resque
+  class VeryVerboseFormatter
+    def call(serverity, datetime, progname, msg)
+      time = Time.now.strftime('%H:%M:%S %Y-%m-%d')
+      "** [#{time}] #$$: #{msg}"
+    end
+  end
+end

lib/resque/logging.rb

@@ -0,0 +1,18 @@
+module Resque
+  # Include this module in classes you wish to have logging facilities
+  module Logging
+    module_function
+
+    # Thunk to the logger's own log method (if configured)
+    def self.log(severity, message)
+      Resque.logger.__send__(severity, message) if Resque.logger
+    end
+
+    # Log level aliases
+    def debug(message); Logging.log :debug, message; end
+    def info(message);  Logging.log :info,  message; end
+    def warn(message);  Logging.log :warn,  message; end
+    def error(message); Logging.log :error, message; end
+    def fatal(message); Logging.log :fatal, message; end
+  end
+end

lib/resque/worker.rb

@@ -9,14 +9,9 @@ module Resque
   # It also ensures workers are always listening to signals from you,
   # their master, and can react accordingly.
   class Worker
+    extend  Resque::Helpers
     include Resque::Helpers
-    extend Resque::Helpers
-
-    # Whether the worker should log basic info to STDOUT
-    attr_accessor :verbose
-
-    # Whether the worker should log lots of info to STDOUT
-    attr_accessor  :very_verbose
+    include Resque::Logging
 
     # Boolean indicating whether this worker can or can not fork.
     # Automatically set if a fork(2) fails.
@@ -241,6 +236,24 @@ def reconnect
       end
     end
 
+    # Reconnect to Redis to avoid sharing a connection with the parent,
+    # retry up to 3 times with increasing delay before giving up.
+    def reconnect
+      tries = 0
+      begin
+        redis.client.reconnect
+      rescue Redis::BaseConnectionError
+        if (tries += 1) <= 3
+          log "Error reconnecting to Redis; retrying"
+          sleep(tries)
+          retry
+        else
+          log "Error reconnecting to Redis; quitting"
+          raise
+        end
+      end
+    end
+
     # Returns a list of queues to use when searching for a job.
     # A splat ("*") means you want every queue (in alpha order) - this
     # can be useful for dynamically adding new queues. Low priority queues
@@ -612,17 +625,62 @@ def procline(string)
       log! $0
     end
 
-    # Log a message to STDOUT if we are verbose or very_verbose.
+    # Log a message to Resque.logger
+    # can't use alias_method since info/debug are private methods
     def log(message)
-      if verbose || very_verbose
-        time = Time.now.strftime('%H:%M:%S %Y-%m-%d')
-        puts "[#{time}] #$$: #{message}"
-      end
+      info(message)
     end
 
-    # Logs a very verbose message to STDOUT.
     def log!(message)
-      log message if very_verbose
+      debug(message)
+    end
+
+    # Deprecated legacy methods for controlling the logging threshhold
+    # Use Resque.logger.level now, e.g.:
+    #
+    #     Resque.logger.level = Logger::DEBUG
+    #
+    def verbose
+      logger_severity_deprecation_warning
+      @verbose
+    end
+
+    def very_verbose
+      logger_severity_deprecation_warning
+      @very_verbose
+    end
+
+    def verbose=(value);
+      logger_severity_deprecation_warning
+
+      if value && !very_verbose
+        Resque.logger.formatter = VerboseFormatter.new
+      elsif !value
+        Resque.logger.formatter = QuietFormatter.new
+      end
+
+      @verbose = value
+    end
+
+    def very_verbose=(value)
+      logger_severity_deprecation_warning
+      if value
+        Resque.logger.formatter = VeryVerboseFormatter.new
+      elsif !value && verbose
+        Resque.logger.formatter = VerboseFormatter.new
+      else
+        Resque.logger.formatter = QuietFormatter.new
+      end
+
+      @very_verbose = value
+    end
+
+    def logger_severity_deprecation_warning
+      return if $warned_logger_severity_deprecation
+      Kernel.warn "*** DEPRECATION WARNING: Resque::Worker#verbose and #very_verbose are deprecated. Please set Resque.logger.level instead"
+      Kernel.warn "Called from: #{caller[0..5].join("\n\t")}"
+      $warned_logger_severity_deprecation = true
+      nil
     end
   end
 end

log/.gitignore

@@ -0,0 +1 @@
+*

test/logging_test.rb

@@ -0,0 +1,24 @@
+require 'test_helper'
+require 'minitest/mock'
+
+describe "Resque::Logging" do
+  after { reset_logger }
+
+  it "sets and receives the active logger" do
+    my_logger = Object.new
+    Resque.logger = my_logger
+    assert_equal my_logger, Resque.logger
+  end
+
+  %w(debug info error fatal).each do |severity|
+    it "logs #{severity} messages" do
+      message       = "test message"
+      mock_logger   = MiniTest::Mock.new
+      mock_logger.expect severity.to_sym, nil, [message]
+      Resque.logger = mock_logger
+
+      Resque::Logging.send severity, message
+      mock_logger.verify
+    end
+  end
+end

test/test_helper.rb

@@ -2,8 +2,7 @@
 require 'timeout'
 require 'bundler/setup'
 require 'redis/namespace'
-require 'minitest/unit'
-require 'minitest/spec'
+require 'minitest/autorun'
 
 $dir = File.dirname(File.expand_path(__FILE__))
 $LOAD_PATH.unshift $dir + '/../lib'
@@ -26,17 +25,12 @@
 # kill it when they end
 #
 
-at_exit do
-  next if $!
-
-  exit_code = MiniTest::Unit.new.run(ARGV)
-
+MiniTest::Unit.after_tests do
   processes = `ps -A -o pid,command | grep [r]edis-test`.split($/)
   pids = processes.map { |process| process.split(" ")[0] }
   puts "Killing test redis server..."
   pids.each { |pid| Process.kill("TERM", pid.to_i) }
   system("rm -f #{$dir}/dump.rdb #{$dir}/dump-cluster.rdb")
-  exit exit_code
 end
 
 if ENV.key? 'RESQUE_DISTRIBUTED'
@@ -143,3 +137,27 @@ def now
 
   self.fake_time = nil
 end
+
+# From minitest/unit
+def capture_io
+  require 'stringio'
+
+  orig_stdout, orig_stderr         = $stdout, $stderr
+  captured_stdout, captured_stderr = StringIO.new, StringIO.new
+  $stdout, $stderr                 = captured_stdout, captured_stderr
+
+  yield
+
+  return captured_stdout.string, captured_stderr.string
+ensure
+  $stdout = orig_stdout
+  $stderr = orig_stderr
+end
+
+# Log to log/test.log
+def reset_logger
+  $test_logger ||= Logger.new(File.open(File.expand_path("../../log/test.log", __FILE__), "w"))
+  Resque.logger = $test_logger
+end
+
+reset_logger