From 6eca32439a0816cd0d8f78cc627f23d7691f7183 Mon Sep 17 00:00:00 2001 From: Omar Rodriguez Arenas Date: Fri, 29 Mar 2024 14:45:57 -0600 Subject: [PATCH 1/5] Rename log_preservation_event method Currently we are only logging successful events with the method ``log_preservation_event``. We want to log more information to reflect the system current work state. For now we simple change the name to that method to: ``log_preservation_success`` --- lib/pushmi_pullyu/cli.rb | 2 +- lib/pushmi_pullyu/logging.rb | 2 +- spec/integration/acceptance_spec.rb | 2 +- spec/pushmi_pullyu/logging_spec.rb | 4 ++-- 4 files changed, 5 insertions(+), 5 deletions(-) diff --git a/lib/pushmi_pullyu/cli.rb b/lib/pushmi_pullyu/cli.rb index 512e7b3e..3d1e582d 100644 --- a/lib/pushmi_pullyu/cli.rb +++ b/lib/pushmi_pullyu/cli.rb @@ -212,7 +212,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 diff --git a/lib/pushmi_pullyu/logging.rb b/lib/pushmi_pullyu/logging.rb index 9d04785a..930597ce 100644 --- a/lib/pushmi_pullyu/logging.rb +++ b/lib/pushmi_pullyu/logging.rb @@ -43,7 +43,7 @@ def log_aip_activity(aip_directory, message) aip_logger.close end - def log_preservation_event(deposited_file, aip_directory) + def log_preservation_success(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") diff --git a/spec/integration/acceptance_spec.rb b/spec/integration/acceptance_spec.rb index 0d823b21..91e9ff76 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_event(deposited_file, aip_folder) + PushmiPullyu::Logging.log_preservation_success(deposited_file, aip_folder) end end diff --git a/spec/pushmi_pullyu/logging_spec.rb b/spec/pushmi_pullyu/logging_spec.rb index cb97557c..42e535d9 100644 --- a/spec/pushmi_pullyu/logging_spec.rb +++ b/spec/pushmi_pullyu/logging_spec.rb @@ -80,7 +80,7 @@ class LoggerTest end end - describe '.log_preservation_event' do + describe '.log_preservation_success' do let(:tmp_log_dir) { 'tmp/logs' } let(:tmp_aip_dir) { 'tmp/test_aip_dir' } @@ -100,7 +100,7 @@ class LoggerTest 'project' => 'ERA' } ) - PushmiPullyu::Logging.log_preservation_event(deposited_file, tmp_aip_dir) + PushmiPullyu::Logging.log_preservation_success(deposited_file, tmp_aip_dir) expect(File.exist?("#{tmp_log_dir}/preservation_events.log")).to be(true) expect(PushmiPullyu::Logging.logger).to have_received(:info).with(an_instance_of(String)).once From dc7876ddf08bf0ff1d9aa2bc29c62c4f2088ceaa Mon Sep 17 00:00:00 2001 From: Omar Rodriguez Arenas Date: Fri, 5 Apr 2024 15:13:54 -0600 Subject: [PATCH 2/5] WIP Add new logging methods This WIP commit adds the different methods that will be used for logging the specific preservation events. Next we will be adding them to the logic. --- lib/pushmi_pullyu/logging.rb | 77 +++++++++++++++++++++++++++++++----- 1 file changed, 68 insertions(+), 9 deletions(-) diff --git a/lib/pushmi_pullyu/logging.rb b/lib/pushmi_pullyu/logging.rb index 930597ce..06ddf815 100644 --- a/lib/pushmi_pullyu/logging.rb +++ b/lib/pushmi_pullyu/logging.rb @@ -43,10 +43,20 @@ def log_aip_activity(aip_directory, message) aip_logger.close end - def log_preservation_success(deposited_file, aip_directory) + def log_preservation_event(message, message_json) preservation_logger = Logger.new("#{PushmiPullyu.options[:logdir]}/preservation_events.log") preservation_json_logger = Logger.new("#{PushmiPullyu.options[:logdir]}/preservation_events.json") + logger.info(message) + preservation_logger.info(message) + + preservation_logger.close + + preservation_json_logger.info("#{message_json},") + preservation_json_logger.close + 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 +78,64 @@ def log_preservation_success(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 tyoe: #{exception.type}\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_type: exception.type, + 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_type: exception.type, + 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,7 +166,7 @@ def log_preservation_success(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 From ed1db2dcffe3b5be87a931e5df23edd9c3ae0f21 Mon Sep 17 00:00:00 2001 From: Omar Rodriguez Arenas Date: Fri, 10 May 2024 11:20:46 -0600 Subject: [PATCH 3/5] WIP Add more preservation events to logs This work in progress adds more information about all logging events in order to get a better idea of the behavior on PMPY. Right now the preservation event loggers are initialized on startup instead of being instantiated every time there is a preservation event. All is done in the logger reader method. We could change it so the preservation loggers are instantiated on their own access. There are 3 placeholder tests that need to be completed. --- lib/pushmi_pullyu/cli.rb | 10 ++++++- lib/pushmi_pullyu/logging.rb | 28 ++++++++--------- lib/pushmi_pullyu/preservation_queue.rb | 7 +++++ spec/integration/acceptance_spec.rb | 4 +-- spec/pushmi_pullyu/cli_spec.rb | 8 ++--- spec/pushmi_pullyu/logging_spec.rb | 40 ++++++++++++++++++++++++- 6 files changed, 73 insertions(+), 24 deletions(-) diff --git a/lib/pushmi_pullyu/cli.rb b/lib/pushmi_pullyu/cli.rb index 3d1e582d..0f539f12 100644 --- a/lib/pushmi_pullyu/cli.rb +++ b/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) @@ -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 diff --git a/lib/pushmi_pullyu/logging.rb b/lib/pushmi_pullyu/logging.rb index 06ddf815..f4aaf8c6 100644 --- a/lib/pushmi_pullyu/logging.rb +++ b/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) @@ -44,16 +47,9 @@ def log_aip_activity(aip_directory, message) end def log_preservation_event(message, message_json) - preservation_logger = Logger.new("#{PushmiPullyu.options[:logdir]}/preservation_events.log") - preservation_json_logger = Logger.new("#{PushmiPullyu.options[:logdir]}/preservation_events.json") - logger.info(message) - preservation_logger.info(message) - - preservation_logger.close - - preservation_json_logger.info("#{message_json},") - preservation_json_logger.close + @preservation_logger.info(message) + @preservation_json_logger.info("#{message_json},") end def log_preservation_success(deposited_file, aip_directory) @@ -86,7 +82,7 @@ def log_preservation_fail_and_retry(entity, retry_attempt, exception) "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 tyoe: #{exception.type}\n" \ + "\tError of type: #{exception.class.name}\n" \ "\tError message: #{exception.message}\n" message_information = { @@ -95,7 +91,7 @@ def log_preservation_fail_and_retry(entity, retry_attempt, exception) entity_type: entity[:type], entity_uuid: entity[:uuid], retry_attempt: retry_attempt, - error_type: exception.type, + error_type: exception.class.name, error_message: exception.message } @@ -114,7 +110,7 @@ def log_preservation_failure(entity, retry_attempt, exception) entity_type: entity[:type], entity_uuid: entity[:uuid], retry_attempt: retry_attempt, - error_type: exception.type, + error_type: exception.class.name, error_message: exception.message } @@ -173,7 +169,7 @@ def preservation_success_to_json(deposited_file, aip_directory) 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.to_json file_details = file_log_details(aip_directory) @@ -197,7 +193,7 @@ def reopen if @logger @logger.reopen else - @logger = initialize_logger + @logger = initialize_loggers end end diff --git a/lib/pushmi_pullyu/preservation_queue.rb b/lib/pushmi_pullyu/preservation_queue.rb index 5ecd6798..29f575e9 100644 --- a/lib/pushmi_pullyu/preservation_queue.rb +++ b/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]}" diff --git a/spec/integration/acceptance_spec.rb b/spec/integration/acceptance_spec.rb index 91e9ff76..01cf4af6 100644 --- a/spec/integration/acceptance_spec.rb +++ b/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: diff --git a/spec/pushmi_pullyu/cli_spec.rb b/spec/pushmi_pullyu/cli_spec.rb index da74b8d5..eff05236 100644 --- a/spec/pushmi_pullyu/cli_spec.rb +++ b/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]}") diff --git a/spec/pushmi_pullyu/logging_spec.rb b/spec/pushmi_pullyu/logging_spec.rb index 42e535d9..4a76a23b 100644 --- a/spec/pushmi_pullyu/logging_spec.rb +++ b/spec/pushmi_pullyu/logging_spec.rb @@ -31,7 +31,13 @@ class LoggerTest describe '.reopen' do let(:tmp_dir) { 'tmp/test_dir' } let(:logfile) { "#{tmp_dir}/pushmi_pullyu.log" } - let(:logger) { PushmiPullyu::Logging.initialize_logger(logfile) } + let(:log_events) { "#{tmp_dir}/events.log" } + let(:log_json) { "#{tmp_dir}/json.log" } + let(:logger) do + PushmiPullyu::Logging.initialize_loggers(log_target: logfile, + events_target: log_events, + json_target: log_json) + end before do FileUtils.mkdir_p(tmp_dir) @@ -84,8 +90,19 @@ class LoggerTest let(:tmp_log_dir) { 'tmp/logs' } let(:tmp_aip_dir) { 'tmp/test_aip_dir' } + before do + FileUtils.mkdir_p(tmp_aip_dir) + end + + after do + FileUtils.rm_rf(tmp_aip_dir) + end + it 'logs preservation event to both preservation log and application log' do FileUtils.mkdir_p(tmp_log_dir) + # Make sure we are initialize logger with expected file destinations and not default stdout destination + PushmiPullyu::Logging.initialize_loggers(events_target: "#{tmp_log_dir}/preservation_events.log", + json_target: "#{tmp_log_dir}/preservation_events.json") allow(PushmiPullyu::Logging.logger).to receive(:info) allow(PushmiPullyu).to receive(:options) { { logdir: tmp_log_dir } } @@ -112,6 +129,27 @@ class LoggerTest end end + # XXX Placeholder test to be filled in + describe '.log_preservation_attempt' do + it 'logs preservation attempts' do + expect(true).to be(false) + end + end + + # XXX Placeholder test to be filled in + describe '.log_preservation_fail_and_retry' do + it 'logs preservation fail and retry' do + expect(true).to be(false) + end + end + + # XXX Placeholder test to be filled in + describe '.log_preservation_failure' do + it 'logs preservation failure' do + expect(true).to be(false) + end + end + context 'when included in classes' do let(:dummy_class) { LoggerTest.new } From c0c73705ba90337cc507b792e085b170c8819a5a Mon Sep 17 00:00:00 2001 From: Omar Rodriguez Arenas Date: Wed, 15 May 2024 12:32:47 -0600 Subject: [PATCH 4/5] Add missing tests and cleanup log JSON format Just add the tests for the new methods and make sure the JSON log includes its values in JSON format when needed. --- lib/pushmi_pullyu/logging.rb | 4 +- spec/pushmi_pullyu/logging_spec.rb | 158 +++++++++++++++++++++++++++-- 2 files changed, 150 insertions(+), 12 deletions(-) diff --git a/lib/pushmi_pullyu/logging.rb b/lib/pushmi_pullyu/logging.rb index f4aaf8c6..cad651c9 100644 --- a/lib/pushmi_pullyu/logging.rb +++ b/lib/pushmi_pullyu/logging.rb @@ -91,7 +91,6 @@ def log_preservation_fail_and_retry(entity, retry_attempt, exception) entity_type: entity[:type], entity_uuid: entity[:uuid], retry_attempt: retry_attempt, - error_type: exception.class.name, error_message: exception.message } @@ -110,7 +109,6 @@ def log_preservation_failure(entity, retry_attempt, exception) entity_type: entity[:type], entity_uuid: entity[:uuid], retry_attempt: retry_attempt, - error_type: exception.class.name, error_message: exception.message } @@ -169,7 +167,7 @@ def preservation_success_to_json(deposited_file, aip_directory) 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 + message['aip_metadata'] = deposited_file.metadata file_details = file_log_details(aip_directory) diff --git a/spec/pushmi_pullyu/logging_spec.rb b/spec/pushmi_pullyu/logging_spec.rb index 4a76a23b..fd146b71 100644 --- a/spec/pushmi_pullyu/logging_spec.rb +++ b/spec/pushmi_pullyu/logging_spec.rb @@ -1,5 +1,6 @@ require 'spec_helper' - +require 'time' +require 'timecop' ## # Dummy class, so that we can mix in the Logging module and test it. # @@ -92,14 +93,17 @@ class LoggerTest before do FileUtils.mkdir_p(tmp_aip_dir) + FileUtils.mkdir_p(tmp_log_dir) + Timecop.freeze(Time.now) end after do FileUtils.rm_rf(tmp_aip_dir) + FileUtils.mkdir_p(tmp_log_dir) + Timecop.return end it 'logs preservation event to both preservation log and application log' do - FileUtils.mkdir_p(tmp_log_dir) # Make sure we are initialize logger with expected file destinations and not default stdout destination PushmiPullyu::Logging.initialize_loggers(events_target: "#{tmp_log_dir}/preservation_events.log", json_target: "#{tmp_log_dir}/preservation_events.json") @@ -119,34 +123,170 @@ class LoggerTest PushmiPullyu::Logging.log_preservation_success(deposited_file, tmp_aip_dir) + # Check log expect(File.exist?("#{tmp_log_dir}/preservation_events.log")).to be(true) expect(PushmiPullyu::Logging.logger).to have_received(:info).with(an_instance_of(String)).once expect( File.read("#{tmp_log_dir}/preservation_events.log") ).to include("#{deposited_file.name} was successfully deposited into Swift Storage!") - FileUtils.rm_rf(tmp_log_dir) + # 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' => [] + ) end end - # XXX Placeholder test to be filled in describe '.log_preservation_attempt' do + let(:tmp_log_dir) { 'tmp/logs' } + + before do + FileUtils.mkdir_p(tmp_log_dir) + # Lets freeze time to make sure timestamp checks match + Timecop.freeze(Time.now) + end + + after do + FileUtils.rm_rf(tmp_log_dir) + Timecop.return + end + it 'logs preservation attempts' do - expect(true).to be(false) + # Make sure we are initialize logger with expected file destinations and not default stdout destination + PushmiPullyu::Logging.initialize_loggers(events_target: "#{tmp_log_dir}/preservation_events.log", + json_target: "#{tmp_log_dir}/preservation_events.json") + allow(PushmiPullyu::Logging.logger).to receive(:info) + allow(PushmiPullyu).to receive(:options) { { logdir: tmp_log_dir } } + # Test goes here + entity = { uuid: 'e2ec88e3-3266-4e95-8575-8b04fac2a679', type: 'items' } + PushmiPullyu::Logging.log_preservation_attempt(entity, 1) + + # Check log + 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") + + # 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' => 'attempt', + 'entity_type' => 'items', + 'entity_uuid' => 'e2ec88e3-3266-4e95-8575-8b04fac2a679', + 'retry_attempt' => 1, + 'event_time' => Time.now.to_s + ) end end - # XXX Placeholder test to be filled in describe '.log_preservation_fail_and_retry' do + let(:tmp_log_dir) { 'tmp/logs' } + + before do + FileUtils.mkdir_p(tmp_log_dir) + Timecop.freeze(Time.now) + end + + after do + FileUtils.rm_rf(tmp_log_dir) + Timecop.return + end + it 'logs preservation fail and retry' do - expect(true).to be(false) + # Make sure we are initialize logger with expected file destinations and not default stdout destination + PushmiPullyu::Logging.initialize_loggers(events_target: "#{tmp_log_dir}/preservation_events.log", + json_target: "#{tmp_log_dir}/preservation_events.json") + allow(PushmiPullyu::Logging.logger).to receive(:info) + allow(PushmiPullyu).to receive(:options) { { logdir: tmp_log_dir } } + # Test goes here + entity = { uuid: 'e2ec88e3-3266-4e95-8575-8b04fac2a679', type: 'items' } + PushmiPullyu::Logging.log_preservation_fail_and_retry( + entity, + 2, + PushmiPullyu::AIP::Downloader::JupiterDownloadError.new + ) + + # Check log + 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 and will try again.") + expect(log_data).to include( + "#{entity[:type]} uuid: #{entity[:uuid]} Readding to preservation queue with retry attempt: 2" + ) + + # 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', + 'entity_type' => 'items', + 'entity_uuid' => 'e2ec88e3-3266-4e95-8575-8b04fac2a679', + 'retry_attempt' => 2, + 'error_message' => 'PushmiPullyu::AIP::Downloader::JupiterDownloadError', + 'event_time' => Time.now.to_s + ) end end - # XXX Placeholder test to be filled in describe '.log_preservation_failure' do + let(:tmp_log_dir) { 'tmp/logs' } + + before do + FileUtils.mkdir_p(tmp_log_dir) + Timecop.freeze(Time.now) + end + + after do + FileUtils.rm_rf(tmp_log_dir) + Timecop.return + end + it 'logs preservation failure' do - expect(true).to be(false) + # Make sure we are initialize logger with expected file destinations and not default stdout destination + PushmiPullyu::Logging.initialize_loggers(events_target: "#{tmp_log_dir}/preservation_events.log", + json_target: "#{tmp_log_dir}/preservation_events.json") + allow(PushmiPullyu::Logging.logger).to receive(:info) + allow(PushmiPullyu).to receive(:options) { { logdir: tmp_log_dir } } + # Test goes here + entity = { uuid: 'e2ec88e3-3266-4e95-8575-8b04fac2a679', type: 'items' } + PushmiPullyu::Logging.log_preservation_failure(entity, + 15, + PushmiPullyu::PreservationQueue::MaxDepositAttemptsReached.new) + + # Check log + 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") + + # 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', + 'entity_type' => 'items', + 'entity_uuid' => 'e2ec88e3-3266-4e95-8575-8b04fac2a679', + 'retry_attempt' => 15, + 'error_message' => 'PushmiPullyu::PreservationQueue::MaxDepositAttemptsReached', + 'event_time' => Time.now.to_s + ) end end From 6a6ea6a3312372ec74cf770a642dee1dec58e35a Mon Sep 17 00:00:00 2001 From: Omar Rodriguez Arenas Date: Wed, 15 May 2024 12:38:29 -0600 Subject: [PATCH 5/5] Add CHANGELOG entry --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 8c03ea18..b03b8265 100644 --- a/CHANGELOG.md +++ b/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) ## [2.0.7] - 2023-09-13