WIP - add ActionControllerSubscriber

solnic · solnic · commit 0b6cb50d2e17 · 2025-08-21T11:11:42.000Z
diff --git a/sentry-rails/lib/sentry/rails/log_subscribers/action_controller_subscriber.rb b/sentry-rails/lib/sentry/rails/log_subscribers/action_controller_subscriber.rb
@@ -0,0 +1,129 @@
+# 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
+          duration = event.time.round(2)
+
+          controller = payload[:controller]
+          action = payload[:action]
+
+          status = extract_status(payload)
+
+          attributes = {
+            controller: controller,
+            action: action,
+            status: status,
+            duration_ms: duration,
+            method: payload[:method],
+            path: payload[:path],
+            format: payload[:format]
+          }
+
+          if payload[:view_runtime]
+            attributes[:view_runtime_ms] = payload[:view_runtime].round(2)
+          end
+
+          if payload[:db_runtime]
+            attributes[:db_runtime_ms] = payload[:db_runtime].round(2)
+          end
+
+          if Sentry.configuration.send_default_pii && payload[:params]
+            filtered_params = filter_sensitive_params(payload[:params])
+            attributes[:params] = filtered_params unless filtered_params.empty?
+          end
+
+          level = level_for_request(payload)
+          message = "#{controller}##{action}"
+
+          log_structured_event(
+            message: message,
+            level: level,
+            attributes: attributes
+          )
+        end
+
+        private
+
+        def extract_status(payload)
+          if payload[:status]
+            payload[:status]
+          elsif payload[:exception]
+            case payload[:exception].first
+            when "ActionController::RoutingError"
+              404
+            when "ActionController::BadRequest"
+              400
+            else
+              500
+            end
+          end
+        end
+
+        def level_for_request(payload)
+          status = payload[:status]
+
+          # In Rails < 6.0 status is not set when an action raised an exception
+          if status.nil? && payload[:exception]
+            case payload[:exception].first
+            when "ActionController::RoutingError"
+              :warn
+            when "ActionController::BadRequest"
+              :warn
+            else
+              :error
+            end
+          elsif status >= 200 && status < 400
+            :info
+          elsif status >= 400 && status < 500
+            :warn
+          elsif status >= 500
+            :error
+          else
+            :info
+          end
+        end
+
+        def filter_sensitive_params(params)
+          return {} unless params.is_a?(Hash)
+
+          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
diff --git a/sentry-rails/spec/sentry/rails/log_subscribers/action_controller_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/action_controller_subscriber_spec.rb
@@ -0,0 +1,204 @@
+# 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 bad requests appropriately" do
+      sentry_transport.events.clear
+      sentry_transport.envelopes.clear
+
+      # FIXME: in our setup this actually raises BadRequests which is confusing
+      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_sym).to be(: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
+
+      if Rails.version.to_f >= 6.0
+        expect(log_event[:attributes][:db_runtime_ms]).to be_present
+        expect(log_event[:attributes][:db_runtime_ms][:value]).to be >= 0
+      else
+        if log_event[:attributes][:db_runtime_ms]
+          expect(log_event[:attributes][:db_runtime_ms][:value]).to be >= 0
+        end
+      end
+    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
