From d71ca6216fd9850781712adcd0c07bfc8fc76955 Mon Sep 17 00:00:00 2001
From: dominh <11135943+dominh@users.noreply.github.com>
Date: Fri, 29 Nov 2024 10:34:42 +0000
Subject: [PATCH] Change exceptions logging: Add logging of exceptions' causes
 (#38)

---
 README.md                             |  7 +++
 lib/sidekiq/exception_utils.rb        | 26 +++++++++++
 lib/sidekiq/logging/shared.rb         | 15 +++++--
 lib/sidekiq/logstash/configuration.rb |  9 +++-
 spec/sidekiq/logstash_spec.rb         | 63 ++++++++++++++++++++++++++-
 spec/workers/spec_worker.rb           | 12 ++++-
 6 files changed, 124 insertions(+), 8 deletions(-)
 create mode 100644 lib/sidekiq/exception_utils.rb

diff --git a/README.md b/README.md
index 94a4a74..e230495 100644
--- a/README.md
+++ b/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
 ```
 
diff --git a/lib/sidekiq/exception_utils.rb b/lib/sidekiq/exception_utils.rb
new file mode 100644
index 0000000..f7e1765
--- /dev/null
+++ b/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
diff --git a/lib/sidekiq/logging/shared.rb b/lib/sidekiq/logging/shared.rb
index 67df5e5..4001fd9 100644
--- a/lib/sidekiq/logging/shared.rb
+++ b/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
diff --git a/lib/sidekiq/logstash/configuration.rb b/lib/sidekiq/logstash/configuration.rb
index d03677d..c2f1d75 100644
--- a/lib/sidekiq/logstash/configuration.rb
+++ b/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
diff --git a/spec/sidekiq/logstash_spec.rb b/spec/sidekiq/logstash_spec.rb
index 6310298..c6bfd1b 100644
--- a/spec/sidekiq/logstash_spec.rb
+++ b/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
 
diff --git a/spec/workers/spec_worker.rb b/spec/workers/spec_worker.rb
index 39e6547..d8dd3e7 100644
--- a/spec/workers/spec_worker.rb
+++ b/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