From d05af8cfcb7b23645b4a39bdb28a1c5b65da81e6 Mon Sep 17 00:00:00 2001 From: Murny Date: Fri, 11 May 2018 14:00:49 -0600 Subject: [PATCH 1/3] Add file details to preservation logs on successful upload --- lib/pushmi_pullyu/aip.rb | 2 +- lib/pushmi_pullyu/cli.rb | 4 +- lib/pushmi_pullyu/logging.rb | 118 ++++++++++++++++++---------- spec/integration/acceptance_spec.rb | 33 +++++++- spec/pushmi_pullyu/logging_spec.rb | 3 +- 5 files changed, 114 insertions(+), 46 deletions(-) diff --git a/lib/pushmi_pullyu/aip.rb b/lib/pushmi_pullyu/aip.rb index b2e23c8..4fd1333 100644 --- a/lib/pushmi_pullyu/aip.rb +++ b/lib/pushmi_pullyu/aip.rb @@ -12,7 +12,7 @@ def create(noid) PushmiPullyu::AIP::Downloader.new(noid, aip_directory).run PushmiPullyu::AIP::Creator.new(noid, aip_directory, aip_filename).run - yield aip_filename + yield aip_filename, aip_directory FileUtils.rm_rf(aip_filename) if File.exist?(aip_filename) FileUtils.rm_rf(aip_directory) if File.exist?(aip_directory) diff --git a/lib/pushmi_pullyu/cli.rb b/lib/pushmi_pullyu/cli.rb index 98e9330..ab4f9fa 100644 --- a/lib/pushmi_pullyu/cli.rb +++ b/lib/pushmi_pullyu/cli.rb @@ -174,11 +174,11 @@ def run_preservation_cycle Rollbar.scoped(noid: item) do begin # Download AIP from Fedora, bag and tar AIP directory and cleanup after block code - PushmiPullyu::AIP.create(item) do |aip_filename| + PushmiPullyu::AIP.create(item) do |aip_filename, aip_directory| # 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) + PushmiPullyu::Logging.log_preservation_event(deposited_file, aip_directory) end # rubocop:disable Lint/RescueException rescue Exception => e diff --git a/lib/pushmi_pullyu/logging.rb b/lib/pushmi_pullyu/logging.rb index c6093e1..e7797ff 100644 --- a/lib/pushmi_pullyu/logging.rb +++ b/lib/pushmi_pullyu/logging.rb @@ -13,58 +13,96 @@ def call(_severity, _timestamp, _program_name, msg) end - def self.initialize_logger(log_target = STDOUT) - @logger = Logger.new(log_target) - @logger.level = Logger::INFO - @logger + def logger + PushmiPullyu::Logging.logger end - def self.logger - @logger ||= initialize_logger - end + class << self - def self.log_aip_activity(aip_directory, message) - log_file = "#{aip_directory}/data/logs/aipcreation.log" - aip_logger = Logger.new(log_file) - aip_logger.level = logger.level + attr_writer :logger - # Log to both the application log, and the log file that gets archived in the AIP - logger.info(message) - aip_logger.info(message) + def initialize_logger(log_target = STDOUT) + @logger = Logger.new(log_target) + @logger.level = Logger::INFO + @logger + end - aip_logger.close - end + def logger + @logger ||= initialize_logger + end - def self.log_preservation_event(deposited_file) - preservation_logger = Logger.new("#{PushmiPullyu.options[:logdir]}/preservation_events.log") + def log_aip_activity(aip_directory, message) + log_file = "#{aip_directory}/data/logs/aipcreation.log" + aip_logger = Logger.new(log_file) + aip_logger.level = logger.level - message = "#{deposited_file.name} was successfully deposited into Swift Storage! \n"\ - "Here are the details of this preservation event: \n"\ - "\t NOID: '#{deposited_file.name}' \n"\ - "\t Timestamp of Completion: '#{deposited_file.last_modified}' \n"\ - "\t AIP Checksum: '#{deposited_file.etag}' \n"\ - "\t Metadata: #{deposited_file.metadata} \n" + # Log to both the application log, and the log file that gets archived in the AIP + logger.info(message) + aip_logger.info(message) - # Log to both the application log, and the preservation log file - logger.info(message) - preservation_logger.info(message) + aip_logger.close + end - preservation_logger.close - end + def log_preservation_event(deposited_file, aip_directory) + preservation_logger = Logger.new("#{PushmiPullyu.options[:logdir]}/preservation_events.log") - def self.logger=(log) - @logger = log - end + message = "#{deposited_file.name} was successfully deposited into Swift Storage!\n"\ + "Here are the details of this preservation event:\n"\ + "\tNOID: '#{deposited_file.name}'\n"\ + "\tTimestamp of Completion: '#{deposited_file.last_modified}'\n"\ + "\tAIP Checksum: '#{deposited_file.etag}'\n"\ + "\tMetadata: #{deposited_file.metadata}\n"\ + + file_details = file_log_details(aip_directory) + + if file_details.present? + message << "\tFile Details:\n" + file_details.each do |file_detail| + message << %(\t\t{"fileset_uuid": "#{file_detail[:fileset_name]}", +\t\t"details": { +\t\t\t"file_name": "#{file_detail[:file_name]}", +\t\t\t"file_type": "#{file_detail[:file_extension]}", +\t\t\t"file_size": #{file_detail[:file_size]} +\t\t}}\n) + end + end - def self.reopen - if @logger - @logger.reopen - else - @logger = initialize_logger + # Log to both the application log, and the preservation log file + logger.info(message) + preservation_logger.info(message) + + preservation_logger.close + end + + def reopen + if @logger + @logger.reopen + else + @logger = initialize_logger + end + end + + private + + def file_log_details(aip_directory) + file_details = [] + data_files_location = "#{aip_directory}/data/objects/files" + + if Dir.exist?(data_files_location) + Dir.glob("#{data_files_location}/*") do |folder| + Dir.glob("#{folder}/*") do |file| + file_details << { + fileset_name: File.dirname(file).split('/')[-1], + file_name: File.basename(file), + file_size: File.size(file), + file_extension: File.extname(file).strip.downcase[1..-1] + } + end + end + end + + file_details end - end - def logger - PushmiPullyu::Logging.logger end end diff --git a/spec/integration/acceptance_spec.rb b/spec/integration/acceptance_spec.rb index 3e91b78..ec501fc 100644 --- a/spec/integration/acceptance_spec.rb +++ b/spec/integration/acceptance_spec.rb @@ -62,14 +62,43 @@ expect(deposited_file.metadata['promise']).to eql 'bronze' # Log successful preservation event to the log files - PushmiPullyu::Logging.log_preservation_event(deposited_file) + PushmiPullyu::Logging.log_preservation_event(deposited_file, aip_folder) end end expect(File.exist?("#{log_folder}/preservation_events.log")).to eq(true) + + expected_log_output = <<~HEREDOC + #{noid} was successfully deposited into Swift Storage! + Here are the details of this preservation event: + \tNOID: '#{noid}' + \tTimestamp of Completion: 'Wed, 07 Jun 2017 20:55:45 GMT' + \tAIP Checksum: '2752dc32b7a56b42aee3dd4d235a24a2' + \tMetadata: {"project-id"=>"#{noid}", "aip-version"=>"1.0", "promise"=>"bronze", "project"=>"ERA"} + \tFile Details: + \t\t\{"fileset_uuid": "837977d6-de61-49ea-a912-a65af5c9005e", + \t\t"details": { + \t\t\t"file_name": "image-sample.jpeg", + \t\t\t"file_type": "jpeg", + \t\t\t"file_size": 12401 + \t\t}} + \t\t{"fileset_uuid": "856444b6-8dd5-4dfa-857d-435e354a2ead", + \t\t"details": { + \t\t\t"file_name": "era-logo.png", + \t\t\t"file_type": "png", + \t\t\t"file_size": 5612 + \t\t}} + \t\t{"fileset_uuid": "01bb1b09-974d-478b-8826-2c606a447606", + \t\t"details": { + \t\t\t"file_name": "theses.jpg", + \t\t\t"file_type": "jpg", + \t\t\t"file_size": 53678 + \t\t}} +HEREDOC + expect( File.read("#{log_folder}/preservation_events.log") - ).to include("#{noid} was successfully deposited into Swift Storage!") + ).to include(expected_log_output) # aip file and folder should have been cleaned up expect(File.exist?(aip_folder)).to eq(false) diff --git a/spec/pushmi_pullyu/logging_spec.rb b/spec/pushmi_pullyu/logging_spec.rb index a0bb803..2247568 100644 --- a/spec/pushmi_pullyu/logging_spec.rb +++ b/spec/pushmi_pullyu/logging_spec.rb @@ -82,6 +82,7 @@ class LoggerTest describe '.log_preservation_event' do let(:tmp_log_dir) { 'tmp/logs' } + let(:tmp_aip_dir) { 'tmp/test_aip_dir' } it 'logs preservation event to both preservation log and application log' do FileUtils.mkdir_p(tmp_log_dir) @@ -99,7 +100,7 @@ class LoggerTest 'project' => 'ERA' } ) - PushmiPullyu::Logging.log_preservation_event(deposited_file) + PushmiPullyu::Logging.log_preservation_event(deposited_file, tmp_aip_dir) expect(File.exist?("#{tmp_log_dir}/preservation_events.log")).to eq(true) expect(PushmiPullyu::Logging.logger).to have_received(:info).with(an_instance_of(String)).once From 96e588aed68b3e9d12259b4f084957746ae23c33 Mon Sep 17 00:00:00 2001 From: Shane Murnaghan Date: Mon, 14 May 2018 11:23:03 -0600 Subject: [PATCH 2/3] Fix tests? May be a race condition with order of file details... --- spec/integration/acceptance_spec.rb | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/spec/integration/acceptance_spec.rb b/spec/integration/acceptance_spec.rb index ec501fc..1a402a8 100644 --- a/spec/integration/acceptance_spec.rb +++ b/spec/integration/acceptance_spec.rb @@ -76,7 +76,13 @@ \tAIP Checksum: '2752dc32b7a56b42aee3dd4d235a24a2' \tMetadata: {"project-id"=>"#{noid}", "aip-version"=>"1.0", "promise"=>"bronze", "project"=>"ERA"} \tFile Details: - \t\t\{"fileset_uuid": "837977d6-de61-49ea-a912-a65af5c9005e", + \t\t{"fileset_uuid": "01bb1b09-974d-478b-8826-2c606a447606", + \t\t"details": { + \t\t\t"file_name": "theses.jpg", + \t\t\t"file_type": "jpg", + \t\t\t"file_size": 53678 + \t\t}} + \t\t{"fileset_uuid": "837977d6-de61-49ea-a912-a65af5c9005e", \t\t"details": { \t\t\t"file_name": "image-sample.jpeg", \t\t\t"file_type": "jpeg", @@ -88,12 +94,6 @@ \t\t\t"file_type": "png", \t\t\t"file_size": 5612 \t\t}} - \t\t{"fileset_uuid": "01bb1b09-974d-478b-8826-2c606a447606", - \t\t"details": { - \t\t\t"file_name": "theses.jpg", - \t\t\t"file_type": "jpg", - \t\t\t"file_size": 53678 - \t\t}} HEREDOC expect( From 635d7ab02ac9b0fc4e2ff325f35e60f9e8ac4ce7 Mon Sep 17 00:00:00 2001 From: Shane Murnaghan Date: Mon, 14 May 2018 11:34:30 -0600 Subject: [PATCH 3/3] Fix race condition, cannot guarantee order of files --- spec/integration/acceptance_spec.rb | 22 +++++++++++++++++----- 1 file changed, 17 insertions(+), 5 deletions(-) diff --git a/spec/integration/acceptance_spec.rb b/spec/integration/acceptance_spec.rb index 1a402a8..0b8342b 100644 --- a/spec/integration/acceptance_spec.rb +++ b/spec/integration/acceptance_spec.rb @@ -68,7 +68,7 @@ expect(File.exist?("#{log_folder}/preservation_events.log")).to eq(true) - expected_log_output = <<~HEREDOC + log_details = <<~HEREDOC #{noid} was successfully deposited into Swift Storage! Here are the details of this preservation event: \tNOID: '#{noid}' @@ -76,29 +76,41 @@ \tAIP Checksum: '2752dc32b7a56b42aee3dd4d235a24a2' \tMetadata: {"project-id"=>"#{noid}", "aip-version"=>"1.0", "promise"=>"bronze", "project"=>"ERA"} \tFile Details: + HEREDOC + + file_details_one = <<~HEREDOC \t\t{"fileset_uuid": "01bb1b09-974d-478b-8826-2c606a447606", \t\t"details": { \t\t\t"file_name": "theses.jpg", \t\t\t"file_type": "jpg", \t\t\t"file_size": 53678 \t\t}} + HEREDOC + + file_details_two = <<~HEREDOC \t\t{"fileset_uuid": "837977d6-de61-49ea-a912-a65af5c9005e", \t\t"details": { \t\t\t"file_name": "image-sample.jpeg", \t\t\t"file_type": "jpeg", \t\t\t"file_size": 12401 \t\t}} + HEREDOC + + file_details_three = <<~HEREDOC \t\t{"fileset_uuid": "856444b6-8dd5-4dfa-857d-435e354a2ead", \t\t"details": { \t\t\t"file_name": "era-logo.png", \t\t\t"file_type": "png", \t\t\t"file_size": 5612 \t\t}} -HEREDOC + HEREDOC + + log_file = File.read("#{log_folder}/preservation_events.log") - expect( - File.read("#{log_folder}/preservation_events.log") - ).to include(expected_log_output) + expect(log_file).to include(log_details) + expect(log_file).to include(file_details_one) + expect(log_file).to include(file_details_two) + expect(log_file).to include(file_details_three) # aip file and folder should have been cleaned up expect(File.exist?(aip_folder)).to eq(false)