Merge branch 'an/gitaly-timeouts' into 'master'

Add timeouts for Gitaly calls

Closes gitaly#656

See merge request gitlab-org/gitlab-ce!15047

app/helpers/application_settings_helper.rb

@@ -177,6 +177,9 @@ module ApplicationSettingsHelper
       :ed25519_key_restriction,
       :email_author_in_body,
       :enabled_git_access_protocol,
+      :gitaly_timeout_default,
+      :gitaly_timeout_medium,
+      :gitaly_timeout_fast,
       :gravatar_enabled,
       :hashed_storage_enabled,
       :help_page_hide_commercial_content,

app/models/application_setting.rb

@@ -172,6 +172,27 @@ class ApplicationSetting < ActiveRecord::Base
     end
   end
 
+  validates :gitaly_timeout_default,
+            presence: true,
+            numericality: { only_integer: true, greater_than_or_equal_to: 0 }
+
+  validates :gitaly_timeout_medium,
+            presence: true,
+            numericality: { only_integer: true, greater_than_or_equal_to: 0 }
+  validates :gitaly_timeout_medium,
+            numericality: { less_than_or_equal_to: :gitaly_timeout_default },
+            if: :gitaly_timeout_default
+  validates :gitaly_timeout_medium,
+            numericality: { greater_than_or_equal_to: :gitaly_timeout_fast },
+            if: :gitaly_timeout_fast
+
+  validates :gitaly_timeout_fast,
+            presence: true,
+            numericality: { only_integer: true, greater_than_or_equal_to: 0 }
+  validates :gitaly_timeout_fast,
+            numericality: { less_than_or_equal_to: :gitaly_timeout_default },
+            if: :gitaly_timeout_default
+
   SUPPORTED_KEY_TYPES.each do |type|
     validates :"#{type}_key_restriction", presence: true, key_restriction: { type: type }
   end
@@ -308,7 +329,10 @@ class ApplicationSetting < ActiveRecord::Base
       two_factor_grace_period: 48,
       user_default_external: false,
       polling_interval_multiplier: 1,
-      usage_ping_enabled: Settings.gitlab['usage_ping_enabled']
+      usage_ping_enabled: Settings.gitlab['usage_ping_enabled'],
+      gitaly_timeout_fast: 10,
+      gitaly_timeout_medium: 30,
+      gitaly_timeout_default: 55
     }
   end
 

app/views/admin/application_settings/_form.html.haml

@@ -731,6 +731,30 @@
         .help-block
           Number of Git pushes after which 'git gc' is run.
 
+  %fieldset
+    %legend Gitaly Timeouts
+    .form-group
+      = f.label :gitaly_timeout_default, 'Default Timeout Period', class: 'control-label col-sm-2'
+      .col-sm-10
+        = f.number_field :gitaly_timeout_default, class: 'form-control'
+        .help-block
+          Timeout for Gitaly calls from the GitLab application (in seconds). This timeout is not enforced
+          for git fetch/push operations or Sidekiq jobs.
+    .form-group
+      = f.label :gitaly_timeout_fast, 'Fast Timeout Period', class: 'control-label col-sm-2'
+      .col-sm-10
+        = f.number_field :gitaly_timeout_fast, class: 'form-control'
+        .help-block
+          Fast operation timeout (in seconds). Some Gitaly operations are expected to be fast.
+          If they exceed this threshold, there may be a problem with a storage shard and 'failing fast'
+          can help maintain the stability of the GitLab instance.
+    .form-group
+      = f.label :gitaly_timeout_medium, 'Medium Timeout Period', class: 'control-label col-sm-2'
+      .col-sm-10
+        = f.number_field :gitaly_timeout_medium, class: 'form-control'
+        .help-block
+          Medium operation timeout (in seconds). This should be a value between the Fast and the Default timeout.
+
   %fieldset
     %legend Web terminal
     .form-group

changelogs/unreleased/an-gitaly-timeouts.yml

+---
+title: Add timeouts for Gitaly calls
+merge_request: 15047
+author:
+type: performance

db/migrate/20171101130535_add_gitaly_timeout_properties_to_application_settings.rb

+# See http://doc.gitlab.com/ce/development/migration_style_guide.html
+# for more information on how to write migrations for GitLab.
+
+class AddGitalyTimeoutPropertiesToApplicationSettings < ActiveRecord::Migration
+  include Gitlab::Database::MigrationHelpers
+
+  DOWNTIME = false
+
+  disable_ddl_transaction!
+
+  def up
+    add_column_with_default :application_settings,
+                            :gitaly_timeout_default,
+                            :integer,
+                            default: 55
+    add_column_with_default :application_settings,
+                            :gitaly_timeout_medium,
+                            :integer,
+                            default: 30
+    add_column_with_default :application_settings,
+                            :gitaly_timeout_fast,
+                            :integer,
+                            default: 10
+  end
+
+  def down
+    remove_column :application_settings, :gitaly_timeout_default
+    remove_column :application_settings, :gitaly_timeout_medium
+    remove_column :application_settings, :gitaly_timeout_fast
+  end
+end

db/schema.rb

@@ -150,6 +150,9 @@ ActiveRecord::Schema.define(version: 20171124132536) do
     t.integer "throttle_authenticated_web_period_in_seconds", default: 3600, null: false
     t.boolean "password_authentication_enabled_for_web"
     t.boolean "password_authentication_enabled_for_git", default: true
+    t.integer "gitaly_timeout_default", default: 55, null: false
+    t.integer "gitaly_timeout_medium", default: 30, null: false
+    t.integer "gitaly_timeout_fast", default: 10, null: false
   end
 
   create_table "audit_events", force: :cascade do |t|

lib/api/settings.rb

@@ -123,6 +123,9 @@ module API
       end
       optional :terminal_max_session_time, type: Integer, desc: 'Maximum time for web terminal websocket connection (in seconds). Set to 0 for unlimited time.'
       optional :polling_interval_multiplier, type: BigDecimal, desc: 'Interval multiplier used by endpoints that perform polling. Set to 0 to disable polling.'
+      optional :gitaly_timeout_default, type: Integer, desc: 'Default Gitaly timeout, in seconds. Set to 0 to disable timeouts.'
+      optional :gitaly_timeout_medium, type: Integer, desc: 'Medium Gitaly timeout, in seconds. Set to 0 to disable timeouts.'
+      optional :gitaly_timeout_fast, type: Integer, desc: 'Gitaly fast operation timeout, in seconds. Set to 0 to disable timeouts.'
 
       ApplicationSetting::SUPPORTED_KEY_TYPES.each do |type|
         optional :"#{type}_key_restriction",

lib/gitlab/gitaly_client.rb

@@ -117,11 +117,11 @@ module Gitlab
     #   kwargs.merge(deadline: Time.now + 10)
     # end
     #
-    def self.call(storage, service, rpc, request, remote_storage: nil)
+    def self.call(storage, service, rpc, request, remote_storage: nil, timeout: nil)
       start = Gitlab::Metrics::System.monotonic_time
       enforce_gitaly_request_limits(:call)
 
-      kwargs = request_kwargs(storage, remote_storage: remote_storage)
+      kwargs = request_kwargs(storage, timeout, remote_storage: remote_storage)
       kwargs = yield(kwargs) if block_given?
 
       stub(service, storage).__send__(rpc, request, kwargs) # rubocop:disable GitlabSecurity/PublicSend
@@ -140,7 +140,7 @@ module Gitlab
     end
     private_class_method :current_transaction_labels
 
-    def self.request_kwargs(storage, remote_storage: nil)
+    def self.request_kwargs(storage, timeout, remote_storage: nil)
       encoded_token = Base64.strict_encode64(token(storage).to_s)
       metadata = {
         'authorization' => "Bearer #{encoded_token}",
@@ -152,7 +152,22 @@ module Gitlab
       metadata['call_site'] = feature.to_s if feature
       metadata['gitaly-servers'] = address_metadata(remote_storage) if remote_storage
 
-      { metadata: metadata }
+      result = { metadata: metadata }
+
+      # nil timeout indicates that we should use the default
+      timeout = default_timeout if timeout.nil?
+
+      return result unless timeout > 0
+
+      # Do not use `Time.now` for deadline calculation, since it
+      # will be affected by Timecop in some tests, but grpc's c-core
+      # uses system time instead of timecop's time, so tests will fail
+      # `Time.at(Process.clock_gettime(Process::CLOCK_REALTIME))` will
+      # circumvent timecop
+      deadline = Time.at(Process.clock_gettime(Process::CLOCK_REALTIME)) + timeout
+      result[:deadline] = deadline
+
+      result
     end
 
     def self.token(storage)
@@ -325,6 +340,26 @@ module Gitlab
       Google::Protobuf::RepeatedField.new(:bytes, a.map { |s| self.encode(s) } )
     end
 
+    # The default timeout on all Gitaly calls
+    def self.default_timeout
+      return 0 if Sidekiq.server?
+
+      timeout(:gitaly_timeout_default)
+    end
+
+    def self.fast_timeout
+      timeout(:gitaly_timeout_fast)
+    end
+
+    def self.medium_timeout
+      timeout(:gitaly_timeout_medium)
+    end
+
+    def self.timeout(timeout_name)
+      Gitlab::CurrentSettings.current_application_settings[timeout_name]
+    end
+    private_class_method :timeout
+
     # Count a stack. Used for n+1 detection
     def self.count_stack
       return unless RequestStore.active?

lib/gitlab/gitaly_client/commit_service.rb

@@ -16,7 +16,7 @@ module Gitlab
           revision: GitalyClient.encode(revision)
         )
 
-        response = GitalyClient.call(@repository.storage, :commit_service, :list_files, request)
+        response = GitalyClient.call(@repository.storage, :commit_service, :list_files, request, timeout: GitalyClient.medium_timeout)
         response.flat_map do |msg|
           msg.paths.map { |d| EncodingHelper.encode!(d.dup) }
         end
@@ -29,7 +29,7 @@ module Gitlab
           child_id: child_id
         )
 
-        GitalyClient.call(@repository.storage, :commit_service, :commit_is_ancestor, request).value
+        GitalyClient.call(@repository.storage, :commit_service, :commit_is_ancestor, request, timeout: GitalyClient.fast_timeout).value
       end
 
       def diff(from, to, options = {})
@@ -77,7 +77,7 @@ module Gitlab
           limit: limit.to_i
         )
 
-        response = GitalyClient.call(@repository.storage, :commit_service, :tree_entry, request)
+        response = GitalyClient.call(@repository.storage, :commit_service, :tree_entry, request, timeout: GitalyClient.medium_timeout)
 
         entry = nil
         data = ''
@@ -102,7 +102,7 @@ module Gitlab
           path: path.present? ? GitalyClient.encode(path) : '.'
         )
 
-        response = GitalyClient.call(@repository.storage, :commit_service, :get_tree_entries, request)
+        response = GitalyClient.call(@repository.storage, :commit_service, :get_tree_entries, request, timeout: GitalyClient.medium_timeout)
 
         response.flat_map do |message|
           message.entries.map do |gitaly_tree_entry|
@@ -129,7 +129,7 @@ module Gitlab
         request.before = Google::Protobuf::Timestamp.new(seconds: options[:before].to_i) if options[:before].present?
         request.path = options[:path] if options[:path].present?
 
-        GitalyClient.call(@repository.storage, :commit_service, :count_commits, request).count
+        GitalyClient.call(@repository.storage, :commit_service, :count_commits, request, timeout: GitalyClient.medium_timeout).count
       end
 
       def last_commit_for_path(revision, path)
@@ -139,7 +139,7 @@ module Gitlab
           path: GitalyClient.encode(path.to_s)
         )
 
-        gitaly_commit = GitalyClient.call(@repository.storage, :commit_service, :last_commit_for_path, request).commit
+        gitaly_commit = GitalyClient.call(@repository.storage, :commit_service, :last_commit_for_path, request, timeout: GitalyClient.fast_timeout).commit
         return unless gitaly_commit
 
         Gitlab::Git::Commit.new(@repository, gitaly_commit)
@@ -152,7 +152,7 @@ module Gitlab
           to: to
         )
 
-        response = GitalyClient.call(@repository.storage, :commit_service, :commits_between, request)
+        response = GitalyClient.call(@repository.storage, :commit_service, :commits_between, request, timeout: GitalyClient.medium_timeout)
         consume_commits_response(response)
       end
 
@@ -165,7 +165,7 @@ module Gitlab
         )
         request.order = opts[:order].upcase if opts[:order].present?
 
-        response = GitalyClient.call(@repository.storage, :commit_service, :find_all_commits, request)
+        response = GitalyClient.call(@repository.storage, :commit_service, :find_all_commits, request, timeout: GitalyClient.medium_timeout)
         consume_commits_response(response)
       end
 
@@ -179,7 +179,7 @@ module Gitlab
           offset: offset.to_i
         )
 
-        response = GitalyClient.call(@repository.storage, :commit_service, :commits_by_message, request)
+        response = GitalyClient.call(@repository.storage, :commit_service, :commits_by_message, request, timeout: GitalyClient.medium_timeout)
         consume_commits_response(response)
       end
 
@@ -197,7 +197,7 @@ module Gitlab
           path: GitalyClient.encode(path)
         )
 
-        response = GitalyClient.call(@repository.storage, :commit_service, :raw_blame, request)
+        response = GitalyClient.call(@repository.storage, :commit_service, :raw_blame, request, timeout: GitalyClient.medium_timeout)
         response.reduce("") { |memo, msg| memo << msg.data }
       end
 
@@ -207,7 +207,7 @@ module Gitlab
           revision: GitalyClient.encode(revision)
         )
 
-        response = GitalyClient.call(@repository.storage, :commit_service, :find_commit, request)
+        response = GitalyClient.call(@repository.storage, :commit_service, :find_commit, request, timeout: GitalyClient.medium_timeout)
 
         response.commit
       end
@@ -217,7 +217,7 @@ module Gitlab
           repository: @gitaly_repo,
           revision: GitalyClient.encode(revision)
         )
-        response = GitalyClient.call(@repository.storage, :diff_service, :commit_patch, request)
+        response = GitalyClient.call(@repository.storage, :diff_service, :commit_patch, request, timeout: GitalyClient.medium_timeout)
 
         response.sum(&:data)
       end
@@ -227,7 +227,7 @@ module Gitlab
           repository: @gitaly_repo,
           revision: GitalyClient.encode(revision)
         )
-        GitalyClient.call(@repository.storage, :commit_service, :commit_stats, request)
+        GitalyClient.call(@repository.storage, :commit_service, :commit_stats, request, timeout: GitalyClient.medium_timeout)
       end
 
       def find_commits(options)
@@ -245,7 +245,7 @@ module Gitlab
 
         request.paths = GitalyClient.encode_repeated(Array(options[:path])) if options[:path].present?
 
-        response = GitalyClient.call(@repository.storage, :commit_service, :find_commits, request)
+        response = GitalyClient.call(@repository.storage, :commit_service, :find_commits, request, timeout: GitalyClient.medium_timeout)
 
         consume_commits_response(response)
       end
@@ -259,7 +259,7 @@ module Gitlab
         request_params.merge!(Gitlab::Git::DiffCollection.collection_limits(options).to_h)
 
         request = Gitaly::CommitDiffRequest.new(request_params)
-        response = GitalyClient.call(@repository.storage, :diff_service, :commit_diff, request)
+        response = GitalyClient.call(@repository.storage, :diff_service, :commit_diff, request, timeout: GitalyClient.medium_timeout)
         GitalyClient::DiffStitcher.new(response)
       end
 

lib/gitlab/gitaly_client/ref_service.rb

@@ -46,7 +46,8 @@ module Gitlab
           commit_id: commit_id,
           prefix: ref_prefix
         )
-        encode!(GitalyClient.call(@storage, :ref_service, :find_ref_name, request).name.dup)
+        response = GitalyClient.call(@storage, :ref_service, :find_ref_name, request, timeout: GitalyClient.medium_timeout)
+        encode!(response.name.dup)
       end
 
       def count_tag_names

lib/gitlab/gitaly_client/repository_service.rb

@@ -10,7 +10,9 @@ module Gitlab
       def exists?
         request = Gitaly::RepositoryExistsRequest.new(repository: @gitaly_repo)
 
-        GitalyClient.call(@storage, :repository_service, :repository_exists, request).exists
+        response = GitalyClient.call(@storage, :repository_service, :repository_exists, request, timeout: GitalyClient.fast_timeout)
+
+        response.exists
       end
 
       def garbage_collect(create_bitmap)
@@ -30,7 +32,8 @@ module Gitlab
 
       def repository_size
         request = Gitaly::RepositorySizeRequest.new(repository: @gitaly_repo)
-        GitalyClient.call(@storage, :repository_service, :repository_size, request).size
+        response = GitalyClient.call(@storage, :repository_service, :repository_size, request)
+        response.size
       end
 
       def apply_gitattributes(revision)
@@ -61,7 +64,7 @@ module Gitlab
 
       def has_local_branches?
         request = Gitaly::HasLocalBranchesRequest.new(repository: @gitaly_repo)
-        response = GitalyClient.call(@storage, :repository_service, :has_local_branches, request)
+        response = GitalyClient.call(@storage, :repository_service, :has_local_branches, request, timeout: GitalyClient.fast_timeout)
 
         response.value
       end

spec/lib/gitlab/gitaly_client_spec.rb

@@ -278,4 +278,20 @@ describe Gitlab::GitalyClient, skip_gitaly_mock: true do
       end
     end
   end
+
+  describe 'timeouts' do
+    context 'with default values' do
+      before do
+        stub_application_setting(gitaly_timeout_default: 55)
+        stub_application_setting(gitaly_timeout_medium: 30)
+        stub_application_setting(gitaly_timeout_fast: 10)
+      end
+
+      it 'returns expected values' do
+        expect(described_class.default_timeout).to be(55)
+        expect(described_class.medium_timeout).to be(30)
+        expect(described_class.fast_timeout).to be(10)
+      end
+    end
+  end
 end

spec/models/application_setting_spec.rb

@@ -219,6 +219,65 @@ describe ApplicationSetting do
         expect(subject).to be_valid
       end
     end
+
+    context 'gitaly timeouts' do
+      [:gitaly_timeout_default, :gitaly_timeout_medium, :gitaly_timeout_fast].each do |timeout_name|
+        it do
+          is_expected.to validate_presence_of(timeout_name)
+          is_expected.to validate_numericality_of(timeout_name).only_integer
+            .is_greater_than_or_equal_to(0)
+        end
+      end
+
+      [:gitaly_timeout_medium, :gitaly_timeout_fast].each do |timeout_name|
+        it "validates that #{timeout_name} is lower than timeout_default" do
+          subject[:gitaly_timeout_default] = 50
+          subject[timeout_name] = 100
+
+          expect(subject).to be_invalid
+        end
+      end
+
+      it 'accepts all timeouts equal' do
+        subject.gitaly_timeout_default = 0
+        subject.gitaly_timeout_medium = 0
+        subject.gitaly_timeout_fast = 0
+
+        expect(subject).to be_valid
+      end
+
+      it 'accepts timeouts in descending order' do
+        subject.gitaly_timeout_default = 50
+        subject.gitaly_timeout_medium = 30
+        subject.gitaly_timeout_fast = 20
+
+        expect(subject).to be_valid
+      end
+
+      it 'rejects timeouts in ascending order' do
+        subject.gitaly_timeout_default = 20
+        subject.gitaly_timeout_medium = 30
+        subject.gitaly_timeout_fast = 50
+
+        expect(subject).to be_invalid
+      end
+
+      it 'rejects medium timeout larger than default' do
+        subject.gitaly_timeout_default = 30
+        subject.gitaly_timeout_medium = 50
+        subject.gitaly_timeout_fast = 20
+
+        expect(subject).to be_invalid
+      end
+
+      it 'rejects medium timeout smaller than fast' do
+        subject.gitaly_timeout_default = 30
+        subject.gitaly_timeout_medium = 15
+        subject.gitaly_timeout_fast = 20
+
+        expect(subject).to be_invalid
+      end
+    end
   end
 
   describe '.current' do