Log Resque::Worker through Resque::Logger

This change includes Resque::Logger, a set of wrappers around the
underlying Resque.logger, into Resque::Worker, sending all logging
through that as opposed to just printing it to STDOUT.

Some notes on this change:

* Users can now configure any stdlib Logger duck type they want to do
  their logging. By default it uses Logger.new(STDOUT)

* Resque::Worker.verbose and .very_verbose are presently noops. They
  should probably be deprecated in lieu of setting a severity threshold
  on the logger itself (i.e. Logger::INFO vs Logger::DEBUG). That said,
  they could be made backwards compatible and set the severity level
  automatically (hopefully we'd still deprecate them anyway).

* Testing is made easier by the fact that logging can be intercepted as
  opposed to having to use "capture_io" to make assertions about what is
  being logged or not o_O

* Kernel#warn is now intercepted in classes that include Resque::Logger
  and directed to the log as opposed to STDERR. This may or may not be
  desirable.

* I deleted some tests (which might be a bad idea):
  - "very verbose works in the afternoon" hardcoded the timestamp
    format. I'm going to guess stdlib Logger works in the afternoon
  - There were tests for "displays warning when not using term_child"
    which were using capture_io. Uncertain about the importance of
    displaying this warning and given the wonky nature of the tests, I
    just deleted them for now. I can potentially add them back if they
    were important.

Author: tarcieri

lib/resque/logger.rb

@@ -2,14 +2,14 @@ module Resque
   # Include this module in classes you wish to have logging facilities
   module Logger
     module_function
-    
+
     # Log level aliases
     def debug(message); __log__ :debug, message; end
     def info(message);  __log__ :info,  message; end
     def warn(message);  __log__ :warn,  message; end
     def error(message); __log__ :error, message; end
     def fatal(message); __log__ :fatal, message; end
-    
+
     # Low-level thunk to the logger's own log method
     def __log__(severity, message)
       Resque.logger.__send__(severity, message) if Resque.logger

lib/resque/worker.rb

@@ -7,8 +7,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
+    include Resque::Logger
 
     # Whether the worker should log basic info to STDOUT
     attr_accessor :verbose
@@ -606,19 +607,8 @@ def procline(string)
       log! $0
     end
 
-    # Log a message to STDOUT if we are verbose or very_verbose.
-    def log(message)
-      if verbose
-        puts "*** #{message}"
-      elsif very_verbose
-        time = Time.now.strftime('%H:%M:%S %Y-%m-%d')
-        puts "** [#{time}] #$$: #{message}"
-      end
-    end
-
-    # Logs a very verbose message to STDOUT.
-    def log!(message)
-      log message if very_verbose
-    end
+    # Log a message to Resque.logger
+    alias_method :log,  :info
+    alias_method :log!, :debug
   end
 end

test/logger_test.rb

@@ -1,15 +1,15 @@
 require 'test_helper'
 require 'minitest/mock'
 
-context "Resque.logger" do
+context "Resque::Logger" do
+  teardown { reset_logger }
+
   test "sets and receives the active logger" do
     my_logger = Object.new
     Resque.logger = my_logger
     assert_equal my_logger, Resque.logger
   end
-end
 
-context "Resque::Logger" do
   %w(debug info error fatal).each do |severity|
     test "logs #{severity} messages" do
       message       = "test message"

test/test_helper.rb

@@ -176,3 +176,11 @@ def capture_io
   $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

test/worker_test.rb

@@ -399,25 +399,6 @@ def self.perform
     assert !$BEFORE_FORK_CALLED, "before_fork should not have been called after job runs"
   end
 
-  test "very verbose works in the afternoon" do
-    begin
-      require 'time'
-      last_puts = ""
-      Time.fake_time = Time.parse("15:44:33 2011-03-02")
-
-      @worker.extend(Module.new {
-        define_method(:puts) { |thing| last_puts = thing }
-      })
-
-      @worker.very_verbose = true
-      @worker.log("some log text")
-
-      assert_match /\*\* \[15:44:33 2011-03-02\] \d+: some log text/, last_puts
-    ensure
-      Time.fake_time = nil
-    end
-  end
-
   test "Will call an after_fork hook if we're forking" do
     Resque.redis.flushall
     $AFTER_FORK_CALLED = false
@@ -491,11 +472,32 @@ def sleep(duration = nil)
         end
       end
 
+      class DummyLogger
+        attr_reader :messages
+
+        def initialize
+          @messages = []
+        end
+
+        def info(message); @messages << message; end
+        alias_method :debug, :info
+        alias_method :warn,  :info
+        alias_method :error, :info
+        alias_method :fatal, :info
+      end
+
       @worker.very_verbose = true
-      stdout, stderr = capture_io { @worker.work(0) }
 
-      assert_equal 3, stdout.scan(/retrying/).count
-      assert_equal 1, stdout.scan(/quitting/).count
+      Resque.logger = DummyLogger.new
+      begin
+        @worker.work(0)
+        messages = Resque.logger.messages
+      ensure
+        reset_logger
+      end
+
+      assert_equal 3, messages.grep(/retrying/).count
+      assert_equal 1, messages.grep(/quitting/).count
     ensure
       class Redis::Client
         alias_method :reconnect, :original_reconnect
@@ -640,18 +642,5 @@ def self.perform( run_time, rescue_time=nil )
         end
       end
     end
-
-    test "displays warning when not using term_child" do
-      stdout, stderr = capture_io { @worker.work(0) }
-
-      assert stderr.match(/^WARNING:/)
-    end
-
-    test "it does not display warning when using term_child" do
-      @worker.term_child = "1"
-      stdout, stderr = capture_io { @worker.work(0) }
-
-      assert !stderr.match(/^WARNING:/)
-    end
   end
 end