Merge pull request #996 from ninoseki/improve-logging

refactor: improve logging & error handling

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?

lib/mihari/analyzers/base.rb

@@ -80,27 +80,25 @@ def call
       end
 
       def result(...)
-        res = Try[StandardError] do
+        result = Try[StandardError] do
           retry_on_error(
             times: retry_times,
             interval: retry_interval,
             exponential_backoff: retry_exponential_backoff
           ) 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

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)

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

lib/mihari/emitters/base.rb

@@ -30,13 +30,17 @@ def call(artifacts)
       # @return [Dry::Monads::Result::Success<Object>, 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

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<Object>, 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

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
 

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

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
 

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

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

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