WIP - add LogSubscribers::ActiveRecordSubscriber

solnic · solnic · commit 814c9b48818e · 2025-08-21T11:11:42.000Z
diff --git a/sentry-rails/lib/sentry/rails/log_subscribers/active_record_subscriber.rb b/sentry-rails/lib/sentry/rails/log_subscribers/active_record_subscriber.rb
@@ -0,0 +1,149 @@
+# frozen_string_literal: true
+
+require "sentry/rails/log_subscriber"
+
+module Sentry
+  module Rails
+    module LogSubscribers
+      # LogSubscriber for ActiveRecord events that captures database queries
+      # and logs them using Sentry's structured logging system.
+      #
+      # This subscriber captures sql.active_record events and formats them
+      # with relevant database information including SQL queries, duration,
+      # database configuration, and caching information.
+      #
+      # @example Usage
+      #   # Automatically attached when structured logging is enabled for :active_record
+      #   Sentry.init do |config|
+      #     config.enable_logs = true
+      #     config.rails.structured_logging = true
+      #     config.rails.structured_logging.attach_to = [:active_record]
+      #   end
+      class ActiveRecordSubscriber < Sentry::Rails::LogSubscriber
+        EXCLUDED_EVENTS = ["SCHEMA", "TRANSACTION"].freeze
+
+        # Handle sql.active_record events
+        #
+        # @param event [ActiveSupport::Notifications::Event] The SQL event
+        def sql(event)
+          return if excluded_event?(event)
+
+          sql = event.payload[:sql]
+          statement_name = event.payload[:name]
+          # Rails 5.0.0 doesn't include :cached in the payload, it was added in Rails 5.1
+          cached = event.payload.fetch(:cached, false)
+          connection_id = event.payload[:connection_id]
+          duration = duration_ms(event)
+
+          db_config = extract_db_config(event.payload)
+
+          attributes = {
+            sql: sql,
+            duration_ms: duration,
+            cached: cached
+          }
+
+          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)
+
+          message = build_log_message(statement_name)
+
+          log_structured_event(
+            message: message,
+            level: :info,
+            attributes: attributes
+          )
+        end
+
+        protected
+
+        def excluded_event?(event)
+          return true if super
+          return true if EXCLUDED_EVENTS.include?(event.payload[:name])
+
+          false
+        end
+
+        private
+
+        def build_log_message(statement_name)
+          if statement_name && statement_name != "SQL"
+            "Database query: #{statement_name}"
+          else
+            "Database query"
+          end
+        end
+
+        def extract_db_config(payload)
+          connection = payload[:connection]
+
+          if payload[:connection_id] && !connection
+            connection = ActiveRecord::Base.connection_pool.connections.find do |conn|
+              conn.object_id == payload[:connection_id]
+            end
+          end
+
+          return unless connection
+
+          extract_db_config_from_connection(connection)
+        rescue => e
+          Sentry.configuration.sdk_logger.debug("Failed to extract db config: #{e.message}")
+          nil
+        end
+
+        def add_db_config_attributes(attributes, db_config)
+          return unless db_config
+
+          attributes[:db_system] = db_config[:adapter] if db_config[:adapter]
+
+          if db_config[:database]
+            db_name = db_config[:database]
+
+            if db_config[:adapter] == "sqlite3" && db_name.include?("/")
+              db_name = File.basename(db_name)
+            end
+
+            attributes[:db_name] = db_name
+          end
+
+          attributes[:server_address] = db_config[:host] if db_config[:host]
+          attributes[:server_port] = db_config[:port] if db_config[:port]
+          attributes[:server_socket_address] = db_config[:socket] if db_config[:socket]
+        end
+
+        if ::Rails.version.to_f >= 6.1
+          def extract_db_config_from_connection(connection)
+            if connection.pool.respond_to?(:db_config)
+              db_config = connection.pool.db_config
+              if db_config.respond_to?(:configuration_hash)
+                return db_config.configuration_hash
+              elsif db_config.respond_to?(:config)
+                return db_config.config
+              end
+            end
+
+            extract_db_config_fallback(connection)
+          end
+        else
+          # Rails 6.0 and earlier use spec API
+          def extract_db_config_from_connection(connection)
+            if connection.pool.respond_to?(:spec)
+              spec = connection.pool.spec
+              if spec.respond_to?(:config)
+                return spec.config
+              end
+            end
+
+            extract_db_config_fallback(connection)
+          end
+        end
+
+        def extract_db_config_fallback(connection)
+          connection.config if connection.respond_to?(:config)
+        end
+      end
+    end
+  end
+end
diff --git a/sentry-rails/spec/sentry/rails/log_subscribers/active_record_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/active_record_subscriber_spec.rb
@@ -0,0 +1,170 @@
+# frozen_string_literal: true
+
+require "spec_helper"
+require "sentry/rails/log_subscribers/active_record_subscriber"
+
+RSpec.describe Sentry::Rails::LogSubscribers::ActiveRecordSubscriber do
+  before do
+    make_basic_app do |config|
+      config.enable_logs = true
+      config.rails.structured_logging.enabled = true
+      config.rails.structured_logging.attach_to = [:active_record]
+    end
+  end
+
+  describe "integration with ActiveSupport::Notifications" do
+    it "logs SQL events when database queries are executed" do
+      sentry_transport.events.clear
+      sentry_transport.envelopes.clear
+
+      Post.create!
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      expect(sentry_logs).not_to be_empty
+
+      log_event = sentry_logs.find { |log| log[:body]&.include?("Database query") && log[:attributes][:sql][:value]&.include?("INSERT") }
+      expect(log_event).not_to be_nil
+      expect(log_event[:level]).to eq("info")
+      expect(log_event[:attributes][:sql][:value]).to include("INSERT INTO")
+      expect(log_event[:attributes][:duration_ms][:value]).to be > 0
+    end
+
+    it "logs SELECT queries with proper attributes" do
+      post = Post.create!
+
+      Sentry.get_current_client.log_event_buffer.flush
+      sentry_transport.events.clear
+      sentry_transport.envelopes.clear
+
+      Post.find(post.id)
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      log_event = sentry_logs.find { |log| log[:body]&.include?("Database query") }
+      expect(log_event).not_to be_nil
+      expect(log_event[:attributes][:sql][:value]).to include("SELECT")
+      expect(log_event[:attributes][:sql][:value]).to include("posts")
+    end
+
+    it "excludes SCHEMA events" do
+      sentry_transport.events.clear
+      sentry_transport.envelopes.clear
+
+      ActiveSupport::Notifications.instrument("sql.active_record",
+        sql: "CREATE TABLE temp_test_table (id INTEGER)",
+        name: "SCHEMA",
+        connection: ActiveRecord::Base.connection
+      )
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      schema_logs = sentry_logs.select { |log| log[:attributes]&.dig(:sql, :value)&.include?("CREATE TABLE") }
+      expect(schema_logs).to be_empty
+    end
+
+    it "excludes events starting with !" do
+      subscriber = described_class.new
+      event = double("event", name: "!connection.active_record", payload: {})
+      expect(subscriber.send(:excluded_event?, event)).to be true
+    end
+  end
+
+  describe "database configuration extraction" do
+    it "includes database configuration in log attributes" do
+      sentry_transport.events.clear
+      sentry_transport.envelopes.clear
+
+      Post.create!
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      log_event = sentry_logs.find do |log|
+        log[:body]&.include?("Database query") &&
+          log[:attributes]&.dig(:sql, :value)&.include?("INSERT")
+      end
+
+      expect(log_event).not_to be_nil
+
+      attributes = log_event[:attributes]
+      expect(attributes[:db_system][:value]).to eq("sqlite3")
+      expect(attributes[:db_name][:value]).to eq("db")
+    end
+  end
+
+  describe "statement name handling" do
+    it "includes statement name in log message when available" do
+      post = Post.create!
+      sentry_transport.events.clear
+      sentry_transport.envelopes.clear
+
+      Post.find(post.id)
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      log_event = sentry_logs.find do |log|
+        log[:body]&.include?("Database query") &&
+          log[:attributes]&.dig(:sql, :value)&.include?("SELECT") &&
+          log[:attributes]&.dig(:statement_name, :value)&.include?("Load")
+      end
+      expect(log_event).not_to be_nil
+      expect(log_event[:attributes][:statement_name][:value]).to include("Load")
+    end
+
+    it "handles queries without specific statement names" do
+      sentry_transport.events.clear
+      sentry_transport.envelopes.clear
+
+      ActiveRecord::Base.connection.execute("SELECT 1")
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      log_event = sentry_logs.find do |log|
+        log[:body] == "Database query" &&
+          log[:attributes]&.dig(:sql, :value) == "SELECT 1"
+      end
+      expect(log_event).not_to be_nil
+      expect(log_event[:attributes][:sql][:value]).to include("SELECT 1")
+    end
+  end
+
+  describe "caching information" do
+    it "includes cached flag when query is cached", skip: Rails.version.to_f < 5.1 ? "Rails 5.0.0 doesn't include cached flag in sql.active_record events" : false do
+      ActiveRecord::Base.cache do
+        post = Post.create!
+        sentry_transport.events.clear
+        sentry_transport.envelopes.clear
+
+        Post.find(post.id)
+        Post.find(post.id)
+
+        Sentry.get_current_client.log_event_buffer.flush
+
+        cached_log = sentry_logs.find { |log| log[:attributes]&.dig(:cached, :value) == true }
+        expect(cached_log).not_to be_nil
+      end
+    end
+  end
+
+  describe "when logging is disabled" do
+    before do
+      make_basic_app do |config|
+        config.enable_logs = false
+        config.rails.structured_logging.enabled = true
+        config.rails.structured_logging.attach_to = [:active_record]
+      end
+    end
+
+    it "does not log events when logging is disabled" do
+      initial_log_count = sentry_logs.count
+
+      Post.create!
+
+      if Sentry.get_current_client&.log_event_buffer
+        Sentry.get_current_client.log_event_buffer.flush
+      end
+
+      expect(sentry_logs.count).to eq(initial_log_count)
+    end
+  end
+end
