Merge branch 'improve-feature-flag-logging' into 'master'

Improve logging on feature flag modification

See merge request gitlab-org/gitlab!48417

changelogs/unreleased/improve-feature-flag-logging.yml

+---
+title: Improve logging on feature flag modification
+merge_request: 48417
+author:
+type: other

doc/administration/logs.md

@@ -665,6 +665,31 @@ installations from source.
 
 It logs the progress of the export process.
 
+## `features_json.log`
+
+> [Introduced](https://gitlab.com/gitlab-org/gitlab-foss/-/issues/59587) in GitLab 13.7.
+
+This file's location depends on how you installed GitLab:
+
+- For Omnibus GitLab packages: `/var/log/gitlab/gitlab-rails/features_json.log`
+- For installations from source: `/home/git/gitlab/log/features_json.log`
+
+The modification events from [Feature flags in development of GitLab](../development/feature_flags/index.md)
+are recorded in this file. For example:
+
+```json
+{"severity":"INFO","time":"2020-11-24T02:30:59.860Z","correlation_id":null,"key":"cd_auto_rollback","action":"enable","extra.thing":"true"}
+{"severity":"INFO","time":"2020-11-24T02:31:29.108Z","correlation_id":null,"key":"cd_auto_rollback","action":"enable","extra.thing":"true"}
+{"severity":"INFO","time":"2020-11-24T02:31:29.129Z","correlation_id":null,"key":"cd_auto_rollback","action":"disable","extra.thing":"false"}
+{"severity":"INFO","time":"2020-11-24T02:31:29.177Z","correlation_id":null,"key":"cd_auto_rollback","action":"enable","extra.thing":"Project:1"}
+{"severity":"INFO","time":"2020-11-24T02:31:29.183Z","correlation_id":null,"key":"cd_auto_rollback","action":"disable","extra.thing":"Project:1"}
+{"severity":"INFO","time":"2020-11-24T02:31:29.188Z","correlation_id":null,"key":"cd_auto_rollback","action":"enable_percentage_of_time","extra.percentage":"50"}
+{"severity":"INFO","time":"2020-11-24T02:31:29.193Z","correlation_id":null,"key":"cd_auto_rollback","action":"disable_percentage_of_time"}
+{"severity":"INFO","time":"2020-11-24T02:31:29.198Z","correlation_id":null,"key":"cd_auto_rollback","action":"enable_percentage_of_actors","extra.percentage":"50"}
+{"severity":"INFO","time":"2020-11-24T02:31:29.203Z","correlation_id":null,"key":"cd_auto_rollback","action":"disable_percentage_of_actors"}
+{"severity":"INFO","time":"2020-11-24T02:31:29.329Z","correlation_id":null,"key":"cd_auto_rollback","action":"remove"}
+```
+
 ## `auth.log`
 
 > Introduced in GitLab 12.0.

doc/development/feature_flags/controls.md

@@ -228,8 +228,10 @@ existing gates (e.g. `--group=gitlab-org`) in the above processes.
 
 ### Feature flag change logging
 
-Any feature flag change that affects GitLab.com (production) will
-automatically be logged in an issue.
+#### Chatops level
+
+Any feature flag change that affects GitLab.com (production) via [Chatops](https://gitlab.com/gitlab-com/chatops)
+is automatically logged in an issue.
 
 The issue is created in the
 [gl-infra/feature-flag-log](https://gitlab.com/gitlab-com/gl-infra/feature-flag-log/-/issues?scope=all&utf8=%E2%9C%93&state=closed)
@@ -243,6 +245,12 @@ marker to make the change even more visible.
 Changes to the issue format can be submitted in the
 [Chatops project](https://gitlab.com/gitlab-com/chatops).
 
+#### Instance level
+
+Any feature flag change that affects any GitLab instance is automatically logged in
+[features_json.log](../../administration/logs.md#features_jsonlog).
+You can search the change history in [Kibana](https://about.gitlab.com/handbook/support/workflows/kibana.html).
+
 ## Cleaning up
 
 A feature flag should be removed as soon as it is no longer needed. Each additional

ee/spec/lib/ee/feature_spec.rb

@@ -44,44 +44,4 @@ RSpec.describe Feature, stub_feature_flags: false do
       end
     end
   end
-
-  describe '.enable_group' do
-    context 'when running on a Geo primary node' do
-      before do
-        stub_primary_node
-      end
-
-      it 'does not create a Geo::CacheInvalidationEvent if there are no Geo secondary nodes' do
-        allow(Gitlab::Geo).to receive(:secondary_nodes) { [] }
-
-        expect { described_class.enable_group(:foo, :bar) }.not_to change(Geo::CacheInvalidationEvent, :count)
-      end
-
-      it 'creates a Geo::CacheInvalidationEvent' do
-        allow(Gitlab::Geo).to receive(:secondary_nodes) { [double] }
-
-        expect { described_class.enable_group(:foo, :bar) }.to change(Geo::CacheInvalidationEvent, :count).by(1)
-      end
-    end
-  end
-
-  describe '.disable_group' do
-    context 'when running on a Geo primary node' do
-      before do
-        stub_primary_node
-      end
-
-      it 'does not create a Geo::CacheInvalidationEvent if there are no Geo secondary nodes' do
-        allow(Gitlab::Geo).to receive(:secondary_nodes) { [] }
-
-        expect { described_class.disable_group(:foo, :bar) }.not_to change(Geo::CacheInvalidationEvent, :count)
-      end
-
-      it 'creates a Geo::CacheInvalidationEvent' do
-        allow(Gitlab::Geo).to receive(:secondary_nodes) { [double] }
-
-        expect { described_class.disable_group(:foo, :bar) }.to change(Geo::CacheInvalidationEvent, :count).by(1)
-      end
-    end
-  end
 end

lib/feature.rb

@@ -87,40 +87,39 @@ class Feature
     end
 
     def enable(key, thing = true)
+      log(key: key, action: __method__, thing: thing)
       get(key).enable(thing)
     end
 
     def disable(key, thing = false)
+      log(key: key, action: __method__, thing: thing)
       get(key).disable(thing)
     end
 
-    def enable_group(key, group)
-      get(key).enable_group(group)
-    end
-
-    def disable_group(key, group)
-      get(key).disable_group(group)
-    end
-
     def enable_percentage_of_time(key, percentage)
+      log(key: key, action: __method__, percentage: percentage)
       get(key).enable_percentage_of_time(percentage)
     end
 
     def disable_percentage_of_time(key)
+      log(key: key, action: __method__)
       get(key).disable_percentage_of_time
     end
 
     def enable_percentage_of_actors(key, percentage)
+      log(key: key, action: __method__, percentage: percentage)
       get(key).enable_percentage_of_actors(percentage)
     end
 
     def disable_percentage_of_actors(key)
+      log(key: key, action: __method__)
       get(key).disable_percentage_of_actors
     end
 
     def remove(key)
       return unless persisted_name?(key)
 
+      log(key: key, action: __method__)
       get(key).remove
     end
 
@@ -145,6 +144,10 @@ class Feature
       Feature::Definition.register_hot_reloader!
     end
 
+    def logger
+      @logger ||= Feature::Logger.build
+    end
+
     private
 
     def flipper
@@ -192,6 +195,14 @@ class Feature
     def l2_cache_backend
       Rails.cache
     end
+
+    def log(key:, action:, **extra)
+      extra ||= {}
+      extra = extra.transform_keys { |k| "extra.#{k}" }
+      extra = extra.transform_values { |v| v.respond_to?(:flipper_id) ? v.flipper_id : v }
+      extra = extra.transform_values(&:to_s)
+      logger.info(key: key, action: action, **extra)
+    end
   end
 
   class Target

lib/feature/logger.rb

+# frozen_string_literal: true
+
+class Feature
+  class Logger < ::Gitlab::JsonLogger
+    def self.file_name_noext
+      'features_json'
+    end
+  end
+end

spec/lib/feature_spec.rb

@@ -300,7 +300,119 @@ RSpec.describe Feature, stub_feature_flags: false do
     end
   end
 
+  shared_examples_for 'logging' do
+    let(:expected_action) { }
+    let(:expected_extra) { }
+
+    it 'logs the event' do
+      expect(Feature.logger).to receive(:info).with(key: key, action: expected_action, **expected_extra)
+
+      subject
+    end
+  end
+
+  describe '.enable' do
+    subject { described_class.enable(key, thing) }
+
+    let(:key) { :awesome_feature }
+    let(:thing) { true }
+
+    it_behaves_like 'logging' do
+      let(:expected_action) { :enable }
+      let(:expected_extra) { { "extra.thing" => "true" } }
+    end
+
+    context 'when thing is an actor' do
+      let(:thing) { create(:project) }
+
+      it_behaves_like 'logging' do
+        let(:expected_action) { :enable }
+        let(:expected_extra) { { "extra.thing" => "#{thing.flipper_id}" } }
+      end
+    end
+  end
+
+  describe '.disable' do
+    subject { described_class.disable(key, thing) }
+
+    let(:key) { :awesome_feature }
+    let(:thing) { false }
+
+    it_behaves_like 'logging' do
+      let(:expected_action) { :disable }
+      let(:expected_extra) { { "extra.thing" => "false" } }
+    end
+
+    context 'when thing is an actor' do
+      let(:thing) { create(:project) }
+
+      it_behaves_like 'logging' do
+        let(:expected_action) { :disable }
+        let(:expected_extra) { { "extra.thing" => "#{thing.flipper_id}" } }
+      end
+    end
+  end
+
+  describe '.enable_percentage_of_time' do
+    subject { described_class.enable_percentage_of_time(key, percentage) }
+
+    let(:key) { :awesome_feature }
+    let(:percentage) { 50 }
+
+    it_behaves_like 'logging' do
+      let(:expected_action) { :enable_percentage_of_time }
+      let(:expected_extra) { { "extra.percentage" => "#{percentage}" } }
+    end
+  end
+
+  describe '.disable_percentage_of_time' do
+    subject { described_class.disable_percentage_of_time(key) }
+
+    let(:key) { :awesome_feature }
+
+    it_behaves_like 'logging' do
+      let(:expected_action) { :disable_percentage_of_time }
+      let(:expected_extra) { {} }
+    end
+  end
+
+  describe '.enable_percentage_of_actors' do
+    subject { described_class.enable_percentage_of_actors(key, percentage) }
+
+    let(:key) { :awesome_feature }
+    let(:percentage) { 50 }
+
+    it_behaves_like 'logging' do
+      let(:expected_action) { :enable_percentage_of_actors }
+      let(:expected_extra) { { "extra.percentage" => "#{percentage}" } }
+    end
+  end
+
+  describe '.disable_percentage_of_actors' do
+    subject { described_class.disable_percentage_of_actors(key) }
+
+    let(:key) { :awesome_feature }
+
+    it_behaves_like 'logging' do
+      let(:expected_action) { :disable_percentage_of_actors }
+      let(:expected_extra) { {} }
+    end
+  end
+
   describe '.remove' do
+    subject { described_class.remove(key) }
+
+    let(:key) { :awesome_feature }
+
+    before do
+      described_class.enable(key)
+    end
+
+    it_behaves_like 'logging' do
+      let(:expected_action) { :remove }
+      let(:expected_extra) { {} }
+    end
+
     context 'for a non-persisted feature' do
       it 'returns nil' do
         expect(described_class.remove(:non_persisted_feature_flag)).to be_nil