Update Sidekiq logging to use standard Ruby logger

lib/sidekiq/cli.rb

@@ -19,6 +19,7 @@ module Sidekiq
   class CLI
     include Util
 
+    # Used for CLI testing
     attr_accessor :options, :code
 
     def initialize
@@ -26,6 +27,7 @@ module Sidekiq
     end
 
     def parse(args=ARGV)
+      Sidekiq::Util.logger
       parse_options(args)
       validate!
       boot_system
@@ -35,14 +37,14 @@ module Sidekiq
       Sidekiq::Manager.redis = RedisConnection.create(:url => @options[:server], :namespace => @options[:namespace])
       manager = Sidekiq::Manager.new(@options)
       begin
-        log 'Starting processing, hit Ctrl-C to stop'
+        logger.info 'Starting processing, hit Ctrl-C to stop'
         manager.start!
         # HACK need to determine how to pause main thread while
         # waiting for signals.
         sleep
       rescue Interrupt
         # TODO Need clean shutdown support from Celluloid
-        log 'Shutting down, pausing 5 seconds to let workers finish...'
+        logger.info 'Shutting down, pausing 5 seconds to let workers finish...'
         manager.stop!
         manager.wait(:shutdown)
       end
@@ -75,22 +77,19 @@ module Sidekiq
       @options[:queues] << 'default' if @options[:queues].empty?
       @options[:queues].shuffle!
 
-      $DEBUG = @options[:verbose]
-
       if !File.exist?(@options[:require]) ||
          (File.directory?(@options[:require]) && !File.exist?("#{@options[:require]}/config/application.rb"))
-        log "=================================================================="
+        logger.info "=================================================================="
-        log "  Please point sidekiq to a Rails 3 application or a Ruby file    "
+        logger.info "  Please point sidekiq to a Rails 3 application or a Ruby file    "
-        log "  to load your worker classes with -r [DIR|FILE]."
+        logger.info "  to load your worker classes with -r [DIR|FILE]."
-        log "=================================================================="
+        logger.info "=================================================================="
-        log @parser
+        logger.info @parser
         die(1)
       end
     end
 
     def parse_options(argv)
       @options = {
-        :verbose => false,
         :queues => [],
         :processor_count => 25,
         :require => '.',
@@ -106,7 +105,7 @@ module Sidekiq
         end
 
         o.on "-v", "--verbose", "Print more verbose output" do
-          @options[:verbose] = true
+          Sidekiq::Util.logger.level = Logger::DEBUG
         end
 
         o.on "-n", "--namespace NAMESPACE", "namespace worker queues are under" do |arg|
@@ -132,7 +131,7 @@ module Sidekiq
 
       @parser.banner = "sidekiq [options]"
       @parser.on_tail "-h", "--help", "Show help" do
-        log @parser
+        logger.info @parser
         die 1
       end
       @parser.parse!(argv)

lib/sidekiq/manager.rb

@@ -23,8 +23,8 @@ module Sidekiq
     end
 
     def initialize(options={})
-      log "Booting sidekiq #{Sidekiq::VERSION} with Redis at #{redis.client.location}"
+      logger.info "Booting sidekiq #{Sidekiq::VERSION} with Redis at #{redis.client.location}"
-      verbose options.inspect
+      logger.debug { options.inspect }
       @count = options[:processor_count] || 25
       @queues = options[:queues]
       @done_callback = nil
@@ -74,11 +74,6 @@ module Sidekiq
     def processor_died(processor, reason)
       @busy.delete(processor)
 
-      if reason
-        err "Processor death: #{reason}"
-        err reason.backtrace.join("\n")
-      end
-
       unless stopped?
         @ready << Processor.new_link(current_actor)
         dispatch
@@ -103,18 +98,20 @@ module Sidekiq
 
         # Dispatch loop
         loop do
-          break verbose('no processors') if @ready.empty?
+          break logger.debug('no processors') if @ready.empty?
           found = false
           @ready.size.times do
             found ||= find_work(@queues.sample)
           end
-          break verbose('nothing to process') unless found
+          break logger.debug('nothing to process') unless found
         end
 
         # This is the polling loop that ensures we check Redis every
         # second for work, even if there was nothing to do this time
         # around.
-        after(1) { verbose('ping'); dispatch(schedule) } if schedule
+        after(1) do
+          dispatch(schedule)
+        end if schedule
       end
     end
 

lib/sidekiq/middleware/server/airbrake.rb

@@ -1,10 +1,15 @@
+require 'sidekiq/util'
+
 module Sidekiq
   module Middleware
     module Server
       class Airbrake
+        include Util
         def call(*args)
           yield
         rescue => ex
+          logger.warn ex
+          logger.warn ex.backtrace.join("\n")
           send_to_airbrake(args[1], ex) if defined?(::Airbrake)
           raise
         end

lib/sidekiq/testing.rb

@@ -2,17 +2,27 @@ module Sidekiq
   module Worker
 
     ##
-    # The Sidekiq testing infrastructure just overrides perform_async
+    # The Sidekiq testing infrastructure overrides perform_async
     # so that it does not actually touch the network.  Instead it
-    # just stores the asynchronous jobs in a per-class array so that
+    # stores the asynchronous jobs in a per-class array so that
     # their presence/absence can be asserted by your tests.
     #
     # This is similar to ActionMailer's :test delivery_method and its
     # ActionMailer::Base.deliveries array.
+    #
+    # Example:
+    #
+    #   require 'sidekiq/testing'
+    #
+    #   assert_equal 0, HardWorker.jobs.size
+    #   HardWorker.perform_async(:something)
+    #   assert_equal 1, HardWorker.jobs.size
+    #   assert_equal :something, HardWorker.jobs[0]['args'][0]
+    #
     module ClassMethods
       alias_method :perform_async_old, :perform_async
       def perform_async(*args)
-        jobs << args
+        jobs << { 'class' => self.name, 'args' => args }
         true
       end
 

lib/sidekiq/util.rb

@@ -1,6 +1,20 @@
+require 'logger'
+
 module Sidekiq
   module Util
 
+    def self.logger
+      @logger ||= begin
+        log = Logger.new(STDERR)
+        log.level = Logger::INFO
+        log
+      end
+    end
+
+    def self.logger=(log)
+      @logger = (log ? log : Logger.new('/dev/null'))
+    end
+
     def constantize(camel_cased_word)
       names = camel_cased_word.split('::')
       names.shift if names.empty? || names.first.empty?
@@ -15,21 +29,13 @@ module Sidekiq
     def watchdog(last_words)
       yield
     rescue => ex
-      err last_words
+      logger.error last_words
-      err ex
+      logger.error ex
-      err ex.backtrace.join("\n")
+      logger.error ex.backtrace.join("\n")
     end
 
-    def err(msg)
+    def logger
-      STDERR.puts(msg)
+      Sidekiq::Util.logger
-    end
-
-    def log(msg)
-      STDOUT.puts(msg) unless $TESTING
-    end
-
-    def verbose(msg)
-      STDOUT.puts(msg) if $DEBUG
     end
 
     def redis

lib/sidekiq/worker.rb

@@ -24,13 +24,8 @@ module Sidekiq
       base.extend(ClassMethods)
     end
 
-    def info(msg)
+    def logger
-      print "#{msg}\n"
+      Sidekiq::Util.logger
-    end
-    alias_method :log, :info
-
-    def debug(msg)
-      print "#{msg}\n" if $DEBUG
     end
 
     module ClassMethods

test/helper.rb

@@ -7,3 +7,6 @@ end
 require 'minitest/unit'
 require 'minitest/pride'
 require 'minitest/autorun'
+
+require 'sidekiq/util'
+Sidekiq::Util.logger.level = Logger::ERROR