Add deadlines based on the request to gitaly

This makes sure that the deadline we set on a gitaly call never
exceeds the request deadline.

We also raise an exception if the request deadline has already been
exceeded by the time we're trying to make a Gitaly call.

These deadlines don't apply when calling gitaly from Sidekiq.

We do this by storing the start time of the request in the request
store on the thread (using the RequestStore).

The maximum request duration defaults to 55 seconds, as the default
worker timeout is 60 seconds. But can be configured through
gitlab.yml.

app/controllers/concerns/requires_whitelisted_monitoring_client.rb

@@ -18,7 +18,7 @@ module RequiresWhitelistedMonitoringClient
     # debugging purposes
     return true if Rails.env.development? && request.local?
 
-    ip_whitelist.any? { |e| e.include?(Gitlab::RequestContext.client_ip) }
+    ip_whitelist.any? { |e| e.include?(Gitlab::RequestContext.instance.client_ip) }
   end
 
   def ip_whitelist

app/models/application_setting.rb

@@ -169,7 +169,11 @@ class ApplicationSetting < ApplicationRecord
 
   validates :gitaly_timeout_default,
             presence: true,
-            numericality: { only_integer: true, greater_than_or_equal_to: 0 }
+            numericality: {
+              only_integer: true,
+              greater_than_or_equal_to: 0,
+              less_than_or_equal_to: Settings.gitlab.max_request_duration_seconds
+            }
 
   validates :gitaly_timeout_medium,
             presence: true,

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

@@ -8,6 +8,9 @@
       .form-text.text-muted
         Timeout for Gitaly calls from the GitLab application (in seconds). This timeout is not enforced
         for git fetch/push operations or Sidekiq jobs.
+        This timeout should be less than the worker timeout. If a Gitaly call timeout would exceed the
+        worker timeout, the remaining time from the worker timeout would be used to avoid having to terminate
+        the worker.
     .form-group
       = f.label :gitaly_timeout_fast, 'Fast Timeout Period', class: 'label-bold'
       = f.number_field :gitaly_timeout_fast, class: 'form-control'

changelogs/unreleased/bvl-gitaly-dynamic-deadline.yml

+---
+title: Don't let Gitaly calls exceed a request time of 55 seconds
+merge_request: 21492
+author:
+type: performance

config/gitlab.yml.example

@@ -33,6 +33,9 @@ production: &base
     host: localhost
     port: 80 # Set to 443 if using HTTPS, see installation.md#using-https for additional HTTPS configuration details
     https: false # Set to true if using HTTPS, see installation.md#using-https for additional HTTPS configuration details
+    # The maximum time unicorn/puma can spend on the request. This needs to be smaller than the worker timeout.
+    # Default is 95% of the worker timeout
+    max_request_duration: 57
 
     # Uncomment this line below if your ssh host is different from HTTP/HTTPS one
     # (you'd obviously need to replace ssh.host_example.com with your own host).

config/initializers/1_settings.rb

@@ -209,6 +209,7 @@ Settings.gitlab['content_security_policy'] ||= Gitlab::ContentSecurityPolicy::Co
 Settings.gitlab['no_todos_messages'] ||= YAML.load_file(Rails.root.join('config', 'no_todos_messages.yml'))
 Settings.gitlab['impersonation_enabled'] ||= true if Settings.gitlab['impersonation_enabled'].nil?
 Settings.gitlab['usage_ping_enabled'] = true if Settings.gitlab['usage_ping_enabled'].nil?
+Settings.gitlab['max_request_duration_seconds'] ||= 57
 
 Gitlab.ee do
   Settings.gitlab['mirror_max_delay'] ||= 300

config/initializers/lograge.rb

@@ -37,7 +37,7 @@ unless Gitlab::Runtime.sidekiq?
       payload[:response] = event.payload[:response] if event.payload[:response]
       payload[Labkit::Correlation::CorrelationId::LOG_KEY] = Labkit::Correlation::CorrelationId.current_id
 
-      if cpu_s = Gitlab::Metrics::System.thread_cpu_duration(::Gitlab::RequestContext.start_thread_cpu_time)
+      if cpu_s = Gitlab::Metrics::System.thread_cpu_duration(::Gitlab::RequestContext.instance.start_thread_cpu_time)
         payload[:cpu_s] = cpu_s
       end
 

config/initializers/request_context.rb

 Rails.application.configure do |config|
-  config.middleware.insert_after RequestStore::Middleware, Gitlab::RequestContext
+  config.middleware.insert_after RequestStore::Middleware, Gitlab::Middleware::RequestContext
 end

lib/gitlab/auth/unique_ips_limiter.rb

@@ -8,7 +8,7 @@ module Gitlab
       class << self
         def limit_user_id!(user_id)
           if config.unique_ips_limit_enabled
-            ip = RequestContext.client_ip
+            ip = RequestContext.instance.client_ip
             unique_ips = update_and_return_ips_count(user_id, ip)
 
             raise TooManyIps.new(user_id, ip, unique_ips) if unique_ips > config.unique_ips_limit_per_user

lib/gitlab/gitaly_client.rb

@@ -160,6 +160,7 @@ module Gitlab
 
     def self.execute(storage, service, rpc, request, remote_storage:, timeout:)
       enforce_gitaly_request_limits(:call)
+      Gitlab::RequestContext.instance.ensure_deadline_not_exceeded!
 
       kwargs = request_kwargs(storage, timeout: timeout.to_f, remote_storage: remote_storage)
       kwargs = yield(kwargs) if block_given?
@@ -234,12 +235,28 @@ module Gitlab
       metadata['gitaly-session-id'] = session_id
       metadata.merge!(Feature::Gitaly.server_feature_flags)
 
-      result = { metadata: metadata }
+      deadline_info = request_deadline(timeout)
+      metadata.merge!(deadline_info.slice(:deadline_type))
 
-      result[:deadline] = real_time + timeout if timeout > 0
-      result
+      { metadata: metadata, deadline: deadline_info[:deadline] }
     end
 
+    def self.request_deadline(timeout)
+      # timeout being 0 means the request is allowed to run indefinitely.
+      # We can't allow that inside a request, but this won't count towards Gitaly
+      # error budgets
+      regular_deadline = real_time.to_i + timeout if timeout > 0
+
+      return { deadline: regular_deadline } if Sidekiq.server?
+      return { deadline: regular_deadline } unless Gitlab::RequestContext.instance.request_deadline
+
+      limited_deadline = [regular_deadline, Gitlab::RequestContext.instance.request_deadline].compact.min
+      limited = limited_deadline < regular_deadline
+
+      { deadline: limited_deadline, deadline_type: limited ? "limited" : "regular" }
+    end
+    private_class_method :request_deadline
+
     def self.session_id
       Gitlab::SafeRequestStore[:gitaly_session_id] ||= SecureRandom.uuid
     end

lib/gitlab/middleware/request_context.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module Middleware
+    class RequestContext
+      def initialize(app)
+        @app = app
+      end
+
+      def call(env)
+        # We should be using ActionDispatch::Request instead of
+        # Rack::Request to be consistent with Rails, but due to a Rails
+        # bug described in
+        # https://gitlab.com/gitlab-org/gitlab-foss/issues/58573#note_149799010
+        # hosts behind a load balancer will only see 127.0.0.1 for the
+        # load balancer's IP.
+        req = Rack::Request.new(env)
+
+        Gitlab::RequestContext.instance.client_ip = req.ip
+        Gitlab::RequestContext.instance.start_thread_cpu_time = Gitlab::Metrics::System.thread_cpu_time
+        Gitlab::RequestContext.instance.request_start_time = Gitlab::Metrics::System.real_time
+
+        @app.call(env)
+      end
+    end
+  end
+end

lib/gitlab/request_context.rb

@@ -2,34 +2,37 @@
 
 module Gitlab
   class RequestContext
-    class << self
-      def client_ip
-        Gitlab::SafeRequestStore[:client_ip]
-      end
+    include Singleton
+
+    RequestDeadlineExceeded = Class.new(StandardError)
+
+    attr_accessor :client_ip, :start_thread_cpu_time, :request_start_time
 
-      def start_thread_cpu_time
-        Gitlab::SafeRequestStore[:start_thread_cpu_time]
+    class << self
+      def instance
+        Gitlab::SafeRequestStore[:request_context] ||= new
       end
     end
 
-    def initialize(app)
-      @app = app
+    def request_deadline
+      return unless request_start_time
+      return unless Feature.enabled?(:request_deadline)
+
+      @request_deadline ||= request_start_time + max_request_duration_seconds
     end
 
-    def call(env)
-      # We should be using ActionDispatch::Request instead of
-      # Rack::Request to be consistent with Rails, but due to a Rails
-      # bug described in
-      # https://gitlab.com/gitlab-org/gitlab-foss/issues/58573#note_149799010
-      # hosts behind a load balancer will only see 127.0.0.1 for the
-      # load balancer's IP.
-      req = Rack::Request.new(env)
+    def ensure_deadline_not_exceeded!
+      return unless request_deadline
+      return if Gitlab::Metrics::System.real_time < request_deadline
 
-      Gitlab::SafeRequestStore[:client_ip] = req.ip
+      raise RequestDeadlineExceeded,
+            "Request takes longer than #{max_request_duration_seconds}"
+    end
 
-      Gitlab::SafeRequestStore[:start_thread_cpu_time] = Gitlab::Metrics::System.thread_cpu_time
+    private
 
-      @app.call(env)
+    def max_request_duration_seconds
+      Settings.gitlab.max_request_duration_seconds
     end
   end
 end

spec/controllers/health_check_controller_spec.rb

@@ -2,7 +2,7 @@
 
 require 'spec_helper'
 
-describe HealthCheckController do
+describe HealthCheckController, :request_store do
   include StubENV
 
   let(:xml_response) { Hash.from_xml(response.body)['hash'] }
@@ -18,7 +18,7 @@ describe HealthCheckController do
   describe 'GET #index' do
     context 'when services are up but accessed from outside whitelisted ips' do
       before do
-        allow(Gitlab::RequestContext).to receive(:client_ip).and_return(not_whitelisted_ip)
+        allow(Gitlab::RequestContext.instance).to receive(:client_ip).and_return(not_whitelisted_ip)
       end
 
       it 'returns a not found page' do
@@ -48,7 +48,7 @@ describe HealthCheckController do
 
     context 'when services are up and accessed from whitelisted ips' do
       before do
-        allow(Gitlab::RequestContext).to receive(:client_ip).and_return(whitelisted_ip)
+        allow(Gitlab::RequestContext.instance).to receive(:client_ip).and_return(whitelisted_ip)
       end
 
       it 'supports successful plaintext response' do
@@ -95,7 +95,7 @@ describe HealthCheckController do
       before do
         allow(HealthCheck::Utils).to receive(:process_checks).with(['standard']).and_return('The server is on fire')
         allow(HealthCheck::Utils).to receive(:process_checks).with(['email']).and_return('Email is on fire')
-        allow(Gitlab::RequestContext).to receive(:client_ip).and_return(whitelisted_ip)
+        allow(Gitlab::RequestContext.instance).to receive(:client_ip).and_return(whitelisted_ip)
       end
 
       it 'supports failure plaintext response' do

spec/controllers/metrics_controller_spec.rb

@@ -2,7 +2,7 @@
 
 require 'spec_helper'
 
-describe MetricsController do
+describe MetricsController, :request_store do
   include StubENV
 
   let(:metrics_multiproc_dir) { @metrics_multiproc_dir }
@@ -53,7 +53,7 @@ describe MetricsController do
 
     context 'accessed from whitelisted ip' do
       before do
-        allow(Gitlab::RequestContext).to receive(:client_ip).and_return(whitelisted_ip)
+        allow(Gitlab::RequestContext.instance).to receive(:client_ip).and_return(whitelisted_ip)
       end
 
       it_behaves_like 'endpoint providing metrics'
@@ -61,7 +61,7 @@ describe MetricsController do
 
     context 'accessed from ip in whitelisted range' do
       before do
-        allow(Gitlab::RequestContext).to receive(:client_ip).and_return(ip_in_whitelisted_range)
+        allow(Gitlab::RequestContext.instance).to receive(:client_ip).and_return(ip_in_whitelisted_range)
       end
 
       it_behaves_like 'endpoint providing metrics'
@@ -69,7 +69,7 @@ describe MetricsController do
 
     context 'accessed from not whitelisted ip' do
       before do
-        allow(Gitlab::RequestContext).to receive(:client_ip).and_return(not_whitelisted_ip)
+        allow(Gitlab::RequestContext.instance).to receive(:client_ip).and_return(not_whitelisted_ip)
       end
 
       it 'returns the expected error response' do

spec/lib/gitlab/gitaly_client_spec.rb

@@ -229,6 +229,59 @@ describe Gitlab::GitalyClient do
         end
       end
     end
+
+    context 'deadlines', :request_store do
+      let(:request_deadline) { real_time + 10.0 }
+
+      before do
+        allow(Gitlab::RequestContext.instance).to receive(:request_deadline).and_return(request_deadline)
+      end
+
+      it 'includes the deadline information' do
+        kword_args = described_class.request_kwargs('default', timeout: 2)
+
+        expect(kword_args[:deadline])
+          .to be_within(1).of(real_time + 2)
+        expect(kword_args[:metadata][:deadline_type]).to eq("regular")
+      end
+
+      it 'limits the deadline do the request deadline if that is closer', :aggregate_failures do
+        kword_args = described_class.request_kwargs('default', timeout: 15)
+
+        expect(kword_args[:deadline]).to eq(request_deadline)
+        expect(kword_args[:metadata][:deadline_type]).to eq("limited")
+      end
+
+      it 'does not limit calls in sidekiq' do
+        expect(Sidekiq).to receive(:server?).and_return(true)
+
+        kword_args = described_class.request_kwargs('default', timeout: 6.hours.to_i)
+
+        expect(kword_args[:deadline]).to be_within(1).of(real_time + 6.hours.to_i)
+        expect(kword_args[:metadata][:deadline_type]).to be_nil
+      end
+
+      it 'does not limit calls in sidekiq when allowed unlimited' do
+        expect(Sidekiq).to receive(:server?).and_return(true)
+
+        kword_args = described_class.request_kwargs('default', timeout: 0)
+
+        expect(kword_args[:deadline]).to be_nil
+        expect(kword_args[:metadata][:deadline_type]).to be_nil
+      end
+
+      it 'includes only the deadline specified by the timeout when there was no deadline' do
+        allow(Gitlab::RequestContext.instance).to receive(:request_deadline).and_return(nil)
+        kword_args = described_class.request_kwargs('default', timeout: 6.hours.to_i)
+
+        expect(kword_args[:deadline]).to be_within(1).of(Gitlab::Metrics::System.real_time + 6.hours.to_i)
+        expect(kword_args[:metadata][:deadline_type]).to be_nil
+      end
+
+      def real_time
+        Gitlab::Metrics::System.real_time
+      end
+    end
   end
 
   describe 'enforce_gitaly_request_limits?' do

spec/lib/gitlab/middleware/request_context_spec.rb

+# frozen_string_literal: true
+require 'fast_spec_helper'
+require 'rack'
+require 'request_store'
+require_relative '../../../support/helpers/next_instance_of'
+
+describe Gitlab::Middleware::RequestContext do
+  include NextInstanceOf
+
+  let(:app) { -> (env) {} }
+  let(:env) { {} }
+
+  around do |example|
+    RequestStore.begin!
+    example.run
+    RequestStore.end!
+    RequestStore.clear!
+  end
+
+  describe '#call' do
+    context 'setting the client ip' do
+      subject { Gitlab::RequestContext.instance.client_ip }
+
+      context 'with X-Forwarded-For headers' do
+        let(:load_balancer_ip) { '1.2.3.4' }
+        let(:headers) do
+          {
+            'HTTP_X_FORWARDED_FOR' => "#{load_balancer_ip}, 127.0.0.1",
+            'REMOTE_ADDR' => '127.0.0.1'
+          }
+        end
+
+        let(:env) { Rack::MockRequest.env_for("/").merge(headers) }
+
+        it 'returns the load balancer IP' do
+          endpoint = proc do
+            [200, {}, ["Hello"]]
+          end
+
+          described_class.new(endpoint).call(env)
+
+          expect(subject).to eq(load_balancer_ip)
+        end
+      end
+
+      context 'request' do
+        let(:ip) { '192.168.1.11' }
+
+        before do
+          allow_next_instance_of(Rack::Request) do |instance|
+            allow(instance).to receive(:ip).and_return(ip)
+          end
+          described_class.new(app).call(env)
+        end
+
+        it { is_expected.to eq(ip) }
+      end
+
+      context 'before RequestContext middleware run' do
+        it { is_expected.to be_nil }
+      end
+    end
+  end
+
+  context 'setting the thread cpu time' do
+    it 'sets the `start_thread_cpu_time`' do
+      expect { described_class.new(app).call(env) }
+        .to change { Gitlab::RequestContext.instance.start_thread_cpu_time }.from(nil).to(Float)
+    end
+  end
+
+  context 'setting the request start time' do
+    it 'sets the `request_start_time`' do
+      expect { described_class.new(app).call(env) }
+        .to change { Gitlab::RequestContext.instance.request_start_time }.from(nil).to(Float)
+    end
+  end
+end

spec/lib/gitlab/request_context_spec.rb

@@ -2,59 +2,44 @@
 
 require 'spec_helper'
 
-describe Gitlab::RequestContext do
-  describe '#client_ip' do
-    subject { described_class.client_ip }
+describe Gitlab::RequestContext, :request_store do
+  subject { described_class.instance }
 
-    let(:app) { -> (env) {} }
-    let(:env) { Hash.new }
+  it { is_expected.to have_attributes(client_ip: nil, start_thread_cpu_time: nil, request_start_time: nil) }
 
-    context 'with X-Forwarded-For headers', :request_store do
-      let(:load_balancer_ip) { '1.2.3.4' }
-      let(:headers) do
-        {
-          'HTTP_X_FORWARDED_FOR' => "#{load_balancer_ip}, 127.0.0.1",
-          'REMOTE_ADDR' => '127.0.0.1'
-        }
-      end
+  describe '#request_deadline' do
+    let(:request_start_time) { 1575982156.206008 }
 
-      let(:env) { Rack::MockRequest.env_for("/").merge(headers) }
+    it "sets the time to #{Settings.gitlab.max_request_duration_seconds} seconds in the future" do
+      allow(subject).to receive(:request_start_time).and_return(request_start_time)
 
-      it 'returns the load balancer IP' do
-        client_ip = nil
-
-        endpoint = proc do
-          client_ip = Gitlab::SafeRequestStore[:client_ip]
-          [200, {}, ["Hello"]]
-        end
+      expect(subject.request_deadline).to eq(1575982156.206008 + Settings.gitlab.max_request_duration_seconds)
+      expect(subject.request_deadline).to be_a(Float)
+    end
 
-        described_class.new(endpoint).call(env)
+    it 'returns nil if there is no start time' do
+      allow(subject).to receive(:request_start_time).and_return(nil)
 
-        expect(client_ip).to eq(load_balancer_ip)
-      end
+      expect(subject.request_deadline).to be_nil
     end
+  end
 
-    context 'when RequestStore::Middleware is used' do
-      around do |example|
-        RequestStore::Middleware.new(-> (env) { example.run }).call({})
-      end
+  describe '#ensure_request_deadline_not_exceeded!' do
+    it 'does not raise an error when there was no deadline' do
+      expect(subject).to receive(:request_deadline).and_return(nil)
+      expect { subject.ensure_deadline_not_exceeded! }.not_to raise_error
+    end
 
-      context 'request' do
-        let(:ip) { '192.168.1.11' }
+    it 'does not raise an error if the deadline is in the future' do
+      allow(subject).to receive(:request_deadline).and_return(Gitlab::Metrics::System.real_time + 10)
 
-        before do
-          allow_next_instance_of(Rack::Request) do |instance|
-            allow(instance).to receive(:ip).and_return(ip)
-          end
-          described_class.new(app).call(env)
-        end
+      expect { subject.ensure_deadline_not_exceeded! }.not_to raise_error
+    end
 
-        it { is_expected.to eq(ip) }
-      end
+    it 'raises an error when the deadline is in the past' do
+      allow(subject).to receive(:request_deadline).and_return(Gitlab::Metrics::System.real_time - 10)
 
-      context 'before RequestContext middleware run' do
-        it { is_expected.to be_nil }
-      end
+      expect { subject.ensure_deadline_not_exceeded! }.to raise_error(described_class::RequestDeadlineExceeded)
     end
   end
 end

spec/models/application_setting_spec.rb

@@ -319,6 +319,11 @@ describe ApplicationSetting do
     end
 
     context 'gitaly timeouts' do
+      it "validates that the default_timeout is lower than the max_request_duration" do
+        is_expected.to validate_numericality_of(:gitaly_timeout_default)
+          .is_less_than_or_equal_to(Settings.gitlab.max_request_duration_seconds)
+      end
+
       [:gitaly_timeout_default, :gitaly_timeout_medium, :gitaly_timeout_fast].each do |timeout_name|
         it do
           is_expected.to validate_presence_of(timeout_name)

spec/support/shared_examples/unique_ip_check_shared_examples.rb

@@ -2,6 +2,8 @@
 
 shared_context 'unique ips sign in limit' do
   include StubENV
+  let(:request_context) { Gitlab::RequestContext.instance }
+
   before do
     Gitlab::Redis::Cache.with(&:flushall)
     Gitlab::Redis::Queues.with(&:flushall)
@@ -15,10 +17,13 @@ shared_context 'unique ips sign in limit' do
       unique_ips_limit_enabled: true,
       unique_ips_limit_time_window: 10000
     )
+
+    # Make sure we're working with the same reqeust context everywhere
+    allow(Gitlab::RequestContext).to receive(:instance).and_return(request_context)
   end
 
   def change_ip(ip)
-    allow(Gitlab::RequestContext).to receive(:client_ip).and_return(ip)
+    allow(request_context).to receive(:client_ip).and_return(ip)
   end
 
   def request_from_ip(ip)