diff options
author | Tiago Botelho <tiagonbotelho@hotmail.com> | 2018-10-22 15:49:20 +0100 |
---|---|---|
committer | Tiago Botelho <tiagonbotelho@hotmail.com> | 2018-10-25 10:10:45 +0100 |
commit | 084a8b6101c25e5d3d4f97f078abd9a649a2fb64 (patch) | |
tree | 888cd28681c079561effde22bf6094e7c8db71b4 /lib/gitlab/checks | |
parent | f5d71ad8f3d1899a29bc12c4fcc8847b14195e3a (diff) | |
download | gitlab-ce-084a8b6101c25e5d3d4f97f078abd9a649a2fb64.tar.gz |
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
Diffstat (limited to 'lib/gitlab/checks')
-rw-r--r-- | lib/gitlab/checks/change_access.rb | 108 | ||||
-rw-r--r-- | lib/gitlab/checks/lfs_integrity.rb | 5 | ||||
-rw-r--r-- | lib/gitlab/checks/timed_logger.rb | 69 |
3 files changed, 144 insertions, 38 deletions
diff --git a/lib/gitlab/checks/change_access.rb b/lib/gitlab/checks/change_access.rb index 49e7f7e1fd7..52a72de3b15 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 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 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..cbb079a5383 --- /dev/null +++ b/lib/gitlab/checks/timed_logger.rb @@ -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 |