diff --git a/app/sidekiq/hca/ezr_submission_job.rb b/app/sidekiq/hca/ezr_submission_job.rb index 1b2eccf35e4..41010cff4e3 100644 --- a/app/sidekiq/hca/ezr_submission_job.rb +++ b/app/sidekiq/hca/ezr_submission_job.rb @@ -6,17 +6,32 @@ module HCA class EzrSubmissionJob include Sidekiq::Job - include SentryLogging + extend SentryLogging VALIDATION_ERROR = HCA::SOAPParser::ValidationError + STATSD_KEY_PREFIX = 'api.1010ezr' + # 14 retries was decided on because it's the closest to a 24-hour time span based on + # Sidekiq's backoff formula: https://github.com/sidekiq/sidekiq/wiki/Error-Handling#automatic-job-retry sidekiq_options retry: 14 sidekiq_retries_exhausted do |msg, _e| - log_submission_failure(decrypt_form(msg['args'][0])) - end - - def self.log_submission_failure(parsed_form) - Form1010Ezr::Service.new(nil).log_submission_failure(parsed_form) + parsed_form = decrypt_form(msg['args'][0]) + + StatsD.increment("#{STATSD_KEY_PREFIX}.failed_wont_retry") + + if parsed_form.present? + PersonalInformationLog.create!( + data: parsed_form, + error_class: 'Form1010Ezr FailedWontRetry' + ) + + log_message_to_sentry( + '1010EZR total failure', + :error, + Form1010Ezr::Service.new(nil).veteran_initials(parsed_form), + ezr: :total_failure + ) + end end def self.decrypt_form(encrypted_form) @@ -29,10 +44,10 @@ def perform(encrypted_form, user_uuid) Form1010Ezr::Service.new(user).submit_sync(parsed_form) rescue VALIDATION_ERROR => e - self.class.log_submission_failure(parsed_form) - log_exception_to_sentry(e) + Form1010Ezr::Service.new(nil).log_submission_failure(parsed_form) + self.class.log_exception_to_sentry(e) rescue - StatsD.increment("#{Form1010Ezr::Service::STATSD_KEY_PREFIX}.async.retries") + StatsD.increment("#{STATSD_KEY_PREFIX}.async.retries") raise end end diff --git a/lib/form1010_ezr/service.rb b/lib/form1010_ezr/service.rb index c87e9cabda4..2f6b459aeb3 100644 --- a/lib/form1010_ezr/service.rb +++ b/lib/form1010_ezr/service.rb @@ -41,7 +41,11 @@ def submit_sync(parsed_form) end # Log the 'formSubmissionId' for successful submissions - Rails.logger.info("SubmissionID=#{res[:formSubmissionId]}") + Rails.logger.info( + '1010EZR successfully submitted', + submission_id: res[:formSubmissionId], + veteran_initials: veteran_initials(parsed_form) + ) res rescue => e @@ -61,27 +65,31 @@ def submit_form(parsed_form) end def log_submission_failure(parsed_form) - StatsD.increment("#{Form1010Ezr::Service::STATSD_KEY_PREFIX}.failed_wont_retry") + StatsD.increment("#{Form1010Ezr::Service::STATSD_KEY_PREFIX}.failed") if parsed_form.present? PersonalInformationLog.create!( data: parsed_form, - error_class: 'Form1010Ezr FailedWontRetry' + error_class: 'Form1010Ezr Failed' ) log_message_to_sentry( - '1010EZR total failure', + '1010EZR failure', :error, - { - first_initial: parsed_form.dig('veteranFullName', 'first')&.chr || 'no initial provided', - middle_initial: parsed_form.dig('veteranFullName', 'middle')&.chr || 'no initial provided', - last_initial: parsed_form.dig('veteranFullName', 'last')&.chr || 'no initial provided' - }, - ezr: :total_failure + veteran_initials(parsed_form), + ezr: :failure ) end end + def veteran_initials(parsed_form) + { + first_initial: parsed_form.dig('veteranFullName', 'first')&.chr || 'no initial provided', + middle_initial: parsed_form.dig('veteranFullName', 'middle')&.chr || 'no initial provided', + last_initial: parsed_form.dig('veteranFullName', 'last')&.chr || 'no initial provided' + } + end + private # Compare the 'parsed_form' to the JSON form schema in vets-json-schema diff --git a/spec/lib/form1010_ezr/service_spec.rb b/spec/lib/form1010_ezr/service_spec.rb index 61a1159dc89..0b36a41c372 100644 --- a/spec/lib/form1010_ezr/service_spec.rb +++ b/spec/lib/form1010_ezr/service_spec.rb @@ -62,6 +62,13 @@ def ezr_form_with_attachments ) end + def expect_personal_info_log(message) + pii_log = PersonalInformationLog.last + + expect(pii_log.error_class).to eq(message) + expect(pii_log.data).to eq(form) + end + describe '#add_financial_flag' do context 'when the form has veteran gross income' do let(:parsed_form) do @@ -91,12 +98,13 @@ def ezr_form_with_attachments 'hca/ee/lookup_user', VCR::MATCH_EVERYTHING.merge(erb: true) ) do - expect(form['isEssentialAcaCoverage']).to eq(nil) - expect(form['vaMedicalFacility']).to eq(nil) + expect(form.keys).not_to include('isEssentialAcaCoverage', 'vaMedicalFacility') service.send(:post_fill_required_fields, form) expect(form.keys).to include('isEssentialAcaCoverage', 'vaMedicalFacility') + expect(form['isEssentialAcaCoverage']).to eq(false) + expect(form['vaMedicalFacility']).to eq('988') end end end @@ -156,6 +164,38 @@ def ezr_form_with_attachments end end + describe '#log_submission_failure' do + context "when 'parsed_form' is not present" do + it 'only increments StatsD' do + allow(StatsD).to receive(:increment) + expect(StatsD).to receive(:increment).with('api.1010ezr.failed') + + described_class.new(nil).log_submission_failure(nil) + end + end + + context "when 'parsed_form' is present" do + it "increments StatsD, creates a 'PersonalInformationLog' record, and logs a failure message to sentry" do + allow(StatsD).to receive(:increment) + expect(StatsD).to receive(:increment).with('api.1010ezr.failed') + expect_any_instance_of(SentryLogging).to receive(:log_message_to_sentry).with( + '1010EZR failure', + :error, + { + first_initial: 'F', + middle_initial: 'M', + last_initial: 'Z' + }, + ezr: :failure + ) + + described_class.new(nil).log_submission_failure(form) + + expect_personal_info_log('Form1010Ezr Failed') + end + end + end + describe '#submit_form' do it 'submits the ezr with a background job', run_at: 'Tue, 21 Nov 2023 20:42:44 GMT' do VCR.use_cassette( @@ -260,7 +300,7 @@ def ezr_form_with_attachments it 'increments StatsD as well as logs and raises the error' do allow(StatsD).to receive(:increment) - expect(StatsD).to receive(:increment).with('api.1010ezr.failed_wont_retry') + expect(StatsD).to receive(:increment).with('api.1010ezr.failed') expect { submit_form(form) }.to raise_error( StandardError, 'Uh oh. Some bad error occurred.' ) @@ -310,7 +350,8 @@ def ezr_form_with_attachments end end - it 'logs the submission id, payload size, and individual attachment sizes in descending order (if applicable)', + it "logs the submission id, user's initials, payload size, and individual attachment sizes in descending " \ + 'order (if applicable)', run_at: 'Wed, 17 Jul 2024 18:17:30 GMT' do VCR.use_cassette( 'form1010_ezr/authorized_submit_with_attachments', @@ -318,7 +359,15 @@ def ezr_form_with_attachments ) do submission_response = service.submit_sync(ezr_form_with_attachments) - expect(Rails.logger).to have_received(:info).with("SubmissionID=#{submission_response[:formSubmissionId]}") + expect(Rails.logger).to have_received(:info).with( + '1010EZR successfully submitted', + submission_id: submission_response[:formSubmissionId], + veteran_initials: { + first_initial: 'F', + middle_initial: 'M', + last_initial: 'Z' + } + ) expect(Rails.logger).to have_received(:info).with('Payload for submitted 1010EZR: ' \ 'Body size of 362 KB with 2 attachment(s)') expect(Rails.logger).to have_received(:info).with( diff --git a/spec/sidekiq/hca/ezr_submission_job_spec.rb b/spec/sidekiq/hca/ezr_submission_job_spec.rb index b86465558de..ae93a87c7f6 100644 --- a/spec/sidekiq/hca/ezr_submission_job_spec.rb +++ b/spec/sidekiq/hca/ezr_submission_job_spec.rb @@ -12,18 +12,44 @@ end let(:ezr_service) { double } - describe 'when job has failed' do - let(:msg) do - { - 'args' => [encrypted_form, nil] - } + describe 'when retries are exhausted' do + context 'when the parsed form is not present' do + it 'only increments StatsD' do + msg = { + 'args' => [HealthCareApplication::LOCKBOX.encrypt({}.to_json), nil] + } + + described_class.within_sidekiq_retries_exhausted_block(msg) do + allow(StatsD).to receive(:increment) + expect(StatsD).to receive(:increment).with('api.1010ezr.failed_wont_retry') + end + end end - it 'passes unencrypted form to 1010ezr service' do - expect_any_instance_of(Form1010Ezr::Service).to receive(:log_submission_failure).with( - form - ) - described_class.new.sidekiq_retries_exhausted_block.call(msg) + context 'when the parsed form is present' do + it "increments StatsD, creates a 'PersonalInformationLog' record, and logs a failure message to sentry" do + msg = { + 'args' => [encrypted_form, nil] + } + + described_class.within_sidekiq_retries_exhausted_block(msg) do + expect(StatsD).to receive(:increment).with('api.1010ezr.failed_wont_retry') + expect(described_class).to receive(:log_message_to_sentry).with( + '1010EZR total failure', + :error, + { + first_initial: 'F', + middle_initial: 'M', + last_initial: 'Z' + }, + ezr: :total_failure + ) + end + + pii_log = PersonalInformationLog.last + expect(pii_log.error_class).to eq('Form1010Ezr FailedWontRetry') + expect(pii_log.data).to eq(form) + end end end @@ -47,7 +73,7 @@ # of the 'Form1010Ezr::Service', we need to stub out a new instance of the service allow(Form1010Ezr::Service).to receive(:new).with(nil).once.and_return(ezr_service) - expect_any_instance_of(HCA::EzrSubmissionJob).to receive(:log_exception_to_sentry).with(error) + expect(HCA::EzrSubmissionJob).to receive(:log_exception_to_sentry).with(error) expect(ezr_service).to receive(:log_submission_failure).with( form )