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

Author: nookala

lib/cloud_controller/logs/request_logs.rb

@@ -26,11 +26,13 @@ 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?
-
-        @logger.info("Completed #{status} vcap-request-id: #{request_id}",
-                     { status_code: status })
+        request = ActionDispatch::Request.new(env)
+        @logger.info("Completed #{status} vcap-request-id: #{request_id} Response Time: #{time_taken}", 
+                     { status_code: status,
+                      request_method: request.request_method,
+                      request_fullpath: request.filtered_path })
       end
 
       def log_incomplete_requests

middleware/request_logs.rb

@@ -9,10 +9,12 @@ 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)
+        time_taken = Time.now - start_time
+        @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,14 @@ 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(/Completed 200 vcap-request-id: ID Response Time: 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