From 228f428ee9aa3fb43beb827cf2b9075e765476fe Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?R=C3=A9my=20Coutable?= <remy@rymai.me>
Date: Thu, 3 Aug 2023 17:44:52 +0000
Subject: [PATCH] Add a Gitlab::WebHooks::Logger class
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit
Signed-off-by: Rémy Coutable <remy@rymai.me>
---
.../concerns/web_hooks/auto_disabling.rb | 27 ++--
app/workers/web_hook_worker.rb | 5 +-
doc/administration/logs/index.md | 17 +++
ee/spec/lib/gitlab/web_hooks/logger_spec.rb | 11 ++
lib/gitlab/web_hooks/logger.rb | 11 ++
.../auto_disabling_hooks_shared_examples.rb | 116 +++++++++++-------
.../unstoppable_hooks_shared_examples.rb | 12 +-
.../requests/api/hooks_shared_examples.rb | 2 +-
spec/workers/web_hook_worker_spec.rb | 12 +-
9 files changed, 150 insertions(+), 63 deletions(-)
create mode 100644 ee/spec/lib/gitlab/web_hooks/logger_spec.rb
create mode 100644 lib/gitlab/web_hooks/logger.rb
diff --git a/app/models/concerns/web_hooks/auto_disabling.rb b/app/models/concerns/web_hooks/auto_disabling.rb
index d6c900f75a973..72812f35f724d 100644
--- a/app/models/concerns/web_hooks/auto_disabling.rb
+++ b/app/models/concerns/web_hooks/auto_disabling.rb
@@ -3,6 +3,7 @@
module WebHooks
module AutoDisabling
extend ActiveSupport::Concern
+ include ::Gitlab::Loggable
ENABLED_HOOK_TYPES = %w[ProjectHook].freeze
MAX_FAILURES = 100
@@ -86,17 +87,14 @@ def permanently_disabled?
recent_failures > FAILURE_THRESHOLD && disabled_until.blank?
end
- def disable!
- return if !auto_disabling_enabled? || permanently_disabled?
-
- update_attribute(:recent_failures, EXCEEDED_FAILURE_THRESHOLD)
- end
-
def enable!
return unless auto_disabling_enabled?
return if recent_failures == 0 && disabled_until.nil? && backoff_count == 0
- assign_attributes(recent_failures: 0, disabled_until: nil, backoff_count: 0)
+ attrs = { recent_failures: 0, disabled_until: nil, backoff_count: 0 }
+
+ assign_attributes(attrs)
+ logger.info(hook_id: id, action: 'enable', **attrs)
save(validate: false)
end
@@ -114,14 +112,21 @@ def backoff!
end
assign_attributes(attrs)
- save(validate: false) if changed?
+
+ return unless changed?
+
+ logger.info(hook_id: id, action: 'backoff', **attrs)
+ save(validate: false)
end
def failed!
return unless auto_disabling_enabled?
return unless recent_failures < MAX_FAILURES
- assign_attributes(disabled_until: nil, backoff_count: 0, recent_failures: next_failure_count)
+ attrs = { disabled_until: nil, backoff_count: 0, recent_failures: next_failure_count }
+
+ assign_attributes(**attrs)
+ logger.info(hook_id: id, action: 'disable', **attrs)
save(validate: false)
end
@@ -147,6 +152,10 @@ def alert_status
private
+ def logger
+ @logger ||= Gitlab::WebHooks::Logger.build
+ end
+
def next_failure_count
recent_failures.succ.clamp(1, MAX_FAILURES)
end
diff --git a/app/workers/web_hook_worker.rb b/app/workers/web_hook_worker.rb
index 043a16e3527b0..cea0816f5a6d0 100644
--- a/app/workers/web_hook_worker.rb
+++ b/app/workers/web_hook_worker.rb
@@ -24,7 +24,10 @@ def perform(hook_id, data, hook_name, params = {})
# present in the request header so the hook can pass this same header value in its request.
Gitlab::WebHooks::RecursionDetection.set_request_uuid(params[:recursion_detection_request_uuid])
- WebHookService.new(hook, data, hook_name, jid).execute
+ WebHookService.new(hook, data, hook_name, jid).execute.tap do |response|
+ log_extra_metadata_on_done(:response_status, response.status)
+ log_extra_metadata_on_done(:http_status, response[:http_status])
+ end
end
end
# rubocop:enable Scalability/IdempotentWorker
diff --git a/doc/administration/logs/index.md b/doc/administration/logs/index.md
index f18fa05416be6..60d4ee223eef7 100644
--- a/doc/administration/logs/index.md
+++ b/doc/administration/logs/index.md
@@ -820,6 +820,23 @@ This file is located at:
This structured log file records internal activity in the `mail_room` gem.
Its name and path are configurable, so the name and path may not match the above.
+## `web_hooks.log`
+
+> Introduced in GitLab 16.3.
+
+This file is located at:
+
+- `/var/log/gitlab/gitlab-rails/web_hooks.log` on Linux package installations.
+- `/home/git/gitlab/log/web_hooks.log` on self-compiled installations.
+
+The back-off, disablement, and re-enablement events for Webhook are recorded in this file. For example:
+
+```json
+{"severity":"INFO","time":"2020-11-24T02:30:59.860Z","hook_id":12,"action":"backoff","disabled_until":"2020-11-24T04:30:59.860Z","backoff_count":2,"recent_failures":2}
+{"severity":"INFO","time":"2020-11-24T02:30:59.860Z","hook_id":12,"action":"disable","disabled_until":null,"backoff_count":5,"recent_failures":100}
+{"severity":"INFO","time":"2020-11-24T02:30:59.860Z","hook_id":12,"action":"enable","disabled_until":null,"backoff_count":0,"recent_failures":0}
+```
+
## Reconfigure logs
Reconfigure log files are in `/var/log/gitlab/reconfigure` for Linux package installations. Self-compiled installations
diff --git a/ee/spec/lib/gitlab/web_hooks/logger_spec.rb b/ee/spec/lib/gitlab/web_hooks/logger_spec.rb
new file mode 100644
index 0000000000000..ec4bdce317a19
--- /dev/null
+++ b/ee/spec/lib/gitlab/web_hooks/logger_spec.rb
@@ -0,0 +1,11 @@
+# frozen_string_literal: true
+
+require 'spec_helper'
+
+RSpec.describe ::Gitlab::WebHooks::Logger, feature_category: :webhooks do
+ describe '.build' do
+ it 'builds an instance' do
+ expect(described_class.build).to be_an_instance_of(described_class)
+ end
+ end
+end
diff --git a/lib/gitlab/web_hooks/logger.rb b/lib/gitlab/web_hooks/logger.rb
new file mode 100644
index 0000000000000..010e40a3dab4b
--- /dev/null
+++ b/lib/gitlab/web_hooks/logger.rb
@@ -0,0 +1,11 @@
+# frozen_string_literal: true
+
+module Gitlab
+ module WebHooks
+ class Logger < ::Gitlab::JsonLogger
+ def self.file_name_noext
+ 'web_hooks'
+ end
+ end
+ end
+end
diff --git a/spec/support/shared_examples/models/concerns/auto_disabling_hooks_shared_examples.rb b/spec/support/shared_examples/models/concerns/auto_disabling_hooks_shared_examples.rb
index a33a846417b66..33b62564e5f98 100644
--- a/spec/support/shared_examples/models/concerns/auto_disabling_hooks_shared_examples.rb
+++ b/spec/support/shared_examples/models/concerns/auto_disabling_hooks_shared_examples.rb
@@ -1,6 +1,13 @@
# frozen_string_literal: true
RSpec.shared_examples 'a hook that gets automatically disabled on failure' do
+ let(:logger) { instance_double('Gitlab::WebHooks::Logger') }
+
+ before do
+ allow(hook).to receive(:logger).and_return(logger)
+ allow(logger).to receive(:info)
+ end
+
shared_examples 'is tolerant of invalid records' do
specify do
hook.url = nil
@@ -171,6 +178,23 @@
expect { hook.enable! }.to change { hook.executable? }.from(false).to(true)
end
+ it 'logs relevant information' do
+ hook.recent_failures = 1000
+ hook.disabled_until = 1.hour.from_now
+
+ expect(logger)
+ .to receive(:info)
+ .with(a_hash_including(
+ hook_id: hook.id,
+ action: 'enable',
+ recent_failures: 0,
+ disabled_until: nil,
+ backoff_count: 0
+ ))
+
+ hook.enable!
+ end
+
it 'does not update hooks unless necessary' do
hook
@@ -188,11 +212,25 @@ def run_expectation
end
end
- describe '#backoff!' do
+ describe '#backoff!', :freeze_time do
context 'when we have not backed off before' do
it 'does not disable the hook' do
expect { hook.backoff! }.not_to change { hook.executable? }.from(true)
end
+
+ it 'increments recent_failures' do
+ expect { hook.backoff! }.to change { hook.recent_failures }.from(0).to(1)
+ end
+
+ it 'logs relevant information' do
+ expect(logger)
+ .to receive(:info)
+ .with(a_hash_including(
+ hook_id: hook.id, action: 'backoff', recent_failures: 1
+ ))
+
+ hook.backoff!
+ end
end
context 'when we have exhausted the grace period' do
@@ -200,6 +238,32 @@ def run_expectation
hook.update!(recent_failures: WebHooks::AutoDisabling::FAILURE_THRESHOLD)
end
+ it 'disables the hook' do
+ expect { hook.backoff! }.to change { hook.executable? }.from(true).to(false)
+ end
+
+ it 'increments backoff_count' do
+ expect { hook.backoff! }.to change { hook.backoff_count }.from(0).to(1)
+ end
+
+ it 'sets disabled_until' do
+ expect { hook.backoff! }.to change { hook.disabled_until }.from(nil).to(1.minute.from_now)
+ end
+
+ it 'logs relevant information' do
+ expect(logger)
+ .to receive(:info)
+ .with(a_hash_including(
+ hook_id: hook.id,
+ action: 'backoff',
+ recent_failures: WebHooks::AutoDisabling::FAILURE_THRESHOLD + 1,
+ disabled_until: 1.minute.from_now,
+ backoff_count: 1
+ ))
+
+ hook.backoff!
+ end
+
context 'when the hook is permanently disabled' do
before do
allow(hook).to receive(:permanently_disabled?).and_return(true)
@@ -218,15 +282,15 @@ def run_expectation
def run_expectation
expect { hook.backoff! }.to change { hook.backoff_count }.by(1)
end
+ end
- context 'when the flag is disabled' do
- before do
- stub_feature_flags(auto_disabling_web_hooks: false)
- end
+ context 'when the flag is disabled' do
+ before do
+ stub_feature_flags(auto_disabling_web_hooks: false)
+ end
- it 'does not increment backoff count' do
- expect { hook.failed! }.not_to change { hook.backoff_count }
- end
+ it 'does not increment backoff count' do
+ expect { hook.failed! }.not_to change { hook.backoff_count }
end
end
end
@@ -250,36 +314,6 @@ def run_expectation
end
end
- describe '#disable!' do
- it 'disables a hook' do
- expect { hook.disable! }.to change { hook.executable? }.from(true).to(false)
- end
-
- context 'when the flag is disabled' do
- before do
- stub_feature_flags(auto_disabling_web_hooks: false)
- end
-
- it 'does not disable the hook' do
- expect { hook.disable! }.not_to change { hook.executable? }
- end
- end
-
- it 'does nothing if the hook is already disabled' do
- allow(hook).to receive(:permanently_disabled?).and_return(true)
-
- sql_count = ActiveRecord::QueryRecorder.new { hook.disable! }.count
-
- expect(sql_count).to eq(0)
- end
-
- include_examples 'is tolerant of invalid records' do
- def run_expectation
- expect { hook.disable! }.to change { hook.executable? }.from(true).to(false)
- end
- end
- end
-
describe '#temporarily_disabled?' do
it 'is false when not temporarily disabled' do
expect(hook).not_to be_temporarily_disabled
@@ -324,7 +358,7 @@ def run_expectation
context 'when hook has been disabled' do
before do
- hook.disable!
+ hook.update!(recent_failures: WebHooks::AutoDisabling::EXCEEDED_FAILURE_THRESHOLD)
end
it 'is true' do
@@ -350,7 +384,7 @@ def run_expectation
context 'when hook has been disabled' do
before do
- hook.disable!
+ hook.update!(recent_failures: WebHooks::AutoDisabling::EXCEEDED_FAILURE_THRESHOLD)
end
it { is_expected.to eq :disabled }
@@ -366,7 +400,7 @@ def run_expectation
context 'when hook has been backed off' do
before do
- hook.update!(recent_failures: WebHooks::AutoDisabling::FAILURE_THRESHOLD + 1)
+ hook.update!(recent_failures: WebHooks::AutoDisabling::EXCEEDED_FAILURE_THRESHOLD)
hook.disabled_until = 1.hour.from_now
end
diff --git a/spec/support/shared_examples/models/concerns/unstoppable_hooks_shared_examples.rb b/spec/support/shared_examples/models/concerns/unstoppable_hooks_shared_examples.rb
index 8cadad0959b77..32e36c74a732a 100644
--- a/spec/support/shared_examples/models/concerns/unstoppable_hooks_shared_examples.rb
+++ b/spec/support/shared_examples/models/concerns/unstoppable_hooks_shared_examples.rb
@@ -137,12 +137,6 @@
end
end
- describe '#disable!' do
- it 'does not disable a group hook' do
- expect { hook.disable! }.not_to change { hook.executable? }.from(true)
- end
- end
-
describe '#temporarily_disabled?' do
it 'is false' do
# Initially
@@ -164,7 +158,7 @@
# Initially
expect(hook).not_to be_permanently_disabled
- hook.disable!
+ hook.update!(recent_failures: WebHooks::AutoDisabling::EXCEEDED_FAILURE_THRESHOLD)
expect(hook).not_to be_permanently_disabled
end
@@ -177,7 +171,7 @@
context 'when hook has been disabled' do
before do
- hook.disable!
+ hook.update!(recent_failures: WebHooks::AutoDisabling::EXCEEDED_FAILURE_THRESHOLD)
end
it { is_expected.to eq :executable }
@@ -185,7 +179,7 @@
context 'when hook has been backed off' do
before do
- hook.update!(recent_failures: WebHooks::AutoDisabling::FAILURE_THRESHOLD + 1)
+ hook.update!(recent_failures: WebHooks::AutoDisabling::EXCEEDED_FAILURE_THRESHOLD)
hook.disabled_until = 1.hour.from_now
end
diff --git a/spec/support/shared_examples/requests/api/hooks_shared_examples.rb b/spec/support/shared_examples/requests/api/hooks_shared_examples.rb
index a2c34aa6a5418..7489dc7c1d6f2 100644
--- a/spec/support/shared_examples/requests/api/hooks_shared_examples.rb
+++ b/spec/support/shared_examples/requests/api/hooks_shared_examples.rb
@@ -121,7 +121,7 @@ def hook_param_overrides
context 'the hook is disabled' do
before do
- hook.disable!
+ hook.update!(recent_failures: hook.class::EXCEEDED_FAILURE_THRESHOLD)
end
it "has the correct alert status", :aggregate_failures do
diff --git a/spec/workers/web_hook_worker_spec.rb b/spec/workers/web_hook_worker_spec.rb
index be43b83ec0a36..cd58dd93b8069 100644
--- a/spec/workers/web_hook_worker_spec.rb
+++ b/spec/workers/web_hook_worker_spec.rb
@@ -7,10 +7,14 @@
let_it_be(:project_hook) { create(:project_hook) }
let_it_be(:data) { { foo: 'bar' } }
let_it_be(:hook_name) { 'push_hooks' }
+ let_it_be(:response) { ServiceResponse.success }
describe '#perform' do
it 'delegates to WebHookService' do
- expect_next(WebHookService, project_hook, data.with_indifferent_access, hook_name, anything).to receive(:execute)
+ expect_next(WebHookService, project_hook, data.with_indifferent_access, hook_name, anything)
+ .to receive(:execute).and_return(response)
+ expect(subject).to receive(:log_extra_metadata_on_done).with(:response_status, response.status)
+ expect(subject).to receive(:log_extra_metadata_on_done).with(:http_status, response[:http_status])
subject.perform(project_hook.id, data, hook_name)
end
@@ -23,7 +27,11 @@
uuid = SecureRandom.uuid
params = { recursion_detection_request_uuid: uuid }
- expect_next(WebHookService, project_hook, data.with_indifferent_access, hook_name, anything).to receive(:execute)
+ expect_next(WebHookService, project_hook, data.with_indifferent_access, hook_name, anything)
+ .to receive(:execute).and_return(response)
+ expect(subject).to receive(:log_extra_metadata_on_done).with(:response_status, response.status)
+ expect(subject).to receive(:log_extra_metadata_on_done).with(:http_status, response[:http_status])
+
expect { subject.perform(project_hook.id, data, hook_name, params) }
.to change { Gitlab::WebHooks::RecursionDetection::UUID.instance.request_uuid }.to(uuid)
end
--
GitLab