diff --git a/GITLAB_SHELL_VERSION b/GITLAB_SHELL_VERSION index 9da0a092a0d..6da4de57dc6 100644 --- a/GITLAB_SHELL_VERSION +++ b/GITLAB_SHELL_VERSION @@ -1 +1 @@ -8.4.0 \ No newline at end of file +8.4.1 diff --git a/app/controllers/projects/git_http_controller.rb b/app/controllers/projects/git_http_controller.rb index be708835e30..c0aa39d87c6 100644 --- a/app/controllers/projects/git_http_controller.rb +++ b/app/controllers/projects/git_http_controller.rb @@ -8,6 +8,7 @@ class Projects::GitHttpController < Projects::GitHttpClientController rescue_from Gitlab::GitAccess::UnauthorizedError, with: :render_403 rescue_from Gitlab::GitAccess::NotFoundError, with: :render_404 rescue_from Gitlab::GitAccess::ProjectCreationError, with: :render_422 + rescue_from Gitlab::GitAccess::TimeoutError, with: :render_503 # GET /foo/bar.git/info/refs?service=git-upload-pack (git pull) # GET /foo/bar.git/info/refs?service=git-receive-pack (git push) @@ -62,6 +63,10 @@ class Projects::GitHttpController < Projects::GitHttpClientController render plain: exception.message, status: :unprocessable_entity end + def render_503(exception) + render plain: exception.message, status: :service_unavailable + end + def access @access ||= access_klass.new(access_actor, project, 'http', authentication_abilities: authentication_abilities, diff --git a/changelogs/unreleased/42790-improve-feedback-for-internal-git-access-checks-timeouts.yml b/changelogs/unreleased/42790-improve-feedback-for-internal-git-access-checks-timeouts.yml new file mode 100644 index 00000000000..d58d8da3a0e --- /dev/null +++ b/changelogs/unreleased/42790-improve-feedback-for-internal-git-access-checks-timeouts.yml @@ -0,0 +1,5 @@ +--- +title: Adds trace of each access check when git push times out +merge_request: 22265 +author: +type: added diff --git a/lib/api/internal.rb b/lib/api/internal.rb index 4dd6b19e353..ae40b5f7557 100644 --- a/lib/api/internal.rb +++ b/lib/api/internal.rb @@ -65,6 +65,8 @@ module API result rescue Gitlab::GitAccess::UnauthorizedError => e break response_with_status(code: 401, success: false, message: e.message) + rescue Gitlab::GitAccess::TimeoutError => e + break response_with_status(code: 503, success: false, message: e.message) rescue Gitlab::GitAccess::NotFoundError => e break response_with_status(code: 404, success: false, message: e.message) end diff --git a/lib/gitlab/checks/change_access.rb b/lib/gitlab/checks/change_access.rb index 49e7f7e1fd7..074afe9c412 100644 --- a/lib/gitlab/checks/change_access.rb +++ b/lib/gitlab/checks/change_access.rb @@ -18,11 +18,24 @@ module Gitlab lfs_objects_missing: 'LFS objects are missing. Ensure LFS is properly set up or try a manual "git lfs push --all".' }.freeze - attr_reader :user_access, :project, :skip_authorization, :skip_lfs_integrity_check, :protocol, :oldrev, :newrev, :ref, :branch_name, :tag_name + LOG_MESSAGES = { + push_checks: "Checking if you are allowed to push...", + delete_default_branch_check: "Checking if default branch is being deleted...", + protected_branch_checks: "Checking if you are force pushing to a protected branch...", + protected_branch_push_checks: "Checking if you are allowed to push to the protected branch...", + protected_branch_deletion_checks: "Checking if you are allowed to delete the protected branch...", + tag_checks: "Checking if you are allowed to change existing tags...", + protected_tag_checks: "Checking if you are creating, updating or deleting a protected tag...", + lfs_objects_exist_check: "Scanning repository for blobs stored in LFS and verifying their files have been uploaded to GitLab...", + commits_check_file_paths_validation: "Validating commits' file paths...", + commits_check: "Validating commit contents..." + }.freeze + + attr_reader :user_access, :project, :skip_authorization, :skip_lfs_integrity_check, :protocol, :oldrev, :newrev, :ref, :branch_name, :tag_name, :logger def initialize( change, user_access:, project:, skip_authorization: false, - skip_lfs_integrity_check: false, protocol: + skip_lfs_integrity_check: false, protocol:, logger: ) @oldrev, @newrev, @ref = change.values_at(:oldrev, :newrev, :ref) @branch_name = Gitlab::Git.branch_name(@ref) @@ -32,6 +45,9 @@ module Gitlab @skip_authorization = skip_authorization @skip_lfs_integrity_check = skip_lfs_integrity_check @protocol = protocol + + @logger = logger + @logger.append_message("Running checks for ref: #{@branch_name || @tag_name}") end def exec(skip_commits_check: false) @@ -49,26 +65,32 @@ module Gitlab protected def push_checks - unless can_push? - raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:push_code] + logger.log_timed(LOG_MESSAGES[__method__]) do + unless can_push? + raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:push_code] + end end end def branch_checks return unless branch_name - if deletion? && branch_name == project.default_branch - raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:delete_default_branch] + logger.log_timed(LOG_MESSAGES[:delete_default_branch_check]) do + if deletion? && branch_name == project.default_branch + raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:delete_default_branch] + end end protected_branch_checks end def protected_branch_checks - return unless ProtectedBranch.protected?(project, branch_name) + logger.log_timed(LOG_MESSAGES[__method__]) do + return unless ProtectedBranch.protected?(project, branch_name) # rubocop:disable Cop/AvoidReturnFromBlocks - if forced_push? - raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:force_push_protected_branch] + if forced_push? + raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:force_push_protected_branch] + end end if deletion? @@ -79,23 +101,27 @@ module Gitlab end def protected_branch_deletion_checks - unless user_access.can_delete_branch?(branch_name) - raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:non_master_delete_protected_branch] - end + logger.log_timed(LOG_MESSAGES[__method__]) do + unless user_access.can_delete_branch?(branch_name) + raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:non_master_delete_protected_branch] + end - unless updated_from_web? - raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:non_web_delete_protected_branch] + unless updated_from_web? + raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:non_web_delete_protected_branch] + end end end def protected_branch_push_checks - if matching_merge_request? - unless user_access.can_merge_to_branch?(branch_name) || user_access.can_push_to_branch?(branch_name) - raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:merge_protected_branch] - end - else - unless user_access.can_push_to_branch?(branch_name) - raise GitAccess::UnauthorizedError, push_to_protected_branch_rejected_message + logger.log_timed(LOG_MESSAGES[__method__]) do + if matching_merge_request? + unless user_access.can_merge_to_branch?(branch_name) || user_access.can_push_to_branch?(branch_name) + raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:merge_protected_branch] + end + else + unless user_access.can_push_to_branch?(branch_name) + raise GitAccess::UnauthorizedError, push_to_protected_branch_rejected_message + end end end end @@ -103,21 +129,25 @@ module Gitlab def tag_checks return unless tag_name - if tag_exists? && user_access.cannot_do_action?(:admin_project) - raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:change_existing_tags] + logger.log_timed(LOG_MESSAGES[__method__]) do + if tag_exists? && user_access.cannot_do_action?(:admin_project) + raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:change_existing_tags] + end end protected_tag_checks end def protected_tag_checks - return unless ProtectedTag.protected?(project, tag_name) + logger.log_timed(LOG_MESSAGES[__method__]) do + return unless ProtectedTag.protected?(project, tag_name) # rubocop:disable Cop/AvoidReturnFromBlocks - raise(GitAccess::UnauthorizedError, ERROR_MESSAGES[:update_protected_tag]) if update? - raise(GitAccess::UnauthorizedError, ERROR_MESSAGES[:delete_protected_tag]) if deletion? + raise(GitAccess::UnauthorizedError, ERROR_MESSAGES[:update_protected_tag]) if update? + raise(GitAccess::UnauthorizedError, ERROR_MESSAGES[:delete_protected_tag]) if deletion? - unless user_access.can_create_tag?(tag_name) - raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:create_protected_tag] + unless user_access.can_create_tag?(tag_name) + raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:create_protected_tag] + end end end @@ -125,14 +155,20 @@ module Gitlab return if deletion? || newrev.nil? return unless should_run_commit_validations? - # n+1: https://gitlab.com/gitlab-org/gitlab-ee/issues/3593 - ::Gitlab::GitalyClient.allow_n_plus_1_calls do - commits.each do |commit| - commit_check.validate(commit, validations_for_commit(commit)) + logger.log_timed(LOG_MESSAGES[__method__]) do + # n+1: https://gitlab.com/gitlab-org/gitlab-ee/issues/3593 + ::Gitlab::GitalyClient.allow_n_plus_1_calls do + commits.each do |commit| + logger.check_timeout_reached + + commit_check.validate(commit, validations_for_commit(commit)) + end end end - commit_check.validate_file_paths + logger.log_timed(LOG_MESSAGES[:commits_check_file_paths_validation]) do + commit_check.validate_file_paths + end end # Method overwritten in EE to inject custom validations @@ -194,10 +230,12 @@ module Gitlab end def lfs_objects_exist_check - lfs_check = Checks::LfsIntegrity.new(project, newrev) + logger.log_timed(LOG_MESSAGES[__method__]) do + lfs_check = Checks::LfsIntegrity.new(project, newrev, logger.time_left) - if lfs_check.objects_missing? - raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:lfs_objects_missing] + if lfs_check.objects_missing? + raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:lfs_objects_missing] + end end end diff --git a/lib/gitlab/checks/lfs_integrity.rb b/lib/gitlab/checks/lfs_integrity.rb index fa3dc1808df..1652d5a30a4 100644 --- a/lib/gitlab/checks/lfs_integrity.rb +++ b/lib/gitlab/checks/lfs_integrity.rb @@ -3,9 +3,10 @@ module Gitlab module Checks class LfsIntegrity - def initialize(project, newrev) + def initialize(project, newrev, time_left) @project = project @newrev = newrev + @time_left = time_left end # rubocop: disable CodeReuse/ActiveRecord @@ -13,7 +14,7 @@ module Gitlab return false unless @newrev && @project.lfs_enabled? new_lfs_pointers = Gitlab::Git::LfsChanges.new(@project.repository, @newrev) - .new_pointers(object_limit: ::Gitlab::Git::Repository::REV_LIST_COMMIT_LIMIT) + .new_pointers(object_limit: ::Gitlab::Git::Repository::REV_LIST_COMMIT_LIMIT, dynamic_timeout: @time_left) return false unless new_lfs_pointers.present? diff --git a/lib/gitlab/checks/timed_logger.rb b/lib/gitlab/checks/timed_logger.rb new file mode 100644 index 00000000000..f365e0a43f6 --- /dev/null +++ b/lib/gitlab/checks/timed_logger.rb @@ -0,0 +1,83 @@ +# frozen_string_literal: true + +module Gitlab + module Checks + class TimedLogger + TimeoutError = Class.new(StandardError) + + attr_reader :start_time, :header, :log, :timeout + + def initialize(start_time: Time.now, log: [], header: "", timeout:) + @start_time = start_time + @timeout = timeout + @header = header + @log = log + end + + # Adds trace of method being tracked with + # the correspondent time it took to run it. + # We make use of the start default argument + # on unit tests related to this method + # + def log_timed(log_message, start = Time.now) + check_timeout_reached + + timed = true + + yield + + append_message(log_message + time_suffix_message(start: start)) + rescue GRPC::DeadlineExceeded, TimeoutError + args = { cancelled: true } + args[:start] = start if timed + + append_message(log_message + time_suffix_message(args)) + + raise TimeoutError + end + + def check_timeout_reached + return unless time_expired? + + raise TimeoutError + end + + def time_left + (start_time + timeout.seconds) - Time.now + end + + def full_message + header + log.join("\n") + end + + # We always want to append in-place on the log + def append_message(message) + log << message + end + + private + + def time_expired? + time_left <= 0 + end + + def time_suffix_message(cancelled: false, start: nil) + return " (#{elapsed_time(start)}ms)" unless cancelled + + if start + " (cancelled after #{elapsed_time(start)}ms)" + else + " (cancelled)" + end + end + + def elapsed_time(start) + to_ms(Time.now - start) + end + + def to_ms(elapsed) + (elapsed.to_f * 1000).round(2) + end + end + end +end diff --git a/lib/gitlab/git/lfs_changes.rb b/lib/gitlab/git/lfs_changes.rb index f0fab1e76a3..d7148165408 100644 --- a/lib/gitlab/git/lfs_changes.rb +++ b/lib/gitlab/git/lfs_changes.rb @@ -6,8 +6,8 @@ module Gitlab @newrev = newrev end - def new_pointers(object_limit: nil, not_in: nil) - @repository.gitaly_blob_client.get_new_lfs_pointers(@newrev, object_limit, not_in) + def new_pointers(object_limit: nil, not_in: nil, dynamic_timeout: nil) + @repository.gitaly_blob_client.get_new_lfs_pointers(@newrev, object_limit, not_in, dynamic_timeout) end def all_pointers diff --git a/lib/gitlab/git_access.rb b/lib/gitlab/git_access.rb index 827c04ae035..802fa65dd63 100644 --- a/lib/gitlab/git_access.rb +++ b/lib/gitlab/git_access.rb @@ -9,6 +9,7 @@ module Gitlab UnauthorizedError = Class.new(StandardError) NotFoundError = Class.new(StandardError) ProjectCreationError = Class.new(StandardError) + TimeoutError = Class.new(StandardError) ProjectMovedError = Class.new(NotFoundError) ERROR_MESSAGES = { @@ -26,11 +27,18 @@ module Gitlab cannot_push_to_read_only: "You can't push code to a read-only GitLab instance." }.freeze + INTERNAL_TIMEOUT = 50.seconds.freeze + LOG_HEADER = <<~MESSAGE + Push operation timed out + + Timing information for debugging purposes: + MESSAGE + DOWNLOAD_COMMANDS = %w{git-upload-pack git-upload-archive}.freeze PUSH_COMMANDS = %w{git-receive-pack}.freeze ALL_COMMANDS = DOWNLOAD_COMMANDS + PUSH_COMMANDS - attr_reader :actor, :project, :protocol, :authentication_abilities, :namespace_path, :project_path, :redirected_path, :auth_result_type, :changes + attr_reader :actor, :project, :protocol, :authentication_abilities, :namespace_path, :project_path, :redirected_path, :auth_result_type, :changes, :logger def initialize(actor, project, protocol, authentication_abilities:, namespace_path: nil, project_path: nil, redirected_path: nil, auth_result_type: nil) @actor = actor @@ -44,6 +52,7 @@ module Gitlab end def check(cmd, changes) + @logger = Checks::TimedLogger.new(timeout: INTERNAL_TIMEOUT, header: LOG_HEADER) @changes = changes check_protocol! @@ -269,14 +278,19 @@ module Gitlab end def check_single_change_access(change, skip_lfs_integrity_check: false) - Checks::ChangeAccess.new( + change_access = Checks::ChangeAccess.new( change, user_access: user_access, project: project, skip_authorization: deploy_key?, skip_lfs_integrity_check: skip_lfs_integrity_check, - protocol: protocol - ).exec + protocol: protocol, + logger: logger + ) + + change_access.exec + rescue Checks::TimedLogger::TimeoutError + raise TimeoutError, logger.full_message end def deploy_key diff --git a/lib/gitlab/gitaly_client/blob_service.rb b/lib/gitlab/gitaly_client/blob_service.rb index 1840bf45154..086ce31e678 100644 --- a/lib/gitlab/gitaly_client/blob_service.rb +++ b/lib/gitlab/gitaly_client/blob_service.rb @@ -72,7 +72,7 @@ module Gitlab GitalyClient::BlobsStitcher.new(response) end - def get_new_lfs_pointers(revision, limit, not_in) + def get_new_lfs_pointers(revision, limit, not_in, dynamic_timeout = nil) request = Gitaly::GetNewLFSPointersRequest.new( repository: @gitaly_repo, revision: encode_binary(revision), @@ -85,7 +85,20 @@ module Gitlab request.not_in_refs += not_in end - response = GitalyClient.call(@gitaly_repo.storage_name, :blob_service, :get_new_lfs_pointers, request, timeout: GitalyClient.medium_timeout) + timeout = + if dynamic_timeout + [dynamic_timeout, GitalyClient.medium_timeout].min + else + GitalyClient.medium_timeout + end + + response = GitalyClient.call( + @gitaly_repo.storage_name, + :blob_service, + :get_new_lfs_pointers, + request, + timeout: timeout + ) map_lfs_pointers(response) end diff --git a/spec/lib/gitlab/checks/change_access_spec.rb b/spec/lib/gitlab/checks/change_access_spec.rb index 4df426c54ae..81804ba5c76 100644 --- a/spec/lib/gitlab/checks/change_access_spec.rb +++ b/spec/lib/gitlab/checks/change_access_spec.rb @@ -10,13 +10,16 @@ describe Gitlab::Checks::ChangeAccess do let(:ref) { 'refs/heads/master' } let(:changes) { { oldrev: oldrev, newrev: newrev, ref: ref } } let(:protocol) { 'ssh' } + let(:timeout) { Gitlab::GitAccess::INTERNAL_TIMEOUT } + let(:logger) { Gitlab::Checks::TimedLogger.new(timeout: timeout) } subject(:change_access) do described_class.new( changes, project: project, user_access: user_access, - protocol: protocol + protocol: protocol, + logger: logger ) end @@ -30,6 +33,19 @@ describe Gitlab::Checks::ChangeAccess do end end + context 'when time limit was reached' do + it 'raises a TimeoutError' do + logger = Gitlab::Checks::TimedLogger.new(start_time: timeout.ago, timeout: timeout) + access = described_class.new(changes, + project: project, + user_access: user_access, + protocol: protocol, + logger: logger) + + expect { access.exec }.to raise_error(Gitlab::Checks::TimedLogger::TimeoutError) + end + end + context 'when the user is not allowed to push to the repo' do it 'raises an error' do expect(user_access).to receive(:can_do_action?).with(:push_code).and_return(false) diff --git a/spec/lib/gitlab/checks/lfs_integrity_spec.rb b/spec/lib/gitlab/checks/lfs_integrity_spec.rb index ec22e3a198e..0488720cec8 100644 --- a/spec/lib/gitlab/checks/lfs_integrity_spec.rb +++ b/spec/lib/gitlab/checks/lfs_integrity_spec.rb @@ -3,6 +3,7 @@ require 'spec_helper' describe Gitlab::Checks::LfsIntegrity do include ProjectForksHelper + let!(:time_left) { 50 } let(:project) { create(:project, :repository) } let(:repository) { project.repository } let(:newrev) do @@ -15,7 +16,7 @@ describe Gitlab::Checks::LfsIntegrity do operations.commit_tree('8856a329dd38ca86dfb9ce5aa58a16d88cc119bd', "New LFS objects") end - subject { described_class.new(project, newrev) } + subject { described_class.new(project, newrev, time_left) } describe '#objects_missing?' do let(:blob_object) { repository.blob_at_branch('lfs', 'files/lfs/lfs_object.iso') } diff --git a/spec/lib/gitlab/checks/timed_logger_spec.rb b/spec/lib/gitlab/checks/timed_logger_spec.rb new file mode 100644 index 00000000000..0ed3940c038 --- /dev/null +++ b/spec/lib/gitlab/checks/timed_logger_spec.rb @@ -0,0 +1,63 @@ +# frozen_string_literal: true + +require 'spec_helper' + +describe Gitlab::Checks::TimedLogger do + let!(:timeout) { 50.seconds } + let!(:start) { Time.now } + let!(:ref) { "bar" } + let!(:logger) { described_class.new(start_time: start, timeout: timeout) } + let!(:log_messages) do + { + foo: "Foo message..." + } + end + + before do + logger.append_message("Checking ref: #{ref}") + end + + describe '#log_timed' do + it 'logs message' do + Timecop.freeze(start + 30.seconds) do + logger.log_timed(log_messages[:foo], start) { bar_check } + end + + expect(logger.full_message).to eq("Checking ref: bar\nFoo message... (30000.0ms)") + end + + context 'when time limit was reached' do + it 'cancels action' do + Timecop.freeze(start + 50.seconds) do + expect do + logger.log_timed(log_messages[:foo], start) do + bar_check + end + end.to raise_error(described_class::TimeoutError) + end + + expect(logger.full_message).to eq("Checking ref: bar\nFoo message... (cancelled)") + end + + it 'cancels action with time elapsed if work was performed' do + Timecop.freeze(start + 30.seconds) do + expect do + logger.log_timed(log_messages[:foo], start) do + grpc_check + end + end.to raise_error(described_class::TimeoutError) + + expect(logger.full_message).to eq("Checking ref: bar\nFoo message... (cancelled after 30000.0ms)") + end + end + end + end + + def bar_check + 2 + 2 + end + + def grpc_check + raise GRPC::DeadlineExceeded + end +end diff --git a/spec/lib/gitlab/git/lfs_changes_spec.rb b/spec/lib/gitlab/git/lfs_changes_spec.rb index c5e7ab959b2..d035df7e0c2 100644 --- a/spec/lib/gitlab/git/lfs_changes_spec.rb +++ b/spec/lib/gitlab/git/lfs_changes_spec.rb @@ -15,5 +15,9 @@ describe Gitlab::Git::LfsChanges do it 'limits new_objects using object_limit' do expect(subject.new_pointers(object_limit: 1)).to eq([]) end + + it 'times out if given a small dynamic timeout' do + expect { subject.new_pointers(dynamic_timeout: 0.001) }.to raise_error(GRPC::DeadlineExceeded) + end end end diff --git a/spec/lib/gitlab/git_access_spec.rb b/spec/lib/gitlab/git_access_spec.rb index e7da5565c26..a417ef77c9e 100644 --- a/spec/lib/gitlab/git_access_spec.rb +++ b/spec/lib/gitlab/git_access_spec.rb @@ -934,6 +934,16 @@ describe Gitlab::GitAccess do # There is still an N+1 query with protected branches expect { access.check('git-receive-pack', changes) }.not_to exceed_query_limit(control_count).with_threshold(1) end + + it 'raises TimeoutError when #check_single_change_access raises a timeout error' do + message = "Push operation timed out\n\nTiming information for debugging purposes:\nRunning checks for ref: wow" + + expect_next_instance_of(Gitlab::Checks::ChangeAccess) do |check| + expect(check).to receive(:exec).and_raise(Gitlab::Checks::TimedLogger::TimeoutError) + end + + expect { access.check('git-receive-pack', changes) }.to raise_error(described_class::TimeoutError, message) + end end end diff --git a/spec/requests/api/internal_spec.rb b/spec/requests/api/internal_spec.rb index e0b5b34f9c4..2ebcb787d06 100644 --- a/spec/requests/api/internal_spec.rb +++ b/spec/requests/api/internal_spec.rb @@ -494,6 +494,24 @@ describe API::Internal do end end + context 'request times out' do + context 'git push' do + it 'responds with a gateway timeout' do + personal_project = create(:project, namespace: user.namespace) + + expect_next_instance_of(Gitlab::GitAccess) do |access| + expect(access).to receive(:check).and_raise(Gitlab::GitAccess::TimeoutError, "Foo") + end + push(key, personal_project) + + expect(response).to have_gitlab_http_status(503) + expect(json_response['status']).to be_falsey + expect(json_response['message']).to eq("Foo") + expect(user.reload.last_activity_on).to be_nil + end + end + end + context "archived project" do before do project.add_developer(user)