Merge branch '344109-improve-observability-over-feature-flags' into 'master'

Log Feature.enabled? requests

See merge request gitlab-org/gitlab!73729

config/feature_flags/ops/feature_flag_state_logs.yml

+---
+name: feature_flag_state_logs
+introduced_by_url: https://gitlab.com/gitlab-org/gitlab/-/merge_requests/73729
+rollout_issue_url: https://gitlab.com/gitlab-org/gitlab/-/issues/345888
+milestone: '14.6'
+type: ops
+group: group::incubation
+default_enabled: false

lib/feature.rb

@@ -83,7 +83,12 @@ class Feature
       # `persisted?` can potentially generate DB queries and also checks for inclusion
       # in an array of feature names (177 at last count), possibly reducing performance by half.
       # So we only perform the `persisted` check if `default_enabled: true`
-      !default_enabled || Feature.persisted_name?(feature.name) ? feature.enabled?(thing) : true
+      feature_value = !default_enabled || Feature.persisted_name?(feature.name) ? feature.enabled?(thing) : true
+
+      # If we don't filter out this flag here we will enter an infinite loop
+      log_feature_flag_state(key, feature_value) if log_feature_flag_states?(key)
+
+      feature_value
     end
 
     def disabled?(key, thing = nil, type: :development, default_enabled: false)
@@ -153,6 +158,18 @@ class Feature
       @logger ||= Feature::Logger.build
     end
 
+    def log_feature_flag_states?(key)
+      key != :feature_flag_state_logs && Feature.enabled?(:feature_flag_state_logs, type: :ops)
+    end
+
+    def log_feature_flag_state(key, feature_value)
+      logged_states[key] ||= feature_value
+    end
+
+    def logged_states
+      RequestStore.fetch(:feature_flag_events) { {} }
+    end
+
     private
 
     def flipper

lib/gitlab/lograge/custom_options.rb

@@ -32,6 +32,10 @@ module Gitlab
 
         ::Gitlab::ExceptionLogFormatter.format!(exception, payload)
 
+        if Feature.enabled?(:feature_flag_state_logs, type: :ops)
+          payload[:feature_flag_states] = Feature.logged_states.map { |key, state| "#{key}:#{state ? 1 : 0}" }
+        end
+
         payload
       end
     end

spec/lib/feature_spec.rb

@@ -127,6 +127,10 @@ RSpec.describe Feature, stub_feature_flags: false do
   end
 
   describe '.enabled?' do
+    before do
+      allow(Feature).to receive(:log_feature_flag_states?).and_return(false)
+    end
+
     it 'returns false for undefined feature' do
       expect(described_class.enabled?(:some_random_feature_flag)).to be_falsey
     end
@@ -179,6 +183,24 @@ RSpec.describe Feature, stub_feature_flags: false do
       expect(described_class.enabled?(:a_feature, default_enabled: fake_default)).to eq(fake_default)
     end
 
+    context 'logging is enabled', :request_store do
+      before do
+        allow(Feature).to receive(:log_feature_flag_states?).and_call_original
+        described_class.enable(:feature_flag_state_logs)
+        described_class.enable(:enabled_feature_flag)
+        described_class.enabled?(:enabled_feature_flag)
+      end
+
+      it 'does not log feature_flag_state_logs' do
+        expect(described_class.logged_states).not_to have_key("feature_flag_state_logs")
+      end
+
+      it 'logs other feature flags' do
+        expect(described_class.logged_states).to have_key(:enabled_feature_flag)
+        expect(described_class.logged_states[:enabled_feature_flag]).to be_truthy
+      end
+    end
+
     context 'cached feature flag', :request_store do
       let(:flag) { :some_feature_flag }
 

spec/lib/gitlab/experimentation/experiment_spec.rb

@@ -16,6 +16,7 @@ RSpec.describe Gitlab::Experimentation::Experiment do
   before do
     skip_feature_flags_yaml_validation
     skip_default_enabled_yaml_check
+    allow(Feature).to receive(:log_feature_flag_states?).and_return(false)
     feature = double('FeatureFlag', percentage_of_time_value: percentage, enabled?: true)
     allow(Feature).to receive(:get).with(:experiment_key_experiment_percentage).and_return(feature)
   end

spec/lib/gitlab/lograge/custom_options_spec.rb

@@ -95,5 +95,47 @@ RSpec.describe Gitlab::Lograge::CustomOptions do
         expect(subject[correlation_id_key]).to eq('123456')
       end
     end
+
+    context  'when feature flags are present', :request_store do
+      before do
+        allow(Feature::Definition).to receive(:valid_usage!).and_return(true)
+
+        allow(Feature).to receive(:log_feature_flag_states?).and_return(false)
+
+        Feature.enable(:enabled_feature)
+        Feature.disable(:disabled_feature)
+
+        allow(Feature).to receive(:log_feature_flag_states?).with(:enabled_feature).and_call_original
+        allow(Feature).to receive(:log_feature_flag_states?).with(:disabled_feature).and_call_original
+      end
+
+      context 'and :feature_flag_log_states is enabled' do
+        before do
+          Feature.enable(:feature_flag_state_logs)
+        end
+
+        it 'adds feature flag events' do
+          Feature.enabled?(:enabled_feature)
+          Feature.enabled?(:disabled_feature)
+
+          expect(subject).to have_key(:feature_flag_states)
+          expect(subject[:feature_flag_states]).to match_array(%w[enabled_feature:1 disabled_feature:0])
+        end
+      end
+
+      context 'and :feature_flag_log_states is disabled' do
+        before do
+          Feature.disable(:feature_flag_state_logs)
+        end
+
+        it 'does not track or add feature flag events' do
+          Feature.enabled?(:enabled_feature)
+          Feature.enabled?(:disabled_feature)
+
+          expect(subject).not_to have_key(:feature_flag_states)
+          expect(Feature).not_to receive(:log_feature_flag_state)
+        end
+      end
+    end
   end
 end