Merge branch 'ajk-query-limiting-middleware-logs' into 'master'

Show log of SQL statements in QueryLimiting middleware error messages

See merge request gitlab-org/gitlab!55630

lib/gitlab/query_limiting/active_support_subscriber.rb

@@ -6,9 +6,10 @@ module Gitlab
       attach_to :active_record
 
       def sql(event)
-        unless event.payload.fetch(:cached, event.payload[:name] == 'CACHE')
-          Transaction.current&.increment
-        end
+        return if !Transaction.current || event.payload.fetch(:cached, event.payload[:name] == 'CACHE')
+
+        Transaction.current.increment
+        Transaction.current.executed_sql(event.payload[:sql])
       end
     end
   end

lib/gitlab/query_limiting/transaction.rb

@@ -15,6 +15,7 @@ module Gitlab
       # the sake of keeping things simple we hardcode this value here, it's not
       # supposed to be changed very often anyway.
       THRESHOLD = 100
+      LOG_THRESHOLD = THRESHOLD * 1.5
 
       # Error that is raised whenever exceeding the maximum number of queries.
       ThresholdExceededError = Class.new(StandardError)
@@ -45,6 +46,7 @@ module Gitlab
         @action = nil
         @count = 0
         @whitelisted = false
+        @sql_executed = []
       end
 
       # Sends a notification based on the number of executed SQL queries.
@@ -60,6 +62,10 @@ module Gitlab
         @count += 1 unless whitelisted
       end
 
+      def executed_sql(sql)
+        @sql_executed << sql if @count <= LOG_THRESHOLD
+      end
+
       def raise_error?
         Rails.env.test?
       end
@@ -71,8 +77,11 @@ module Gitlab
       def error_message
         header = 'Too many SQL queries were executed'
         header = "#{header} in #{action}" if action
+        msg = "a maximum of #{THRESHOLD} is allowed but #{count} SQL queries were executed"
+        log = @sql_executed.each_with_index.map { |sql, i| "#{i}: #{sql}" }.join("\n").presence
+        ellipsis = '...' if @count > LOG_THRESHOLD
 
-        "#{header}: a maximum of #{THRESHOLD} is allowed but #{count} SQL queries were executed"
+        ["#{header}: #{msg}", log, ellipsis].compact.join("\n")
       end
     end
   end

spec/lib/gitlab/query_limiting/active_support_subscriber_spec.rb

@@ -3,7 +3,7 @@
 require 'spec_helper'
 
 RSpec.describe Gitlab::QueryLimiting::ActiveSupportSubscriber do
-  let(:transaction) { instance_double(Gitlab::QueryLimiting::Transaction, increment: true) }
+  let(:transaction) { instance_double(Gitlab::QueryLimiting::Transaction, executed_sql: true, increment: true) }
 
   before do
     allow(Gitlab::QueryLimiting::Transaction)
@@ -18,6 +18,11 @@ RSpec.describe Gitlab::QueryLimiting::ActiveSupportSubscriber do
       expect(transaction)
         .to have_received(:increment)
         .once
+
+      expect(transaction)
+        .to have_received(:executed_sql)
+        .once
+        .with(String)
     end
 
     context 'when the query is actually a rails cache hit' do
@@ -30,6 +35,11 @@ RSpec.describe Gitlab::QueryLimiting::ActiveSupportSubscriber do
         expect(transaction)
           .to have_received(:increment)
           .once
+
+        expect(transaction)
+          .to have_received(:executed_sql)
+          .once
+          .with(String)
       end
     end
   end

spec/lib/gitlab/query_limiting/transaction_spec.rb

@@ -118,6 +118,30 @@ RSpec.describe Gitlab::QueryLimiting::Transaction do
       )
     end
 
+    it 'includes a list of executed queries' do
+      transaction = described_class.new
+      transaction.count = max = described_class::THRESHOLD
+      %w[foo bar baz].each { |sql| transaction.executed_sql(sql) }
+
+      message = transaction.error_message
+
+      expect(message).to start_with(
+        "Too many SQL queries were executed: a maximum of #{max} " \
+        "is allowed but #{max} SQL queries were executed"
+      )
+
+      expect(message).to include("0: foo", "1: bar", "2: baz")
+    end
+
+    it 'indicates if the log is truncated' do
+      transaction = described_class.new
+      transaction.count = described_class::THRESHOLD * 2
+
+      message = transaction.error_message
+
+      expect(message).to end_with('...')
+    end
+
     it 'includes the action name in the error message when present' do
       transaction = described_class.new
       transaction.count = max = described_class::THRESHOLD