From 511945576344b4195d2c758ed429bb39855769c6 Mon Sep 17 00:00:00 2001 From: Nathan Burgess Date: Tue, 3 Dec 2024 10:30:17 -0500 Subject: [PATCH] [Lighthouse Document Upload] Refactor Lighthouse error response handling (#19623) * Refactor Lighthouse document upload error handling Refactors the LighthouseSupplementalDocumentUploadProvider to catch any exception raised during the upload process and ensure they are logged properly. This includes those custom exceptions raised in the Lighthouse::ServiceException class via our Lighthouse API client. Prior to this change, an exception raised elsewhere, including the service exceptions, would have prevented the code that handles a Lighthouse response in this provider from properly logging an upload failure because the code would raise instead of continuing to execute * Handle exception class returning object Lighthouse::ServiceException can either raise an error or return an error object so we need to account for both cases when we use this class to handle errors from the Lighthouse upload response * Remove invalid 200 response handling Instead of logging an upload as a failure, if we recieve a 200 response from Lighthouse but the metadata doesn't match what we expect, we want to fail loudly so we can address the mismatch instead of simply logging an upload failure, which is reserved for actual failed upload responses from the Lighthouse API * Complete renaming of request id key in logs for clarity * Remove non-200 response Lighthouse handling tests We are no longer expecting to handle non-200 responses from Lighthouse within the LighthouseSupplementalDocumentUploadProvider, since these responses are passed to the Lighthouse::ServiceException class, which logs and re-raises the exception, so it will never get to the code this tested * Remove unused validate_upload_document method from doc upload providers This method was intended to be used by our document upload providers to validate veteran uploaded evidence, but we are actually checking this validation and raising an expection in the SubmitUploads job before we even use the provider, so this is now unecessary dead code * Fix linting errors * Fix upload service spec to reflect exception handling changes * Refactor Submit0781 failure tests for new exception handling * Update BDD upload spec for new logging paradigm * Update submit uploads tests for new logging paradigm * Revert "Remove unused validate_upload_document method from doc upload providers" This reverts commit 130d26cc8c25531ec31c4d5c8997b316c0241ff9. * Refactor provider spec to match more realistic specs implemented in upload jobs --- ...e_supplemental_document_upload_provider.rb | 38 +++---- .../upload_supplemental_document_service.rb | 6 +- ...plemental_document_upload_provider_spec.rb | 102 ++++++++++-------- ...load_supplemental_document_service_spec.rb | 34 +++++- .../submit_form0781_spec.rb | 90 ++++------------ .../submit_uploads_spec.rb | 28 ++--- .../upload_bdd_instructions_spec.rb | 32 ++---- 7 files changed, 152 insertions(+), 178 deletions(-) diff --git a/lib/disability_compensation/providers/document_upload/lighthouse_supplemental_document_upload_provider.rb b/lib/disability_compensation/providers/document_upload/lighthouse_supplemental_document_upload_provider.rb index 1237d8f2b53..8261b29634d 100644 --- a/lib/disability_compensation/providers/document_upload/lighthouse_supplemental_document_upload_provider.rb +++ b/lib/disability_compensation/providers/document_upload/lighthouse_supplemental_document_upload_provider.rb @@ -61,7 +61,14 @@ def validate_upload_document(lighthouse_document) # @param file_body [String] def submit_upload_document(lighthouse_document, file_body) log_upload_attempt - api_response = BenefitsDocuments::Form526::UploadSupplementalDocumentService.call(file_body, lighthouse_document) + + begin + api_response = BenefitsDocuments::Form526::UploadSupplementalDocumentService.call(file_body, lighthouse_document) + rescue => e + log_upload_failure(e) + raise e + end + handle_lighthouse_response(api_response) end @@ -102,28 +109,24 @@ def log_upload_attempt StatsD.increment("#{@statsd_metric_prefix}.#{STATSD_PROVIDER_METRIC}.#{STATSD_ATTEMPT_METRIC}") end - def log_upload_success(lighthouse_request_id) + def log_upload_success(lighthouse_document_request_id) Rails.logger.info( 'LighthouseSupplementalDocumentUploadProvider upload successful', { **base_logging_info, - lighthouse_request_id: + lighthouse_document_request_id: } ) StatsD.increment("#{@statsd_metric_prefix}.#{STATSD_PROVIDER_METRIC}.#{STATSD_SUCCESS_METRIC}") end - # For logging an error response from the Lighthouse Benefits Document API - # - # @param lighthouse_error_response [Hash] parsed JSON response from the Lighthouse API - # this will be an array of errors - def log_upload_failure(lighthouse_error_response) + def log_upload_failure(exception) Rails.logger.error( 'LighthouseSupplementalDocumentUploadProvider upload failed', { **base_logging_info, - lighthouse_error_response: + error_info: exception.errors } ) @@ -137,13 +140,9 @@ def log_upload_failure(lighthouse_error_response) def handle_lighthouse_response(api_response) response_body = api_response.body - if lighthouse_success_response?(response_body) - lighthouse_request_id = response_body.dig('data', 'requestId') - create_lighthouse_polling_record(lighthouse_request_id) - log_upload_success(lighthouse_request_id) - else - log_upload_failure(response_body) - end + lighthouse_document_request_id = response_body['data']['requestId'] + create_lighthouse_polling_record(lighthouse_document_request_id) + log_upload_success(lighthouse_document_request_id) end # @param response_body [JSON] Lighthouse API response returned from the UploadSupplementalDocumentService @@ -153,12 +152,13 @@ def lighthouse_success_response?(response_body) # Creates a Lighthouse526DocumentUpload polling record # - # @param lighthouse_request_id [String] unique ID Lighthouse provides us in the API response for polling later - def create_lighthouse_polling_record(lighthouse_request_id) + # @param lighthouse_document_request_id [String] unique ID Lighthouse provides us + # in the API response for polling later + def create_lighthouse_polling_record(lighthouse_document_request_id) Lighthouse526DocumentUpload.create!( form526_submission: @form526_submission, document_type: polling_record_document_type, - lighthouse_document_request_id: lighthouse_request_id, + lighthouse_document_request_id: lighthouse_document_request_id, # The Lighthouse526DocumentUpload form_attachment association is # required for uploads of type Lighthouse526DocumentUpload::VETERAN_UPLOAD_DOCUMENT_TYPE **form_attachment_params diff --git a/lib/lighthouse/benefits_documents/form526/upload_supplemental_document_service.rb b/lib/lighthouse/benefits_documents/form526/upload_supplemental_document_service.rb index b950b618bee..c20104b255a 100644 --- a/lib/lighthouse/benefits_documents/form526/upload_supplemental_document_service.rb +++ b/lib/lighthouse/benefits_documents/form526/upload_supplemental_document_service.rb @@ -34,11 +34,13 @@ def call client.upload_document(@file_body, @lighthouse_document) rescue => e # NOTE: third argument, lighthouse_client_id is left nil so it isn't logged. - Lighthouse::ServiceException.send_error( + error = Lighthouse::ServiceException.send_error( e, self.class.to_s.underscore, nil, BenefitsDocuments::Configuration::DOCUMENTS_PATH ) - raise e + # Lighthouse::ServiceException can either raise an error or return an error object, so we need to + # assign it to a variable and re-raise it here manually if it is the latter + raise error end end end diff --git a/spec/lib/disability_compensation/providers/document_upload/lighthouse_supplemental_document_upload_provider_spec.rb b/spec/lib/disability_compensation/providers/document_upload/lighthouse_supplemental_document_upload_provider_spec.rb index a1091495e9b..d1bbe68546c 100644 --- a/spec/lib/disability_compensation/providers/document_upload/lighthouse_supplemental_document_upload_provider_spec.rb +++ b/spec/lib/disability_compensation/providers/document_upload/lighthouse_supplemental_document_upload_provider_spec.rb @@ -31,7 +31,7 @@ end let(:faraday_response) { instance_double(Faraday::Response) } - let(:lighthouse_request_id) { Faker::Number.number(digits: 8) } + let(:lighthouse_document_request_id) { Faker::Number.number(digits: 8) } # Mock Lighthouse API response before do @@ -43,7 +43,7 @@ { 'data' => { 'success' => true, - 'requestId' => lighthouse_request_id + 'requestId' => lighthouse_document_request_id } } ) @@ -99,13 +99,52 @@ form526_submission_id: submission.id, # Polling record type mapped to L023 used in tests document_type: Lighthouse526DocumentUpload::BDD_INSTRUCTIONS_DOCUMENT_TYPE, - lighthouse_document_request_id: lighthouse_request_id + lighthouse_document_request_id: lighthouse_document_request_id } expect do provider.submit_upload_document(lighthouse_document, file_body) end.to change { Lighthouse526DocumentUpload.where(**upload_attributes).count }.by(1) end + + context 'when there is an exception thrown when the upload is attempted' do + let(:exception_errors) { [{ detail: 'Something Broke' }] } + + before do + # Skip upload attempt logging + allow(provider).to receive(:log_upload_attempt) + + allow(BenefitsDocuments::Form526::UploadSupplementalDocumentService).to receive(:call) + .and_raise(Common::Exceptions::BadRequest.new(errors: exception_errors)) + end + + it 'increments a StatsD failure metric and re-raises the error' do + expect(StatsD).to receive(:increment).with( + 'my_stats_metric_prefix.lighthouse_supplemental_document_upload_provider.upload_failure' + ) + + expect { provider.submit_upload_document(lighthouse_document, file_body) } + .to raise_error(Common::Exceptions::BadRequest) + end + + it 'logs the failure to the Rails logger and re-raises the error' do + expect(Rails.logger).to receive(:error).with( + 'LighthouseSupplementalDocumentUploadProvider upload failed', + { + class: 'LighthouseSupplementalDocumentUploadProvider', + submitted_claim_id: submission.submitted_claim_id, + submission_id: submission.id, + user_uuid: submission.user_uuid, + va_document_type_code: va_document_type, + primary_form: 'Form526', + error_info: exception_errors + } + ) + + expect { provider.submit_upload_document(lighthouse_document, file_body) } + .to raise_error(Common::Exceptions::BadRequest) + end + end end context 'For SupportingEvidenceAttachment uploads' do @@ -133,7 +172,7 @@ aasm_state: 'pending', form526_submission_id: submission.id, document_type: Lighthouse526DocumentUpload::VETERAN_UPLOAD_DOCUMENT_TYPE, - lighthouse_document_request_id: lighthouse_request_id, + lighthouse_document_request_id: lighthouse_document_request_id, form_attachment: supporting_evidence_attachment } @@ -191,7 +230,7 @@ user_uuid: submission.user_uuid, va_document_type_code: va_document_type, primary_form: 'Form526', - lighthouse_request_id: + lighthouse_document_request_id: } ) @@ -207,55 +246,30 @@ end end - context 'when we get a non-200 response from Lighthouse' do - let(:error_response_body) do - # From vcr_cassettes/lighthouse/benefits_claims/documents/lighthouse_form_526_document_upload_400.yml - { - 'errors' => [ - { - 'detail' => 'Something broke', - 'status' => 400, - 'title' => 'Bad Request', - 'instance' => Faker::Internet.uuid - } - ] - } - end - + # We expect 200 successful upload responses to match a certain shape from Lighthouse but if they don't for whatever + # reason, we want an exception to be raised loudly instead of logging a failed upload + context 'when we get a 200 response from Lighthouse but response body does not match the expected upload success' do before do - # Skip upload attempt logging - allow(provider).to receive(:log_upload_attempt) - allow(BenefitsDocuments::Form526::UploadSupplementalDocumentService).to receive(:call) .with(file_body, lighthouse_document) .and_return(faraday_response) - allow(faraday_response).to receive(:body).and_return(error_response_body) - end - - it 'logs to the Rails logger' do - expect(Rails.logger).to receive(:error).with( - 'LighthouseSupplementalDocumentUploadProvider upload failed', + allow(faraday_response).to receive(:body).and_return( + # Simulate missing Lighthouse request ID { - class: 'LighthouseSupplementalDocumentUploadProvider', - submitted_claim_id: submission.submitted_claim_id, - submission_id: submission.id, - user_uuid: submission.user_uuid, - va_document_type_code: va_document_type, - primary_form: 'Form526', - lighthouse_error_response: error_response_body + 'data' => + { + 'foo' => 'Did not expect me did you?!??' + } } ) - - provider.submit_upload_document(lighthouse_document, file_body) end - it 'increments a StatsD metric' do - expect(StatsD).to receive(:increment).with( - 'my_stats_metric_prefix.lighthouse_supplemental_document_upload_provider.upload_failure' - ) - - provider.submit_upload_document(lighthouse_document, file_body) + it 'fails loudly' do + # Test falls through to raising validation error when creating + # Lighthouse526DocumentUpload polling record without request ID + expect { provider.submit_upload_document(lighthouse_document, file_body) } + .to raise_error(ActiveRecord::RecordInvalid) end end diff --git a/spec/lib/lighthouse/benefits_documents/form526/upload_supplemental_document_service_spec.rb b/spec/lib/lighthouse/benefits_documents/form526/upload_supplemental_document_service_spec.rb index ea7c156c09e..e430b3dfe35 100644 --- a/spec/lib/lighthouse/benefits_documents/form526/upload_supplemental_document_service_spec.rb +++ b/spec/lib/lighthouse/benefits_documents/form526/upload_supplemental_document_service_spec.rb @@ -57,17 +57,45 @@ ) end - it 'logs the error via Lighthouse::ServiceException and re-raises the error' do + it 'logs the error via Lighthouse::ServiceException and does not swallow the exception' do VCR.use_cassette('lighthouse/benefits_claims/documents/lighthouse_form_526_document_upload_400') do expect(Lighthouse::ServiceException).to receive(:send_error).with( an_instance_of(Faraday::BadRequestError), 'benefits_documents/form526/upload_supplemental_document_service', nil, 'services/benefits-documents/v1/documents' - ) + ).and_raise(Common::Exceptions::BadRequest) + expect { subject.call(file_body, lighthouse_document) }.to raise_error(Common::Exceptions::BadRequest) + end + end + end + + describe 'Lighthouse::ServiceException handling' do + # Lighthouse::ServiceException can either raise an error or return an error object, + # so we need to account for both cases + context 'when the service exception class returns an error object' do + before do + allow(Lighthouse::ServiceException).to receive(:send_error) + .and_return(Faraday::BadRequestError) + end + + it 're-raises the error' do + expect do + subject.call(file_body, LighthouseDocument.new) + end.to raise_error(Faraday::BadRequestError) + end + end + + context 'when the service exception class raises an exception' do + before do + allow(Lighthouse::ServiceException).to receive(:send_error) + .and_raise(Faraday::BadRequestError) + end + + it 'the exception gets raised' do expect do - subject.call(file_body, lighthouse_document) + subject.call(file_body, LighthouseDocument.new) end.to raise_error(Faraday::BadRequestError) end end diff --git a/spec/sidekiq/evss/disability_compensation_form/submit_form0781_spec.rb b/spec/sidekiq/evss/disability_compensation_form/submit_form0781_spec.rb index f854c6da7c2..3acc2cb1197 100644 --- a/spec/sidekiq/evss/disability_compensation_form/submit_form0781_spec.rb +++ b/spec/sidekiq/evss/disability_compensation_form/submit_form0781_spec.rb @@ -281,19 +281,6 @@ let(:expected_statsd_metrics_prefix) do 'worker.evss.submit_form0781.lighthouse_supplemental_document_upload_provider' end - let(:error_response_body) do - # From vcr_cassettes/lighthouse/benefits_claims/documents/lighthouse_form_526_document_upload_400.yml - { - 'errors' => [ - { - 'detail' => 'Something broke', - 'status' => 400, - 'title' => 'Bad Request', - 'instance' => Faker::Internet.uuid - } - ] - } - end before do allow(Flipper).to receive(:enabled?).with('disability_compensation_upload_0781_to_lighthouse', @@ -377,51 +364,6 @@ .where(document_type: 'Form 0781a').count).to eq(1) end end - - context 'when Lighthouse returns an error response' do - before do - allow(faraday_response).to receive(:body).and_return(error_response_body) - end - - it 'logs the Lighthouse error response' do - # 0781 - expect(Rails.logger).to receive(:error).with( - 'LighthouseSupplementalDocumentUploadProvider upload failed', - { - class: 'LighthouseSupplementalDocumentUploadProvider', - submission_id: submission.id, - submitted_claim_id: submission.submitted_claim_id, - user_uuid: submission.user_uuid, - va_document_type_code: 'L228', - primary_form: 'Form526', - lighthouse_error_response: error_response_body - } - ) - # 0781a - expect(Rails.logger).to receive(:error).with( - 'LighthouseSupplementalDocumentUploadProvider upload failed', - { - class: 'LighthouseSupplementalDocumentUploadProvider', - submission_id: submission.id, - submitted_claim_id: submission.submitted_claim_id, - user_uuid: submission.user_uuid, - va_document_type_code: 'L229', - primary_form: 'Form526', - lighthouse_error_response: error_response_body - } - ) - - perform_upload - end - - it 'increments the correct status failure metric' do - expect(StatsD).to receive(:increment).with( - "#{expected_statsd_metrics_prefix}.upload_failure" - ).twice # For 0781 and 0781a - - perform_upload - end - end end context 'when a submission has 0781 only' do @@ -449,11 +391,17 @@ end context 'when Lighthouse returns an error response' do + let(:exception_errors) { [{ detail: 'Something Broke' }] } + before do - allow(faraday_response).to receive(:body).and_return(error_response_body) + # Skip additional logging that occurs in Lighthouse::ServiceException handling + allow(Rails.logger).to receive(:error) + + allow(BenefitsDocuments::Form526::UploadSupplementalDocumentService).to receive(:call) + .and_raise(Common::Exceptions::BadRequest.new(errors: exception_errors)) end - it 'logs the Lighthouse error response' do + it 'logs the Lighthouse error response and re-raises the exception' do expect(Rails.logger).to receive(:error).with( 'LighthouseSupplementalDocumentUploadProvider upload failed', { @@ -463,11 +411,11 @@ user_uuid: submission.user_uuid, va_document_type_code: 'L228', primary_form: 'Form526', - lighthouse_error_response: error_response_body + error_info: exception_errors } ) - perform_upload + expect { perform_upload }.to raise_error(Common::Exceptions::BadRequest) end it 'increments the correct status failure metric' do @@ -475,7 +423,7 @@ "#{expected_statsd_metrics_prefix}.upload_failure" ) - perform_upload + expect { perform_upload }.to raise_error(Common::Exceptions::BadRequest) end end end @@ -505,11 +453,17 @@ end context 'when Lighthouse returns an error response' do + let(:exception_errors) { [{ detail: 'Something Broke' }] } + before do - allow(faraday_response).to receive(:body).and_return(error_response_body) + # Skip additional logging that occurs in Lighthouse::ServiceException handling + allow(Rails.logger).to receive(:error) + + allow(BenefitsDocuments::Form526::UploadSupplementalDocumentService).to receive(:call) + .and_raise(Common::Exceptions::BadRequest.new(errors: exception_errors)) end - it 'logs the Lighthouse error response' do + it 'logs the Lighthouse error response and re-raises the exception' do expect(Rails.logger).to receive(:error).with( 'LighthouseSupplementalDocumentUploadProvider upload failed', { @@ -519,11 +473,11 @@ user_uuid: submission.user_uuid, va_document_type_code: 'L229', primary_form: 'Form526', - lighthouse_error_response: error_response_body + error_info: exception_errors } ) - perform_upload + expect { perform_upload }.to raise_error(Common::Exceptions::BadRequest) end it 'increments the correct status failure metric' do @@ -531,7 +485,7 @@ "#{expected_statsd_metrics_prefix}.upload_failure" ) - perform_upload + expect { perform_upload }.to raise_error(Common::Exceptions::BadRequest) end end end diff --git a/spec/sidekiq/evss/disability_compensation_form/submit_uploads_spec.rb b/spec/sidekiq/evss/disability_compensation_form/submit_uploads_spec.rb index 8434fd2acf9..54e14c73900 100644 --- a/spec/sidekiq/evss/disability_compensation_form/submit_uploads_spec.rb +++ b/spec/sidekiq/evss/disability_compensation_form/submit_uploads_spec.rb @@ -258,26 +258,14 @@ end context 'when Lighthouse returns an error response' do - let(:error_response_body) do - # From vcr_cassettes/lighthouse/benefits_claims/documents/lighthouse_form_526_document_upload_400.yml - { - 'errors' => [ - { - 'detail' => 'Something broke', - 'status' => 400, - 'title' => 'Bad Request', - 'instance' => Faker::Internet.uuid - } - ] - } - end + let(:exception_errors) { [{ detail: 'Something Broke' }] } before do - allow(BenefitsDocuments::Form526::UploadSupplementalDocumentService).to receive(:call) - .with(file.read, expected_lighthouse_document) - .and_return(faraday_response) + # Skip additional logging that occurs in Lighthouse::ServiceException handling + allow(Rails.logger).to receive(:error) - allow(faraday_response).to receive(:body).and_return(error_response_body) + allow(BenefitsDocuments::Form526::UploadSupplementalDocumentService).to receive(:call) + .and_raise(Common::Exceptions::BadRequest.new(errors: exception_errors)) end it 'logs the Lighthouse error response' do @@ -290,11 +278,11 @@ user_uuid: submission.user_uuid, va_document_type_code: 'L451', primary_form: 'Form526', - lighthouse_error_response: error_response_body + error_info: exception_errors } ) - perform_upload + expect { perform_upload }.to raise_error(Common::Exceptions::BadRequest) end it 'increments the correct status failure metric' do @@ -302,7 +290,7 @@ "#{expected_statsd_metrics_prefix}.upload_failure" ) - perform_upload + expect { perform_upload }.to raise_error(Common::Exceptions::BadRequest) end end end diff --git a/spec/sidekiq/evss/disability_compensation_form/upload_bdd_instructions_spec.rb b/spec/sidekiq/evss/disability_compensation_form/upload_bdd_instructions_spec.rb index e06a64d7b49..fac96596a2a 100644 --- a/spec/sidekiq/evss/disability_compensation_form/upload_bdd_instructions_spec.rb +++ b/spec/sidekiq/evss/disability_compensation_form/upload_bdd_instructions_spec.rb @@ -142,29 +142,17 @@ end context 'when Lighthouse returns an error response' do - let(:error_response_body) do - # From vcr_cassettes/lighthouse/benefits_claims/documents/lighthouse_form_526_document_upload_400.yml - { - 'errors' => [ - { - 'detail' => 'Something broke', - 'status' => 400, - 'title' => 'Bad Request', - 'instance' => Faker::Internet.uuid - } - ] - } - end + let(:exception_errors) { [{ detail: 'Something Broke' }] } before do - allow(BenefitsDocuments::Form526::UploadSupplementalDocumentService).to receive(:call) - .with(file_read, expected_lighthouse_document) - .and_return(faraday_response) + # Skip additional logging that occurs in Lighthouse::ServiceException handling + allow(Rails.logger).to receive(:error) - allow(faraday_response).to receive(:body).and_return(error_response_body) + allow(BenefitsDocuments::Form526::UploadSupplementalDocumentService).to receive(:call) + .and_raise(Common::Exceptions::BadRequest.new(errors: exception_errors)) end - it 'logs the Lighthouse error response' do + it 'logs the Lighthouse error response and re-raises the error' do expect(Rails.logger).to receive(:error).with( 'LighthouseSupplementalDocumentUploadProvider upload failed', { @@ -174,19 +162,19 @@ user_uuid: submission.user_uuid, va_document_type_code: 'L023', primary_form: 'Form526', - lighthouse_error_response: error_response_body + error_info: exception_errors } ) - perform_upload + expect { perform_upload }.to raise_error(Common::Exceptions::BadRequest) end - it 'increments the correct status failure metric' do + it 'increments the correct status failure metric and re-raises the error' do expect(StatsD).to receive(:increment).with( "#{expected_statsd_metrics_prefix}.upload_failure" ) - perform_upload + expect { perform_upload }.to raise_error(Common::Exceptions::BadRequest) end end end