Fix request metrics logging if log_db_queries is false

* if log_db_queries is falses, the two new fields would be logged but always with "0" as value

Author: jochenehret

lib/cloud_controller/logs/request_logs.rb

@@ -26,17 +26,21 @@ def start_request(request_id, env)
         @incomplete_requests.store(request_id, env)
       end
 
-      def complete_request(request_id, status, env, time_taken_ms, total_db_query_time_us, db_query_count)
+      def complete_request(request_id, status, env, time_taken_ms, total_db_query_time_us=nil, db_query_count=nil)
         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,
-                       time_taken_in_ms: time_taken_ms,
-                       total_db_query_time_in_ms: (total_db_query_time_us.to_f / 1_000),
-                       db_query_count: db_query_count,
-                       request_method: request.request_method,
-                       request_fullpath: request.filtered_path })
+
+        log_fields = {
+          status_code: status,
+          time_taken_in_ms: time_taken_ms,
+          request_method: request.request_method,
+          request_fullpath: request.filtered_path
+        }
+        log_fields[:total_db_query_time_in_ms] = (total_db_query_time_us.to_f / 1_000) unless total_db_query_time_us.nil?
+        log_fields[:db_query_count] = db_query_count unless db_query_count.nil?
+
+        @logger.info("Completed #{status} vcap-request-id: #{request_id}", log_fields)
       end
 
       def log_incomplete_requests

middleware/request_logs.rb

@@ -13,8 +13,13 @@ def call(env)
 
         status, headers, body = @app.call(env)
         time_taken_ms = timer - start_timer
-        db_query_metrics = ::VCAP::Request.db_query_metrics
-        @request_logs.complete_request(request_id, status, env, time_taken_ms, db_query_metrics.total_query_time_us, db_query_metrics.query_count)
+
+        args = [request_id, status, env, time_taken_ms]
+        if VCAP::CloudController::Config.config.get(:db, :log_db_queries)
+          db_query_metrics = ::VCAP::Request.db_query_metrics
+          args += [db_query_metrics.total_query_time_us, db_query_metrics.query_count]
+        end
+        @request_logs.complete_request(*args)
 
         [status, headers, body]
       end

spec/unit/middleware/request_logs_spec.rb

@@ -10,6 +10,10 @@ module Middleware
       let(:env) { { 'cf.request_id' => 'ID' } }
 
       describe 'handling the request' do
+        before do
+          VCAP::CloudController::Config.config.get(:db)[:log_db_queries] = true
+        end
+
         it 'calls start request on request logs before the request' do
           middleware.call(env)
           expect(request_logs).to have_received(:start_request).with('ID', env)
@@ -24,6 +28,17 @@ module Middleware
           expect(request_logs).to have_received(:complete_request).with('ID', 200, { 'cf.request_id' => 'ID' }, be_a(Numeric), be_a(Numeric), be_a(Numeric))
         end
       end
+
+      describe 'when db query logging is disabled' do
+        before do
+          VCAP::CloudController::Config.config.get(:db)[:log_db_queries] = false
+        end
+
+        it 'calls complete request on request logs without db query metrics' do
+          middleware.call(env)
+          expect(request_logs).to have_received(:complete_request).with('ID', 200, { 'cf.request_id' => 'ID' }, be_a(Numeric))
+        end
+      end
     end
   end
 end