Reduce logcache timeout from 250 to 10s (#4187)

* Reduce logcache timeout from 250 to 10s

* Adjust unittest

* Add response time in a parsable formation `

* Optimize based on review

Author: WeiQuan0605

lib/logcache/client.rb

@@ -16,13 +16,13 @@ def initialize(host:, port:, client_ca_path:, client_cert_path:, client_key_path
           "#{host}:#{port}",
           GRPC::Core::ChannelCredentials.new(client_ca, client_key, client_cert),
           channel_args: { GRPC::Core::Channel::SSL_TARGET => tls_subject_name },
-          timeout: 250
+          timeout: 10
         )
       else
         @service = Logcache::V1::Egress::Stub.new(
           "#{host}:#{port}",
           :this_channel_is_insecure,
-          timeout: 250
+          timeout: 10
         )
       end
     end
@@ -44,9 +44,16 @@ def container_metrics(source_guid:, start_time:, end_time:, envelope_limit: DEFA
 
     private
 
-    def with_request_error_handling(_source_guid)
+    def with_request_error_handling(source_guid)
       tries ||= 3
-      yield
+      start_time = Time.now
+
+      result = yield
+      time_taken_in_ms = ((Time.now - start_time) * 1000).to_i # convert to milliseconds to get more precise information
+      logger.info('logcache.response',
+                  { source_id: source_guid,
+                    time_taken_in_ms: time_taken_in_ms })
+      result
     rescue StandardError => e
       raise CloudController::Errors::ApiError.new_from_details('ServiceUnavailable', 'Connection to Log Cache timed out') if e.is_a?(GRPC::DeadlineExceeded)
 

spec/logcache/client_spec.rb

@@ -26,6 +26,7 @@ module Logcache
       let(:client_ca) { File.read(client_ca_path) }
       let(:client_key) { File.read(client_key_path) }
       let(:client_cert) { File.read(client_cert_path) }
+      let(:mock_logger) { double(Steno::Logger, info: nil) }
 
       describe '#container_metrics' do
         let(:instance_count) { 2 }
@@ -36,9 +37,10 @@ module Logcache
             with(client_ca, client_key, client_cert).
             and_return(credentials)
           expect(Logcache::V1::Egress::Stub).to receive(:new).
-            with("#{host}:#{port}", credentials, channel_args: channel_arg_hash, timeout: 250).
+            with("#{host}:#{port}", credentials, channel_args: channel_arg_hash, timeout: 10).
             and_return(logcache_service)
           allow(Logcache::V1::ReadRequest).to receive(:new).and_return(logcache_request)
+          allow_any_instance_of(Client).to receive(:logger).and_return(mock_logger)
         end
 
         it 'calls Logcache with the correct parameters and returns envelopes' do
@@ -56,6 +58,17 @@ module Logcache
           )
           expect(logcache_service).to have_received(:read).with(logcache_request)
         end
+
+        it 'logs the response time and metadata' do
+          client.container_metrics(source_guid: process.guid, envelope_limit: 1000, start_time: 100, end_time: 101)
+          expect(mock_logger).to have_received(:info).with(
+            a_string_matching(/logcache.response/),
+            hash_including(
+              source_id: process.guid,
+              time_taken_in_ms: be_a(Integer)
+            )
+          )
+        end
       end
 
       describe 'when logcache is unavailable' do
@@ -68,7 +81,7 @@ module Logcache
             with(client_ca, client_key, client_cert).
             and_return(credentials)
           expect(Logcache::V1::Egress::Stub).to receive(:new).
-            with("#{host}:#{port}", credentials, channel_args: channel_arg_hash, timeout: 250).
+            with("#{host}:#{port}", credentials, channel_args: channel_arg_hash, timeout: 10).
             and_return(logcache_service)
           allow(client).to receive(:sleep)
           allow(Logcache::V1::ReadRequest).to receive(:new).and_return(logcache_request)
@@ -99,7 +112,7 @@ module Logcache
             with(client_ca, client_key, client_cert).
             and_return(credentials)
           expect(Logcache::V1::Egress::Stub).to receive(:new).
-            with("#{host}:#{port}", credentials, channel_args: channel_arg_hash, timeout: 250).
+            with("#{host}:#{port}", credentials, channel_args: channel_arg_hash, timeout: 10).
             and_return(logcache_service)
           allow(client).to receive(:sleep)
           allow(Logcache::V1::ReadRequest).to receive(:new).and_return(logcache_request)
@@ -130,7 +143,7 @@ module Logcache
             with(client_ca, client_key, client_cert).
             and_return(credentials)
           expect(Logcache::V1::Egress::Stub).to receive(:new).
-            with("#{host}:#{port}", credentials, channel_args: channel_arg_hash, timeout: 250).
+            with("#{host}:#{port}", credentials, channel_args: channel_arg_hash, timeout: 10).
             and_return(logcache_service)
           allow(client).to receive(:sleep)
           allow(Logcache::V1::ReadRequest).to receive(:new).and_return(logcache_request)
@@ -164,7 +177,7 @@ module Logcache
         before do
           expect(GRPC::Core::ChannelCredentials).not_to receive(:new)
           expect(Logcache::V1::Egress::Stub).to receive(:new).
-            with("#{host}:#{port}", :this_channel_is_insecure, timeout: 250).
+            with("#{host}:#{port}", :this_channel_is_insecure, timeout: 10).
             and_return(logcache_service)
           allow(Logcache::V1::ReadRequest).to receive(:new).and_return(logcache_request)
         end