From 4a7da4302dbca2d0b23369b0910a0a2e39b9f428 Mon Sep 17 00:00:00 2001
From: Rachael Ludwick <rachael@ilkjar.com>
Date: Wed, 29 Nov 2017 16:23:49 -0800
Subject: [PATCH] Log at error level on redis exceptions and then warn for
 exception

Backout previous change to the exception handler signature and instead
just log at error level the main part of the redis exception then just
use the original exception handler as-is (at warn level) for the
backtrace. This is a compromise in compatibility insofar as the
backtrace is now at a lower log level, but alerting specifically on
these error strings likely uses the main error strings explicitly logged
before the very verbose backtrace.
---
 lib/sidekiq/exception_handler.rb | 25 ++++++------------------
 lib/sidekiq/processor.rb         |  3 ++-
 lib/sidekiq/scheduled.rb         |  6 ++----
 test/test_processor.rb           | 33 ++------------------------------
 4 files changed, 12 insertions(+), 55 deletions(-)

diff --git a/lib/sidekiq/exception_handler.rb b/lib/sidekiq/exception_handler.rb
index 608e3236..ff07d2ec 100644
--- a/lib/sidekiq/exception_handler.rb
+++ b/lib/sidekiq/exception_handler.rb
@@ -5,32 +5,19 @@ module Sidekiq
   module ExceptionHandler
 
     class Logger
-      def call(ex, ctxHash, options={})
-        # In practice, this will only be called on exceptions so this increase
-        # in complexity in selecting log level is low compared to expense of
-        # the logging messages themselves.
-        options = options || {}
-        level = options.fetch(:level, :warn)
-        Sidekiq.logger.send(level, options[:message]) if options.key?(:message)
-        Sidekiq.logger.send(level, Sidekiq.dump_json(ctxHash)) if !ctxHash.empty?
-        Sidekiq.logger.send(level, "#{ex.class.name}: #{ex.message}")
-        Sidekiq.logger.send(level, ex.backtrace.join("\n")) unless ex.backtrace.nil?
+      def call(ex, ctxHash)
+        Sidekiq.logger.warn(Sidekiq.dump_json(ctxHash)) if !ctxHash.empty?
+        Sidekiq.logger.warn("#{ex.class.name}: #{ex.message}")
+        Sidekiq.logger.warn(ex.backtrace.join("\n")) unless ex.backtrace.nil?
       end
 
-      # Set up default handler which just logs the error
       Sidekiq.error_handlers << Sidekiq::ExceptionHandler::Logger.new
     end
 
-    def handle_exception(ex, ctxHash={}, options={})
+    def handle_exception(ex, ctxHash={})
       Sidekiq.error_handlers.each do |handler|
         begin
-          arity = handler.method(:call).arity
-          # new-style three argument method or fully variable arguments
-          if arity == -3 || arity == -1
-            handler.call(ex, ctxHash, options)
-          else
-            handler.call(ex, ctxHash)
-          end
+          handler.call(ex, ctxHash)
         rescue => ex
           Sidekiq.logger.error "!!! ERROR HANDLER THREW AN ERROR !!!"
           Sidekiq.logger.error ex
diff --git a/lib/sidekiq/processor.rb b/lib/sidekiq/processor.rb
index 1a3f2de1..34a120b0 100644
--- a/lib/sidekiq/processor.rb
+++ b/lib/sidekiq/processor.rb
@@ -110,7 +110,8 @@ module Sidekiq
     def handle_fetch_exception(ex)
       if !@down
         @down = Time.now
-        handle_exception(ex, {}, level: :error, message: 'Error fetching job:')
+        logger.error("Error fetching job: #{ex}")
+        handle_exception(ex, {})
       end
       sleep(1)
       nil
diff --git a/lib/sidekiq/scheduled.rb b/lib/sidekiq/scheduled.rb
index 6f1e87ee..9774c5b6 100644
--- a/lib/sidekiq/scheduled.rb
+++ b/lib/sidekiq/scheduled.rb
@@ -79,9 +79,7 @@ module Sidekiq
           # Most likely a problem with redis networking.
           # Punt and try again at the next interval
           logger.error ex.message
-          ex.backtrace.each do |bt|
-            logger.error(bt)
-          end
+          handle_exception(ex, {})
         end
       end
 
@@ -95,7 +93,7 @@ module Sidekiq
         # if poll_interval_average hasn't been calculated yet, we can
         # raise an error trying to reach Redis.
         logger.error ex.message
-        logger.error ex.backtrace.first
+        handle_exception(ex, {})
         sleep 5
       end
 
diff --git a/test/test_processor.rb b/test/test_processor.rb
index aa87d3a5..c498e8ad 100644
--- a/test/test_processor.rb
+++ b/test/test_processor.rb
@@ -69,8 +69,8 @@ class TestProcessor < Sidekiq::Test
     describe 'exception handling' do
       let(:errors) { [] }
       let(:error_handler) do
-        proc do |exception, context, options={}|
-          errors << { exception: exception, context: context, options: options }
+        proc do |exception, context|
+          errors << { exception: exception, context: context }
         end
       end
 
@@ -139,35 +139,6 @@ class TestProcessor < Sidekiq::Test
         end
 
         assert_instance_of StandardError, errors.last[:exception]
-        assert_equal :error, errors.last[:options][:level]
-      end
-
-      class TestHandler
-        attr_reader :count
-
-        def initialize
-          @count = 0
-        end
-
-        def call(exc, ctx)
-          @count += 1
-        end
-      end
-
-      it 'can call two argument exception handlers' do
-        handler = TestHandler.new
-        Sidekiq.error_handlers << handler
-        job_hash = { 'class' => MockWorker.to_s, 'args' => ['boom'] }
-        msg = Sidekiq.dump_json(job_hash)
-        @processor.instance_variable_set(:'@reloader', proc { raise TEST_EXCEPTION })
-        job = work(msg)
-        begin
-          @processor.instance_variable_set(:'@job', job)
-          @processor.process(job)
-        rescue TestException
-        end
-        assert_equal 1, handler.count
-        Sidekiq.error_handlers.pop
       end
     end