diff --git a/app/jobs/get_usps_proofing_results_job.rb b/app/jobs/get_usps_proofing_results_job.rb index 16dcb4d0aec..b0b7d2d2276 100644 --- a/app/jobs/get_usps_proofing_results_job.rb +++ b/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') diff --git a/app/services/analytics_events.rb b/app/services/analytics_events.rb index 089c3e1365b..45f2e4e6000 100644 --- a/app/services/analytics_events.rb +++ b/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 diff --git a/spec/jobs/get_usps_proofing_results_job_spec.rb b/spec/jobs/get_usps_proofing_results_job_spec.rb index a39addc7f90..08f4addf971 100644 --- a/spec/jobs/get_usps_proofing_results_job_spec.rb +++ b/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