Log state changes caused by webhook execution

This adds a log entry if we enable or disable a web-hook.

app/models/hooks/web_hook.rb

@@ -37,14 +37,14 @@ class WebHook < ApplicationRecord
     !temporarily_disabled? && !permanently_disabled?
   end
 
-  def temporarily_disabled?
-    return false unless web_hooks_disable_failed?
+  def temporarily_disabled?(ignore_flag: false)
+    return false unless ignore_flag || web_hooks_disable_failed?
 
     disabled_until.present? && disabled_until >= Time.current
   end
 
-  def permanently_disabled?
-    return false unless web_hooks_disable_failed?
+  def permanently_disabled?(ignore_flag: false)
+    return false unless ignore_flag || web_hooks_disable_failed?
 
     recent_failures > FAILURE_THRESHOLD
   end
@@ -106,6 +106,13 @@ class WebHook < ApplicationRecord
     save(validate: false)
   end
 
+  def active_state(ignore_flag: false)
+    return :permanently_disabled if permanently_disabled?(ignore_flag: ignore_flag)
+    return :temporarily_disabled if temporarily_disabled?(ignore_flag: ignore_flag)
+
+    :enabled
+  end
+
   # @return [Boolean] Whether or not the WebHook is currently throttled.
   def rate_limited?
     return false unless rate_limit

app/services/web_hooks/log_execution_service.rb

@@ -12,8 +12,9 @@ module WebHooks
 
     def initialize(hook:, log_data:, response_category:)
       @hook = hook
-      @log_data = log_data
+      @log_data = log_data.transform_keys(&:to_sym)
       @response_category = response_category
+      @prev_state = hook.active_state(ignore_flag: true)
     end
 
     def execute
@@ -24,7 +25,7 @@ module WebHooks
     private
 
     def log_execution
-      WebHookLog.create!(web_hook: hook, **log_data.transform_keys(&:to_sym))
+      WebHookLog.create!(web_hook: hook, **log_data)
     end
 
     # Perform this operation within an `Gitlab::ExclusiveLease` lock to make it
@@ -41,11 +42,36 @@ module WebHooks
         when :failed
           hook.failed!
         end
+
+        log_state_change
       end
     rescue Gitlab::ExclusiveLeaseHelpers::FailedToObtainLockError
       raise if raise_lock_error?
     end
 
+    def log_state_change
+      new_state = hook.active_state(ignore_flag: true)
+
+      return if @prev_state == new_state
+
+      Gitlab::AuthLogger.info(
+        message: 'WebHook change active_state',
+        # identification
+        hook_id: hook.id,
+        hook_type: hook.type,
+        project_id: hook.project_id,
+        group_id: hook.group_id,
+        # relevant data
+        prev_state: @prev_state,
+        new_state: new_state,
+        duration: log_data[:execution_duration],
+        response_status: log_data[:response_status],
+        recent_hook_failures: hook.recent_failures,
+        # context
+        **Gitlab::ApplicationContext.current
+      )
+    end
+
     def lock_name
       "web_hooks:update_hook_failure_state:#{hook.id}"
     end

spec/models/hooks/web_hook_spec.rb

@@ -432,6 +432,12 @@ RSpec.describe WebHook do
 
         expect(hook).not_to be_temporarily_disabled
       end
+
+      it 'can ignore the feature flag' do
+        stub_feature_flags(web_hooks_disable_failed: false)
+
+        expect(hook).to be_temporarily_disabled(ignore_flag: true)
+      end
     end
   end
 
@@ -454,6 +460,12 @@ RSpec.describe WebHook do
 
         expect(hook).not_to be_permanently_disabled
       end
+
+      it 'can ignore the feature flag' do
+        stub_feature_flags(web_hooks_disable_failed: false)
+
+        expect(hook).to be_permanently_disabled(ignore_flag: true)
+      end
     end
   end
 

spec/services/web_hooks/log_execution_service_spec.rb

@@ -95,12 +95,37 @@ RSpec.describe WebHooks::LogExecutionService do
         it 'resets the failure count' do
           expect { service.execute }.to change(project_hook, :recent_failures).to(0)
         end
+
+        it 'sends a message to AuthLogger if the hook as not previously enabled' do
+          project_hook.update!(recent_failures: ::WebHook::FAILURE_THRESHOLD + 1)
+
+          expect(Gitlab::AuthLogger).to receive(:info).with include(
+            message: 'WebHook change active_state',
+            # identification
+            hook_id: project_hook.id,
+            hook_type: project_hook.type,
+            project_id: project_hook.project_id,
+            group_id: nil,
+            # relevant data
+            prev_state: :permanently_disabled,
+            new_state: :enabled,
+            duration: 1.2,
+            response_status: '200',
+            recent_hook_failures: 0
+          )
+
+          service.execute
+        end
       end
     end
 
     context 'when response_category is :failed' do
       let(:response_category) { :failed }
 
+      before do
+        data[:response_status] = '400'
+      end
+
       it 'increments the failure count' do
         expect { service.execute }.to change(project_hook, :recent_failures).by(1)
       end
@@ -127,11 +152,36 @@ RSpec.describe WebHooks::LogExecutionService do
           expect { service.execute }.not_to change(project_hook, :recent_failures)
         end
       end
+
+      it 'sends a message to AuthLogger if the state would change' do
+        project_hook.update!(recent_failures: ::WebHook::FAILURE_THRESHOLD)
+
+        expect(Gitlab::AuthLogger).to receive(:info).with include(
+          message: 'WebHook change active_state',
+          # identification
+          hook_id: project_hook.id,
+          hook_type: project_hook.type,
+          project_id: project_hook.project_id,
+          group_id: nil,
+          # relevant data
+          prev_state: :enabled,
+          new_state: :permanently_disabled,
+          duration: (be > 0),
+          response_status: data[:response_status],
+          recent_hook_failures: ::WebHook::FAILURE_THRESHOLD + 1
+        )
+
+        service.execute
+      end
     end
 
     context 'when response_category is :error' do
       let(:response_category) { :error }
 
+      before do
+        data[:response_status] = '500'
+      end
+
       it 'does not increment the failure count' do
         expect { service.execute }.not_to change(project_hook, :recent_failures)
       end
@@ -144,6 +194,25 @@ RSpec.describe WebHooks::LogExecutionService do
         expect { service.execute }.to change(project_hook, :backoff_count).by(1)
       end
 
+      it 'sends a message to AuthLogger if the state would change' do
+        expect(Gitlab::AuthLogger).to receive(:info).with include(
+          message: 'WebHook change active_state',
+          # identification
+          hook_id: project_hook.id,
+          hook_type: project_hook.type,
+          project_id: project_hook.project_id,
+          group_id: nil,
+          # relevant data
+          prev_state: :enabled,
+          new_state: :temporarily_disabled,
+          duration: (be > 0),
+          response_status: data[:response_status],
+          recent_hook_failures: 0
+        )
+
+        service.execute
+      end
+
       context 'when the previous cool-off was near the maximum' do
         before do
           project_hook.update!(disabled_until: 5.minutes.ago, backoff_count: 8)