Merge pull request #5 from bnorton/feature/logging

Log information around Message Processing Error handling

lib/howler.rb

@@ -5,6 +5,9 @@ module Howler
   def self.next(id)
     redis.with {|redis| redis.hincrby("next", id.to_s, 1) }.to_i
   end
+  def self.args(args)
+    args.to_s.gsub(/^\[|\]$/, '')
+  end
   def self.redis
     @connection ||= ConnectionPool.new(:timeout => 1, :size => 5) { _redis }
   end

lib/howler/manager.rb

@@ -50,7 +50,7 @@ def run!
 
           messages.each do |message|
             message = Howler::Message.new(MultiJson.decode(message))
-            log.debug("MESG - #{message.klass}.new.#{message.method}(#{message.args.to_s.gsub(/^\[|\]$/, '')})")
+            log.debug("MESG - #{message.id} #{message.klass}.new.#{message.method}(#{Howler.args(message.args)})")
 
             worker = begin_chewing
             worker.perform(message, Howler::Queue::DEFAULT)
@@ -99,6 +99,8 @@ def build_workers
 
     def scale_workers
       delta = ((@workers.size + @chewing.size) - Howler::Config[:concurrency].to_i)
+      return if delta == 0
+
       if delta > 0
         [@workers.size, delta].min.times { @workers.pop }
       elsif delta < 0

lib/howler/queue.rb

@@ -8,6 +8,7 @@ class Queue
     def initialize(identifier = DEFAULT)
       @id = identifier
       @name = "queues:" + identifier
+      @logger = Howler::Logger.new
 
       after_initialize
     end
@@ -35,21 +36,27 @@ def statistics(klass = nil, method = nil, args = nil, created_at = nil, &block)
         :status => 'success'
       }
 
-      begin
-        time = Benchmark.measure do
-          block.call
+      @logger.log do |log|
+        begin
+          time = Benchmark.measure do
+            block.call
+          end
+          metadata.merge!(:time => parse_time(time))
+          Howler.redis.with {|redis| redis.hincrby(name, "success", 1) }
+        rescue Howler::Message::Retry => e
+          log.debug("Howler::Message::Retry - #{klass}.new.#{method}(#{Howler.args(args)})")
+          requeue(metadata, e)
+        rescue Howler::Message::Failed => e
+          log.debug("Howler::Message::Failed - #{klass}.new.#{method}(#{Howler.args(args)})")
+          failed(metadata, e)
+        rescue Howler::Message::Notify => e
+          log.debug("Howler::Message::Notify - #{klass}.new.#{method}(#{Howler.args(args)})")
+          notify(metadata, e)
+        rescue Exception => e
+          log.debug("#{e.to_s} - #{klass}.new.#{method}(#{Howler.args(args)})")
+          metadata[:status] = 'error'
+          Howler.redis.with {|redis| redis.hincrby(name, "error", 1) }
         end
-        metadata.merge!(:time => parse_time(time))
-        Howler.redis.with {|redis| redis.hincrby(name, "success", 1) }
-      rescue Howler::Message::Retry => e
-        requeue(metadata, e)
-      rescue Howler::Message::Failed => e
-        failed(metadata, e)
-      rescue Howler::Message::Notify => e
-        notify(metadata, e)
-      rescue Exception => e
-        metadata[:status] = 'error'
-        Howler.redis.with {|redis| redis.hincrby(name, "error", 1) }
       end
 
       Howler.redis.with {|redis| redis.zadd("#{name}:messages", Time.now.to_f, MultiJson.encode(metadata)) } if %w(success error).include?(metadata[:status])

spec/models/howler_spec.rb

@@ -32,6 +32,16 @@
     end
   end
 
+  describe ".args" do
+    it "should remove square brackets" do
+      Howler.args([]).should == ""
+    end
+
+    it "should remove only leading and trailing brackets" do
+      Howler.args([10, {'akey' => 'avalue'}]).should == '10, {"akey"=>"avalue"}'
+    end
+  end
+
   describe ".redis" do
     let(:pool) { mock("ConnectionPool2") }
 

spec/models/manager_spec.rb

@@ -230,8 +230,8 @@ class SampleEx < Exception; end
         end
 
         it "should show a digest of the messages" do
-          log.should_receive(:debug).with('MESG - Array.new.send_notification(0, "2s")')
-          log.should_receive(:debug).with('MESG - Array.new.enforce_avgs(1, "5k")')
+          log.should_receive(:debug).with('MESG - 123 Array.new.send_notification(0, "2s")')
+          log.should_receive(:debug).with('MESG - 123 Array.new.enforce_avgs(1, "5k")')
 
           subject.run!
         end

spec/models/queue_spec.rb

@@ -19,6 +19,12 @@
 
       Howler.redis.with {|redis| redis.smembers(Howler::Queue::INDEX).include?("queue_name").should be_true }
     end
+
+    it "should have a logger" do
+      Howler::Logger.should_receive(:new)
+
+      Howler::Queue.new
+    end
   end
 
   describe "#id" do
@@ -381,6 +387,105 @@
         end
       end
     end
+
+    describe "logging" do
+      let!(:logger) { mock(Howler::Logger) }
+      let!(:log) { mock(Howler::Logger, :info => nil, :debug => nil) }
+      let!(:block) { lambda {} }
+
+      before do
+        subject.instance_variable_set(:@logger, logger)
+        logger.stub(:log).and_yield(log)
+      end
+
+      describe "information" do
+        before do
+          Howler::Config[:log] = 'info'
+        end
+
+        it "should log the number of messages to be processed" do
+          log.should_not_receive(:info)
+
+          subject.statistics(&block)
+        end
+      end
+
+      describe "debug" do
+        before do
+          Howler::Config[:log] = 'debug'
+        end
+
+        describe "when the block Fails (explicitly)" do
+          before do
+            block.stub(:call).and_raise(Howler::Message::Failed)
+          end
+
+          it "should log to debugging" do
+            log.should_receive(:debug).with("Howler::Message::Failed - Array.new.send(2)")
+
+            subject.statistics(Array, :send, [2], &block)
+          end
+
+          it "should not log information" do
+            log.should_not_receive(:info)
+
+            subject.statistics(Array, :send, [2], &block)
+          end
+        end
+
+        describe "when the block Retries" do
+          before do
+            block.stub(:call).and_raise(Howler::Message::Retry)
+          end
+
+          it "should log to debugging" do
+            log.should_receive(:debug).with("Howler::Message::Retry - Array.new.send(2)")
+
+            subject.statistics(Array, :send, [2], &block)
+          end
+
+          it "should not log information" do
+            log.should_not_receive(:info)
+
+            subject.statistics(Array, :send, [2], &block)
+          end
+        end
+
+        describe "when the block Notifies" do
+          let(:block) { lambda { raise Howler::Message::Notify.new(:after => 1.minute)} }
+
+          it "should log to debugging" do
+            log.should_receive(:debug).with("Howler::Message::Notify - Array.new.send(2)")
+
+            subject.statistics(Array, :send, [2], &block)
+          end
+
+          it "should not log information" do
+            log.should_not_receive(:info)
+
+            subject.statistics(Array, :send, [2], &block)
+          end
+        end
+
+        describe "when the block fails" do
+          before do
+            block.stub(:call).and_raise(Exception)
+          end
+
+          it "should log to debugging" do
+            log.should_receive(:debug).with("Exception - Array.new.send(2)")
+
+            subject.statistics(Array, :send, [2], &block)
+          end
+
+          it "should not log information" do
+            log.should_not_receive(:info)
+
+            subject.statistics(Array, :send, [2], &block)
+          end
+        end
+      end
+    end
   end
 
   describe "#requeue" do