Log SQL queries from timeouts to Rails logs

Right now we only send these to Sentry. This also adds the SQL query to
our JSON request logs so that we don't have to correlate with Sentry
when looking at Kibana.

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