WIP - add ActionControllerSubscriber

Author: solnic

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

@@ -0,0 +1,110 @@
+# frozen_string_literal: true
+
+require "sentry/rails/log_subscriber"
+
+module Sentry
+  module Rails
+    module LogSubscribers
+      # LogSubscriber for ActionController events that captures HTTP request processing
+      # and logs them using Sentry's structured logging system.
+      #
+      # This subscriber captures process_action.action_controller events and formats them
+      # with relevant request information including controller, action, HTTP status,
+      # request parameters, and performance metrics.
+      #
+      # @example Usage
+      #   # Enable structured logging for ActionController
+      #   Sentry.init do |config|
+      #     config.enable_logs = true
+      #     config.rails.structured_logging = true
+      #     config.rails.structured_logging.attach_to = [:action_controller]
+      #   end
+      class ActionControllerSubscriber < Sentry::Rails::LogSubscriber
+        # Handle process_action.action_controller events
+        #
+        # @param event [ActiveSupport::Notifications::Event] The controller action event
+        def process_action(event)
+          return if excluded_event?(event)
+
+          payload = event.payload
+          controller = payload[:controller]
+          action = payload[:action]
+          status = payload[:status]
+          duration = duration_ms(event)
+
+          # Prepare structured attributes
+          attributes = {
+            controller: controller,
+            action: action,
+            status: status,
+            duration_ms: duration,
+            method: payload[:method],
+            path: payload[:path],
+            format: payload[:format]
+          }
+
+          # Add view and database timing if available
+          attributes[:view_runtime_ms] = payload[:view_runtime]&.round(2) if payload[:view_runtime]
+          attributes[:db_runtime_ms] = payload[:db_runtime]&.round(2) if payload[:db_runtime]
+
+          # Add request parameters if configured to send PII
+          if Sentry.configuration.send_default_pii && payload[:params]
+            # Filter out sensitive parameters
+            filtered_params = filter_sensitive_params(payload[:params])
+            attributes[:params] = filtered_params unless filtered_params.empty?
+          end
+
+          # Determine log level based on status code and duration
+          level = level_for_request(status, duration)
+          message = "#{controller}##{action}"
+
+          # Log the structured event
+          log_structured_event(
+            message: message,
+            level: level,
+            attributes: attributes
+          )
+        end
+
+        private
+
+        # Determine log level based on HTTP status and duration
+        #
+        # @param status [Integer] HTTP status code
+        # @param duration_ms [Float] Request duration in milliseconds
+        # @return [Symbol] Log level
+        def level_for_request(status, duration_ms)
+          # Error status codes get warn/error level
+          return :error if status >= 500
+          return :warn if status >= 400
+
+          # Slow requests get warn level
+          return :warn if duration_ms > 5000 # 5 seconds
+
+          :info
+        end
+
+        # Filter sensitive parameters from request params
+        #
+        # @param params [Hash] Request parameters
+        # @return [Hash] Filtered parameters
+        def filter_sensitive_params(params)
+          return {} unless params.is_a?(Hash)
+
+          # Common sensitive parameter names to exclude
+          sensitive_keys = %w[
+            password password_confirmation
+            secret token api_key
+            credit_card ssn social_security_number
+            authorization auth
+          ]
+
+          params.reject do |key, _value|
+            key_str = key.to_s.downcase
+            sensitive_keys.any? { |sensitive| key_str.include?(sensitive) }
+          end
+        end
+      end
+    end
+  end
+end

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

@@ -0,0 +1,196 @@
+# frozen_string_literal: true
+
+require "spec_helper"
+require "sentry/rails/log_subscribers/action_controller_subscriber"
+
+RSpec.describe Sentry::Rails::LogSubscribers::ActionControllerSubscriber, type: :request do
+  before do
+    make_basic_app do |config|
+      config.enable_logs = true
+      config.rails.structured_logging.enabled = true
+      config.rails.structured_logging.attach_to = [:action_controller]
+    end
+  end
+
+  describe "integration with ActiveSupport::Notifications" do
+    it "logs controller action events when requests are processed" do
+      sentry_transport.events.clear
+      sentry_transport.envelopes.clear
+
+      get "/world"
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      expect(sentry_logs).not_to be_empty
+
+      log_event = sentry_logs.find { |log| log[:body] == "HelloController#world" }
+      expect(log_event).not_to be_nil
+      expect(log_event[:level]).to eq("info")
+      expect(log_event[:attributes][:controller][:value]).to eq("HelloController")
+      expect(log_event[:attributes][:action][:value]).to eq("world")
+      expect(log_event[:attributes][:status][:value]).to eq(200)
+      expect(log_event[:attributes][:duration_ms][:value]).to be > 0
+      expect(log_event[:attributes][:method][:value]).to eq("GET")
+      expect(log_event[:attributes][:path][:value]).to eq("/world")
+      expect(log_event[:attributes][:format][:value]).to eq(:html)
+    end
+
+    it "logs different status codes appropriately" do
+      sentry_transport.events.clear
+      sentry_transport.envelopes.clear
+
+      get "/not_found"
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      expect(sentry_logs).not_to be_empty
+
+      log_event = sentry_logs.find { |log| log[:body] == "HelloController#not_found" }
+      expect(log_event).not_to be_nil
+      expect(log_event[:level]).to eq("warn")
+      expect(log_event[:attributes][:status][:value]).to eq(400)
+    end
+
+    it "logs error status codes with error level" do
+      sentry_transport.events.clear
+      sentry_transport.envelopes.clear
+
+      get "/exception"
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      expect(sentry_logs).not_to be_empty
+
+      log_event = sentry_logs.find { |log| log[:body] == "HelloController#exception" }
+      expect(log_event).not_to be_nil
+      expect(log_event[:level]).to eq("error")
+      expect(log_event[:attributes][:status][:value]).to eq(500)
+    end
+
+    it "includes view runtime when available" do
+      sentry_transport.events.clear
+      sentry_transport.envelopes.clear
+
+      get "/view"
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      expect(sentry_logs).not_to be_empty
+
+      log_event = sentry_logs.find { |log| log[:body] == "HelloController#view" }
+      expect(log_event).not_to be_nil
+      expect(log_event[:attributes][:view_runtime_ms]).to be_present
+      expect(log_event[:attributes][:view_runtime_ms][:value]).to be >= 0
+    end
+
+    it "includes database runtime when available" do
+      sentry_transport.events.clear
+      sentry_transport.envelopes.clear
+
+      Post.create!
+      get "/posts"
+
+      Sentry.get_current_client.log_event_buffer.flush
+
+      expect(sentry_logs).not_to be_empty
+
+      log_event = sentry_logs.find { |log| log[:body] == "PostsController#index" }
+      expect(log_event).not_to be_nil
+      expect(log_event[:attributes][:db_runtime_ms]).to be_present
+      expect(log_event[:attributes][:db_runtime_ms][:value]).to be >= 0
+    end
+
+    context "when send_default_pii is enabled" do
+      before do
+        Sentry.configuration.send_default_pii = true
+      end
+
+      after do
+        Sentry.configuration.send_default_pii = false
+      end
+
+      it "includes filtered request parameters" do
+        sentry_transport.events.clear
+        sentry_transport.envelopes.clear
+
+        get "/world", params: { safe_param: "value", password: "secret" }
+
+        Sentry.get_current_client.log_event_buffer.flush
+
+        expect(sentry_logs).not_to be_empty
+
+        log_event = sentry_logs.find { |log| log[:body] == "HelloController#world" }
+        expect(log_event).not_to be_nil
+        expect(log_event[:attributes][:params]).to be_present
+        expect(log_event[:attributes][:params][:value]).to include("safe_param" => "value")
+        expect(log_event[:attributes][:params][:value]).not_to include("password")
+      end
+
+      it "filters sensitive parameter names" do
+        sentry_transport.events.clear
+        sentry_transport.envelopes.clear
+
+        get "/world", params: {
+          normal_param: "value",
+          password: "secret",
+          api_key: "key123",
+          credit_card: "1234567890",
+          authorization: "Bearer token"
+        }
+
+        Sentry.get_current_client.log_event_buffer.flush
+
+        expect(sentry_logs).not_to be_empty
+
+        log_event = sentry_logs.find { |log| log[:body] == "HelloController#world" }
+        expect(log_event).not_to be_nil
+
+        params = log_event[:attributes][:params][:value]
+        expect(params).to include("normal_param" => "value")
+        expect(params).not_to have_key("password")
+        expect(params).not_to have_key("api_key")
+        expect(params).not_to have_key("credit_card")
+        expect(params).not_to have_key("authorization")
+      end
+    end
+
+    context "when send_default_pii is disabled" do
+      it "does not include request parameters" do
+        sentry_transport.events.clear
+        sentry_transport.envelopes.clear
+
+        get "/world", params: { param: "value" }
+
+        Sentry.get_current_client.log_event_buffer.flush
+
+        expect(sentry_logs).not_to be_empty
+
+        log_event = sentry_logs.find { |log| log[:body] == "HelloController#world" }
+        expect(log_event).not_to be_nil
+        expect(log_event[:attributes]).not_to have_key(:params)
+      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 = [:action_controller]
+      end
+    end
+
+    it "does not log events when logging is disabled" do
+      initial_log_count = sentry_logs.count
+
+      get "/world"
+
+      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