fix(logging): improve error handling in AR subscriber (#2798)

* fix(logging): rescue from unexpected errors when getting binds

* fix(logging): don't crash if getting db connection info failed

* Update CHANGELOG

* Just rescue from any error

* Fix spec and remove redundant resques

Author: solnic

CHANGELOG.md

@@ -7,6 +7,7 @@
 ### Fixes
 
 - Prevent logging from crashing main thread ([2795](https://github.com/getsentry/sentry-ruby/pull/2795))
+- Improve error handling in ActiveRecord subscriber ([2798](https://github.com/getsentry/sentry-ruby/pull/2798))
 
 ## 6.1.2
 

sentry-rails/lib/sentry/rails/log_subscriber.rb

@@ -1,6 +1,7 @@
 # frozen_string_literal: true
 
 require "active_support/log_subscriber"
+require "sentry/utils/logging_helper"
 
 module Sentry
   module Rails
@@ -27,6 +28,8 @@ module Rails
     #     end
     #   end
     class LogSubscriber < ActiveSupport::LogSubscriber
+      include Sentry::LoggingHelper
+
       ORIGIN = "auto.log.rails.log_subscriber"
 
       class << self

sentry-rails/lib/sentry/rails/log_subscribers/active_record_subscriber.rb

@@ -24,6 +24,7 @@ class ActiveRecordSubscriber < Sentry::Rails::LogSubscriber
         include ParameterFilter
 
         EXCLUDED_NAMES = ["SCHEMA", "TRANSACTION"].freeze
+        EMPTY_ARRAY = [].freeze
 
         # Handle sql.active_record events
         #
@@ -40,8 +41,6 @@ def sql(event)
           cached = event.payload.fetch(:cached, false)
           connection_id = event.payload[:connection_id]
 
-          db_config = extract_db_config(event.payload)
-
           attributes = {
             sql: sql,
             duration_ms: duration_ms(event),
@@ -53,18 +52,18 @@ def sql(event)
           if Sentry.configuration.send_default_pii && (binds && !binds.empty?)
             type_casted_binds = type_casted_binds(event)
 
-            binds.each_with_index do |bind, index|
-              key = bind.respond_to?(:name) ? bind.name : index.to_s
-              value = type_casted_binds[index].to_s
+            type_casted_binds.each_with_index do |value, index|
+              bind = binds[index]
+              name = bind.respond_to?(:name) ? bind.name : index.to_s
 
-              attributes["db.query.parameter.#{key}"] = value
+              attributes["db.query.parameter.#{name}"] = value.to_s
             end
           end
 
           attributes[:statement_name] = statement_name if statement_name && statement_name != "SQL"
           attributes[:connection_id] = connection_id if connection_id
 
-          add_db_config_attributes(attributes, db_config)
+          maybe_add_db_config_attributes(attributes, event.payload)
 
           message = build_log_message(statement_name)
 
@@ -73,6 +72,8 @@ def sql(event)
             level: :info,
             attributes: attributes
           )
+        rescue => e
+          log_debug("[#{self.class}] failed to log sql event: #{e.message}")
         end
 
         def type_casted_binds(event)
@@ -97,15 +98,9 @@ def build_log_message(statement_name)
           end
         end
 
-        def extract_db_config(payload)
-          connection = payload[:connection]
-
-          return unless connection
-
-          extract_db_config_from_connection(connection)
-        end
+        def maybe_add_db_config_attributes(attributes, payload)
+          db_config = extract_db_config(payload)
 
-        def add_db_config_attributes(attributes, db_config)
           return unless db_config
 
           attributes[:db_system] = db_config[:adapter] if db_config[:adapter]
@@ -125,6 +120,14 @@ def add_db_config_attributes(attributes, db_config)
           attributes[:server_socket_address] = db_config[:socket] if db_config[:socket]
         end
 
+        def extract_db_config(payload)
+          connection = payload[:connection]
+
+          return unless connection
+
+          extract_db_config_from_connection(connection)
+        end
+
         if ::Rails.version.to_f >= 6.1
           def extract_db_config_from_connection(connection)
             if connection.pool.respond_to?(:db_config)

sentry-rails/spec/sentry/rails/log_subscribers/active_record_subscriber_spec.rb

@@ -178,6 +178,42 @@
             type: "string", value: "test"
           )
         end
+
+        it "does not choke on type_casted_binds errors" do
+          ActiveSupport::Notifications.instrument("sql.active_record",
+            sql: "SELECT error",
+            name: "SQL",
+            connection: ActiveRecord::Base.connection,
+            binds: ["foo"],
+            type_casted_binds: -> { raise StandardError.new("boom") }
+          )
+
+          Sentry.get_current_client.flush
+
+          log_event = sentry_logs.find { |log| log[:attributes].dig(:sql, :value) == "SELECT error" }
+
+          expect(log_event).to be_nil
+        end
+
+        it "does not choke on retrieving connection info" do
+          connection = double(ActiveRecord::Base.connection.class)
+
+          expect(connection).to receive(:pool).and_raise(StandardError.new("boom"))
+
+          ActiveSupport::Notifications.instrument("sql.active_record",
+            sql: "SELECT error",
+            name: "SQL",
+            connection: connection,
+            binds: [:foo],
+            type_casted_binds: -> { ["foo"] }
+          )
+
+          Sentry.get_current_client.flush
+
+          log_event = sentry_logs.find { |log| log[:attributes].dig(:sql, :value) == "SELECT error" }
+
+          expect(log_event).to be_nil
+        end
       end
 
       context "when send_default_pii is disabled" do