Change exceptions logging: Add logging of exceptions' causes (#38)

README.md

@@ -83,6 +83,13 @@ Sidekiq::Logstash.configure do |config|
   # by default, sidekiq-logstash removes the default error handler
   # to keep it, simply set this to true
   config.keep_default_error_handler = true
+
+  # To enable a log structure that includes details about exception causes,
+  # uncomment the following lines:
+  #
+  # config.log_job_exception_with_causes = true
+  # # To specify the maximum depth of causes to log:
+  # config.causes_logging_max_depth = 3 # Default is 2
 end
 ```
 

lib/sidekiq/exception_utils.rb

@@ -0,0 +1,26 @@
+# frozen_string_literal: true
+
+# Utility that allows us to get a hash representation of an exception
+module ExceptionUtils
+  def self.get_exception_with_cause_hash(exc, parent_backtrace = nil, max_depth_left)
+    backtrace = exc.backtrace || []
+    if parent_backtrace
+      common_lines = backtrace.reverse.zip(parent_backtrace.reverse).take_while { |a, b| a == b }
+
+      backtrace = backtrace[0...-common_lines.length] if common_lines.any?
+    end
+
+    error_hash = {
+      'class' => exc.class.to_s,
+      'message' => exc.message,
+      'backtrace' => backtrace
+    }
+
+    if (cause = exc.cause) && max_depth_left.positive?
+      # Pass the current backtrace as the parent_backtrace to the cause to shorten cause's backtrace list
+      error_hash['cause'] = get_exception_with_cause_hash(cause, exc.backtrace, max_depth_left - 1)
+    end
+
+    error_hash
+  end
+end

lib/sidekiq/logging/shared.rb

@@ -1,5 +1,7 @@
 # frozen_string_literal: true
 
+require 'sidekiq/exception_utils'
+
 module Sidekiq
   module Logging
     # Shared module with all the logics used by job loggers.
@@ -50,10 +52,15 @@ def log_job_exception(job, started_at, exc)
         payload['message'] += ": fail: #{payload['duration']} sec"
         payload['job_status'] = 'fail'
 
-        exc = exc.cause || exc if exc.is_a? Sidekiq::JobRetry::Handled
-        payload['error_message'] = exc.message
-        payload['error'] = exc.class
-        payload['error_backtrace'] = %('#{exc.backtrace.join("\n")}')
+        config = Sidekiq::Logstash.configuration
+        if config.log_job_exception_with_causes
+          payload['error'] = ExceptionUtils.get_exception_with_cause_hash(exc, config.causes_logging_max_depth)
+        else
+          exc = exc.cause || exc if exc.is_a? Sidekiq::JobRetry::Handled
+          payload['error_message'] = exc.message
+          payload['error'] = exc.class
+          payload['error_backtrace'] = %('#{exc.backtrace.join("\n")}')
+        end
 
         process_payload(payload)
       end

lib/sidekiq/logstash/configuration.rb

@@ -4,11 +4,18 @@ module Sidekiq
   module Logstash
     # Class that allows to configure the gem behaviour.
     class Configuration
-      attr_accessor :custom_options, :filter_args, :job_start_log, :keep_default_error_handler
+      attr_accessor :custom_options,
+                    :filter_args,
+                    :job_start_log,
+                    :keep_default_error_handler,
+                    :log_job_exception_with_causes,
+                    :causes_logging_max_depth
 
       def initialize
         @filter_args = []
         @job_start_log = false
+        @log_job_exception_with_causes = false
+        @causes_logging_max_depth = 2
       end
 
       # Added to ensure custom_options is a Proc

spec/sidekiq/logstash_spec.rb

@@ -122,7 +122,7 @@ def process(worker, params = [], encrypt: false)
 
       expect(log_message['error_message']).to eq('You know nothing, Jon Snow.')
       expect(log_message['error']).to eq('RuntimeError')
-      expect(log_message['error_backtrace'].split("\n").first).to include('workers/spec_worker.rb:7')
+      expect(log_message['error_backtrace'].split("\n").first).to include('workers/spec_worker.rb:')
     end
 
     it 'logs the exception without job retry' do
@@ -132,7 +132,66 @@ def process(worker, params = [], encrypt: false)
 
       expect(log_message['error_message']).to eq('You know nothing, Jon Snow.')
       expect(log_message['error']).to eq('RuntimeError')
-      expect(log_message['error_backtrace'].split("\n").first).to include('workers/spec_worker.rb:7')
+      expect(log_message['error_backtrace'].split("\n").first).to include('workers/spec_worker.rb:')
+    end
+
+    context 'log_job_exception_with_causes enabled' do
+      before do
+        Sidekiq::Logstash.configure do |config|
+          config.log_job_exception_with_causes = true
+        end
+      end
+
+      after do
+        Sidekiq::Logstash.configure do |config|
+          config.log_job_exception_with_causes = false
+        end
+      end
+
+      it 'logs the exception with its two causes' do
+        expect { process(SpecWorker, [true]) }.to raise_error(RuntimeError)
+
+        expect(log_message['error']['class']).to eq('Sidekiq::JobRetry::Handled')
+        expect(log_message['error']['message']).to eq('Sidekiq::JobRetry::Handled')
+
+        expect(log_message['error']['cause']['class']).to eq('RuntimeError')
+        expect(log_message['error']['cause']['message']).to eq('You know nothing, Jon Snow.')
+
+        expect(log_message['error']['cause']['cause']['class']).to eq('RuntimeError')
+        expect(log_message['error']['cause']['cause']['message']).to eq('Error rescuing error')
+      end
+
+      context 'causes_logging_max_depth is set to 3' do
+        before do
+          Sidekiq::Logstash.configure do |config|
+            config.log_job_exception_with_causes = true
+            config.causes_logging_max_depth = 3
+          end
+        end
+
+        after do
+          Sidekiq::Logstash.configure do |config|
+            config.log_job_exception_with_causes = true
+            config.causes_logging_max_depth = 2
+          end
+        end
+
+        it 'logs the exception with its three causes' do
+          expect { process(SpecWorker, [true]) }.to raise_error(RuntimeError)
+
+          expect(log_message['error']['class']).to eq('Sidekiq::JobRetry::Handled')
+          expect(log_message['error']['message']).to eq('Sidekiq::JobRetry::Handled')
+
+          expect(log_message['error']['cause']['class']).to eq('RuntimeError')
+          expect(log_message['error']['cause']['message']).to eq('You know nothing, Jon Snow.')
+
+          expect(log_message['error']['cause']['cause']['class']).to eq('RuntimeError')
+          expect(log_message['error']['cause']['cause']['message']).to eq('Error rescuing error')
+
+          expect(log_message['error']['cause']['cause']['cause']['class']).to eq('RuntimeError')
+          expect(log_message['error']['cause']['cause']['cause']['message']).to eq('Deepest error')
+        end
+      end
     end
   end
 

spec/workers/spec_worker.rb

@@ -4,6 +4,16 @@ class SpecWorker
   include Sidekiq::Worker
 
   def perform(fail = false, _params = {})
-    raise 'You know nothing, Jon Snow.' if fail
+    raise_error if fail
+  rescue StandardError
+    raise 'You know nothing, Jon Snow.'
+  end
+
+  private
+
+  def raise_error
+    raise 'Deepest error'
+  rescue StandardError
+    raise 'Error rescuing error'
   end
 end