From 1235845e545877d84cdc648006cdf173fbdb3395 Mon Sep 17 00:00:00 2001
From: Jeremy Lecour <jlecour@evolix.fr>
Date: Thu, 30 Aug 2018 17:50:38 +0200
Subject: [PATCH] Add a logger to CheckProcessor to log errors for each batch
 of checks

---
 app/services/check_processor.rb       | 47 ++++++++++++++++++++++-----
 lib/tasks/checks.rake                 | 41 +++++++++++++++++------
 test/services/check_processor_test.rb | 13 +++-----
 3 files changed, 74 insertions(+), 27 deletions(-)

diff --git a/app/services/check_processor.rb b/app/services/check_processor.rb
index 9b5a5f9..1b77758 100644
--- a/app/services/check_processor.rb
+++ b/app/services/check_processor.rb
@@ -2,23 +2,54 @@
 # License: GNU AGPL-3+ (see full text in LICENSE file)
 
 module CheckProcessor
-  attr_reader :configuration
+  attr_reader :configuration, :logger
 
   def initialize(configuration:, logger: NullLogger.new)
+    # Levels: debug info warn error fatal
     @logger = logger
     @configuration = configuration
   end
 
-  def sync_dates
-    @sync_started_at = Time.now
-    resolvers.each do |resolver|
-      public_send(resolver).find_each(batch_size: 100).each do |check|
-        process(check)
+  def sync_dates # rubocop:disable Metrics/AbcSize,Metrics/MethodLength
+    sync_started_at = Time.now
+    logger.info "#{self.class.name}: sync_dates has started"
 
-        sleep configuration.interval
+    resolvers.each do |resolver|
+      logger.info "#{self.class.name}: using resolver '#{resolver}'"
+
+      public_send(resolver).find_in_batches(batch_size: 100) do |checks|
+        group_started_at = Time.now
+
+        checks.each do |check|
+          logger.info "#{self.class.name}: processing check ##{check.id}"
+          process(check)
+
+          logger.debug "#{self.class.name}: sleeping #{configuration.interval} seconds"
+          sleep configuration.interval
+        end
+
+        group_finished_at = Time.now
+
+        check_errors_scope(check_ids: checks.map(&:id),
+                           after_date: group_started_at,
+                           before_date: group_finished_at).includes(:check).each do |check_log|
+          message = "#{self.class.name}: check ##{check_log.check_id} for '#{check_log.check.domain}' failed (#{check_log.exit_status}) ; #{check_log.error.lines.first}" # rubocop:disable Metrics/LineLength
+          logger.error(message)
+        end
       end
     end
-    @sync_finished_at = Time.now
+
+    sync_finished_at = Time.now
+    duration = (sync_finished_at - sync_started_at).to_i
+    logger.info "#{self.class.name}: sync_dates has finished (#{duration}s)"
+  end
+
+  def check_errors_scope(check_ids:, before_date: nil, after_date: nil)
+    scope = CheckLog.failed.where("exit_status > 0").where(id: check_ids)
+    scope = scope.where("created_at <= ?", before_date) if before_date
+    scope = scope.where("created_at >= ?", after_date) if after_date
+
+    scope
   end
 
   # :nocov:
diff --git a/lib/tasks/checks.rake b/lib/tasks/checks.rake
index a4ffaf6..7f0e6a6 100644
--- a/lib/tasks/checks.rake
+++ b/lib/tasks/checks.rake
@@ -1,27 +1,48 @@
 # Copyright (C) 2018 Colin Darie <colin@darie.eu>, 2018 Evolix <info@evolix.fr>
 # License: GNU AGPL-3+ (see full text in LICENSE file)
 
+require "null_logger"
+
 namespace :checks do
   namespace :sync_dates do
     task all: [:domain, :ssl]
 
+    def stdout_logger(env={})
+      verbose_mode = env.fetch("VERBOSE") { 0 }.to_i == 1
+      quiet_mode   = env.fetch("QUIET")   { 0 }.to_i == 1
+      silent_mode  = env.fetch("SILENT")  { 0 }.to_i == 1
+
+      if silent_mode
+        NullLogger.new 
+      else
+        logger = Logging.logger(STDOUT)
+        logger.level = if quiet_mode
+          :error
+        elsif verbose_mode
+          :debug
+        else
+          :info
+        end
+
+        logger
+      end
+    end
+
     desc "Refresh domains expiry dates"
     task domain: :environment do
-      logger = Logging.logger(STDOUT)
-      logger.level = :warn
-      configuration = Rails.configuration.chexpire.fetch("checks_domain")
-
-      process = CheckDomainProcessor.new(logger: logger, configuration: configuration)
+      process = CheckDomainProcessor.new(
+        logger: stdout_logger(ENV),
+        configuration: Rails.configuration.chexpire.fetch("checks_domain")
+      )
       process.sync_dates
     end
 
     desc "Refresh SSL expiry dates"
     task ssl: :environment do
-      logger = Logging.logger(STDOUT)
-      logger.level = :warn
-      configuration = Rails.configuration.chexpire.fetch("checks_ssl")
-
-      process = CheckSSLProcessor.new(logger: logger, configuration: configuration)
+      process = CheckSSLProcessor.new(
+        logger: stdout_logger(ENV),
+        configuration: Rails.configuration.chexpire.fetch("checks_ssl")
+      )
       process.sync_dates
     end
   end
diff --git a/test/services/check_processor_test.rb b/test/services/check_processor_test.rb
index 8f8694f..da5b914 100644
--- a/test/services/check_processor_test.rb
+++ b/test/services/check_processor_test.rb
@@ -108,19 +108,15 @@ class CheckProcessorTest < ActiveSupport::TestCase
   test "#sync_dates respects the interval configuration between sends" do
     create_list(:check, 3, :expires_next_week)
 
-    configuration = Minitest::Mock.new
-    2.times do configuration.expect(:long_term_interval, 300) end
-    configuration.expect(:long_term_frequency, 4)
-
-    3.times do
-      configuration.expect(:interval, 0.000001)
-    end
+    configuration = OpenStruct.new(long_term_interval: 300,
+                                   long_term_frequency: 4,
+                                   interval: 0.000001)
 
     processor = CheckDummyProcessor.new(configuration: configuration)
 
     mock = Minitest::Mock.new
     assert_stub = lambda { |actual_time|
-      assert_equal 0.000001, actual_time
+      assert_equal configuration.interval, actual_time
       mock
     }
 
@@ -130,7 +126,6 @@ class CheckProcessorTest < ActiveSupport::TestCase
       end
     end
 
-    configuration.verify
     mock.verify
   end
 end