From 104dc8d7e6d8bc293a9a7f4e8d51d717b5a9922d Mon Sep 17 00:00:00 2001 From: Omar Rodriguez Arenas Date: Tue, 4 Jun 2024 18:32:49 -0600 Subject: [PATCH] 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 | 10 ++++--- lib/pushmi_pullyu/logging.rb | 32 ++++++++++++-------- lib/pushmi_pullyu/preservation_queue.rb | 2 +- spec/integration/acceptance_spec.rb | 2 +- spec/pushmi_pullyu/logging_spec.rb | 39 +++++++++++++++---------- 5 files changed, 51 insertions(+), 34 deletions(-) diff --git a/lib/pushmi_pullyu/cli.rb b/lib/pushmi_pullyu/cli.rb index bba5ee17..6d33536d 100644 --- a/lib/pushmi_pullyu/cli.rb +++ b/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 diff --git a/lib/pushmi_pullyu/logging.rb b/lib/pushmi_pullyu/logging.rb index cad651c9..79d32d1e 100644 --- a/lib/pushmi_pullyu/logging.rb +++ b/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 diff --git a/lib/pushmi_pullyu/preservation_queue.rb b/lib/pushmi_pullyu/preservation_queue.rb index 29f575e9..1453528e 100644 --- a/lib/pushmi_pullyu/preservation_queue.rb +++ b/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 diff --git a/spec/integration/acceptance_spec.rb b/spec/integration/acceptance_spec.rb index 01cf4af6..ebf56da5 100644 --- a/spec/integration/acceptance_spec.rb +++ b/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 diff --git a/spec/pushmi_pullyu/logging_spec.rb b/spec/pushmi_pullyu/logging_spec.rb index fd146b71..66cf20be 100644 --- a/spec/pushmi_pullyu/logging_spec.rb +++ b/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 )