From ab1b54f5c8575f21c4c19fba7e17bdf0cea06d09 Mon Sep 17 00:00:00 2001 From: Manabu Niseki Date: Mon, 8 Jan 2024 16:02:14 +0900 Subject: [PATCH] refactor: improve logging & error handling --- lib/mihari.rb | 11 ++++++++++ lib/mihari/analyzers/base.rb | 18 +++++++--------- lib/mihari/cli/application.rb | 20 ++++++++++++++---- lib/mihari/database.rb | 2 +- lib/mihari/emitters/base.rb | 6 +++++- lib/mihari/enrichers/base.rb | 8 ++++++- lib/mihari/rule.rb | 16 ++------------ spec/mihari_spec.rb | 12 +++++++++++ spec/rule_spec.rb | 27 ++---------------------- spec/services/enrichers_spec.rb | 13 ++++++++++++ spec/sidekiq/artifact_enrich_job_spec.rb | 6 +----- spec/web/endpoints/artifacts_spec.rb | 4 ++-- 12 files changed, 80 insertions(+), 63 deletions(-) create mode 100644 spec/services/enrichers_spec.rb diff --git a/lib/mihari.rb b/lib/mihari.rb index 97da2f93..27c56e3e 100644 --- a/lib/mihari.rb +++ b/lib/mihari.rb @@ -125,6 +125,8 @@ def config end def logger + SemanticLogger.sync! unless puma? + SemanticLogger.default_level = :info SemanticLogger.add_appender(io: $stderr, formatter: :color) SemanticLogger["Mihari"] @@ -152,6 +154,15 @@ def sidekiq? !Mihari.config.sidekiq_redis_url.nil? end + # + # @return [Boolean] + # + def puma? + !Puma.stats.nil? + rescue StandardError + false + end + def initialize_sentry return if Mihari.config.sentry_dsn.nil? return if Sentry.initialized? diff --git a/lib/mihari/analyzers/base.rb b/lib/mihari/analyzers/base.rb index 74121785..026034b1 100644 --- a/lib/mihari/analyzers/base.rb +++ b/lib/mihari/analyzers/base.rb @@ -80,7 +80,7 @@ def call end def result(...) - res = Try[StandardError] do + result = Try[StandardError] do retry_on_error( times: retry_times, interval: retry_interval, @@ -88,19 +88,17 @@ def result(...) ) do call(...) end - end - - return res.recover { [] } if ignore_error? + end.to_result - result = res.to_result return result if result.success? # Wrap failure with AnalyzerError to explicitly name a failed analyzer - Failure AnalyzerError.new( - result.failure.message, - self.class.class_key, - cause: result.failure - ) + error = AnalyzerError.new(result.failure.message, self.class.class_key, cause: result.failure) + return Failure(error) unless ignore_error? + + # Return Success if ignore_error? is true with logging + Mihari.logger.warn("Analyzer:#{self.class.class_key} failed - #{result.failure}") + Success([]) end class << self diff --git a/lib/mihari/cli/application.rb b/lib/mihari/cli/application.rb index 9fba5df5..f772a670 100644 --- a/lib/mihari/cli/application.rb +++ b/lib/mihari/cli/application.rb @@ -38,6 +38,21 @@ class App < Base include Concerns::ErrorUnwrappable no_commands do + # + # @param [StandardError] error + # + # @return [String, Hash, nil] + # + def error_to_detail(error) + # Dirty hack to show the DB error message + # (NOTE: #safe_execute block suppress #with_db_connection's error message) + if error.is_a?(ActiveRecord::StatementInvalid) + return "DB migration is not yet complete. Please run 'mihari db migrate'." + end + + error.respond_to?(:detail) ? error.detail : nil + end + def safe_execute yield rescue StandardError => e @@ -48,10 +63,7 @@ def safe_execute # Raise error if debug is set as true raise error if options["debug"] - data = Entities::ErrorMessage.represent( - message: error.message, - detail: error.respond_to?(:detail) ? error.detail : nil - ) + data = Entities::ErrorMessage.represent(message: error.message, detail: error_to_detail(error)) warn JSON.pretty_generate(data.as_json) Sentry.capture_exception(error) if Sentry.initialized? && !error.is_a?(ValidationError) diff --git a/lib/mihari/database.rb b/lib/mihari/database.rb index d01afb0f..aa58e93d 100644 --- a/lib/mihari/database.rb +++ b/lib/mihari/database.rb @@ -156,7 +156,7 @@ def with_db_connection Mihari::Database.connect unless connected? yield rescue ActiveRecord::StatementInvalid - Mihari.logger.error("The DB migration is not yet complete. Please run 'mihari db migrate'.") + Mihari.logger.error("DB migration is not yet complete. Please run 'mihari db migrate'.") ensure Mihari::Database.close end diff --git a/lib/mihari/emitters/base.rb b/lib/mihari/emitters/base.rb index 0a58a03f..bf1407f1 100644 --- a/lib/mihari/emitters/base.rb +++ b/lib/mihari/emitters/base.rb @@ -30,13 +30,17 @@ def call(artifacts) # @return [Dry::Monads::Result::Success, Dry::Monads::Result::Failure] # def result(artifacts) - Try[StandardError] do + result = Try[StandardError] do retry_on_error( times: retry_times, interval: retry_interval, exponential_backoff: retry_exponential_backoff ) { call(artifacts) } end.to_result + + Mihari.logger.warn("Emitter:#{self.class.class_key} failed - #{result.failure}") if result.failure? + + result end class << self diff --git a/lib/mihari/enrichers/base.rb b/lib/mihari/enrichers/base.rb index bc865e5c..17549ef1 100644 --- a/lib/mihari/enrichers/base.rb +++ b/lib/mihari/enrichers/base.rb @@ -19,17 +19,23 @@ def call(value) raise NotImplementedError, "You must implement #{self.class}##{__method__}" end + # + # @param [Mihari::Models::Artifact] value # # @return [Dry::Monads::Result::Success, Dry::Monads::Result::Failure] # def result(value) - Try[StandardError] do + result = Try[StandardError] do retry_on_error( times: retry_times, interval: retry_interval, exponential_backoff: retry_exponential_backoff ) { call value } end.to_result + + Mihari.logger.warn("Enricher:#{self.class.class_key} failed: #{result.failure}") if result.failure? + + result end class << self diff --git a/lib/mihari/rule.rb b/lib/mihari/rule.rb index 440d0459..fbf2a385 100644 --- a/lib/mihari/rule.rb +++ b/lib/mihari/rule.rb @@ -188,20 +188,8 @@ def enriched_artifacts def bulk_emit return [] if enriched_artifacts.empty? - # NOTE: separate parallel execution and logging - # because the logger does not work along with Parallel - results = Parallel.map(emitters) { |emitter| emitter.result enriched_artifacts } - results.zip(emitters).map do |result_and_emitter| - result, emitter = result_and_emitter - - case result - when Success - Mihari.logger.info "Emission by #{emitter.class} succeed" - else - Mihari.logger.info "Emission by #{emitter.class} failed: #{result.failure}" - end - - result.value_or nil + Parallel.map(emitters) do |emitter| + emitter.result(enriched_artifacts).value_or nil end.compact end diff --git a/spec/mihari_spec.rb b/spec/mihari_spec.rb index 92175ed0..fdda416c 100644 --- a/spec/mihari_spec.rb +++ b/spec/mihari_spec.rb @@ -8,4 +8,16 @@ it "has a config" do expect(described_class.config).not_to be nil end + + describe "#sidekiq?" do + it "returns false in RSpec" do + expect(Mihari.sidekiq?).to eq(false) + end + end + + describe "#puma?" do + it "returns false in RSpec" do + expect(Mihari.puma?).to eq(false) + end + end end diff --git a/spec/rule_spec.rb b/spec/rule_spec.rb index d455425b..b14f2ee6 100644 --- a/spec/rule_spec.rb +++ b/spec/rule_spec.rb @@ -119,37 +119,14 @@ describe "#call" do before do - allow(rule).to receive(:valid_emitters).and_return([]) + allow(rule).to receive(:emitters).and_return([]) allow(rule).to receive(:enriched_artifacts).and_return([ Mihari::Models::Artifact.new(data: Faker::Internet.ip_v4_address) ]) end it "does not raise any error" do - expect do - rule.call - SemanticLogger.flush - end.not_to output.to_stderr - end - - context "when a notifier raises an error" do - before do - # mock emitters - emitter = instance_double("emitter_instance") - allow(emitter).to receive(:configured?).and_return(true) - allow(emitter).to receive(:result).and_return(Dry::Monads::Result::Failure.new("error")) - - # set mocked classes as emitters - allow(rule).to receive(:emitters).and_return([emitter]) - allow(rule).to receive(:enriched_artifacts).and_return([ - Mihari::Models::Artifact.new(data: Faker::Internet.ip_v4_address) - ]) - end - - it do - rule.call - expect(logger_output).to include("Emission by") - end + expect { rule.call }.not_to output.to_stderr end end diff --git a/spec/services/enrichers_spec.rb b/spec/services/enrichers_spec.rb new file mode 100644 index 00000000..1f655f8b --- /dev/null +++ b/spec/services/enrichers_spec.rb @@ -0,0 +1,13 @@ +# frozen_string_literal: true + +RSpec.describe Mihari::Services::ArtifactEnricher do + describe ".call" do + let!(:artifact) do + FactoryBot.create(:artifact, :mail) + end + + it do + expect(described_class.call(artifact.id)).to eq(true) + end + end +end diff --git a/spec/sidekiq/artifact_enrich_job_spec.rb b/spec/sidekiq/artifact_enrich_job_spec.rb index e6bfcefc..6465501b 100644 --- a/spec/sidekiq/artifact_enrich_job_spec.rb +++ b/spec/sidekiq/artifact_enrich_job_spec.rb @@ -3,11 +3,7 @@ RSpec.describe Mihari::Jobs::ArtifactEnrichJob do include_context "with faked Sidekiq configuration" - let!(:artifact) { FactoryBot.create(:artifact) } - - before do - allow(artifact).to receive(:enrich_all).and_return(nil) - end + let!(:artifact) { FactoryBot.create(:artifact, :mail) } it do Sidekiq::Testing.inline! do diff --git a/spec/web/endpoints/artifacts_spec.rb b/spec/web/endpoints/artifacts_spec.rb index db32c7d2..f11f32b1 100644 --- a/spec/web/endpoints/artifacts_spec.rb +++ b/spec/web/endpoints/artifacts_spec.rb @@ -1,9 +1,9 @@ # frozen_string_literal: true -RSpec.describe Mihari::Web::Endpoints::Artifacts, :vcr do +RSpec.describe Mihari::Web::Endpoints::Artifacts do include Rack::Test::Methods - let_it_be(:artifact) { FactoryBot.create(:artifact) } + let_it_be(:artifact) { FactoryBot.create(:artifact, :mail) } let_it_be(:artifact_to_delete) { FactoryBot.create(:artifact) } def app