Merge branch 'qmnguyen0711/751-rack-attack-redis-calls-showing-up-in-the-slowlog' into 'master'

Monitor RackAttack redis usage and enrich auth structured logs

See merge request gitlab-org/gitlab!52471

changelogs/unreleased/qmnguyen0711-751-rack-attack-redis-calls-showing-up-in-the-slowlog.yml

+---
+title: Monitor RackAttack redis usage and enrich auth structured logs
+merge_request: 52471
+author:
+type: changed

config/initializers/rack_attack_logging.rb

-# frozen_string_literal: true
-#
-# Adds logging for all Rack Attack blocks and throttling events.
-
-ActiveSupport::Notifications.subscribe(/rack_attack/) do |name, start, finish, request_id, payload|
-  req = payload[:request]
-
-  case req.env['rack.attack.match_type']
-  when :throttle, :blocklist, :track
-    rack_attack_info = {
-      message: 'Rack_Attack',
-      env: req.env['rack.attack.match_type'],
-      remote_ip: req.ip,
-      request_method: req.request_method,
-      path: req.fullpath,
-      matched: req.env['rack.attack.matched']
-    }
-
-    throttles_with_user_information = [
-      :throttle_authenticated_api,
-      :throttle_authenticated_web,
-      :throttle_authenticated_protected_paths_api,
-      :throttle_authenticated_protected_paths_web
-    ]
-
-    if throttles_with_user_information.include? req.env['rack.attack.matched'].to_sym
-      user_id = req.env['rack.attack.match_discriminator']
-      user = User.find_by(id: user_id)
-
-      rack_attack_info[:user_id] = user_id
-      rack_attack_info['meta.user'] = user.username unless user.nil?
-    end
-
-    Gitlab::AuthLogger.error(rack_attack_info)
-  when :safelist
-    Gitlab::Instrumentation::Throttle.safelist = req.env['rack.attack.matched']
-  end
-end

ee/spec/lib/gitlab/rack_attack_spec.rb

@@ -6,6 +6,7 @@ RSpec.describe Gitlab::RackAttack, :aggregate_failures do
   describe '.configure' do
     let(:fake_rack_attack) { class_double("Rack::Attack") }
     let(:fake_rack_attack_request) { class_double("Rack::Attack::Request") }
+    let(:fake_cache) { instance_double("Rack::Attack::Cache") }
 
     before do
       stub_const("Rack::Attack", fake_rack_attack)
@@ -16,6 +17,8 @@ RSpec.describe Gitlab::RackAttack, :aggregate_failures do
       allow(fake_rack_attack).to receive(:track)
       allow(fake_rack_attack).to receive(:safelist)
       allow(fake_rack_attack).to receive(:blocklist)
+      allow(fake_rack_attack).to receive(:cache).and_return(fake_cache)
+      allow(fake_cache).to receive(:store=)
     end
 
     it 'adds the incident management throttle' do

lib/gitlab/instrumentation_helper.rb

@@ -15,7 +15,8 @@ module Gitlab
                  :elasticsearch_duration_s,
                  *::Gitlab::Instrumentation::Redis.known_payload_keys,
                  *::Gitlab::Metrics::Subscribers::ActiveRecord::DB_COUNTERS,
-                 *::Gitlab::Metrics::Subscribers::ExternalHttp::KNOWN_PAYLOAD_KEYS]
+                 *::Gitlab::Metrics::Subscribers::ExternalHttp::KNOWN_PAYLOAD_KEYS,
+                 *::Gitlab::Metrics::Subscribers::RackAttack::PAYLOAD_KEYS]
     end
 
     def add_instrumentation_data(payload)
@@ -26,6 +27,7 @@ module Gitlab
       instrument_throttle(payload)
       instrument_active_record(payload)
       instrument_external_http(payload)
+      instrument_rack_attack(payload)
     end
 
     def instrument_gitaly(payload)
@@ -80,6 +82,13 @@ module Gitlab
       payload.merge!(db_counters)
     end
 
+    def instrument_rack_attack(payload)
+      rack_attack_redis_count = ::Gitlab::Metrics::Subscribers::RackAttack.payload[:rack_attack_redis_count]
+      return if rack_attack_redis_count == 0
+
+      payload.merge!(::Gitlab::Metrics::Subscribers::RackAttack.payload)
+    end
+
     # Returns the queuing duration for a Sidekiq job in seconds, as a float, if the
     # `enqueued_at` field or `created_at` field is available.
     #

lib/gitlab/metrics/subscribers/rack_attack.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module Metrics
+    module Subscribers
+      # - Adds logging for all Rack Attack blocks and throttling events.
+      # - Instrument the cache operations of RackAttack to use in structured
+      # logs. Two fields are exposed:
+      #   + rack_attack_redis_count: the number of redis calls triggered by
+      #   RackAttack in a request.
+      #   + rack_attack_redis_duration_s: the total duration of all redis calls
+      #   triggered by RackAttack in a request.
+      class RackAttack < ActiveSupport::Subscriber
+        attach_to 'rack_attack'
+
+        INSTRUMENTATION_STORE_KEY = :rack_attack_instrumentation
+
+        THROTTLES_WITH_USER_INFORMATION = [
+          :throttle_authenticated_api,
+          :throttle_authenticated_web,
+          :throttle_authenticated_protected_paths_api,
+          :throttle_authenticated_protected_paths_web
+        ].freeze
+
+        PAYLOAD_KEYS = [
+          :rack_attack_redis_count,
+          :rack_attack_redis_duration_s
+        ].freeze
+
+        def self.payload
+          Gitlab::SafeRequestStore[INSTRUMENTATION_STORE_KEY] ||= {
+            rack_attack_redis_count: 0,
+            rack_attack_redis_duration_s: 0.0
+          }
+        end
+
+        def redis(event)
+          self.class.payload[:rack_attack_redis_count] += 1
+          self.class.payload[:rack_attack_redis_duration_s] += event.duration.to_f / 1000
+        end
+
+        def safelist(event)
+          req = event.payload[:request]
+          Gitlab::Instrumentation::Throttle.safelist = req.env['rack.attack.matched']
+        end
+
+        def throttle(event)
+          log_into_auth_logger(event)
+        end
+
+        def blocklist(event)
+          log_into_auth_logger(event)
+        end
+
+        def track(event)
+          log_into_auth_logger(event)
+        end
+
+        private
+
+        def log_into_auth_logger(event)
+          req = event.payload[:request]
+          rack_attack_info = {
+            message: 'Rack_Attack',
+            env: req.env['rack.attack.match_type'],
+            remote_ip: req.ip,
+            request_method: req.request_method,
+            path: req.fullpath,
+            matched: req.env['rack.attack.matched']
+          }
+
+          if THROTTLES_WITH_USER_INFORMATION.include? req.env['rack.attack.matched'].to_sym
+            user_id = req.env['rack.attack.match_discriminator']
+            user = User.find_by(id: user_id) # rubocop:disable CodeReuse/ActiveRecord
+
+            rack_attack_info[:user_id] = user_id
+            rack_attack_info['meta.user'] = user.username unless user.nil?
+          end
+
+          Gitlab::InstrumentationHelper.add_instrumentation_data(rack_attack_info)
+
+          logger.error(rack_attack_info)
+        end
+
+        def logger
+          Gitlab::AuthLogger
+        end
+      end
+    end
+  end
+end

lib/gitlab/rack_attack.rb

@@ -12,13 +12,15 @@ module Gitlab
       rack_attack::Request.include(Gitlab::RackAttack::Request)
 
       # This is Rack::Attack::DEFAULT_THROTTLED_RESPONSE, modified to allow a custom response
-      Rack::Attack.throttled_response = lambda do |env|
+      rack_attack.throttled_response = lambda do |env|
         throttled_headers = Gitlab::RackAttack.throttled_response_headers(
           env['rack.attack.matched'], env['rack.attack.match_data']
         )
         [429, { 'Content-Type' => 'text/plain' }.merge(throttled_headers), [Gitlab::Throttle.rate_limiting_response_text]]
       end
 
+      rack_attack.cache.store = Gitlab::RackAttack::InstrumentedCacheStore.new
+
       # Configure the throttles
       configure_throttles(rack_attack)
 

lib/gitlab/rack_attack/instrumented_cache_store.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module RackAttack
+    # This class is a proxy for all Redis calls made by RackAttack. All the
+    # calls are instrumented, then redirected to ::Rails.cache. This class
+    # instruments the standard interfaces of ActiveRecord::Cache defined in
+    # https://github.com/rails/rails/blob/v6.0.3.1/activesupport/lib/active_support/cache.rb#L315
+    #
+    # For more information, please see
+    # https://gitlab.com/gitlab-com/gl-infra/scalability/-/issues/751
+    class InstrumentedCacheStore
+      NOTIFICATION_CHANNEL = 'redis.rack_attack'
+
+      delegate :silence!, :mute, to: :@upstream_store
+
+      def initialize(upstream_store: ::Rails.cache, notifier: ActiveSupport::Notifications)
+        @upstream_store = upstream_store
+        @notifier = notifier
+      end
+
+      [:fetch, :read, :read_multi, :write_multi, :fetch_multi, :write, :delete,
+       :exist?, :delete_matched, :increment, :decrement, :cleanup, :clear].each do |interface|
+        define_method interface do |*args, **k_args, &block|
+          @notifier.instrument(NOTIFICATION_CHANNEL, operation: interface) do
+            @upstream_store.public_send(interface, *args, **k_args, &block) # rubocop:disable GitlabSecurity/PublicSend
+          end
+        end
+      end
+    end
+  end
+end

spec/lib/gitlab/auth/ip_rate_limiter_spec.rb

@@ -19,6 +19,9 @@ RSpec.describe Gitlab::Auth::IpRateLimiter, :use_clean_rails_memory_store_cachin
 
   before do
     stub_rack_attack_setting(options)
+    Rack::Attack.reset!
+    Rack::Attack.clear_configuration
+    Gitlab::RackAttack.configure(Rack::Attack)
   end
 
   after do

spec/lib/gitlab/instrumentation_helper_spec.rb

@@ -39,7 +39,9 @@ RSpec.describe Gitlab::InstrumentationHelper do
         :db_write_count,
         :db_cached_count,
         :external_http_count,
-        :external_http_duration_s
+        :external_http_duration_s,
+        :rack_attack_redis_count,
+        :rack_attack_redis_duration_s
       ]
 
       expect(described_class.keys).to eq(expected_keys)

spec/lib/gitlab/metrics/subscribers/rack_attack_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+RSpec.describe Gitlab::Metrics::Subscribers::RackAttack, :request_store do
+  let(:subscriber) { described_class.new }
+
+  describe '.payload' do
+    context 'when the request store is empty' do
+      it 'returns empty data' do
+        expect(described_class.payload).to eql(
+          rack_attack_redis_count: 0,
+          rack_attack_redis_duration_s: 0.0
+        )
+      end
+    end
+
+    context 'when the request store already has data' do
+      before do
+        Gitlab::SafeRequestStore[:rack_attack_instrumentation] = {
+          rack_attack_redis_count: 10,
+          rack_attack_redis_duration_s: 9.0
+        }
+      end
+
+      it 'returns the accumulated data' do
+        expect(described_class.payload).to eql(
+          rack_attack_redis_count: 10,
+          rack_attack_redis_duration_s: 9.0
+        )
+      end
+    end
+  end
+
+  describe '#redis' do
+    it 'accumulates per-request RackAttack cache usage' do
+      freeze_time do
+        subscriber.redis(
+          ActiveSupport::Notifications::Event.new(
+            'redis.rack_attack', Time.current, Time.current + 1.second, '1', { operation: 'fetch' }
+          )
+        )
+        subscriber.redis(
+          ActiveSupport::Notifications::Event.new(
+            'redis.rack_attack', Time.current, Time.current + 2.seconds, '1', { operation: 'write' }
+          )
+        )
+        subscriber.redis(
+          ActiveSupport::Notifications::Event.new(
+            'redis.rack_attack', Time.current, Time.current + 3.seconds, '1', { operation: 'read' }
+          )
+        )
+      end
+
+      expect(Gitlab::SafeRequestStore[:rack_attack_instrumentation]).to eql(
+        rack_attack_redis_count: 3,
+        rack_attack_redis_duration_s: 6.0
+      )
+    end
+  end
+
+  shared_examples 'log into auth logger' do
+    context 'when matched throttle does not require user information' do
+      let(:event) do
+        ActiveSupport::Notifications::Event.new(
+          event_name, Time.current, Time.current + 2.seconds, '1', request: double(
+            :request,
+            ip: '1.2.3.4',
+            request_method: 'GET',
+            fullpath: '/api/v4/internal/authorized_keys',
+            env: {
+              'rack.attack.match_type' => match_type,
+              'rack.attack.matched' => 'throttle_unauthenticated'
+            }
+          )
+        )
+      end
+
+      it 'logs request information' do
+        expect(Gitlab::AuthLogger).to receive(:error).with(
+          include(
+            message: 'Rack_Attack',
+            env: match_type,
+            remote_ip: '1.2.3.4',
+            request_method: 'GET',
+            path: '/api/v4/internal/authorized_keys',
+            matched: 'throttle_unauthenticated'
+          )
+        )
+        subscriber.send(match_type, event)
+      end
+    end
+
+    context 'when matched throttle requires user information' do
+      context 'when user not found' do
+        let(:event) do
+          ActiveSupport::Notifications::Event.new(
+            event_name, Time.current, Time.current + 2.seconds, '1', request: double(
+              :request,
+              ip: '1.2.3.4',
+              request_method: 'GET',
+              fullpath: '/api/v4/internal/authorized_keys',
+              env: {
+                'rack.attack.match_type' => match_type,
+                'rack.attack.matched' => 'throttle_authenticated_api',
+                'rack.attack.match_discriminator' => 'not_exist_user_id'
+              }
+            )
+          )
+        end
+
+        it 'logs request information and user id' do
+          expect(Gitlab::AuthLogger).to receive(:error).with(
+            include(
+              message: 'Rack_Attack',
+              env: match_type,
+              remote_ip: '1.2.3.4',
+              request_method: 'GET',
+              path: '/api/v4/internal/authorized_keys',
+              matched: 'throttle_authenticated_api',
+              user_id: 'not_exist_user_id'
+            )
+          )
+          subscriber.send(match_type, event)
+        end
+      end
+
+      context 'when user found' do
+        let(:user) { create(:user) }
+        let(:event) do
+          ActiveSupport::Notifications::Event.new(
+            event_name, Time.current, Time.current + 2.seconds, '1', request: double(
+              :request,
+              ip: '1.2.3.4',
+              request_method: 'GET',
+              fullpath: '/api/v4/internal/authorized_keys',
+              env: {
+                'rack.attack.match_type' => match_type,
+                'rack.attack.matched' => 'throttle_authenticated_api',
+                'rack.attack.match_discriminator' => user.id
+              }
+            )
+          )
+        end
+
+        it 'logs request information and user meta' do
+          expect(Gitlab::AuthLogger).to receive(:error).with(
+            include(
+              message: 'Rack_Attack',
+              env: match_type,
+              remote_ip: '1.2.3.4',
+              request_method: 'GET',
+              path: '/api/v4/internal/authorized_keys',
+              matched: 'throttle_authenticated_api',
+              user_id: user.id,
+              'meta.user' => user.username
+            )
+          )
+          subscriber.send(match_type, event)
+        end
+      end
+    end
+  end
+
+  describe '#throttle' do
+    let(:match_type) { :throttle }
+    let(:event_name) { 'throttle.rack_attack' }
+
+    it_behaves_like 'log into auth logger'
+  end
+
+  describe '#blocklist' do
+    let(:match_type) { :blocklist }
+    let(:event_name) { 'blocklist.rack_attack' }
+
+    it_behaves_like 'log into auth logger'
+  end
+
+  describe '#track' do
+    let(:match_type) { :track }
+    let(:event_name) { 'track.rack_attack' }
+
+    it_behaves_like 'log into auth logger'
+  end
+
+  describe '#safelist' do
+    let(:event) do
+      ActiveSupport::Notifications::Event.new(
+        'safelist.rack_attack', Time.current, Time.current + 2.seconds, '1', request: double(
+          :request,
+          env: {
+            'rack.attack.matched' => 'throttle_unauthenticated'
+          }
+        )
+      )
+    end
+
+    it 'adds the matched name to safe request store' do
+      subscriber.safelist(event)
+      expect(Gitlab::SafeRequestStore[:instrumentation_throttle_safelist]).to eql('throttle_unauthenticated')
+    end
+  end
+end

spec/lib/gitlab/rack_attack/instrumented_cache_store_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+RSpec.describe Gitlab::RackAttack::InstrumentedCacheStore do
+  using RSpec::Parameterized::TableSyntax
+
+  let(:store) { ::ActiveSupport::Cache::NullStore.new }
+
+  subject { described_class.new(upstream_store: store)}
+
+  where(:operation, :params, :test_proc) do
+    :fetch | [:key] | ->(s) { s.fetch(:key) }
+    :read | [:key] | ->(s) { s.read(:key) }
+    :read_multi | [:key_1, :key_2, :key_3] | ->(s) { s.read_multi(:key_1, :key_2, :key_3) }
+    :write_multi | [{ key_1: 1, key_2: 2, key_3: 3 }] | ->(s) { s.write_multi(key_1: 1, key_2: 2, key_3: 3) }
+    :fetch_multi | [:key_1, :key_2, :key_3] | ->(s) { s.fetch_multi(:key_1, :key_2, :key_3) {} }
+    :write | [:key, :value, { option_1: 1 }] | ->(s) { s.write(:key, :value, option_1: 1) }
+    :delete | [:key] | ->(s) { s.delete(:key) }
+    :exist? | [:key, { option_1: 1 }] | ->(s) { s.exist?(:key, option_1: 1) }
+    :delete_matched | [/^key$/, { option_1: 1 }] | ->(s) { s.delete_matched(/^key$/, option_1: 1 ) }
+    :increment | [:key, 1] | ->(s) { s.increment(:key, 1) }
+    :decrement | [:key, 1] | ->(s) { s.decrement(:key, 1) }
+    :cleanup | [] | ->(s) { s.cleanup }
+    :clear | [] | ->(s) { s.clear }
+  end
+
+  with_them do
+    it 'publishes a notification' do
+      event = nil
+
+      begin
+        subscriber = ActiveSupport::Notifications.subscribe("redis.rack_attack") do |*args|
+          event = ActiveSupport::Notifications::Event.new(*args)
+        end
+
+        test_proc.call(subject)
+      ensure
+        ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber
+      end
+
+      expect(event).not_to be_nil
+      expect(event.name).to eq("redis.rack_attack")
+      expect(event.duration).to be_a(Float).and(be > 0.0)
+      expect(event.payload[:operation]).to eql(operation)
+    end
+
+    it 'publishes a notification even if the cache store returns an error' do
+      allow(store).to receive(operation).and_raise('Something went wrong')
+
+      event = nil
+      exception = nil
+
+      begin
+        subscriber = ActiveSupport::Notifications.subscribe("redis.rack_attack") do |*args|
+          event = ActiveSupport::Notifications::Event.new(*args)
+        end
+
+        begin
+          test_proc.call(subject)
+        rescue => e
+          exception = e
+        end
+      ensure
+        ActiveSupport::Notifications.unsubscribe(subscriber) if subscriber
+      end
+
+      expect(event).not_to be_nil
+      expect(event.name).to eq("redis.rack_attack")
+      expect(event.duration).to be_a(Float).and(be > 0.0)
+      expect(event.payload[:operation]).to eql(operation)
+
+      expect(exception).not_to be_nil
+      expect(exception.message).to eql('Something went wrong')
+    end
+
+    it 'delegates to the upstream store' do
+      allow(store).to receive(operation).and_call_original
+
+      if params.empty?
+        expect(store).to receive(operation).with(no_args)
+      else
+        expect(store).to receive(operation).with(*params)
+      end
+
+      test_proc.call(subject)
+    end
+  end
+end

spec/lib/gitlab/rack_attack_spec.rb

@@ -6,6 +6,7 @@ RSpec.describe Gitlab::RackAttack, :aggregate_failures do
   describe '.configure' do
     let(:fake_rack_attack) { class_double("Rack::Attack") }
     let(:fake_rack_attack_request) { class_double("Rack::Attack::Request") }
+    let(:fake_cache) { instance_double("Rack::Attack::Cache") }
 
     let(:throttles) do
       {
@@ -27,6 +28,8 @@ RSpec.describe Gitlab::RackAttack, :aggregate_failures do
       allow(fake_rack_attack).to receive(:track)
       allow(fake_rack_attack).to receive(:safelist)
       allow(fake_rack_attack).to receive(:blocklist)
+      allow(fake_rack_attack).to receive(:cache).and_return(fake_cache)
+      allow(fake_cache).to receive(:store=)
     end
 
     it 'extends the request class' do

spec/requests/rack_attack_global_spec.rb

@@ -2,7 +2,7 @@
 
 require 'spec_helper'
 
-RSpec.describe 'Rack Attack global throttles' do
+RSpec.describe 'Rack Attack global throttles', :use_clean_rails_memory_store_caching do
   include RackAttackSpecHelpers
 
   let(:settings) { Gitlab::CurrentSettings.current_application_settings }
@@ -149,14 +149,14 @@ RSpec.describe 'Rack Attack global throttles' do
           expect(response).to have_gitlab_http_status(:ok)
         end
 
-        arguments = {
+        arguments = a_hash_including({
           message: 'Rack_Attack',
           env: :throttle,
           remote_ip: '127.0.0.1',
           request_method: 'GET',
           path: '/users/sign_in',
           matched: 'throttle_unauthenticated'
-        }
+        })
 
         expect(Gitlab::AuthLogger).to receive(:error).with(arguments)
 

spec/support/shared_examples/requests/rack_attack_shared_examples.rb

@@ -112,7 +112,7 @@ RSpec.shared_examples 'rate-limited token-authenticated requests' do
         expect(response).not_to have_gitlab_http_status(:too_many_requests)
       end
 
-      arguments = {
+      arguments = a_hash_including({
         message: 'Rack_Attack',
         env: :throttle,
         remote_ip: '127.0.0.1',
@@ -121,7 +121,7 @@ RSpec.shared_examples 'rate-limited token-authenticated requests' do
         user_id: user.id,
         'meta.user' => user.username,
         matched: throttle_types[throttle_setting_prefix]
-      }
+      })
 
       expect(Gitlab::AuthLogger).to receive(:error).with(arguments).once
 
@@ -278,7 +278,7 @@ RSpec.shared_examples 'rate-limited web authenticated requests' do
         expect(response).not_to have_gitlab_http_status(:too_many_requests)
       end
 
-      arguments = {
+      arguments = a_hash_including({
         message: 'Rack_Attack',
         env: :throttle,
         remote_ip: '127.0.0.1',
@@ -287,7 +287,7 @@ RSpec.shared_examples 'rate-limited web authenticated requests' do
         user_id: user.id,
         'meta.user' => user.username,
         matched: throttle_types[throttle_setting_prefix]
-      }
+      })
 
       expect(Gitlab::AuthLogger).to receive(:error).with(arguments).once
       expect { request_authenticated_web_url }.not_to exceed_query_limit(control_count)