Improve log clarity

CHANGELOG.md

@@ -6,6 +6,9 @@ PushmiPullyu is a Ruby application, whose primary job is to manage the flow of c
 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]
+ - Increase clarity of log files [#433](https://github.com/ualbertalib/pushmi_pullyu/issues/433)
+
 ## [2.1.0]
  - Add more logging information [#433](https://github.com/ualbertalib/pushmi_pullyu/issues/433)
  - Add V3 authentication [#349](https://github.com/ualbertalib/pushmi_pullyu/issues/349)

lib/pushmi_pullyu/cli.rb

@@ -214,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_success(deposited_file, aip_directory)
+        PushmiPullyu::Logging.log_preservation_success(entity, 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

lib/pushmi_pullyu/logging.rb

@@ -52,7 +52,7 @@ def log_preservation_event(message, message_json)
       @preservation_json_logger.info("#{message_json},")
     end
 
-    def log_preservation_success(deposited_file, aip_directory)
+    def log_preservation_success(entity, 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" \
@@ -74,14 +74,24 @@ def log_preservation_success(deposited_file, aip_directory)
         end
       end
 
-      log_preservation_event(message, preservation_success_to_json(deposited_file, aip_directory))
+      message_information = {
+        event_type: :success,
+        event_time: Time.now.to_s,
+        entity_type: entity[:type],
+        entity_uuid: entity[:uuid],
+        event_details: preservation_success_to_json(deposited_file, aip_directory)
+      }
+
+      log_preservation_event(message, message_information.to_json)
     end
 
-    def log_preservation_fail_and_retry(entity, retry_attempt, exception)
+    def log_preservation_fail_and_retry(entity, try_attempt, exception)
+      # We add + 1 to try_attempt because humans like to start counting from 1
+      try_attempt += 1
       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" \
+                "\tReadding to preservation queue with try attempt: #{try_attempt}\n" \
                 "\tError of type: #{exception.class.name}\n" \
                 "\tError message: #{exception.message}\n"
 
@@ -90,43 +100,47 @@ def log_preservation_fail_and_retry(entity, retry_attempt, exception)
         event_time: Time.now.to_s,
         entity_type: entity[:type],
         entity_uuid: entity[:uuid],
-        retry_attempt: retry_attempt,
+        try_attempt: try_attempt,
         error_message: exception.message
       }
 
       log_preservation_event(message, message_information.to_json)
     end
 
-    def log_preservation_failure(entity, retry_attempt, exception)
+    def log_preservation_failure(entity, try_attempt, exception)
+      # We add + 1 to try_attempt because humans like to start counting from 1
+      try_attempt += 1
       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"
+                "\tTry attempt: #{try_attempt}\n"
 
       message_information = {
-        event_type: :fail_and_retry,
+        event_type: :failure,
         event_time: Time.now.to_s,
         entity_type: entity[:type],
         entity_uuid: entity[:uuid],
-        retry_attempt: retry_attempt,
+        try_attempt: try_attempt,
         error_message: exception.message
       }
 
       log_preservation_event(message, message_information.to_json)
     end
 
-    def log_preservation_attempt(entity, retry_attempt)
+    def log_preservation_attempt(entity, try_attempt)
+      # We add + 1 to try_attempt because humans like to start counting from 1
+      try_attempt += 1
       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"
+                "\tTry attempt: #{try_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
+        try_attempt: try_attempt
       }
 
       log_preservation_event(message, message_information.to_json)
@@ -184,7 +198,7 @@ def preservation_success_to_json(deposited_file, aip_directory)
       end
 
       message['aip_file_details'] = tmp_details
-      message.to_json
+      message
     end
 
     def reopen

lib/pushmi_pullyu/preservation_queue.rb

@@ -73,7 +73,7 @@ def wait_next_item
   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
+      return connection.get(entity_attempts_key).to_i
     end
   end
 

spec/integration/acceptance_spec.rb

@@ -72,7 +72,7 @@
         expect(deposited_file.metadata['promise']).to eql 'bronze'
 
         # Log successful preservation event to the log files
-        PushmiPullyu::Logging.log_preservation_success(deposited_file, aip_folder)
+        PushmiPullyu::Logging.log_preservation_success(entity, deposited_file, aip_folder)
       end
     end
 

spec/pushmi_pullyu/logging_spec.rb

@@ -120,8 +120,9 @@ class LoggerTest
                     'promise' => 'bronze',
                     'project' => 'ERA' }
       )
+      entity = { uuid: 'e2ec88e3-3266-4e95-8575-8b04fac2a679', type: 'items' }
 
-      PushmiPullyu::Logging.log_preservation_success(deposited_file, tmp_aip_dir)
+      PushmiPullyu::Logging.log_preservation_success(entity, deposited_file, tmp_aip_dir)
 
       # Check log
       expect(File.exist?("#{tmp_log_dir}/preservation_events.log")).to be(true)
@@ -133,17 +134,23 @@ class LoggerTest
       # Check JSON log
       json_data = JSON.parse(File.read("#{tmp_log_dir}/preservation_events.json").split("\n").last[/{.+}/])
       expect(json_data).to include(
-        'do_uuid' => '9p2909328',
-        'aip_deposited_at' => 'Fri, 02 Jun 2017 18:29:07 GMT',
-        'aip_md5sum' => '0f32868de20f3b1d4685bfa497a2c243',
-        'aip_sha256' => '',
-        'aip_metadata' => {
-          'project-id' => '9p2909328',
-          'aip-version' => '1.0',
-          'promise' => 'bronze',
-          'project' => 'ERA'
-        },
-        'aip_file_details' => []
+        'event_type' => 'success',
+        'event_time' => Time.now.to_s,
+        'entity_type' => entity[:type],
+        'entity_uuid' => entity[:uuid],
+        'event_details' => {
+          'do_uuid' => '9p2909328',
+          'aip_deposited_at' => 'Fri, 02 Jun 2017 18:29:07 GMT',
+          'aip_md5sum' => '0f32868de20f3b1d4685bfa497a2c243',
+          'aip_sha256' => '',
+          'aip_metadata' => {
+            'project-id' => '9p2909328',
+            'aip-version' => '1.0',
+            'promise' => 'bronze',
+            'project' => 'ERA'
+          },
+          'aip_file_details' => []
+        }
       )
     end
   end
@@ -176,7 +183,7 @@ class LoggerTest
       expect(File.exist?("#{tmp_log_dir}/preservation_events.log")).to be(true)
       log_data = File.read("#{tmp_log_dir}/preservation_events.log")
       expect(log_data).to include("#{entity[:type]} will attempt to be deposited.")
-      expect(log_data).to include("#{entity[:type]} uuid: #{entity[:uuid]}	Retry attempt: 1")
+      expect(log_data).to include("#{entity[:type]} uuid: #{entity[:uuid]}	Try attempt: 2")
 
       # Check JSON log
       expect(File.exist?("#{tmp_log_dir}/preservation_events.json")).to be(true)
@@ -187,7 +194,7 @@ class LoggerTest
         'event_type' => 'attempt',
         'entity_type' => 'items',
         'entity_uuid' => 'e2ec88e3-3266-4e95-8575-8b04fac2a679',
-        'retry_attempt' => 1,
+        'try_attempt' => 2,
         'event_time' => Time.now.to_s
       )
     end
@@ -225,7 +232,7 @@ class LoggerTest
       log_data = File.read("#{tmp_log_dir}/preservation_events.log")
       expect(log_data).to include("#{entity[:type]} failed to be deposited and will try again.")
       expect(log_data).to include(
-        "#{entity[:type]} uuid: #{entity[:uuid]}	Readding to preservation queue with retry attempt: 2"
+        "#{entity[:type]} uuid: #{entity[:uuid]}	Readding to preservation queue with try attempt: 3"
       )
 
       # Check JSON log
@@ -237,7 +244,7 @@ class LoggerTest
         'event_type' => 'fail_and_retry',
         'entity_type' => 'items',
         'entity_uuid' => 'e2ec88e3-3266-4e95-8575-8b04fac2a679',
-        'retry_attempt' => 2,
+        'try_attempt' => 3,
         'error_message' => 'PushmiPullyu::AIP::Downloader::JupiterDownloadError',
         'event_time' => Time.now.to_s
       )
@@ -273,17 +280,17 @@ class LoggerTest
       expect(File.exist?("#{tmp_log_dir}/preservation_events.log")).to be(true)
       log_data = File.read("#{tmp_log_dir}/preservation_events.log")
       expect(log_data).to include("#{entity[:type]} failed to be deposited.")
-      expect(log_data).to include("#{entity[:type]} uuid: #{entity[:uuid]}	Retry attempt: 15")
+      expect(log_data).to include("#{entity[:type]} uuid: #{entity[:uuid]}	Try attempt: 16")
 
       # Check JSON log
       expect(File.exist?("#{tmp_log_dir}/preservation_events.json")).to be(true)
       # Get the JSON object from the log file
       json_data = JSON.parse(File.read("#{tmp_log_dir}/preservation_events.json").split("\n").last[/{.+}/])
       expect(json_data).to include(
-        'event_type' => 'fail_and_retry',
+        'event_type' => 'failure',
         'entity_type' => 'items',
         'entity_uuid' => 'e2ec88e3-3266-4e95-8575-8b04fac2a679',
-        'retry_attempt' => 15,
+        'try_attempt' => 16,
         'error_message' => 'PushmiPullyu::PreservationQueue::MaxDepositAttemptsReached',
         'event_time' => Time.now.to_s
       )