Add duration logging to LocalBGS service (#11947)

* Add duration logging to LocalBGS service

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

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

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