CAPI logs should for request complete should include the response time (#4089)

* TPCF-27209 - CAPI logs should for request complete should include the response time

Add time taken, request_method and request_full path to complete request log

* TPCF-27209 - CAPI logs should for request complete should include the response time

Add time taken to json based on code review comments

* CAPI logs should for request complete should include the response time

Convert time taken to ms. Fix Robocop errors.

* CAPI logs should for request complete should include the response time

Fix Indentation

* CAPI logs should for request complete should include the response time

Fix indentation

* CAPI logs should for request complete should include the response time

Fix failed unit test

* CAPI logs should for request complete should include the response time

Convert time in ms to integer

Author: nookala

lib/cloud_controller/logs/request_logs.rb

@@ -26,11 +26,15 @@ def start_request(request_id, env)
         @incomplete_requests.store(request_id, env)
       end
 
-      def complete_request(request_id, status)
+      def complete_request(request_id, status, env, time_taken)
         return if @incomplete_requests.delete(request_id).nil?
 
+        request = ActionDispatch::Request.new(env)
         @logger.info("Completed #{status} vcap-request-id: #{request_id}",
-                     { status_code: status })
+                     { status_code: status,
+                       time_taken_in_ms: time_taken,
+                       request_method: request.request_method,
+                       request_fullpath: request.filtered_path })
       end
 
       def log_incomplete_requests

middleware/request_logs.rb

@@ -9,10 +9,13 @@ def initialize(app, request_logs)
       def call(env)
         request_id = env['cf.request_id']
         @request_logs.start_request(request_id, env)
+        start_time = Time.now
 
         status, headers, body = @app.call(env)
-
-        @request_logs.complete_request(request_id, status)
+        # convert to milliseconds
+        time_taken = (Time.now - start_time) * 1000
+        time_taken = time_taken.to_i
+        @request_logs.complete_request(request_id, status, env, time_taken)
 
         [status, headers, body]
       end

spec/unit/lib/cloud_controller/logs/request_logs_spec.rb

@@ -9,6 +9,7 @@ module VCAP::CloudController::Logs
     let(:fake_fullpath) { 'fullpath' }
     let(:fake_request) { double('request', request_method: 'request_method', ip: fake_ip, filtered_path: 'filtered_path', fullpath: fake_fullpath) }
     let(:request_id) { 'ID' }
+    let(:time_taken) { 30 }
     let(:env) { { 'cf.user_guid' => 'user-guid' } }
     let(:status) { 200 }
 
@@ -45,14 +46,20 @@ module VCAP::CloudController::Logs
           end
 
           it 'logs the completion of the request' do
-            request_logs.complete_request(request_id, status)
-            expect(logger).to have_received(:info).with(/Completed 200 vcap-request-id: ID/, { status_code: 200 })
+            request_logs.complete_request(request_id, status, env, time_taken)
+            expect(logger).to have_received(:info).with(
+              /\ACompleted 200 vcap-request-id: ID/,
+              time_taken_in_ms: 30,
+              request_method: 'request_method',
+              request_fullpath: 'filtered_path',
+              status_code: 200
+            )
           end
         end
 
         context 'without a matching start request' do
           it 'does not log the completion of the request' do
-            request_logs.complete_request(request_id, status)
+            request_logs.complete_request(request_id, status, env, time_taken)
             expect(logger).not_to have_received(:info)
           end
         end

spec/unit/middleware/request_logs_spec.rb

@@ -21,7 +21,7 @@ module Middleware
 
         it 'calls complete request on request logs after the request' do
           middleware.call(env)
-          expect(request_logs).to have_received(:complete_request).with('ID', 200)
+          expect(request_logs).to have_received(:complete_request).with('ID', 200, { 'cf.request_id' => 'ID' }, be_a(Numeric))
         end
       end
     end