Log incomplete requests when stopping CC

lib/cloud_controller/logs/request_logs.rb

@@ -0,0 +1,63 @@
+require 'ipaddr'
+
+module VCAP::CloudController
+  module Logs
+    class RequestLogs
+      def initialize(logger)
+        @incomplete_requests = {}
+        @logger = logger
+      end
+
+      def start_request(request_id, env)
+        request = ActionDispatch::Request.new(env)
+
+        @logger.info(
+          sprintf('Started %<method>s "%<path>s" for user: %<user>s, ip: %<ip>s with vcap-request-id: %<request_id>s at %<at>s',
+                  method: request.request_method,
+                  path: request.filtered_path,
+                  user: env['cf.user_guid'],
+                  ip: anonymize_ip(request.ip),
+                  request_id: request_id,
+                  at: Time.now.utc)
+        )
+        @incomplete_requests.store(request_id, env)
+      end
+
+      def complete_request(request_id, status)
+        @incomplete_requests.delete(request_id)
+        @logger.info("Completed #{status} vcap-request-id: #{request_id}")
+      end
+
+      def log_incomplete_requests
+        @incomplete_requests.each do |request_id, env|
+          request = ActionDispatch::Request.new(env)
+
+          @logger.error(
+            sprintf('Incomplete request: %<method>s "%<path>s" for user: %<user>s, ip: %<ip>s with vcap-request-id: %<request_id>s',
+                    method: request.request_method,
+                    path: request.filtered_path,
+                    user: env['cf.user_guid'],
+                    ip: anonymize_ip(request.ip),
+                    request_id: request_id)
+          )
+        end
+      end
+
+      private
+
+      def anonymize_ip(request_ip)
+        # Remove last octet of ip if EU GDPR compliance is needed
+        ip = IPAddr.new(request_ip) rescue nil
+        if VCAP::CloudController::Config.config.get(:logging, :anonymize_ips) && ip.nil?.!
+          if ip.ipv4?
+            ip.to_string.split('.')[0...-1].join('.') + '.0'
+          else
+            ip.to_string.split(':')[0...-5].join(':') + ':0000:0000:0000:0000:0000'
+          end
+        else
+          ip.to_string rescue request_ip
+        end
+      end
+    end
+  end
+end

lib/cloud_controller/rack_app_builder.rb

@@ -11,7 +11,7 @@
 
 module VCAP::CloudController
   class RackAppBuilder
-    def build(config, request_metrics)
+    def build(config, request_metrics, request_logs)
       token_decoder = VCAP::CloudController::UaaTokenDecoder.new(config.get(:uaa))
       configurer = VCAP::CloudController::Security::SecurityContextConfigurer.new(token_decoder)
 
@@ -24,7 +24,7 @@ def build(config, request_metrics)
         use CloudFoundry::Middleware::NewRelicCustomAttributes if config.get(:newrelic_enabled)
         use Honeycomb::Rack::Middleware, client: Honeycomb.client if config.get(:honeycomb)
         use CloudFoundry::Middleware::SecurityContextSetter, configurer
-        use CloudFoundry::Middleware::RequestLogs, Steno.logger('cc.api')
+        use CloudFoundry::Middleware::RequestLogs, request_logs
         use CloudFoundry::Middleware::Zipkin
         if config.get(:rate_limiter, :enabled)
           use CloudFoundry::Middleware::RateLimiter, {

lib/cloud_controller/runner.rb

@@ -8,6 +8,7 @@
 require 'cloud_controller/rack_app_builder'
 require 'cloud_controller/metrics/periodic_updater'
 require 'cloud_controller/metrics/request_metrics'
+require 'cloud_controller/logs/request_logs'
 require 'cloud_controller/telemetry_logger'
 require 'cloud_controller/secrets_fetcher'
 
@@ -80,8 +81,10 @@ def run!
         request_metrics = VCAP::CloudController::Metrics::RequestMetrics.new(statsd_client)
         gather_periodic_metrics
 
+        @request_logs = VCAP::CloudController::Logs::RequestLogs.new(Steno.logger('cc.api'))
+
         builder = RackAppBuilder.new
-        app     = builder.build(@config, request_metrics)
+        app     = builder.build(@config, request_metrics, @request_logs)
 
         start_thin_server(app)
       rescue => e
@@ -208,6 +211,7 @@ def start_thin_server(app)
     def stop_thin_server
       logger.info('Stopping Thin Server.')
       @thin_server.stop if @thin_server
+      @request_logs.log_incomplete_requests if @request_logs
     end
 
     def periodic_updater

middleware/request_logs.rb

@@ -1,43 +1,18 @@
-require 'ipaddr'
-
 module CloudFoundry
   module Middleware
     class RequestLogs
-      def initialize(app, logger)
+      def initialize(app, request_logs)
+        @request_logs = request_logs
         @app = app
-        @logger = logger
-      end
-
-      def anonymize_ip(request_ip)
-        # Remove last octet of ip if EU GDPR compliance is needed
-        ip = IPAddr.new(request_ip) rescue nil
-        if VCAP::CloudController::Config.config.get(:logging, :anonymize_ips) && ip.nil?.!
-          if ip.ipv4?
-            ip.to_string.split('.')[0...-1].join('.') + '.0'
-          else
-            ip.to_string.split(':')[0...-5].join(':') + ':0000:0000:0000:0000:0000'
-          end
-        else
-          ip.to_string rescue request_ip
-        end
       end
 
       def call(env)
-        request = ActionDispatch::Request.new(env)
-
-        @logger.info(
-          sprintf('Started %<method>s "%<path>s" for user: %<user>s, ip: %<ip>s with vcap-request-id: %<request_id>s at %<at>s',
-            method: request.request_method,
-            path: request.filtered_path,
-            user: env['cf.user_guid'],
-            ip: anonymize_ip(request.ip),
-            request_id: env['cf.request_id'],
-            at: Time.now.utc)
-        )
+        request_id = env['cf.request_id']
+        @request_logs.start_request(request_id, env)
 
         status, headers, body = @app.call(env)
 
-        @logger.info("Completed #{status} vcap-request-id: #{env['cf.request_id']}")
+        @request_logs.complete_request(request_id, status)
 
         [status, headers, body]
       end

spec/spec_helper.rb

@@ -200,7 +200,9 @@
     rspec_config.after(:each, type: :legacy_api) { add_deprecation_warning }
 
     RspecApiDocumentation.configure do |c|
-      c.app = VCAP::CloudController::RackAppBuilder.new.build(TestConfig.config_instance, VCAP::CloudController::Metrics::RequestMetrics.new)
+      c.app = VCAP::CloudController::RackAppBuilder.new.build(TestConfig.config_instance,
+                                                              VCAP::CloudController::Metrics::RequestMetrics.new,
+                                                              VCAP::CloudController::Logs::RequestLogs.new(Steno.logger('request.logs')))
       c.format = [:html, :json]
       c.api_name = 'Cloud Foundry API'
       c.template_path = 'spec/api/documentation/templates'

spec/support/request_spec_helper.rb

@@ -4,6 +4,7 @@ module RequestSpecHelper
   def app
     test_config     = TestConfig.config_instance
     request_metrics = VCAP::CloudController::Metrics::RequestMetrics.new
-    VCAP::CloudController::RackAppBuilder.new.build test_config, request_metrics
+    request_logs    = VCAP::CloudController::Logs::RequestLogs.new(Steno.logger('request.logs'))
+    VCAP::CloudController::RackAppBuilder.new.build(test_config, request_metrics, request_logs)
   end
 end

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

@@ -0,0 +1,106 @@
+require 'spec_helper'
+require 'cloud_controller/logs/request_logs'
+
+module VCAP::CloudController::Logs
+  RSpec.describe RequestLogs do
+    let(:request_logs) { RequestLogs.new(logger) }
+    let(:logger) { double('logger', info: nil) }
+    let(:fake_request) { double('request', request_method: 'request_method', ip: 'ip', filtered_path: 'filtered_path') }
+    let(:request_id) { 'ID' }
+    let(:env) { { 'cf.user_guid' => 'user-guid' } }
+    let(:status) { 200 }
+
+    describe 'logging' do
+      before do
+        allow(ActionDispatch::Request).to receive(:new).and_return(fake_request)
+      end
+
+      it 'logs the start of a request' do
+        request_logs.start_request(request_id, env)
+        expect(logger).to have_received(:info).with(/Started.+user: user-guid.+with vcap-request-id: ID/)
+      end
+
+      it 'logs the completion of a request' do
+        request_logs.complete_request(request_id, status)
+        expect(logger).to have_received(:info).with(/Completed 200 vcap-request-id: ID/)
+      end
+
+      context 'anonymize_ips flag is true' do
+        before do
+          TestConfig.override(logging: { anonymize_ips: 'true' })
+        end
+
+        it 'logs non ip addresses in ip field unaltered' do
+          request_logs.start_request(request_id, env)
+          expect(logger).to have_received(:info).with(/ip: ip/)
+        end
+      end
+
+      context 'request with ipv4 address' do
+        let(:fake_request) { double('request', request_method: 'request_method', ip: '192.168.1.80', filtered_path: 'filtered_path') }
+
+        context 'anonymize_ips flag is false' do
+          it 'logs full ipv4 addresses' do
+            request_logs.start_request(request_id, env)
+            expect(logger).to have_received(:info).with(/ip: 192.168.1.80/)
+          end
+        end
+
+        context 'anonymize_ips flag is true' do
+          before do
+            TestConfig.override(logging: { anonymize_ips: 'true' })
+          end
+
+          it 'logs anonymized ipv4 addresses' do
+            request_logs.start_request(request_id, env)
+            expect(logger).to have_received(:info).with(/ip: 192.168.1.0/)
+          end
+        end
+      end
+
+      context 'request with ipv6 address' do
+        let(:fake_request) { double('request', request_method: 'request_method', ip: '2001:0db8:85a3:1234:0000:8a2e:0370:7334', filtered_path: 'filtered_path') }
+
+        context 'anonymize_ips flag is false' do
+          it 'logs canonical and unaltered ipv6 addresses' do
+            request_logs.start_request(request_id, env)
+            expect(logger).to have_received(:info).with(/ip: 2001:0db8:85a3:1234:0000:8a2e:0370:7334/)
+          end
+        end
+
+        context 'anonymize_ips flag is true' do
+          before do
+            TestConfig.override(logging: { anonymize_ips: 'true' })
+          end
+
+          it 'logs canonical and anonymized ipv6 addresses' do
+            request_logs.start_request(request_id, env)
+            expect(logger).to have_received(:info).with(/ip: 2001:0db8:85a3:0000:0000:0000:0000:0000/)
+          end
+        end
+      end
+
+      context 'request with non canonical(shortened) ipv6 address' do
+        let(:fake_request) { double('request', request_method: 'request_method', ip: '2001:db8:85a3:1234::370:0', filtered_path: 'filtered_path') }
+
+        context 'anonymize_ips flag is false' do
+          it 'logs canonical and unaltered ipv6 addresses' do
+            request_logs.start_request(request_id, env)
+            expect(logger).to have_received(:info).with(/ip: 2001:0db8:85a3:1234:0000:0000:0370:0000/)
+          end
+        end
+
+        context 'anonymize_ips flag is true' do
+          before do
+            TestConfig.override(logging: { anonymize_ips: 'true' })
+          end
+
+          it 'logs canonical and anonymized ipv6 addresses' do
+            request_logs.start_request(request_id, env)
+            expect(logger).to have_received(:info).with(/ip: 2001:0db8:85a3:0000:0000:0000:0000:0000/)
+          end
+        end
+      end
+    end
+  end
+end

spec/unit/lib/cloud_controller/rack_app_builder_spec.rb

@@ -5,11 +5,24 @@ module VCAP::CloudController
     subject(:builder) { RackAppBuilder.new }
 
     describe '#build' do
-      let(:request_metrics) { nil }
+      let(:request_metrics) { double }
+      let(:request_logs) { double }
+
+      before do
+        allow(CloudFoundry::Middleware::RequestMetrics).to receive(:new)
+        allow(CloudFoundry::Middleware::RequestLogs).to receive(:new)
+      end
 
       it 'returns a Rack application' do
-        expect(builder.build(TestConfig.config_instance, request_metrics)).to be_a(Rack::Builder)
-        expect(builder.build(TestConfig.config_instance, request_metrics)).to respond_to(:call)
+        expect(builder.build(TestConfig.config_instance, request_metrics, request_logs)).to be_a(Rack::Builder)
+        expect(builder.build(TestConfig.config_instance, request_metrics, request_logs)).to respond_to(:call)
+      end
+
+      it 'uses RequestMetrics and RequestLogs middleware' do
+        builder.build(TestConfig.config_instance, request_metrics, request_logs).to_app
+
+        expect(CloudFoundry::Middleware::RequestMetrics).to have_received(:new).with(anything, request_metrics)
+        expect(CloudFoundry::Middleware::RequestLogs).to have_received(:new).with(anything, request_logs)
       end
 
       describe 'Rack::CommonLogger' do
@@ -18,13 +31,13 @@ module VCAP::CloudController
         end
 
         it 'uses Rack::CommonLogger when nginx is disabled' do
-          builder.build(TestConfig.override(nginx: { use_nginx: false }), request_metrics).to_app
+          builder.build(TestConfig.override(nginx: { use_nginx: false }), request_metrics, request_logs).to_app
 
           expect(Rack::CommonLogger).to have_received(:new).with(anything, instance_of(File))
         end
 
         it 'does not use Rack::CommonLogger when nginx is enabled' do
-          builder.build(TestConfig.override(nginx: { use_nginx: true }), request_metrics).to_app
+          builder.build(TestConfig.override(nginx: { use_nginx: true }), request_metrics, request_logs).to_app
 
           expect(Rack::CommonLogger).to_not have_received(:new)
         end
@@ -42,7 +55,7 @@ module VCAP::CloudController
               reset_interval_in_minutes: 60,
               general_limit: 123,
               unauthenticated_limit: 1,
-            }), request_metrics).to_app
+            }), request_metrics, request_logs).to_app
           end
 
           it 'enables the RateLimiter middleware' do
@@ -63,7 +76,7 @@ module VCAP::CloudController
               reset_interval_in_minutes: 60,
               general_limit: 123,
               unauthenticated_limit: 1
-            }), request_metrics).to_app
+            }), request_metrics, request_logs).to_app
           end
 
           it 'does not enable the RateLimiter middleware' do
@@ -79,7 +92,7 @@ module VCAP::CloudController
 
         context 'when new relic is enabled' do
           before do
-            builder.build(TestConfig.override(newrelic_enabled: true), request_metrics).to_app
+            builder.build(TestConfig.override(newrelic_enabled: true), request_metrics, request_logs).to_app
           end
 
           it 'enables the New Relic custom attribute middleware' do
@@ -89,7 +102,7 @@ module VCAP::CloudController
 
         context 'when new relic is NOT enabled' do
           before do
-            builder.build(TestConfig.override(newrelic_enabled: false), request_metrics).to_app
+            builder.build(TestConfig.override(newrelic_enabled: false), request_metrics, request_logs).to_app
           end
 
           it 'does NOT enable the New Relic custom attribute middleware' do
@@ -104,7 +117,7 @@ module VCAP::CloudController
         end
 
         it 'does not include Cef Middleware when security_event_logging is disabled' do
-          builder.build(TestConfig.override(security_event_logging: { enabled: false }), request_metrics).to_app
+          builder.build(TestConfig.override(security_event_logging: { enabled: false }), request_metrics, request_logs).to_app
 
           expect(CloudFoundry::Middleware::CefLogs).not_to have_received(:new)
         end
@@ -113,7 +126,7 @@ module VCAP::CloudController
           fake_logger = instance_double(Logger)
           allow(Logger).to receive(:new).with(TestConfig.config_instance.get(:security_event_logging, :file)).and_return(fake_logger)
           enabled_config = TestConfig.config_instance.get(:security_event_logging).merge(enabled: true)
-          builder.build(TestConfig.override(security_event_logging: enabled_config), request_metrics).to_app
+          builder.build(TestConfig.override(security_event_logging: enabled_config), request_metrics, request_logs).to_app
 
           expect(CloudFoundry::Middleware::CefLogs).to have_received(:new).with(anything, fake_logger, TestConfig.config_instance.get(:local_route))
         end