diff --git a/lib/cloud_controller/logs/request_logs.rb b/lib/cloud_controller/logs/request_logs.rb index fd45d3edf97..e2a0cf339c2 100644 --- a/lib/cloud_controller/logs/request_logs.rb +++ b/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 diff --git a/middleware/request_logs.rb b/middleware/request_logs.rb index 3ac853f11a9..c23ab8b090d 100644 --- a/middleware/request_logs.rb +++ b/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 diff --git a/spec/unit/lib/cloud_controller/logs/request_logs_spec.rb b/spec/unit/lib/cloud_controller/logs/request_logs_spec.rb index dfb022314fa..1ff34d8c4e3 100644 --- a/spec/unit/lib/cloud_controller/logs/request_logs_spec.rb +++ b/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 diff --git a/spec/unit/middleware/request_logs_spec.rb b/spec/unit/middleware/request_logs_spec.rb index 418e6c241d0..45091aae8c0 100644 --- a/spec/unit/middleware/request_logs_spec.rb +++ b/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