WIP - introduce Rails::LogSubscriber

Author: solnic

sentry-rails/lib/sentry/rails.rb

@@ -5,6 +5,7 @@
 require "sentry/integrable"
 require "sentry/rails/tracing"
 require "sentry/rails/configuration"
+require "sentry/rails/log_subscriber"
 require "sentry/rails/engine"
 require "sentry/rails/railtie"
 

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

@@ -0,0 +1,95 @@
+# frozen_string_literal: true
+
+require "active_support/log_subscriber"
+
+module Sentry
+  module Rails
+    # Base class for Sentry log subscribers that extends ActiveSupport::LogSubscriber
+    # to provide structured logging capabilities for Rails components.
+    #
+    # This class follows Rails' LogSubscriber pattern and provides common functionality
+    # for capturing Rails instrumentation events and logging them through Sentry's
+    # structured logging system.
+    #
+    # @example Creating a custom log subscriber
+    #   class MySubscriber < Sentry::Rails::LogSubscriber
+    #     attach_to :my_component
+    #
+    #     def my_event(event)
+    #       log_structured_event(
+    #         message: "My event occurred",
+    #         level: :info,
+    #         attributes: {
+    #           duration_ms: event.duration,
+    #           custom_data: event.payload[:custom_data]
+    #         }
+    #       )
+    #     end
+    #   end
+    class LogSubscriber < ActiveSupport::LogSubscriber
+      class << self
+        # Override attach_to to ensure our logger is set
+        def attach_to(namespace, subscriber = new, notifier = ActiveSupport::Notifications, inherit_all: false)
+          # Set the logger to nil to prevent Rails from logging to the standard logger
+          # We'll handle logging through Sentry's structured logger instead
+          @logger = nil
+          super
+        end
+
+        # Override detach_from to properly clean up subscriptions
+        def detach_from(namespace, notifier = ActiveSupport::Notifications)
+          super
+        end
+
+        # Override logger to return nil, preventing standard Rails logging
+        def logger
+          nil
+        end
+      end
+
+      protected
+
+      # Log a structured event using Sentry's structured logger
+      #
+      # @param message [String] The log message
+      # @param level [Symbol] The log level (:trace, :debug, :info, :warn, :error, :fatal)
+      # @param attributes [Hash] Additional structured attributes to include
+      def log_structured_event(message:, level: :info, attributes: {})
+        return unless Sentry.configuration.enable_logs
+
+        Sentry.logger.public_send(level, message, **attributes)
+      rescue => e
+        # Silently handle any errors in logging to avoid breaking the application
+        Sentry.configuration.sdk_logger.debug("Failed to log structured event: #{e.message}")
+      end
+
+      # Check if an event should be excluded from logging
+      #
+      # @param event [ActiveSupport::Notifications::Event] The event to check
+      # @return [Boolean] true if the event should be excluded
+      def excluded_event?(event)
+        # Skip Rails' internal events
+        return true if event.name.start_with?("!")
+
+        false
+      end
+
+      # Calculate duration in milliseconds from an event
+      #
+      # @param event [ActiveSupport::Notifications::Event] The event
+      # @return [Float] Duration in milliseconds
+      def duration_ms(event)
+        event.duration.round(2)
+      end
+
+      # Determine log level based on duration (for performance-sensitive events)
+      #
+      # @param duration_ms [Float] Duration in milliseconds
+      # @param slow_threshold [Float] Threshold in milliseconds to consider "slow"
+      # @return [Symbol] Log level (:info or :warn)
+      def level_for_duration(duration_ms, slow_threshold = 1000.0)
+        duration_ms > slow_threshold ? :warn : :info
+      end
+    end
+  end
+end

sentry-rails/spec/sentry/rails/log_subscriber_spec.rb

@@ -0,0 +1,141 @@
+# frozen_string_literal: true
+
+require "spec_helper"
+
+RSpec.describe Sentry::Rails::LogSubscriber do
+  let(:test_subscriber_class) do
+    Class.new(described_class) do
+      def test_event(event)
+        return if excluded_event?(event)
+
+        duration = duration_ms(event)
+
+        log_structured_event(
+          message: "Test event processed",
+          level: :info,
+          attributes: {
+            event_name: event.name,
+            duration_ms: duration,
+            payload_data: event.payload[:data]
+          }
+        )
+      end
+
+      def custom_event(event)
+        return if excluded_event?(event)
+
+        log_structured_event(
+          message: "Custom event: #{event.payload[:action]}",
+          level: :info,
+          attributes: {
+            action: event.payload[:action],
+            user_id: event.payload[:user_id],
+            metadata: event.payload[:metadata]
+          }
+        )
+      end
+    end
+  end
+
+  before do
+    make_basic_app do |config|
+      config.enable_logs = true
+    end
+  end
+
+  describe "integration with ActiveSupport::Notifications" do
+    let(:subscriber) { test_subscriber_class.new }
+
+    before do
+      test_subscriber_class.attach_to :test_component
+    end
+
+    after do
+      test_subscriber_class.detach_from :test_component
+    end
+
+    it "logs events when notifications are published" do
+      ActiveSupport::Notifications.instrument("test_event.test_component", data: "test_data") do
+        sleep(0.01)
+      end
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      expect(sentry_logs).not_to be_empty
+
+      log_event = sentry_logs.find { |log| log[:body] == "Test event processed" }
+      expect(log_event).not_to be_nil
+      expect(log_event[:level]).to eq("info")
+      expect(log_event[:attributes][:event_name]).to eq({ value: "test_event.test_component", type: "string" })
+      expect(log_event[:attributes][:duration_ms][:value]).to be > 0
+      expect(log_event[:attributes][:payload_data]).to eq({ value: "test_data", type: "string" })
+    end
+
+    it "logs custom events with different attributes" do
+      ActiveSupport::Notifications.instrument("custom_event.test_component",
+        action: "user_login",
+        user_id: 123,
+        metadata: { ip: "192.168.1.1" }
+      )
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      expect(sentry_logs).not_to be_empty
+
+      log_event = sentry_logs.find { |log| log[:body] == "Custom event: user_login" }
+      expect(log_event).not_to be_nil
+      expect(log_event[:level]).to eq("info")
+      expect(log_event[:attributes][:action]).to eq({ value: "user_login", type: "string" })
+      expect(log_event[:attributes][:user_id]).to eq({ value: 123, type: "integer" })
+      expect(log_event[:attributes][:metadata][:value]).to eq({ ip: "192.168.1.1" })
+    end
+
+    it "excludes events starting with !" do
+      ActiveSupport::Notifications.instrument("!excluded_event.test_component", data: "should_not_log")
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      excluded_logs = sentry_logs.select { |log| log[:body]&.include?("should_not_log") }
+      expect(excluded_logs).to be_empty
+    end
+  end
+
+  describe "attach_to behavior" do
+    it "sets logger to nil to prevent standard Rails logging" do
+      subscriber_class = Class.new(described_class)
+      subscriber_class.attach_to :test_component
+
+      expect(subscriber_class.logger).to be_nil
+    end
+  end
+
+  describe "when logging is disabled" do
+    before do
+      make_basic_app do |config|
+        config.enable_logs = false
+      end
+    end
+
+    let(:subscriber) { test_subscriber_class.new }
+
+    before do
+      test_subscriber_class.attach_to :test_component
+    end
+
+    after do
+      test_subscriber_class.detach_from :test_component
+    end
+
+    it "does not log events when logging is disabled" do
+      initial_log_count = sentry_logs.count
+
+      ActiveSupport::Notifications.instrument("test_event.test_component", data: "test_data")
+
+      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