Send out an event notification when ETag cache is hit

This lets us add logs for 304 or 429 responses
that Lograge doesn't pick up since this middleware
short-circuits Lograge.

config/initializers/lograge.rb

@@ -35,6 +35,7 @@ unless Gitlab::Runtime.sidekiq?
       ::Gitlab::InstrumentationHelper.add_instrumentation_data(payload)
 
       payload[:response] = event.payload[:response] if event.payload[:response]
+      payload[:etag_route] = event.payload[:etag_route] if event.payload[:etag_route]
       payload[Labkit::Correlation::CorrelationId::LOG_KEY] = Labkit::Correlation::CorrelationId.current_id
 
       if cpu_s = Gitlab::Metrics::System.thread_cpu_duration(::Gitlab::RequestContext.instance.start_thread_cpu_time)

lib/gitlab/etag_caching/middleware.rb

@@ -18,7 +18,7 @@ module Gitlab
         if_none_match = env['HTTP_IF_NONE_MATCH']
 
         if if_none_match == etag
-          handle_cache_hit(etag, route)
+          handle_cache_hit(etag, route, request)
         else
           track_cache_miss(if_none_match, cached_value_present, route)
 
@@ -47,11 +47,13 @@ module Gitlab
         %Q{W/"#{value}"}
       end
 
-      def handle_cache_hit(etag, route)
+      def handle_cache_hit(etag, route, request)
         track_event(:etag_caching_cache_hit, route)
 
         status_code = Gitlab::PollingInterval.polling_enabled? ? 304 : 429
 
+        add_instrument_for_cache_hit(status_code, route, request)
+
         [status_code, { 'ETag' => etag, 'X-Gitlab-From-Cache' => 'true' }, []]
       end
 
@@ -68,6 +70,21 @@ module Gitlab
       def track_event(name, route)
         Gitlab::Metrics.add_event(name, endpoint: route.name)
       end
+
+      def add_instrument_for_cache_hit(status, route, request)
+        payload = {
+          etag_route: route.name,
+          params:     request.filtered_parameters,
+          headers:    request.headers,
+          format:     request.format.ref,
+          method:     request.request_method,
+          path:       request.filtered_path,
+          status:     status
+        }
+
+        ActiveSupport::Notifications.instrument(
+          "process_action.action_controller", payload)
+      end
     end
   end
 end

spec/initializers/lograge_spec.rb

@@ -94,6 +94,11 @@ describe 'lograge', type: :request do
     let(:logger) do
       Logger.new(log_output).tap { |logger| logger.formatter = ->(_, _, _, msg) { msg } }
     end
+    let(:log_data) { JSON.parse(log_output.string) }
+
+    before do
+      Lograge.logger = logger
+    end
 
     describe 'with an exception' do
       let(:exception) { RuntimeError.new('bad request') }
@@ -102,18 +107,29 @@ describe 'lograge', type: :request do
       before do
         allow(exception).to receive(:backtrace).and_return(backtrace)
         event.payload[:exception_object] = exception
-        Lograge.logger = logger
       end
 
       it 'adds exception data to log' do
         subscriber.process_action(event)
 
-        log_data = JSON.parse(log_output.string)
-
         expect(log_data['exception.class']).to eq('RuntimeError')
         expect(log_data['exception.message']).to eq('bad request')
         expect(log_data['exception.backtrace']).to eq(Gitlab::BacktraceCleaner.clean_backtrace(backtrace))
       end
     end
+
+    describe 'with etag_route' do
+      let(:etag_route) { 'etag route' }
+
+      before do
+        event.payload[:etag_route] = etag_route
+      end
+
+      it 'adds etag_route to log' do
+        subscriber.process_action(event)
+
+        expect(log_data['etag_route']).to eq(etag_route)
+      end
+    end
   end
 end

spec/lib/gitlab/etag_caching/middleware_spec.rb

@@ -8,6 +8,7 @@ describe Gitlab::EtagCaching::Middleware do
   let(:app_status_code) { 200 }
   let(:if_none_match) { nil }
   let(:enabled_path) { '/gitlab-org/gitlab-foss/noteable/issue/1/notes' }
+  let(:endpoint) { 'issue_notes' }
 
   context 'when ETag caching is not enabled for current route' do
     let(:path) { '/gitlab-org/gitlab-foss/tree/master/noteable/issue/1/notes' }
@@ -50,9 +51,9 @@ describe Gitlab::EtagCaching::Middleware do
 
       it 'tracks "etag_caching_key_not_found" event' do
         expect(Gitlab::Metrics).to receive(:add_event)
-          .with(:etag_caching_middleware_used, endpoint: 'issue_notes')
+          .with(:etag_caching_middleware_used, endpoint: endpoint)
         expect(Gitlab::Metrics).to receive(:add_event)
-          .with(:etag_caching_key_not_found, endpoint: 'issue_notes')
+          .with(:etag_caching_key_not_found, endpoint: endpoint)
 
         middleware.call(build_request(path, if_none_match))
       end
@@ -74,6 +75,37 @@ describe Gitlab::EtagCaching::Middleware do
     end
   end
 
+  shared_examples 'sends a process_action.action_controller notification' do |status_code|
+    let(:expected_items) do
+      {
+        etag_route: endpoint,
+        params:     {},
+        format:     :html,
+        method:     'GET',
+        path:       enabled_path,
+        status:     status_code
+      }
+    end
+
+    it 'sends the expected payload' do
+      payload = payload_for('process_action.action_controller') do
+        middleware.call(build_request(path, if_none_match))
+      end
+
+      expect(payload).to include(expected_items)
+
+      expect(payload[:headers].env['HTTP_IF_NONE_MATCH']).to eq('W/"123"')
+    end
+
+    it 'log subscriber processes action' do
+      expect_any_instance_of(ActionController::LogSubscriber).to receive(:process_action)
+        .with(instance_of(ActiveSupport::Notifications::Event))
+        .and_call_original
+
+      middleware.call(build_request(path, if_none_match))
+    end
+  end
+
   context 'when If-None-Match header matches ETag in store' do
     let(:path) { enabled_path }
     let(:if_none_match) { 'W/"123"' }
@@ -94,6 +126,8 @@ describe Gitlab::EtagCaching::Middleware do
       expect(status).to eq 304
     end
 
+    it_behaves_like 'sends a process_action.action_controller notification', 304
+
     it 'returns empty body' do
       _, _, body = middleware.call(build_request(path, if_none_match))
 
@@ -102,9 +136,9 @@ describe Gitlab::EtagCaching::Middleware do
 
     it 'tracks "etag_caching_cache_hit" event' do
       expect(Gitlab::Metrics).to receive(:add_event)
-        .with(:etag_caching_middleware_used, endpoint: 'issue_notes')
+        .with(:etag_caching_middleware_used, endpoint: endpoint)
       expect(Gitlab::Metrics).to receive(:add_event)
-        .with(:etag_caching_cache_hit, endpoint: 'issue_notes')
+        .with(:etag_caching_cache_hit, endpoint: endpoint)
 
       middleware.call(build_request(path, if_none_match))
     end
@@ -120,6 +154,8 @@ describe Gitlab::EtagCaching::Middleware do
 
         expect(status).to eq 429
       end
+
+      it_behaves_like 'sends a process_action.action_controller notification', 429
     end
   end
 
@@ -141,9 +177,9 @@ describe Gitlab::EtagCaching::Middleware do
       mock_app_response
 
       expect(Gitlab::Metrics).to receive(:add_event)
-        .with(:etag_caching_middleware_used, endpoint: 'issue_notes')
+        .with(:etag_caching_middleware_used, endpoint: endpoint)
       expect(Gitlab::Metrics).to receive(:add_event)
-        .with(:etag_caching_resource_changed, endpoint: 'issue_notes')
+        .with(:etag_caching_resource_changed, endpoint: endpoint)
 
       middleware.call(build_request(path, if_none_match))
     end
@@ -159,9 +195,9 @@ describe Gitlab::EtagCaching::Middleware do
 
     it 'tracks "etag_caching_header_missing" event' do
       expect(Gitlab::Metrics).to receive(:add_event)
-        .with(:etag_caching_middleware_used, endpoint: 'issue_notes')
+        .with(:etag_caching_middleware_used, endpoint: endpoint)
       expect(Gitlab::Metrics).to receive(:add_event)
-        .with(:etag_caching_header_missing, endpoint: 'issue_notes')
+        .with(:etag_caching_header_missing, endpoint: endpoint)
 
       middleware.call(build_request(path, if_none_match))
     end
@@ -197,6 +233,21 @@ describe Gitlab::EtagCaching::Middleware do
   end
 
   def build_request(path, if_none_match)
-    { 'PATH_INFO' => path, 'HTTP_IF_NONE_MATCH' => if_none_match }
+    { 'PATH_INFO' => path,
+      'HTTP_IF_NONE_MATCH' => if_none_match,
+      'rack.input' => '',
+      'REQUEST_METHOD' => 'GET' }
+  end
+
+  def payload_for(event)
+    payload = nil
+    subscription = ActiveSupport::Notifications.subscribe event do |_, _, _, _, extra_payload|
+      payload = extra_payload
+    end
+
+    yield
+
+    ActiveSupport::Notifications.unsubscribe(subscription)
+    payload
   end
 end