Improve log clarity

This change makes logs easier to understand by humans.

We start counting ingestion attempts at 1.

We will also format all events in the json log in the same way.

lib/pushmi_pullyu/cli.rb

@@ -199,8 +199,9 @@ def rotate_logs
   def run_preservation_cycle
     begin
       entity = queue.wait_next_item
+      # We add + 1 to the get_entity_ingestion_attempt because humans like to start counting from 1
       PushmiPullyu::Logging.log_preservation_attempt(entity,
-                                                     queue.get_entity_ingestion_attempt(entity))
+                                                     queue.get_entity_ingestion_attempt(entity) + 1)
       return unless entity && entity[:type].present? && entity[:uuid].present?
     rescue StandardError => e
       log_exception(e)
@@ -214,7 +215,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
@@ -223,9 +224,10 @@ 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)
+        # We add + 1 to the get_entity_ingestion_attempt because humans like to start counting from 1
+        PushmiPullyu::Logging.log_preservation_fail_and_retry(entity, queue.get_entity_ingestion_attempt(entity) + 1, e)
       rescue PushmiPullyu::PreservationQueue::MaxDepositAttemptsReached => e
-        PushmiPullyu::Logging.log_preservation_failure(entity, queue.get_entity_ingestion_attempt(entity), e)
+        PushmiPullyu::Logging.log_preservation_failure(entity, queue.get_entity_ingestion_attempt(entity) + 1, e)
         log_exception(e)
       end
 

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,22 @@ 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)
       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 +98,43 @@ 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)
       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"
+                "\tRetry attempt: #{try_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,
+        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)
       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"
+                "\tRetry 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 +192,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
@@ -187,7 +194,7 @@ class LoggerTest
         'event_type' => 'attempt',
         'entity_type' => 'items',
         'entity_uuid' => 'e2ec88e3-3266-4e95-8575-8b04fac2a679',
-        'retry_attempt' => 1,
+        'try_attempt' => 1,
         '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: 2"
       )
 
       # 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' => 2,
         'error_message' => 'PushmiPullyu::AIP::Downloader::JupiterDownloadError',
         'event_time' => Time.now.to_s
       )
@@ -283,7 +290,7 @@ class LoggerTest
         'event_type' => 'fail_and_retry',
         'entity_type' => 'items',
         'entity_uuid' => 'e2ec88e3-3266-4e95-8575-8b04fac2a679',
-        'retry_attempt' => 15,
+        'try_attempt' => 15,
         'error_message' => 'PushmiPullyu::PreservationQueue::MaxDepositAttemptsReached',
         'event_time' => Time.now.to_s
       )