LG-8284: Make GetUspsProofingResultsJob terminate gracefully

app/jobs/get_usps_proofing_results_job.rb

@@ -13,46 +13,15 @@ class GetUspsProofingResultsJob < ApplicationJob
 
   queue_as :long_running
 
-  def email_analytics_attributes(enrollment)
-    {
-      timestamp: Time.zone.now,
-      user_id: enrollment.user_id,
-      service_provider: enrollment.issuer,
-      wait_until: mail_delivery_params(enrollment.proofed_at)[:wait_until],
-    }
-  end
-
-  def enrollment_analytics_attributes(enrollment, complete:)
-    {
-      enrollment_code: enrollment.enrollment_code,
-      enrollment_id: enrollment.id,
-      minutes_since_last_status_check: enrollment.minutes_since_last_status_check,
-      minutes_since_last_status_update: enrollment.minutes_since_last_status_update,
-      minutes_since_established: enrollment.minutes_since_established,
-      minutes_to_completion: complete ? enrollment.minutes_since_established : nil,
-      issuer: enrollment.issuer,
-    }
-  end
-
-  def response_analytics_attributes(response)
-    return { response_present: false } unless response.present?
+  rescue_from GoodJob::ActiveJobExtensions::Concurrency::ConcurrencyExceededError do |exception|
+    analytics.idv_in_person_usps_proofing_results_job_terminated(
+      **enrollment_outcomes,
+      duration_seconds: (Time.zone.now - started_at).seconds.round(2),
+      error_class: exception.class.name,
+      error_message: exception.message,
+    )
 
-    {
-      fraud_suspected: response['fraudSuspected'],
-      primary_id_type: response['primaryIdType'],
-      secondary_id_type: response['secondaryIdType'],
-      failure_reason: response['failureReason'],
-      transaction_end_date_time: parse_usps_timestamp(response['transactionEndDateTime']),
-      transaction_start_date_time: parse_usps_timestamp(response['transactionStartDateTime']),
-      status: response['status'],
-      assurance_level: response['assuranceLevel'],
-      proofing_post_office: response['proofingPostOffice'],
-      proofing_city: response['proofingCity'],
-      proofing_state: response['proofingState'],
-      scan_count: response['scanCount'],
-      response_message: response['responseMessage'],
-      response_present: true,
-    }
+    raise exception
   end
 
   def perform(_now)
@@ -66,13 +35,16 @@ def perform(_now)
       enrollments_in_progress: 0,
       enrollments_passed: 0,
     }
+    @request_delay_in_seconds = IdentityConfig.store.
+      get_usps_proofing_results_job_request_delay_milliseconds / MILLISECONDS_PER_SECOND
+
     reprocess_delay_minutes = IdentityConfig.store.
       get_usps_proofing_results_job_reprocess_delay_minutes
     enrollments = InPersonEnrollment.needs_usps_status_check(
       ...reprocess_delay_minutes.minutes.ago,
     )
 
-    started_at = Time.zone.now
+    @started_at = Time.zone.now
     analytics.idv_in_person_usps_proofing_results_job_started(
       enrollments_count: enrollments.count,
       reprocess_delay_minutes: reprocess_delay_minutes,
@@ -91,55 +63,103 @@ def perform(_now)
   private
 
   attr_accessor :enrollment_outcomes
+  attr_accessor :request_delay_in_seconds
+  attr_accessor :started_at
 
   DEFAULT_EMAIL_DELAY_IN_HOURS = 1
 
-  def check_enrollments(enrollments)
-    request_delay_in_seconds = IdentityConfig.store.
-      get_usps_proofing_results_job_request_delay_milliseconds / MILLISECONDS_PER_SECOND
-    proofer = UspsInPersonProofing::Proofer.new
+  def proofer
+    @proofer ||= UspsInPersonProofing::Proofer.new
+  end
 
+  def check_enrollments(enrollments)
     enrollments.each_with_index do |enrollment, idx|
-      # Add a unique ID for enrollments that don't have one
-      enrollment.update(unique_id: enrollment.usps_unique_id) if enrollment.unique_id.blank?
+      check_enrollment(enrollment, (idx < enrollments.length - 1))
+    end
+  end
 
-      status_check_attempted_at = Time.zone.now
-      enrollment_outcomes[:enrollments_checked] += 1
-      response = nil
+  def check_enrollment(enrollment, is_not_last_enrollment)
+    # Add a unique ID for enrollments that don't have one
+    enrollment.update(unique_id: enrollment.usps_unique_id) if enrollment.unique_id.blank?
 
-      begin
-        response = proofer.request_proofing_results(
-          enrollment.unique_id, enrollment.enrollment_code
-        )
-      rescue Faraday::BadRequestError => err
-        # 400 status code. This is used for some status updates and some common client errors
-        handle_bad_request_error(err, enrollment)
-      rescue Faraday::ClientError, Faraday::ServerError => err
-        # 4xx or 5xx status code. These are unexpected but will have some sort of
-        # response body that we can try to log data from
-        handle_client_or_server_error(err, enrollment)
-      rescue Faraday::Error => err
-        # Timeouts, failed connections, parsing errors, and other HTTP errors. These
-        # generally won't have a response body
-        handle_faraday_error(err, enrollment)
-      rescue StandardError => err
-        handle_standard_error(err, enrollment)
-      else
-        process_enrollment_response(enrollment, response)
-      ensure
-        # Record the attempt to update the enrollment
-        enrollment.update(status_check_attempted_at: status_check_attempted_at)
-      end
+    status_check_attempted_at = Time.zone.now
+    enrollment_outcomes[:enrollments_checked] += 1
+    response = nil
 
-      # Sleep for a while before we attempt to make another call to USPS
-      sleep request_delay_in_seconds if idx < enrollments.length - 1
+    begin
+      response = proofer.request_proofing_results(
+        enrollment.unique_id, enrollment.enrollment_code
+      )
+    rescue Faraday::BadRequestError => err
+      # 400 status code. This is used for some status updates and some common client errors
+      handle_bad_request_error(err, enrollment)
+    rescue Faraday::ClientError, Faraday::ServerError => err
+      # 4xx or 5xx status code. These are unexpected but will have some sort of
+      # response body that we can try to log data from
+      handle_client_or_server_error(err, enrollment)
+    rescue Faraday::Error => err
+      # Timeouts, failed connections, parsing errors, and other HTTP errors. These
+      # generally won't have a response body
+      handle_faraday_error(err, enrollment)
+    rescue StandardError => err
+      handle_standard_error(err, enrollment)
+    else
+      process_enrollment_response(enrollment, response)
+    ensure
+      # Record the attempt to update the enrollment
+      enrollment.update(status_check_attempted_at: status_check_attempted_at)
     end
+
+    # Sleep for a while before we attempt to make another call to USPS
+    sleep request_delay_in_seconds if is_not_last_enrollment
   end
 
   def analytics(user: AnonymousUser.new)
     Analytics.new(user: user, request: nil, session: {}, sp: nil)
   end
 
+  def email_analytics_attributes(enrollment)
+    {
+      timestamp: Time.zone.now,
+      user_id: enrollment.user_id,
+      service_provider: enrollment.issuer,
+      wait_until: mail_delivery_params(enrollment.proofed_at)[:wait_until],
+    }
+  end
+
+  def enrollment_analytics_attributes(enrollment, complete:)
+    {
+      enrollment_code: enrollment.enrollment_code,
+      enrollment_id: enrollment.id,
+      minutes_since_last_status_check: enrollment.minutes_since_last_status_check,
+      minutes_since_last_status_update: enrollment.minutes_since_last_status_update,
+      minutes_since_established: enrollment.minutes_since_established,
+      minutes_to_completion: complete ? enrollment.minutes_since_established : nil,
+      issuer: enrollment.issuer,
+    }
+  end
+
+  def response_analytics_attributes(response)
+    return { response_present: false } unless response.present?
+
+    {
+      fraud_suspected: response['fraudSuspected'],
+      primary_id_type: response['primaryIdType'],
+      secondary_id_type: response['secondaryIdType'],
+      failure_reason: response['failureReason'],
+      transaction_end_date_time: parse_usps_timestamp(response['transactionEndDateTime']),
+      transaction_start_date_time: parse_usps_timestamp(response['transactionStartDateTime']),
+      status: response['status'],
+      assurance_level: response['assuranceLevel'],
+      proofing_post_office: response['proofingPostOffice'],
+      proofing_city: response['proofingCity'],
+      proofing_state: response['proofingState'],
+      scan_count: response['scanCount'],
+      response_message: response['responseMessage'],
+      response_present: true,
+    }
+  end
+
   def handle_bad_request_error(err, enrollment)
     response_body = err.response_body
     response_message = response_body&.[]('responseMessage')

app/services/analytics_events.rb

@@ -3238,6 +3238,43 @@ def idv_in_person_usps_proofing_results_job_started(
     )
   end
 
+  # GetUspsProofingResultsJob has been terminated. Includes counts of various outcomes encountered
+  # @param [Float] duration_seconds number of minutes the job was running
+  # @param [Integer] enrollments_checked number of enrollments eligible for status check
+  # @param [Integer] enrollments_errored number of enrollments for which we encountered an error
+  # @param [Integer] enrollments_expired number of enrollments which expired
+  # @param [Integer] enrollments_failed number of enrollments which failed identity proofing
+  # @param [Integer] enrollments_in_progress number of enrollments which did not have any change
+  # @param [Integer] enrollments_passed number of enrollments which passed identity proofing
+  # @param [String] error_class the class of the exception that caused the job to terminate
+  # @param [String] error_message the message from the exception that caused the job to terminate
+  def idv_in_person_usps_proofing_results_job_terminated(
+    duration_seconds:,
+    enrollments_checked:,
+    enrollments_errored:,
+    enrollments_expired:,
+    enrollments_failed:,
+    enrollments_in_progress:,
+    enrollments_passed:,
+    error_class:,
+    error_message:,
+    **extra
+  )
+    track_event(
+      'GetUspsProofingResultsJob: Job terminated',
+      duration_seconds: duration_seconds,
+      enrollments_checked: enrollments_checked,
+      enrollments_errored: enrollments_errored,
+      enrollments_expired: enrollments_expired,
+      enrollments_failed: enrollments_failed,
+      enrollments_in_progress: enrollments_in_progress,
+      enrollments_passed: enrollments_passed,
+      error_class: error_class,
+      error_message: error_message,
+      **extra,
+    )
+  end
+
   # GetUspsProofingResultsJob has completed. Includes counts of various outcomes encountered
   # @param [Float] duration_seconds number of minutes the job was running
   # @param [Integer] enrollments_checked number of enrollments eligible for status check

spec/jobs/get_usps_proofing_results_job_spec.rb

@@ -265,34 +265,89 @@
         )
       end
 
-      it 'logs a message with counts of various outcomes when the job completes' do
-        allow(InPersonEnrollment).to receive(:needs_usps_status_check).
-          and_return(pending_enrollments)
-        stub_request_proofing_results_with_responses(
-          request_passed_proofing_results_args,
-          request_in_progress_proofing_results_args,
-          { status: 500 },
-          request_failed_proofing_results_args,
-          request_expired_proofing_results_args,
-        )
+      context 'with a set of outcomes to log' do
+        let(:responses) do
+          [
+            request_passed_proofing_results_args,
+            request_in_progress_proofing_results_args,
+            { status: 500 },
+            request_failed_proofing_results_args,
+            request_expired_proofing_results_args,
+          ]
+        end
+
+        before do
+          allow(InPersonEnrollment).to receive(:needs_usps_status_check).
+            and_return(pending_enrollments)
+          stub_request_proofing_results_with_responses(*responses)
+        end
 
-        job.perform(Time.zone.now)
+        it 'logs a message with counts of various outcomes when the job completes' do
+          job.perform(Time.zone.now)
 
-        expect(job_analytics).to have_logged_event(
-          'GetUspsProofingResultsJob: Job completed',
-          duration_seconds: anything,
-          enrollments_checked: 5,
-          enrollments_errored: 1,
-          enrollments_expired: 1,
-          enrollments_failed: 1,
-          enrollments_in_progress: 1,
-          enrollments_passed: 1,
-        )
+          expect(job_analytics).to have_logged_event(
+            'GetUspsProofingResultsJob: Job completed',
+            duration_seconds: anything,
+            enrollments_checked: 5,
+            enrollments_errored: 1,
+            enrollments_expired: 1,
+            enrollments_failed: 1,
+            enrollments_in_progress: 1,
+            enrollments_passed: 1,
+          )
+
+          expect(
+            job_analytics.events['GetUspsProofingResultsJob: Job completed'].
+              first[:duration_seconds],
+          ).to be >= 0.0
+        end
+
+        context 'when the job is terminated with a ConcurrencyExceededError' do
+          let(:analytics_title) { 'GetUspsProofingResultsJob: Job terminated' }
+          let(:error_message) { 'too many!' }
+          let(:error_job_class) do
+            Class.new(GetUspsProofingResultsJob) do
+              private
+
+              def check_enrollment(enrollment, is_not_last_enrollment)
+                if is_not_last_enrollment
+                  super(enrollment, is_not_last_enrollment)
+                else
+                  raise GoodJob::ActiveJobExtensions::Concurrency::ConcurrencyExceededError,
+                        'too many!'
+                end
+              end
+            end
+          end
+
+          it 'logs a message with counts of various outcomes when the job is terminated' do
+            allow_any_instance_of(error_job_class).to receive(:analytics).and_return(job_analytics)
 
-        expect(
-          job_analytics.events['GetUspsProofingResultsJob: Job completed'].
-            first[:duration_seconds],
-        ).to be >= 0.0
+            expect { error_job_class.perform_now(Time.zone.now) }.
+              to raise_error(
+                GoodJob::ActiveJobExtensions::Concurrency::ConcurrencyExceededError,
+                error_message,
+              )
+
+            expect(job_analytics).to have_logged_event(
+              analytics_title,
+              duration_seconds: anything,
+              enrollments_checked: 4,
+              enrollments_errored: 1,
+              enrollments_expired: 0,
+              enrollments_failed: 1,
+              enrollments_in_progress: 1,
+              enrollments_passed: 1,
+              error_class: 'GoodJob::ActiveJobExtensions::Concurrency::ConcurrencyExceededError',
+              error_message: error_message,
+            )
+
+            expect(
+              job_analytics.events[analytics_title].
+                first[:duration_seconds],
+            ).to be >= 0.0
+          end
+        end
       end
 
       context 'a standard error is raised when requesting proofing results' do