Adds tracing messages for slow git pushes

Whenever a git push takes more than 50 seconds the user
will receive a trace from each check performed along with
their timings
This commit is contained in:
Tiago Botelho 2018-10-22 15:49:20 +01:00
parent f5d71ad8f3
commit 084a8b6101
No known key found for this signature in database
GPG key ID: E4465E6321AD276D
15 changed files with 317 additions and 48 deletions

View file

@ -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,

View file

@ -0,0 +1,5 @@
---
title: Adds trace of each access check when git push times out
merge_request: 22265
author:
type: added

View file

@ -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

View file

@ -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 commits..." # different message in EE
}.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.log << "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,18 @@ 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|
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 +228,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

View file

@ -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?

View file

@ -0,0 +1,69 @@
# frozen_string_literal: true
module Gitlab
module Checks
class TimedLogger
TimeoutError = Class.new(StandardError)
attr_reader :start_time
attr_accessor :log, :timeout
def initialize(start_time: Time.now, log: [], timeout:)
@start_time = start_time
@timeout = timeout
@log = log
end
def log_timed(log_message, start = Time.now)
check_timeout_reached
timed = true
yield
log << log_message + time_suffix_message(start: start)
rescue GRPC::DeadlineExceeded, TimeoutError
args = { cancelled: true }
args[:start] = start if timed
log << 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
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

View file

@ -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

View file

@ -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,12 @@ module Gitlab
cannot_push_to_read_only: "You can't push code to a read-only GitLab instance."
}.freeze
INTERNAL_TIMEOUT = 50.seconds.freeze
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 +46,7 @@ module Gitlab
end
def check(cmd, changes)
@logger = Checks::TimedLogger.new(timeout: INTERNAL_TIMEOUT)
@changes = changes
check_protocol!
@ -269,14 +272,25 @@ 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
header = <<~MESSAGE
Push operation timed out
Timing information for debugging purposes:
MESSAGE
raise TimeoutError, header + logger.log.join("\n")
end
def deploy_key

View file

@ -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

View file

@ -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)

View file

@ -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') }

View file

@ -0,0 +1,75 @@
# frozen_string_literal: true
require 'spec_helper'
describe Gitlab::Checks::TimedLogger do
let(:log_messages) do
{
foo: "Foo message..."
}
end
class FooCheck
attr_accessor :logger
INTERNAL_TIMEOUT = 50.seconds.freeze
def initialize(start_time, ref)
@logger = Gitlab::Checks::TimedLogger.new(start_time: start_time, timeout: INTERNAL_TIMEOUT)
@logger.log << "Checking ref: #{ref}"
end
def bar_check
2 + 2
end
def grpc_check
raise GRPC::DeadlineExceeded
end
end
describe '#log_timed' do
it 'logs message' do
start = Time.now
check = FooCheck.new(start, "bar")
Timecop.freeze(start + 30.seconds) do
check.logger.log_timed(log_messages[:foo], start) { check.bar_check }
end
expect(check.logger.log).to eq(["Checking ref: bar", "Foo message... (30000.0ms)"])
end
context 'when time limit was reached' do
it 'cancels action' do
start = Time.now
check = FooCheck.new(start, "bar")
Timecop.freeze(start + 50.seconds) do
expect do
check.logger.log_timed(log_messages[:foo], start) do
check.bar_check
end
end.to raise_error(described_class::TimeoutError)
end
expect(check.logger.log).to eq(["Checking ref: bar", "Foo message... (cancelled)"])
end
it 'cancels action with time elapsed if work was performed' do
start = Time.now
check = FooCheck.new(start, "bar")
Timecop.freeze(start + 30.seconds) do
expect do
check.logger.log_timed(log_messages[:foo], start) do
check.grpc_check
end
end.to raise_error(described_class::TimeoutError)
expect(check.logger.log).to eq(["Checking ref: bar", "Foo message... (cancelled after 30000.0ms)"])
end
end
end
end
end

View file

@ -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

View file

@ -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

View file

@ -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)