Merge pull request #432 from ualbertalib/add/more_logging_information

Add/more logging information

CHANGELOG.md

@@ -7,6 +7,7 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 and releases in PushmiPullyu adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
 ## [Unreleased]
+ - Add more logging information [#433](https://github.com/ualbertalib/pushmi_pullyu/issues/433)
 
 - Add logic to perform authentication against the V3 Auth protocol
 

lib/pushmi_pullyu/cli.rb

@@ -199,6 +199,8 @@ def rotate_logs
   def run_preservation_cycle
     begin
       entity = queue.wait_next_item
+      PushmiPullyu::Logging.log_preservation_attempt(entity,
+                                                     queue.get_entity_ingestion_attempt(entity))
       return unless entity && entity[:type].present? && entity[:uuid].present?
     rescue StandardError => e
       log_exception(e)
@@ -212,7 +214,7 @@ def run_preservation_cycle
         # Push tarred AIP to swift API
         deposited_file = swift.deposit_file(aip_filename, options[:swift][:container])
         # Log successful preservation event to the log files
-        PushmiPullyu::Logging.log_preservation_event(deposited_file, aip_directory)
+        PushmiPullyu::Logging.log_preservation_success(deposited_file, aip_directory)
       end
     # An EntityInvalid expection means there is a problem with the entity information format so there is no point in
     # readding it to the queue as it will always fail
@@ -221,7 +223,9 @@ def run_preservation_cycle
       log_exception(e)
       begin
         queue.add_entity_in_timeframe(entity)
+        PushmiPullyu::Logging.log_preservation_fail_and_retry(entity, queue.get_entity_ingestion_attempt(entity), e)
       rescue PushmiPullyu::PreservationQueue::MaxDepositAttemptsReached => e
+        PushmiPullyu::Logging.log_preservation_failure(entity, queue.get_entity_ingestion_attempt(entity), e)
         log_exception(e)
       end
 
@@ -244,7 +248,11 @@ def run_tick_loop
 
   def setup_log
     if options[:daemonize]
-      PushmiPullyu::Logging.initialize_logger(PushmiPullyu.application_log_file)
+      PushmiPullyu::Logging.initialize_loggers(
+        log_target: PushmiPullyu.application_log_file,
+        events_target: "#{PushmiPullyu.options[:logdir]}/preservation_events.log",
+        json_target: "#{PushmiPullyu.options[:logdir]}/preservation_events.json"
+      )
     else
       logger.formatter = PushmiPullyu::Logging::SimpleFormatter.new
     end

lib/pushmi_pullyu/logging.rb

@@ -21,14 +21,17 @@ class << self
 
     attr_writer :logger
 
-    def initialize_logger(log_target = $stdout)
+    def initialize_loggers(log_target: $stdout, events_target: $stdout, json_target: $stdout)
+      @preservation_logger = Logger.new(events_target)
+      @preservation_json_logger = Logger.new(json_target)
+
       @logger = Logger.new(log_target)
       @logger.level = Logger::INFO
       @logger
     end
 
     def logger
-      @logger ||= initialize_logger
+      @logger ||= initialize_loggers
     end
 
     def log_aip_activity(aip_directory, message)
@@ -43,10 +46,13 @@ def log_aip_activity(aip_directory, message)
       aip_logger.close
     end
 
-    def log_preservation_event(deposited_file, aip_directory)
-      preservation_logger = Logger.new("#{PushmiPullyu.options[:logdir]}/preservation_events.log")
-      preservation_json_logger = Logger.new("#{PushmiPullyu.options[:logdir]}/preservation_events.json")
+    def log_preservation_event(message, message_json)
+      logger.info(message)
+      @preservation_logger.info(message)
+      @preservation_json_logger.info("#{message_json},")
+    end
 
+    def log_preservation_success(deposited_file, aip_directory)
       message = "#{deposited_file.name} was successfully deposited into Swift Storage!\n" \
                 "Here are the details of this preservation event:\n" \
                 "\tUUID: '#{deposited_file.name}'\n" \
@@ -68,15 +74,62 @@ def log_preservation_event(deposited_file, aip_directory)
         end
       end
 
-      # Log to both the application log, and the preservation log file
-      logger.info(message)
-      preservation_logger.info(message)
+      log_preservation_event(message, preservation_success_to_json(deposited_file, aip_directory))
+    end
 
-      preservation_logger.close
+    def log_preservation_fail_and_retry(entity, retry_attempt, exception)
+      message = "#{entity[:type]} failed to be deposited and will try again.\n" \
+                "Here are the details of this preservation event:\n" \
+                "\t#{entity[:type]} uuid: #{entity[:uuid]}" \
+                "\tReadding to preservation queue with retry attempt: #{retry_attempt}\n" \
+                "\tError of type: #{exception.class.name}\n" \
+                "\tError message: #{exception.message}\n"
+
+      message_information = {
+        event_type: :fail_and_retry,
+        event_time: Time.now.to_s,
+        entity_type: entity[:type],
+        entity_uuid: entity[:uuid],
+        retry_attempt: retry_attempt,
+        error_message: exception.message
+      }
+
+      log_preservation_event(message, message_information.to_json)
+    end
 
-      message_json_str = preservation_event_to_json(deposited_file, aip_directory)
-      preservation_json_logger.info("#{message_json_str},")
-      preservation_json_logger.close
+    def log_preservation_failure(entity, retry_attempt, exception)
+      message = "#{entity[:type]} failed to be deposited.\n" \
+                "Here are the details of this preservation event:\n" \
+                "\t#{entity[:type]} uuid: #{entity[:uuid]}" \
+                "\tRetry attempt: #{retry_attempt}\n"
+
+      message_information = {
+        event_type: :fail_and_retry,
+        event_time: Time.now.to_s,
+        entity_type: entity[:type],
+        entity_uuid: entity[:uuid],
+        retry_attempt: retry_attempt,
+        error_message: exception.message
+      }
+
+      log_preservation_event(message, message_information.to_json)
+    end
+
+    def log_preservation_attempt(entity, retry_attempt)
+      message = "#{entity[:type]} will attempt to be deposited.\n" \
+                "Here are the details of this preservation event:\n" \
+                "\t#{entity[:type]} uuid: #{entity[:uuid]}" \
+                "\tRetry attempt: #{retry_attempt}\n"
+
+      message_information = {
+        event_type: :attempt,
+        event_time: Time.now.to_s,
+        entity_type: entity[:type],
+        entity_uuid: entity[:uuid],
+        retry_attempt: retry_attempt
+      }
+
+      log_preservation_event(message, message_information.to_json)
     end
 
     ###
@@ -107,14 +160,14 @@ def log_preservation_event(deposited_file, aip_directory)
     # note:
     #   to parse, the prefix "I, ... INFO --:" in each line needs to be
     #   stripped using a bash command such as "sed"
-    def preservation_event_to_json(deposited_file, aip_directory)
+    def preservation_success_to_json(deposited_file, aip_directory)
       message = {}
 
       message['do_uuid'] = deposited_file.name.to_s
       message['aip_deposited_at'] = deposited_file.last_modified.to_s
       message['aip_md5sum'] = deposited_file.etag.to_s
       message['aip_sha256'] = ''
-      message['aip_metadata'] = deposited_file.metadata.to_json.to_s
+      message['aip_metadata'] = deposited_file.metadata
 
       file_details = file_log_details(aip_directory)
 
@@ -138,7 +191,7 @@ def reopen
       if @logger
         @logger.reopen
       else
-        @logger = initialize_logger
+        @logger = initialize_loggers
       end
     end
 

lib/pushmi_pullyu/preservation_queue.rb

@@ -70,6 +70,13 @@ def wait_next_item
     end
   end
 
+  def get_entity_ingestion_attempt(entity)
+    entity_attempts_key = "#{PushmiPullyu.options[:ingestion_prefix]}#{entity[:uuid]}"
+    @redis.with do |connection|
+      return connection.get entity_attempts_key
+    end
+  end
+
   def add_entity_in_timeframe(entity)
     entity_attempts_key = "#{PushmiPullyu.options[:ingestion_prefix]}#{entity[:uuid]}"
 

spec/integration/acceptance_spec.rb

@@ -24,7 +24,8 @@
 
     FileUtils.mkdir_p(workdir)
     FileUtils.mkdir_p(log_folder)
-
+    PushmiPullyu::Logging.initialize_loggers(events_target: "#{log_folder}/preservation_events.log",
+                                             json_target: "#{log_folder}/preservation_events.json")
     allow(PushmiPullyu::Logging.logger).to receive(:info)
   end
 
@@ -46,7 +47,6 @@
     # Should not exist yet
     expect(File.exist?(aip_folder)).to be(false)
     expect(File.exist?(aip_file)).to be(false)
-    expect(File.exist?("#{log_folder}/preservation_events.log")).to be(false)
 
     # Download data from Jupiter, bag and tar AIP directory and cleanup after block code
     VCR.use_cassette('aip_download_and_swift_upload', erb:
@@ -72,7 +72,7 @@
         expect(deposited_file.metadata['promise']).to eql 'bronze'
 
         # Log successful preservation event to the log files
-        PushmiPullyu::Logging.log_preservation_event(deposited_file, aip_folder)
+        PushmiPullyu::Logging.log_preservation_success(deposited_file, aip_folder)
       end
     end
 

spec/pushmi_pullyu/cli_spec.rb

@@ -290,7 +290,7 @@
         # expect((readded_entity_score.to_i - test_time).to_i).to eq 10
         cli.parse(['-C', 'spec/fixtures/config_wrong_swift.yml'])
         redis = Redis.new
-        entity = { uuid: '123e4567-e89b-12d3-a456-426614174000', type: 'items' }
+        entity = { uuid: 'e2ec88e3-3266-4e95-8575-8b04fac2a679', type: 'items' }
 
         start_time = Time.now - 10
         attempt_key = "#{PushmiPullyu.options[:ingestion_prefix]}#{entity[:uuid]}"
@@ -302,7 +302,7 @@
             VCR.use_cassette('aip_download_and_swift_upload') do
               PushmiPullyu::Logging.logger.fatal!
               cli.send(:run_preservation_cycle)
-              PushmiPullyu::Logging.initialize_logger
+              PushmiPullyu::Logging.initialize_loggers
               time_now = Time.now.to_i
               _readded_entity, readded_entity_score = redis.zrange(PushmiPullyu.options[:queue_name],
                                                                    0, 0, with_scores: true).first
@@ -322,7 +322,7 @@
       it 'makes sure an entities information is readded to redis when deposit fails' do
         cli.parse(['-C', 'spec/fixtures/config_wrong_swift.yml'])
         redis = Redis.new
-        entity = { uuid: '123e4567-e89b-12d3-a456-426614174000', type: 'items' }
+        entity = { uuid: 'e2ec88e3-3266-4e95-8575-8b04fac2a679', type: 'items' }
 
         redis.zadd(PushmiPullyu.options[:queue_name], 10, entity.to_json)
         redis.set("#{PushmiPullyu.options[:ingestion_prefix]}#{entity[:uuid]}", 0)
@@ -335,8 +335,8 @@
           # and will re-add the original entity information back into the queue with a different score.
           # We know that we will be getting an error on this method so lets filter out the logs for this bit.
           PushmiPullyu::Logging.logger.fatal!
+          PushmiPullyu::Logging.initialize_loggers
           cli.send(:run_preservation_cycle)
-          PushmiPullyu::Logging.initialize_logger
           readded_entity, readded_entity_score = redis.zrange(PushmiPullyu.options[:queue_name],
                                                               0, 0, with_scores: true).first
           readded_attempt = redis.get("#{PushmiPullyu.options[:ingestion_prefix]}#{entity[:uuid]}")