Merge branch 'fix/DEX-2540/error-handling-fix' into 'master'

[DEX-2540] fix: enhance error logging and handling

Closes DEX-2540

See merge request nstmrt/rubygems/outbox!103

Author: mehanoid

.gitlab-ci.yml

@@ -27,6 +27,7 @@ tests:
     DATABASE_URL: postgres://postgres:secret@postgres:5432
     REDIS_URL: redis://redis:6379/0
   before_script:
+    - gem update --system 3.4.22
     - bin/setup
   script:
     - bundle exec appraisal rspec --format RspecJunitFormatter --out test-results/rspec_$RUBY_VERSION.xml --format documentation

CHANGELOG.md

@@ -13,6 +13,16 @@ and this project adheres to [Semantic Versioning](http://semver.org/).
 
 ### Fixed
 
+## [6.10.0] - 2024-09-19
+
+### Changed
+
+- Renamed `backtrace` log tag to `stacktrace` 
+
+### Fixed
+
+- Fixed handling of errors if database is not available 
+
 ## [6.9.0] - 2024-09-13
 
 ### Added

app/interactors/sbmt/outbox/process_item.rb

@@ -11,7 +11,7 @@ class ProcessItem < Sbmt::Outbox::DryInteractor
 
       METRICS_COUNTERS = %i[error_counter retry_counter sent_counter fetch_error_counter discarded_counter].freeze
 
-      delegate :log_success, :log_failure, to: "Sbmt::Outbox.logger"
+      delegate :log_success, :log_info, :log_failure, to: "Sbmt::Outbox.logger"
       delegate :item_process_middlewares, to: "Sbmt::Outbox"
       delegate :box_type, :box_name, :owner, to: :item_class
 
@@ -73,7 +73,7 @@ def fetch_item
         end
 
         unless item.for_processing?
-          log_error("already processed")
+          log_info("already processed")
           counters[:fetch_error_counter] += 1
           return Failure(:already_processed)
         end
@@ -154,7 +154,7 @@ def process_item(transport, item, payload)
       # rubocop:enable Metrics/MethodLength
 
       def track_failed(ex_or_msg, item = nil)
-        log_error(ex_or_msg, item)
+        log_processing_error(ex_or_msg, item)
 
         item&.touch_processed_at
         item&.add_error(ex_or_msg)
@@ -170,6 +170,8 @@ def track_failed(ex_or_msg, item = nil)
           counters[:retry_counter] += 1
           item.pending!
         end
+      rescue => e
+        log_error_handling_error(e, item)
       end
 
       def track_successed(item)
@@ -196,18 +198,28 @@ def track_discarded(item)
         counters[:discarded_counter] += 1
       end
 
-      def log_error(ex_or_msg, item = nil)
+      def log_processing_error(ex_or_msg, item = nil)
         text = format_exception_error(ex_or_msg)
 
         msg = "Failed processing #{box_type} item with error: #{text}.\n" \
               "Record: #{item_class.name}##{item_id}.\n" \
               "#{item&.log_details&.to_json}"
 
-        log_failure(msg, backtrace: format_backtrace(ex_or_msg))
+        log_failure(msg, stacktrace: format_backtrace(ex_or_msg))
       end
 
-      def format_exception_error(e)
-        text = if e.respond_to?(:cause) && !e.cause.nil?
+      def log_error_handling_error(handling_error, item = nil)
+        text = format_exception_error(handling_error, extract_cause: false)
+
+        msg = "Could not persist status of failed #{box_type} item due to error: #{text}.\n" \
+          "Record: #{item_class.name}##{item_id}.\n" \
+          "#{item&.log_details&.to_json}"
+
+        log_failure(msg, stacktrace: format_backtrace(handling_error))
+      end
+
+      def format_exception_error(e, extract_cause: true)
+        text = if extract_cause && e.respond_to?(:cause) && !e.cause.nil?
           "#{format_exception_error(e.cause)}. "
         else
           ""

lib/sbmt/outbox/v1/worker.rb

@@ -218,7 +218,7 @@ def log_fatal(e, job, worker_number)
 
           logger.log_error(
             "Failed processing #{job.resource_key} with error: #{e.class} #{e.message}",
-            backtrace: backtrace
+            stacktrace: backtrace
           )
         end
 

lib/sbmt/outbox/v2/box_processor.rb

@@ -134,7 +134,7 @@ def log_fatal(e, task)
 
           logger.log_error(
             "Failed processing #{task} with error: #{e.class} #{e.message}",
-            backtrace: backtrace
+            stacktrace: backtrace
           )
         end
 

lib/sbmt/outbox/version.rb

@@ -2,6 +2,6 @@
 
 module Sbmt
   module Outbox
-    VERSION = "6.9.0"
+    VERSION = "6.10.0"
   end
 end

spec/interactors/sbmt/outbox/process_item_spec.rb

@@ -24,7 +24,7 @@
       it "returns error" do
         expect(Sbmt::Outbox.error_tracker).to receive(:error)
         expect(Sbmt::Outbox.logger).to receive(:log_failure)
-          .with(/Failed processing outbox item with error: not found/, backtrace: nil)
+          .with(/Failed processing outbox item with error: not found/, stacktrace: nil)
         expect(result).not_to be_success
         expect(dummy_middleware).not_to have_received(:call)
         expect(result.failure).to eq :not_found
@@ -45,8 +45,9 @@
 
       it "doesn't report error" do
         expect(Sbmt::Outbox.error_tracker).not_to receive(:error)
-        expect(Sbmt::Outbox.logger).to receive(:log_failure)
+        allow(Sbmt::Outbox.logger).to receive(:log_info)
         expect(result).not_to be_success
+        expect(Sbmt::Outbox.logger).to have_received(:log_info).with("already processed")
         expect(dummy_middleware).not_to have_received(:call)
         expect(result.failure).to eq :already_processed
       end
@@ -200,7 +201,7 @@
       it "tracks error" do
         expect(Sbmt::Outbox.error_tracker).to receive(:error)
         expect(Sbmt::Outbox.logger).to receive(:log_failure)
-          .with(/Failed processing outbox item with error: RuntimeError boom/, backtrace: kind_of(String))
+          .with(/Failed processing outbox item with error: RuntimeError boom/, stacktrace: kind_of(String))
         expect(result.failure).to eq :transport_failure
       end
 
@@ -211,6 +212,34 @@
       it "tracks Yabeda error counter" do
         expect { result }.to increment_yabeda_counter(Yabeda.outbox.error_counter).by(1)
       end
+
+      context "when error persisting fails" do
+        before do
+          allow_any_instance_of(OutboxItem).to receive(:failed!).and_raise("boom")
+        end
+
+        it "returns error" do
+          expect(result).to be_failure
+        end
+
+        it "logs failure" do
+          expect(Sbmt::Outbox.error_tracker).to receive(:error)
+          allow(Sbmt::Outbox.logger).to receive(:log_failure)
+          expect(result.failure).to eq :transport_failure
+          expect(Sbmt::Outbox.logger)
+            .to have_received(:log_failure)
+            .with(/Could not persist status of failed outbox item due to error: RuntimeError boom/, stacktrace: kind_of(String))
+        end
+
+        it "calls middleware" do
+          result
+          expect(dummy_middleware).to have_received(:call).with(outbox_item)
+        end
+
+        it "tracks Yabeda error counter" do
+          expect { result }.to increment_yabeda_counter(Yabeda.outbox.error_counter).by(1)
+        end
+      end
     end
 
     context "when item processing returning failure" do

spec/lib/sbmt/outbox/v1/worker_spec.rb

@@ -139,7 +139,7 @@
       end
 
       expect(Sbmt::Outbox.logger).to receive(:log_error)
-        .with(/test error/, hash_including(:backtrace))
+        .with(/test error/, hash_including(:stacktrace))
         .and_call_original
 
       worker.start