From cd1b645fe57f8802912e772e77aab5869f92db6d Mon Sep 17 00:00:00 2001 From: Omar Rodriguez Arenas Date: Wed, 5 Jun 2024 11:14:05 -0600 Subject: [PATCH] Fix problems with logger in JSON format This commit addresses PR comments and fixes a problem with the JSON log --- lib/pushmi_pullyu/cli.rb | 8 +++----- lib/pushmi_pullyu/logging.rb | 10 ++++++++-- spec/pushmi_pullyu/logging_spec.rb | 12 ++++++------ 3 files changed, 17 insertions(+), 13 deletions(-) diff --git a/lib/pushmi_pullyu/cli.rb b/lib/pushmi_pullyu/cli.rb index 6d33536..bfa1277 100644 --- a/lib/pushmi_pullyu/cli.rb +++ b/lib/pushmi_pullyu/cli.rb @@ -199,9 +199,8 @@ 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) + 1) + queue.get_entity_ingestion_attempt(entity)) return unless entity && entity[:type].present? && entity[:uuid].present? rescue StandardError => e log_exception(e) @@ -224,10 +223,9 @@ def run_preservation_cycle log_exception(e) begin queue.add_entity_in_timeframe(entity) - # 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) + 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) + 1, e) + PushmiPullyu::Logging.log_preservation_failure(entity, queue.get_entity_ingestion_attempt(entity), e) log_exception(e) end diff --git a/lib/pushmi_pullyu/logging.rb b/lib/pushmi_pullyu/logging.rb index d880ab5..4b21370 100644 --- a/lib/pushmi_pullyu/logging.rb +++ b/lib/pushmi_pullyu/logging.rb @@ -86,6 +86,8 @@ def log_preservation_success(entity, deposited_file, aip_directory) end 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]}" \ @@ -106,10 +108,12 @@ def log_preservation_fail_and_retry(entity, try_attempt, exception) end 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: #{try_attempt}\n" + "\tTry attempt: #{try_attempt}\n" message_information = { event_type: :failure, @@ -124,10 +128,12 @@ def log_preservation_failure(entity, try_attempt, exception) end 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: #{try_attempt}\n" + "\tTry attempt: #{try_attempt}\n" message_information = { event_type: :attempt, diff --git a/spec/pushmi_pullyu/logging_spec.rb b/spec/pushmi_pullyu/logging_spec.rb index 2d20eca..1da255a 100644 --- a/spec/pushmi_pullyu/logging_spec.rb +++ b/spec/pushmi_pullyu/logging_spec.rb @@ -183,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) @@ -194,7 +194,7 @@ class LoggerTest 'event_type' => 'attempt', 'entity_type' => 'items', 'entity_uuid' => 'e2ec88e3-3266-4e95-8575-8b04fac2a679', - 'try_attempt' => 1, + 'try_attempt' => 2, 'event_time' => Time.now.to_s ) end @@ -232,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 try attempt: 2" + "#{entity[:type]} uuid: #{entity[:uuid]} Readding to preservation queue with try attempt: 3" ) # Check JSON log @@ -244,7 +244,7 @@ class LoggerTest 'event_type' => 'fail_and_retry', 'entity_type' => 'items', 'entity_uuid' => 'e2ec88e3-3266-4e95-8575-8b04fac2a679', - 'try_attempt' => 2, + 'try_attempt' => 3, 'error_message' => 'PushmiPullyu::AIP::Downloader::JupiterDownloadError', 'event_time' => Time.now.to_s ) @@ -280,7 +280,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]} 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) @@ -290,7 +290,7 @@ class LoggerTest 'event_type' => 'failure', 'entity_type' => 'items', 'entity_uuid' => 'e2ec88e3-3266-4e95-8575-8b04fac2a679', - 'try_attempt' => 15, + 'try_attempt' => 16, 'error_message' => 'PushmiPullyu::PreservationQueue::MaxDepositAttemptsReached', 'event_time' => Time.now.to_s )