diff --git a/modules/claims_api/lib/bgs_service/local_bgs.rb b/modules/claims_api/lib/bgs_service/local_bgs.rb index 2d046f0c1d3..f64b5484805 100644 --- a/modules/claims_api/lib/bgs_service/local_bgs.rb +++ b/modules/claims_api/lib/bgs_service/local_bgs.rb @@ -6,6 +6,8 @@ # Additionally, we waive copyright and related rights in the work # worldwide through the CC0 1.0 Universal public domain dedication. +require 'claims_api/claim_logger' + module ClaimsApi class LocalBGS attr_accessor :external_uid, :external_key @@ -74,20 +76,29 @@ def parsed_response(res, action, key) &.deep_symbolize_keys || {} end - def make_request(endpoint:, action:, body:, key:) - connection = Faraday::Connection.new(ssl: { verify_mode: @ssl_verify_mode }) + def make_request(endpoint:, action:, body:, key:) # rubocop:disable Metrics/MethodLength + connection = log_duration event: 'establish_ssl_connection' do + Faraday::Connection.new(ssl: { verify_mode: @ssl_verify_mode }) + end connection.options.timeout = @timeout - wsdl = connection.get("#{Settings.bgs.url}/#{endpoint}?WSDL") + + wsdl = log_duration event: 'connection_wsdl_get', endpoint: endpoint do + connection.get("#{Settings.bgs.url}/#{endpoint}?WSDL") + end target_namespace = Hash.from_xml(wsdl.body).dig('definitions', 'targetNamespace') - response = connection.post("#{Settings.bgs.url}/#{endpoint}", full_body(action: action, - body: body, - namespace: target_namespace), - { - 'Content-Type' => 'text/xml;charset=UTF-8', - 'Host' => "#{@env}.vba.va.gov", - 'Soapaction' => "\"#{action}\"" - }) - parsed_response(response, action, key) + response = log_duration event: 'connection_post', endpoint: endpoint, action: action do + connection.post("#{Settings.bgs.url}/#{endpoint}", full_body(action: action, + body: body, + namespace: target_namespace), + { + 'Content-Type' => 'text/xml;charset=UTF-8', + 'Host' => "#{@env}.vba.va.gov", + 'Soapaction' => "\"#{action}\"" + }) + end + log_duration event: 'parsed_response', key: key do + parsed_response(response, action, key) + end end def find_poa_by_participant_id(id) @@ -115,5 +126,20 @@ def find_by_ssn(ssn) make_request(endpoint: 'PersonWebServiceBean/PersonWebService', action: 'findPersonBySSN', body: body, key: 'PersonDTO') end + + private + + def log_duration(event: 'default', **extra_params) + # Who are we to question sidekiq's use of CLOCK_MONOTONIC to avoid negative durations? + # https://github.com/sidekiq/sidekiq/issues/3999 + start_time = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) + result = yield + duration = (::Process.clock_gettime(::Process::CLOCK_MONOTONIC) - start_time).round(4) + + # event should be first key in log, duration last + ClaimsApi::Logger.log 'local_bgs', { event: event }.merge(extra_params).merge({ duration: duration }) + StatsD.measure("api.claims_api.local_bgs.#{event}.duration", duration, tags: {}) + result + end end end diff --git a/modules/claims_api/lib/claims_api/claim_logger.rb b/modules/claims_api/lib/claims_api/claim_logger.rb index 0657a57ce82..da422e34b41 100644 --- a/modules/claims_api/lib/claims_api/claim_logger.rb +++ b/modules/claims_api/lib/claims_api/claim_logger.rb @@ -47,6 +47,10 @@ def self.format_msg(tag, **params) msg.append("has ptcpnt_id: #{params[:ptcpnt_id]}") if params[:ptcpnt_id].present? msg.append("has birls_id: #{params[:birls_id]}") if params[:birls_id].present? msg.append("MPI Response OK: #{params[:mpi_res_ok]}") if params[:mpi_res_ok].present? + when 'local_bgs' + params.each do |k, v| + msg.append "#{k}: #{v}" + end else msg.append(params.to_json) end diff --git a/modules/claims_api/spec/lib/claims_api/local_bgs_spec.rb b/modules/claims_api/spec/lib/claims_api/local_bgs_spec.rb new file mode 100644 index 00000000000..3e577e56d6f --- /dev/null +++ b/modules/claims_api/spec/lib/claims_api/local_bgs_spec.rb @@ -0,0 +1,37 @@ +# frozen_string_literal: true + +require 'rails_helper' +require 'bgs_service/local_bgs' + +describe ClaimsApi::LocalBGS do + subject { described_class.new external_uid: 'xUid', external_key: 'xKey' } + + describe '#find_poa_by_participant_id' do + it 'responds as expected, with extra ClaimsApi::Logger logging' do + VCR.use_cassette('bgs/claimant_web_service/find_poa_by_participant_id') do + allow_any_instance_of(BGS::OrgWebService).to receive(:find_poa_history_by_ptcpnt_id).and_return({}) + + # Events logged: + # 1: establish_ssl_connection - how long to establish the connection + # 2: connection_wsdl_get - duration of WSDL request cycle + # 3: connection_post - how long does the post itself take for the request cycle + # 4: parsed_response - how long to parse the response + expect(ClaimsApi::Logger).to receive(:log).exactly(4).times + result = subject.find_poa_by_participant_id('does-not-matter') + expect(result).to be_a Hash + expect(result[:end_date]).to eq '08/26/2020' + end + end + + it 'triggers StatsD measurements' do + VCR.use_cassette('bgs/claimant_web_service/find_poa_by_participant_id', allow_playback_repeats: true) do + allow_any_instance_of(BGS::OrgWebService).to receive(:find_poa_history_by_ptcpnt_id).and_return({}) + + %w[establish_ssl_connection connection_wsdl_get connection_post parsed_response].each do |event| + expect { subject.find_poa_by_participant_id('does-not-matter') } + .to trigger_statsd_measure("api.claims_api.local_bgs.#{event}.duration") + end + end + end + end +end