Merge branch 'feature/gb/external-requests-in-transactions-logger' into 'master'

Add external HTTP request within transactions tracking

See merge request gitlab-org/gitlab!81259

lib/gitlab/database/transaction/context.rb

@@ -6,8 +6,10 @@ module Gitlab
       class Context
         attr_reader :context
 
-        LOG_SAVEPOINTS_THRESHOLD = 1    # 1 `SAVEPOINT` created in a transaction
-        LOG_DURATION_S_THRESHOLD = 120  # transaction that is running for 2 minutes or longer
+        LOG_SAVEPOINTS_THRESHOLD = 1                # 1 `SAVEPOINT` created in a transaction
+        LOG_DURATION_S_THRESHOLD = 120              # transaction that is running for 2 minutes or longer
+        LOG_EXTERNAL_HTTP_COUNT_THRESHOLD = 50      # 50 external HTTP requests executed within transaction
+        LOG_EXTERNAL_HTTP_DURATION_S_THRESHOLD = 1  # 1 second spent in HTTP requests in total within transaction
         LOG_THROTTLE_DURATION = 1
 
         def initialize
@@ -43,6 +45,11 @@ module Gitlab
           (@context[:backtraces] ||= []).push(cleaned_backtrace)
         end
 
+        def initialize_external_http_tracking
+          @context[:external_http_count_start] = external_http_requests_count_total
+          @context[:external_http_duration_start] = external_http_requests_duration_total
+        end
+
         def duration
           return unless @context[:start_time].present?
 
@@ -57,10 +64,16 @@ module Gitlab
           duration.to_i >= LOG_DURATION_S_THRESHOLD
         end
 
+        def external_http_requests_threshold_exceeded?
+          external_http_requests_count >= LOG_EXTERNAL_HTTP_COUNT_THRESHOLD ||
+            external_http_requests_duration >= LOG_EXTERNAL_HTTP_DURATION_S_THRESHOLD
+        end
+
         def should_log?
           return false if logged_already?
 
-          savepoints_threshold_exceeded? || duration_threshold_exceeded?
+          savepoints_threshold_exceeded? || duration_threshold_exceeded? ||
+            external_http_requests_threshold_exceeded?
         end
 
         def commit
@@ -75,6 +88,14 @@ module Gitlab
           @context[:backtraces].to_a
         end
 
+        def external_http_requests_count
+          @requests_count ||= external_http_requests_count_total - @context[:external_http_count_start].to_i
+        end
+
+        def external_http_requests_duration
+          @requests_duration ||= external_http_requests_duration_total - @context[:external_http_duration_start].to_f
+        end
+
         private
 
         def queries
@@ -108,6 +129,8 @@ module Gitlab
             savepoints_count: @context[:savepoints].to_i,
             rollbacks_count: @context[:rollbacks].to_i,
             releases_count: @context[:releases].to_i,
+            external_http_requests_count: external_http_requests_count,
+            external_http_requests_duration: external_http_requests_duration,
             sql: queries,
             savepoint_backtraces: backtraces
           }
@@ -118,6 +141,14 @@ module Gitlab
         def application_info(attributes)
           Gitlab::AppJsonLogger.info(attributes)
         end
+
+        def external_http_requests_count_total
+          ::Gitlab::Metrics::Subscribers::ExternalHttp.request_count.to_i
+        end
+
+        def external_http_requests_duration_total
+          ::Gitlab::Metrics::Subscribers::ExternalHttp.duration.to_f
+        end
       end
     end
   end

lib/gitlab/database/transaction/observer.rb

@@ -21,6 +21,7 @@ module Gitlab
             context.set_start_time
             context.set_depth(0)
             context.track_sql(event.payload[:sql])
+            context.initialize_external_http_tracking
           elsif cmd.start_with?('SAVEPOINT', 'EXCEPTION')
             context.set_depth(manager.open_transactions)
             context.increment_savepoints

spec/lib/gitlab/database/transaction/context_spec.rb

@@ -135,4 +135,24 @@ RSpec.describe Gitlab::Database::Transaction::Context do
 
     it_behaves_like 'logs transaction data'
   end
+
+  context 'when there are too many external HTTP requests' do
+    before do
+      allow(::Gitlab::Metrics::Subscribers::ExternalHttp)
+        .to receive(:request_count)
+        .and_return(100)
+    end
+
+    it_behaves_like 'logs transaction data'
+  end
+
+  context 'when there are too many too long external HTTP requests' do
+    before do
+      allow(::Gitlab::Metrics::Subscribers::ExternalHttp)
+        .to receive(:duration)
+        .and_return(5.5)
+    end
+
+    it_behaves_like 'logs transaction data'
+  end
 end

spec/lib/gitlab/database/transaction/observer_spec.rb

@@ -25,7 +25,7 @@ RSpec.describe Gitlab::Database::Transaction::Observer do
           User.first
 
           expect(transaction_context).to be_a(::Gitlab::Database::Transaction::Context)
-          expect(context.keys).to match_array(%i(start_time depth savepoints queries backtraces))
+          expect(context.keys).to match_array(%i(start_time depth savepoints queries backtraces external_http_count_start external_http_duration_start))
           expect(context[:depth]).to eq(2)
           expect(context[:savepoints]).to eq(1)
           expect(context[:queries].length).to eq(1)
@@ -38,6 +38,71 @@ RSpec.describe Gitlab::Database::Transaction::Observer do
       expect(context[:backtraces].length).to eq(1)
     end
 
+    describe 'tracking external network requests', :request_store do
+      it 'tracks external requests' do
+        perform_stubbed_external_http_request(duration: 0.25)
+        perform_stubbed_external_http_request(duration: 1.25)
+
+        ActiveRecord::Base.transaction do
+          User.first
+
+          expect(context[:external_http_count_start]).to eq(2)
+          expect(context[:external_http_duration_start]).to eq(1.5)
+
+          perform_stubbed_external_http_request(duration: 1)
+          perform_stubbed_external_http_request(duration: 3)
+
+          expect(transaction_context.external_http_requests_count).to eq 2
+          expect(transaction_context.external_http_requests_duration).to eq 4
+        end
+      end
+
+      context 'when external HTTP requests duration has been exceeded' do
+        it 'logs transaction details including exceeding thresholds' do
+          expect(Gitlab::AppJsonLogger).to receive(:info).with(
+            hash_including(
+              external_http_requests_count: 2,
+              external_http_requests_duration: 12
+            )
+          )
+
+          ActiveRecord::Base.transaction do
+            User.first
+
+            perform_stubbed_external_http_request(duration: 2)
+            perform_stubbed_external_http_request(duration: 10)
+          end
+        end
+      end
+
+      context 'when external HTTP requests count has been exceeded' do
+        it 'logs transaction details including exceeding thresholds' do
+          expect(Gitlab::AppJsonLogger).to receive(:info).with(
+            hash_including(external_http_requests_count: 55)
+          )
+
+          ActiveRecord::Base.transaction do
+            User.first
+
+            55.times { perform_stubbed_external_http_request(duration: 0.01) }
+          end
+        end
+      end
+
+      def perform_stubbed_external_http_request(duration:)
+        ::Gitlab::Metrics::Subscribers::ExternalHttp.new.request(
+          instance_double(
+            'ActiveSupport::Notifications::Event',
+            payload: {
+              method: 'GET', code: '200', duration: duration,
+              scheme: 'http', host: 'example.gitlab.com', port: 80, path: '/'
+            },
+            time: Time.current
+          )
+        )
+      end
+    end
+
     describe '.extract_sql_command' do
       using RSpec::Parameterized::TableSyntax