Fix bug in Californica::Deleter logging (#882)

Co-authored-by: Parinita Mulak <[email protected]>

app/importers/californica_importer.rb

@@ -33,7 +33,7 @@ def import
     Darlingtonia::Importer.new(parser: parser, record_importer: record_importer, info_stream: @info_stream, error_stream: @error_stream).import
 
     # Reset status of unfinished jobs
-    @csv_import.csv_rows.where.not(status: 'complete').update_all(status: 'queued')
+    @csv_import.csv_rows.where.not(status: 'complete').update_all(status: 'queued', error_messages: [])
 
     @csv_import.csv_rows.where(status: 'queued').each do |csv_row|
       CsvRowImportJob.perform_now(row_id: csv_row.id)

app/jobs/csv_row_import_job.rb

@@ -42,7 +42,6 @@ def perform(row_id:)
       when 'Work', 'Manuscript'
         @row.update(status: 'deleting child works')
         Californica::Deleter.new(id: Californica::IdGenerator.id_from_ark(record.mapper.ark), logger: @row.error_messages).delete_with_children(of_type: ChildWork)
-        @row.update(status: 'in progress')
         selected_importer = actor_record_importer
         new_status = 'complete'
       when 'Collection'

app/jobs/start_csv_import_job.rb

@@ -2,24 +2,14 @@
 
 class StartCsvImportJob < ApplicationJob
   queue_as Hyrax.config.ingest_queue_name
-  rescue_from Mysql2::Error::ConnectionError do
-    Rollbar.error(e, csv_import: csv_import_id)
-    retry_job wait: 600 # wait 10 minutes for MySQL to come back
-  end
+  rescue_from StandardError, with: :log_exception
 
   def perform(csv_import_id)
     @csv_import = CsvImport.find csv_import_id
     setup_logging
     @info_stream << "StartCsvImportJob ~ Starting import with batch ID: #{csv_import_id}"
     importer = CalifornicaImporter.new(@csv_import, info_stream: @info_stream, error_stream: @error_stream)
     importer.import
-
-  rescue => e
-    Rollbar.error(e, csv_import: csv_import_id)
-    @error_stream << "#{e.class}: #{e.message}\n#{e.backtrace.inspect}"
-    @row.update(status: 'error',
-                end_time: Time.current,
-                ingest_duration: @row.start_time - Time.current)
   end
 
   def ingest_log_filename
@@ -31,4 +21,16 @@ def setup_logging
     @info_stream  = CalifornicaLogStream.new(logger: @ingest_log, severity: Logger::INFO)
     @error_stream = CalifornicaLogStream.new(logger: @ingest_log, severity: Logger::ERROR)
   end
+
+private
+
+  def log_exception(e)
+    Rollbar.error(e, csv_import: csv_import_id)
+    @error_stream << "#{e.class}: #{e.message}\n#{e.backtrace.inspect}"
+    @row&.update(status: 'error',
+                 end_time: Time.current,
+                 ingest_duration: @row.start_time - Time.current)
+
+    retry_job(wait: 600) if e.is_a? Mysql2::Error::ConnectionError
+  end
 end

app/lib/californica/deleter.rb

@@ -33,25 +33,40 @@ def delete_children(of_type: nil)
     private
 
       def destroy_and_eradicate
-        record_name = "#{record.class} #{record.ark}"
         record&.destroy&.eradicate
         Hyrax.config.callback.run(:after_destroy, record.id, User.batch_user)
-        logger.info("Deleted #{record_name || id}}")
+        log("Deleted record")
+      rescue Ldp::HttpError, Faraday::TimeoutError => e
+        log("#{e.class}: #{e.message}")
+        retries ||= 0
+        retry if (retries += 1) <= 3
       end
 
       def delete_from_fcrepo
         ActiveFedora.fedora.connection.delete(ActiveFedora::Base.id_to_uri(id))
-        Rollbar.info("Forced delete of #{id} from Fedora")
-        logger.info("Forced delete of #{id} from Fedora")
+        log("Forced delete of record from Fedora")
       rescue Ldp::NotFound
         nil # Everything's good, we just wanted to make sure there wasn't a record in fedora not indexed to solr
       end
 
+      def log(message, status: :info)
+        Rollbar.send((Rollbar.respond_to?(status) ? status : :info), message, id: id)
+        if logger.respond_to?(status)
+          logger.send(status, "#{message} (#{record_name})")
+        elsif logger.respond_to?(:<<)
+          logger << "#{status}: #{message} (#{record_name})"
+        end
+      end
+
       def record
         @record ||= ActiveFedora::Base.find(id)
 
       rescue ActiveFedora::ObjectNotFoundError
         delete_from_fcrepo
       end
+
+      def record_name
+        @record ? "#{record.class} #{record.ark}" : id
+      end
   end
 end

config/fedora.yml

@@ -17,4 +17,4 @@ production:
   password: <%= ENV['FEDORA_PASSWORD'] %>
   url: <%= ENV['FEDORA_URL'] %>
   base_path: <%= ENV['FEDORA_BASE_PATH'] || '/prod' %>
-  request: { timeout: 7200, open_timeout: 60 }
+  request: { timeout: 7200, open_timeout: 600 }

config/initializers/rollbar.rb

@@ -49,9 +49,7 @@
   # config.use_sucker_punch
 
   # Enable delayed reporting (using Sidekiq)
-  # config.use_sidekiq
-  # You can supply custom Sidekiq options:
-  # config.use_sidekiq 'queue' => 'default'
+  config.use_sidekiq 'queue' => 'default'
 
   # If your application runs behind a proxy server, you can set proxy parameters here.
   # If https_proxy is set in your environment, that will be used. Settings here have precedence.
@@ -71,5 +69,4 @@
   # setup for Heroku. See:
   # https://devcenter.heroku.com/articles/deploying-to-a-custom-rails-environment
   config.environment = ENV['ROLLBAR_ENV'].presence || Rails.env
-  config.use_sidekiq
 end

spec/jobs/csv_row_import_job_spec.rb

@@ -16,6 +16,11 @@
     end
     let(:csv_row) { FactoryBot.create(:csv_row, status: nil, csv_import_id: csv_import.id, metadata: metadata) }
 
+    before do
+      test_strategy = Flipflop::FeatureSet.current.test!
+      test_strategy.switch!(:child_works, false)
+    end
+
     it 'can set a status' do
       described_class.perform_now(row_id: csv_row.id)
       csv_row.reload

spec/services/californica/csv_import_service_spec.rb

@@ -15,7 +15,6 @@
       Object Type,Title,Item ARK,Parent ARK,Rights.copyrightStatus,File Name,Import Status
       Work,Apple,ark:/abc/123456,ark:/abc/7890123,copyrighted,clusc_1_1_00010432a.tif,queued
       Work,Banana,ark:/abc/654321,ark:/abc/7890123,copyrighted,clusc_1_1_00010432a.tif,error
-      Work,Mango,ark:/abc/918274,ark:/abc/7890123,copyrighted,clusc_1_1_00010432a.tif,complete
     HEREDOC
   end