From dcbffe91ab26f4411e693747f6f9271de377290e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?R=C3=A9my=20Coutable?= Date: Tue, 1 Aug 2023 11:05:41 +0200 Subject: [PATCH 1/2] 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 --- ee/spec/lib/gitlab/web_hooks/logger_spec.rb | 11 +++++++++++ lib/gitlab/web_hooks/logger.rb | 11 +++++++++++ 2 files changed, 22 insertions(+) create mode 100644 ee/spec/lib/gitlab/web_hooks/logger_spec.rb create mode 100644 lib/gitlab/web_hooks/logger.rb 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 00000000000000..ec4bdce317a195 --- /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 00000000000000..010e40a3dab4b8 --- /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 -- GitLab From 622fc72268e19ea372c7fefa55e4311d1d163072 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?R=C3=A9my=20Coutable?= Date: Tue, 1 Aug 2023 11:06:37 +0200 Subject: [PATCH 2/2] Add logging to the WebHooks::AutoDisabling concern MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Changelog: added Signed-off-by: Rémy Coutable --- .../concerns/web_hooks/auto_disabling.rb | 27 ++-- app/workers/web_hook_worker.rb | 5 +- doc/administration/logs/index.md | 17 +++ .../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 +- 7 files changed, 128 insertions(+), 63 deletions(-) diff --git a/app/models/concerns/web_hooks/auto_disabling.rb b/app/models/concerns/web_hooks/auto_disabling.rb index 2ad2e47ec4eca2..39b3a7bf55f47e 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 @@ -82,17 +83,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 @@ -110,14 +108,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 @@ -143,6 +148,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 043a16e3527b06..cea0816f5a6d0a 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 f18fa05416be6d..60d4ee223eef79 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/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 a196b63585cee4..3ece9511245466 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 @@ -157,6 +164,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 @@ -174,11 +198,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 @@ -186,6 +224,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) @@ -204,15 +268,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 @@ -236,36 +300,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 @@ -310,7 +344,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 @@ -336,7 +370,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 } @@ -352,7 +386,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 f98528ffedc763..5bb781138a3e99 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 @@ -123,12 +123,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 @@ -150,7 +144,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 @@ -163,7 +157,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 } @@ -171,7 +165,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 a2c34aa6a54180..7489dc7c1d6f24 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 be43b83ec0a365..cd58dd93b8069b 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