Unwrap Sidekiq::JobRetry::Handled exception before logging

Issue https://gitlab.com/gitlab-com/gl-infra/scalability/-/issues/640

lib/gitlab/sidekiq_logging/structured_logger.rb

@@ -18,6 +18,17 @@ module Gitlab
         yield
 
         Sidekiq.logger.info log_job_done(job, started_time, base_payload)
+      rescue Sidekiq::JobRetry::Handled => e
+        # Sidekiq::JobRetry::Handled is raised by the internal Sidekiq
+        # processor. It is a wrapper around real exception indicating an
+        # exception is already handled by the Job retrier. The real exception
+        # should be unwrapped before being logged.
+        #
+        # For more information:
+        # https://github.com/mperham/sidekiq/blob/v5.2.7/lib/sidekiq/processor.rb#L173
+        Sidekiq.logger.warn log_job_done(job, started_time, base_payload, e.cause)
+
+        raise
       rescue => job_exception
         Sidekiq.logger.warn log_job_done(job, started_time, base_payload, job_exception)
 
@@ -66,6 +77,7 @@ module Gitlab
           payload['job_status'] = 'fail'
           payload['error_message'] = job_exception.message
           payload['error_class'] = job_exception.class.name
+          add_exception_backtrace!(job_exception, payload)
         else
           payload['message'] = "#{message}: done: #{payload['duration_s']} sec"
           payload['job_status'] = 'done'
@@ -86,6 +98,12 @@ module Gitlab
         payload['completed_at'] = Time.now.utc.to_f
       end
 
+      def add_exception_backtrace!(job_exception, payload)
+        return if job_exception.backtrace.blank?
+
+        payload['error_backtrace'] = Rails.backtrace_cleaner.clean(job_exception.backtrace)
+      end
+
       def elapsed(t0)
         t1 = get_time
         {

spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb

@@ -58,7 +58,8 @@ RSpec.describe Gitlab::SidekiqLogging::StructuredLogger do
         'message' => 'TestWorker JID-da883554ee4fe414012f5f42: fail: 0.0 sec',
         'job_status' => 'fail',
         'error_class' => 'ArgumentError',
-        'error_message' => 'some exception'
+        'error_message' => 'Something went wrong',
+        'error_backtrace' => be_a(Array).and(be_present)
       )
     end
 
@@ -91,18 +92,52 @@ RSpec.describe Gitlab::SidekiqLogging::StructuredLogger do
       it 'logs an exception in job' do
         Timecop.freeze(timestamp) do
           expect(logger).to receive(:info).with(start_payload)
-          expect(logger).to receive(:warn).with(hash_including(exception_payload))
+          expect(logger).to receive(:warn).with(include(exception_payload))
           expect(subject).to receive(:log_job_start).and_call_original
           expect(subject).to receive(:log_job_done).and_call_original
 
           expect do
             subject.call(job, 'test_queue') do
-              raise ArgumentError, 'some exception'
+              raise ArgumentError, 'Something went wrong'
             end
           end.to raise_error(ArgumentError)
         end
       end
 
+      it 'logs the root cause of an Sidekiq::JobRetry::Skip exception in the job' do
+        Timecop.freeze(timestamp) do
+          expect(logger).to receive(:info).with(start_payload)
+          expect(logger).to receive(:warn).with(include(exception_payload))
+          expect(subject).to receive(:log_job_start).and_call_original
+          expect(subject).to receive(:log_job_done).and_call_original
+
+          expect do
+            subject.call(job, 'test_queue') do
+              raise ArgumentError, 'Something went wrong'
+            rescue
+              raise Sidekiq::JobRetry::Skip
+            end
+          end.to raise_error(Sidekiq::JobRetry::Skip)
+        end
+      end
+
+      it 'logs the root cause of an Sidekiq::JobRetry::Handled exception in the job' do
+        Timecop.freeze(timestamp) do
+          expect(logger).to receive(:info).with(start_payload)
+          expect(logger).to receive(:warn).with(include(exception_payload))
+          expect(subject).to receive(:log_job_start).and_call_original
+          expect(subject).to receive(:log_job_done).and_call_original
+
+          expect do
+            subject.call(job, 'test_queue') do
+              raise ArgumentError, 'Something went wrong'
+            rescue
+              raise Sidekiq::JobRetry::Handled
+            end
+          end.to raise_error(Sidekiq::JobRetry::Handled)
+        end
+      end
+
       it 'does not modify the job' do
         Timecop.freeze(timestamp) do
           job_copy = job.deep_dup