From 8cc8fe72c22e051f6c0ca928cf3a4bebb4528954 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=D0=93=D1=80=D0=B8=D0=B3=D0=BE=D1=80=D1=8C=D0=B5=D0=B2=20?= =?UTF-8?q?=D0=9E=D0=BB=D0=B5=D0=B3=20=D0=98=D0=B3=D0=BE=D1=80=D0=B5=D0=B2?= =?UTF-8?q?=D0=B8=D1=87?= Date: Mon, 23 Sep 2024 08:47:47 +0000 Subject: [PATCH] [DEX-2540] fix: enhance error logging and handling --- .gitlab-ci.yml | 1 + CHANGELOG.md | 10 ++++++ app/interactors/sbmt/outbox/process_item.rb | 26 ++++++++++---- lib/sbmt/outbox/v1/worker.rb | 2 +- lib/sbmt/outbox/v2/box_processor.rb | 2 +- lib/sbmt/outbox/version.rb | 2 +- .../sbmt/outbox/process_item_spec.rb | 35 +++++++++++++++++-- spec/lib/sbmt/outbox/v1/worker_spec.rb | 2 +- 8 files changed, 66 insertions(+), 14 deletions(-) diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index 0fcc4c7..9a72bab 100644 --- a/.gitlab-ci.yml +++ b/.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 diff --git a/CHANGELOG.md b/CHANGELOG.md index 5a2c219..33ba154 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/app/interactors/sbmt/outbox/process_item.rb b/app/interactors/sbmt/outbox/process_item.rb index 59d1f70..a3be795 100644 --- a/app/interactors/sbmt/outbox/process_item.rb +++ b/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 "" diff --git a/lib/sbmt/outbox/v1/worker.rb b/lib/sbmt/outbox/v1/worker.rb index 1da513e..a3f37d0 100644 --- a/lib/sbmt/outbox/v1/worker.rb +++ b/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 diff --git a/lib/sbmt/outbox/v2/box_processor.rb b/lib/sbmt/outbox/v2/box_processor.rb index 90f901b..a6f3d12 100644 --- a/lib/sbmt/outbox/v2/box_processor.rb +++ b/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 diff --git a/lib/sbmt/outbox/version.rb b/lib/sbmt/outbox/version.rb index 2fd744f..27386fa 100644 --- a/lib/sbmt/outbox/version.rb +++ b/lib/sbmt/outbox/version.rb @@ -2,6 +2,6 @@ module Sbmt module Outbox - VERSION = "6.9.0" + VERSION = "6.10.0" end end diff --git a/spec/interactors/sbmt/outbox/process_item_spec.rb b/spec/interactors/sbmt/outbox/process_item_spec.rb index 16fbafc..c964df8 100644 --- a/spec/interactors/sbmt/outbox/process_item_spec.rb +++ b/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 diff --git a/spec/lib/sbmt/outbox/v1/worker_spec.rb b/spec/lib/sbmt/outbox/v1/worker_spec.rb index 96a3868..e8e15d7 100644 --- a/spec/lib/sbmt/outbox/v1/worker_spec.rb +++ b/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