Commit 7d8348c4 authored by Stan Hu's avatar Stan Hu

Merge branch '217908-logging' into 'master'

Add logging to MergeTrains::RefreshMergeRequestsService

See merge request gitlab-org/gitlab!40105
parents ec2afafe 0767df3c
......@@ -10,44 +10,60 @@ module MergeTrains
# merge_request ... A merge request pointer in a merge train.
# All the merge requests following the specified merge request will be refreshed.
def execute(merge_request)
@merge_request = merge_request
return unless merge_request.on_train?
queue = Gitlab::BatchPopQueueing.new('merge_trains', queue_id(merge_request))
queue = Gitlab::BatchPopQueueing.new('merge_trains', queue_id)
result = queue.safe_execute([merge_request.id], lock_timeout: 15.minutes) do |items|
logging("Successfuly obtained the exclusive lock. Found merge requests to be refreshed", merge_request_ids: items.map(&:to_i))
first_merge_request = MergeTrain.first_in_train_from(items)
unsafe_refresh(first_merge_request)
end
if result[:status] == :enqueued
logging("This merge request was enqueued because the exclusive lock is obtained by the other process.")
end
if result[:status] == :finished && result[:new_items].present?
MergeTrain.first_in_train_from(result[:new_items]).try do |merge_request|
AutoMergeProcessWorker.perform_async(merge_request.id)
logging("Found more merge requests to be refreshed", merge_request_ids: result[:new_items].map(&:to_i))
MergeTrain.first_in_train_from(result[:new_items]).try do |first_merge_request|
logging("Rescheduled to refresh the merge train from", merge_request_ids: [first_merge_request.id])
AutoMergeProcessWorker.perform_async(first_merge_request.id)
end
end
end
private
def unsafe_refresh(merge_request)
attr_reader :merge_request
def unsafe_refresh(first_merge_request)
require_next_recreate = false
following_merge_requests_from(merge_request).each do |merge_request|
break if merge_request.merge_train.index >= max_concurrency
following_merge_requests_from(first_merge_request).each do |following_mr|
logging("Started refreshing", merge_request_ids: [following_mr.id])
break if following_mr.merge_train.index >= max_concurrency
result = MergeTrains::RefreshMergeRequestService
.new(merge_request.project, merge_request.merge_user,
.new(following_mr.project, following_mr.merge_user,
require_recreate: require_next_recreate)
.execute(merge_request)
.execute(following_mr)
require_next_recreate = (result[:status] == :error || result[:pipeline_created])
end
end
def following_merge_requests_from(merge_request)
merge_request.merge_train.all_next.to_a.unshift(merge_request)
def following_merge_requests_from(first_merge_request)
first_merge_request.merge_train.all_next.to_a.unshift(first_merge_request)
end
def queue_id(merge_request)
def queue_id
"#{merge_request.target_project_id}:#{merge_request.target_branch}"
end
......@@ -56,5 +72,13 @@ module MergeTrains
DEFAULT_CONCURRENCY
end
end
def logging(message, extra = {})
return unless Feature.enabled?(:ci_merge_train_logging, merge_request.project)
Sidekiq.logger.info(
{ class: self.class.to_s, args: [merge_request.id.to_s], message: message }.merge(extra)
)
end
end
end
......@@ -45,6 +45,28 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
allow(refresh_service_2).to receive(:execute) { refresh_service_2_result }
end
shared_examples 'logging results' do |count|
context 'when ci_merge_train_logging is enabled' do
it 'logs results' do
expect(Sidekiq.logger).to receive(:info).exactly(count).times
subject
end
end
context 'when ci_merge_train_logging is disabled' do
before do
stub_feature_flags(ci_merge_train_logging: false)
end
it 'does not log results' do
expect(Sidekiq.logger).not_to receive(:info)
subject
end
end
end
context 'when merge request 1 is passed' do
let(:merge_request) { merge_request_1 }
......@@ -55,6 +77,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
subject
end
it_behaves_like 'logging results', 3
context 'when refresh service 1 returns error status' do
let(:refresh_service_1_result) { { status: :error, message: 'Failed to create ref' } }
......@@ -64,6 +88,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
subject
end
it_behaves_like 'logging results', 3
end
context 'when refresh service 1 returns success status and did not create a pipeline' do
......@@ -75,6 +101,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
subject
end
it_behaves_like 'logging results', 3
end
context 'when refresh service 1 returns success status and created a pipeline' do
......@@ -86,6 +114,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
subject
end
it_behaves_like 'logging results', 3
end
context 'when merge request 1 is not on a merge train' do
......@@ -97,6 +127,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
subject
end
it_behaves_like 'logging results', 0
end
context 'when merge request 1 was on a merge train' do
......@@ -110,6 +142,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
subject
end
it_behaves_like 'logging results', 0
end
context 'when the other thread has already been processing the merge train' do
......@@ -132,6 +166,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
subject
end
it_behaves_like 'logging results', 1
end
end
......@@ -145,6 +181,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
subject
end
it_behaves_like 'logging results', 2
context 'when merge request 1 was tried to be refreshed while the system is refreshing merge request 2' do
before do
allow_any_instance_of(described_class).to receive(:unsafe_refresh).with(merge_request_2) do
......@@ -158,6 +196,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
subject
end
it_behaves_like 'logging results', 4
context 'when merge request 1 has already been merged' do
before do
allow(merge_request_1.merge_train).to receive(:cleanup_ref)
......@@ -169,6 +209,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
subject
end
it_behaves_like 'logging results', 1
end
end
end
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment