Merge branch 'log-sql-to-kibana' into 'master'

Log SQL queries from timeouts to Rails logs

See merge request gitlab-org/gitlab!76752

lib/gitlab/error_tracking.rb

@@ -140,19 +140,9 @@ module Gitlab
       end
 
       def inject_context_for_exception(event, ex)
-        case ex
-        when ActiveRecord::StatementInvalid
-          # StatementInvalid may be caused by a statement timeout or a bad query
-          event.extra[:sql] = normalize_query(ex.sql.to_s)
-        else
-          inject_context_for_exception(event, ex.cause) if ex.cause.present?
-        end
-      end
+        sql = Gitlab::ExceptionLogFormatter.find_sql(ex)
 
-      def normalize_query(sql)
-        PgQuery.normalize(sql)
-      rescue PgQuery::ParseError
-        sql
+        event.extra[:sql] = sql if sql
       end
     end
   end

lib/gitlab/exception_log_formatter.rb

@@ -2,18 +2,41 @@
 
 module Gitlab
   module ExceptionLogFormatter
-    def self.format!(exception, payload)
-      return unless exception
+    class << self
+      def format!(exception, payload)
+        return unless exception
 
-      # Elasticsearch/Fluentd don't handle nested structures well.
-      # Use periods to flatten the fields.
-      payload.merge!(
-        'exception.class' => exception.class.name,
-        'exception.message' => exception.message
-      )
+        # Elasticsearch/Fluentd don't handle nested structures well.
+        # Use periods to flatten the fields.
+        payload.merge!(
+          'exception.class' => exception.class.name,
+          'exception.message' => exception.message
+        )
 
-      if exception.backtrace
-        payload['exception.backtrace'] = Rails.backtrace_cleaner.clean(exception.backtrace)
+        if exception.backtrace
+          payload['exception.backtrace'] = Rails.backtrace_cleaner.clean(exception.backtrace)
+        end
+
+        if sql = find_sql(exception)
+          payload['exception.sql'] = sql
+        end
+      end
+
+      def find_sql(exception)
+        if exception.is_a?(ActiveRecord::StatementInvalid)
+          # StatementInvalid may be caused by a statement timeout or a bad query
+          normalize_query(exception.sql.to_s)
+        elsif exception.cause.present?
+          find_sql(exception.cause)
+        end
+      end
+
+      private
+
+      def normalize_query(sql)
+        PgQuery.normalize(sql)
+      rescue PgQuery::ParseError
+        sql
       end
     end
   end

spec/initializers/lograge_spec.rb

@@ -157,6 +157,16 @@ RSpec.describe 'lograge', type: :request do
         expect(log_data['exception.message']).to eq('bad request')
         expect(log_data['exception.backtrace']).to eq(Gitlab::BacktraceCleaner.clean_backtrace(backtrace))
       end
+
+      context 'with an ActiveRecord::StatementInvalid' do
+        let(:exception) { ActiveRecord::StatementInvalid.new(sql: 'SELECT "users".* FROM "users" WHERE "users"."id" = 1 AND "users"."foo" = $1') }
+
+        it 'adds the SQL query to the log' do
+          subscriber.process_action(event)
+
+          expect(log_data['exception.sql']).to eq('SELECT "users".* FROM "users" WHERE "users"."id" = $2 AND "users"."foo" = $1')
+        end
+      end
     end
 
     describe 'with etag_route' do

spec/lib/gitlab/error_tracking_spec.rb

@@ -205,26 +205,6 @@ RSpec.describe Gitlab::ErrorTracking do
         expect(sentry_event.dig('extra', 'sql')).to eq('SELECT "users".* FROM "users" WHERE "users"."id" = $2 AND "users"."foo" = $1')
       end
     end
-
-    context 'when the `ActiveRecord::StatementInvalid` is wrapped in another exception' do
-      it 'injects the normalized sql query into extra' do
-        allow(exception).to receive(:cause).and_return(ActiveRecord::StatementInvalid.new(sql: 'SELECT "users".* FROM "users" WHERE "users"."id" = 1 AND "users"."foo" = $1'))
-
-        track_exception
-
-        expect(sentry_event.dig('extra', 'sql')).to eq('SELECT "users".* FROM "users" WHERE "users"."id" = $2 AND "users"."foo" = $1')
-      end
-    end
-
-    context 'when the `ActiveRecord::StatementInvalid` is a bad query' do
-      it 'injects the query as-is into extra' do
-        allow(exception).to receive(:cause).and_return(ActiveRecord::StatementInvalid.new(sql: 'SELECT SELECT FROM SELECT'))
-
-        track_exception
-
-        expect(sentry_event.dig('extra', 'sql')).to eq('SELECT SELECT FROM SELECT')
-      end
-    end
   end
 
   context 'event processors' do

spec/lib/gitlab/exception_log_formatter_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+RSpec.describe Gitlab::ExceptionLogFormatter do
+  describe '.format!' do
+    let(:exception) { RuntimeError.new('bad request') }
+    let(:backtrace) { caller }
+
+    let(:payload) { {} }
+
+    before do
+      allow(exception).to receive(:backtrace).and_return(backtrace)
+    end
+
+    it 'adds exception data to log' do
+      described_class.format!(exception, payload)
+
+      expect(payload['exception.class']).to eq('RuntimeError')
+      expect(payload['exception.message']).to eq('bad request')
+      expect(payload['exception.backtrace']).to eq(Gitlab::BacktraceCleaner.clean_backtrace(backtrace))
+      expect(payload['exception.sql']).to be_nil
+    end
+
+    context 'when exception is ActiveRecord::StatementInvalid' do
+      let(:exception) { ActiveRecord::StatementInvalid.new(sql: 'SELECT "users".* FROM "users" WHERE "users"."id" = 1 AND "users"."foo" = $1') }
+
+      it 'adds the normalized SQL query to payload' do
+        described_class.format!(exception, payload)
+
+        expect(payload['exception.sql']).to eq('SELECT "users".* FROM "users" WHERE "users"."id" = $2 AND "users"."foo" = $1')
+      end
+    end
+
+    context 'when the ActiveRecord::StatementInvalid is wrapped in another exception' do
+      before do
+        allow(exception).to receive(:cause).and_return(ActiveRecord::StatementInvalid.new(sql: 'SELECT "users".* FROM "users" WHERE "users"."id" = 1 AND "users"."foo" = $1'))
+      end
+
+      it 'adds the normalized SQL query to payload' do
+        described_class.format!(exception, payload)
+
+        expect(payload['exception.sql']).to eq('SELECT "users".* FROM "users" WHERE "users"."id" = $2 AND "users"."foo" = $1')
+      end
+    end
+
+    context 'when the ActiveRecord::StatementInvalid is a bad query' do
+      let(:exception) { ActiveRecord::StatementInvalid.new(sql: 'SELECT SELECT FROM SELECT') }
+
+      it 'adds the query as-is to payload' do
+        described_class.format!(exception, payload)
+
+        expect(payload['exception.sql']).to eq('SELECT SELECT FROM SELECT')
+      end
+    end
+  end
+end