From e70ac03eb9b2034f9ba99b4237a9612313da0f8c Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 26 Aug 2025 07:36:47 +0000 Subject: [PATCH 01/21] Better warning in Sentry.logger --- sentry-ruby/lib/sentry-ruby.rb | 2 ++ 1 file changed, 2 insertions(+) diff --git a/sentry-ruby/lib/sentry-ruby.rb b/sentry-ruby/lib/sentry-ruby.rb index 986e6d1a8..231ca9765 100644 --- a/sentry-ruby/lib/sentry-ruby.rb +++ b/sentry-ruby/lib/sentry-ruby.rb @@ -646,6 +646,8 @@ def logger warn <<~STR [sentry] `Sentry.logger` will no longer be used as internal SDK logger when `enable_logs` feature is turned on. Use Sentry.configuration.sdk_logger for SDK-specific logging needs." + + Caller: #{caller.first} STR configuration.sdk_logger From 497171a4ffa408a82c6122dcd395a08f07c3d335 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Mon, 11 Aug 2025 14:14:38 +0000 Subject: [PATCH 02/21] Add DebugStructuredLogger --- sentry-rails/spec/spec_helper.rb | 2 + sentry-ruby/lib/sentry-ruby.rb | 6 +- sentry-ruby/lib/sentry/configuration.rb | 20 +++ .../lib/sentry/debug_structured_logger.rb | 94 ++++++++++++ sentry-ruby/lib/sentry/test_helper.rb | 15 +- .../sentry/debug_structured_logger_spec.rb | 136 ++++++++++++++++++ spec/support/test_helper.rb | 8 ++ 7 files changed, 275 insertions(+), 6 deletions(-) create mode 100644 sentry-ruby/lib/sentry/debug_structured_logger.rb create mode 100644 sentry-ruby/spec/sentry/debug_structured_logger_spec.rb diff --git a/sentry-rails/spec/spec_helper.rb b/sentry-rails/spec/spec_helper.rb index e3accdf98..4f1b8f5c0 100644 --- a/sentry-rails/spec/spec_helper.rb +++ b/sentry-rails/spec/spec_helper.rb @@ -54,6 +54,8 @@ expect(Sentry::Rails::Tracing.subscribed_tracing_events).to be_empty Sentry::Rails::Tracing.remove_active_support_notifications_patch + Sentry::TestHelper.clear_sentry_events + if defined?(Sentry::Rails::ActiveJobExtensions) Sentry::Rails::ActiveJobExtensions::SentryReporter.detach_event_handlers end diff --git a/sentry-ruby/lib/sentry-ruby.rb b/sentry-ruby/lib/sentry-ruby.rb index 231ca9765..728675b98 100644 --- a/sentry-ruby/lib/sentry-ruby.rb +++ b/sentry-ruby/lib/sentry-ruby.rb @@ -13,6 +13,7 @@ require "sentry/utils/sample_rand" require "sentry/configuration" require "sentry/structured_logger" +require "sentry/debug_structured_logger" require "sentry/event" require "sentry/error_event" require "sentry/transaction_event" @@ -639,9 +640,10 @@ def logger @logger ||= if configuration.enable_logs # Initialize the public-facing Structured Logger if logs are enabled - # This creates a StructuredLogger instance that implements Sentry's SDK telemetry logs protocol + # Use configured structured logger class or default to StructuredLogger # @see https://develop.sentry.dev/sdk/telemetry/logs/ - StructuredLogger.new(configuration) + logger_class = configuration.structured_logger_class || StructuredLogger + logger_class.new(configuration) else warn <<~STR [sentry] `Sentry.logger` will no longer be used as internal SDK logger when `enable_logs` feature is turned on. diff --git a/sentry-ruby/lib/sentry/configuration.rb b/sentry-ruby/lib/sentry/configuration.rb index eea7d4fce..7e8ef503b 100644 --- a/sentry-ruby/lib/sentry/configuration.rb +++ b/sentry-ruby/lib/sentry/configuration.rb @@ -201,6 +201,18 @@ def capture_exception_frame_locals=(value) # @return [String, nil] attr_accessor :sdk_debug_transport_log_file + # File path for DebugStructuredLogger to log events to. If not set, defaults to a temporary file. + # This is useful for debugging and testing structured logging. + # @return [String, nil] + attr_accessor :sdk_debug_structured_logger_log_file + + # The class to use as a structured logger. + # If this option is not set, it will return `nil`, and Sentry will use + # `Sentry::StructuredLogger` by default when logs are enabled. + # + # @return [Class, nil] + attr_reader :structured_logger_class + # @deprecated Use {#sdk_logger=} instead. def logger=(logger) warn "[sentry] `config.logger=` is deprecated. Please use `config.sdk_logger=` instead." @@ -612,6 +624,14 @@ def profiler_class=(profiler_class) @profiler_class = profiler_class end + def structured_logger_class=(klass) + unless klass.is_a?(Class) + raise Sentry::Error.new("config.structured_logger_class must be a class. got: #{klass.class}") + end + + @structured_logger_class = klass + end + def sending_allowed? spotlight || sending_to_dsn_allowed? end diff --git a/sentry-ruby/lib/sentry/debug_structured_logger.rb b/sentry-ruby/lib/sentry/debug_structured_logger.rb new file mode 100644 index 000000000..88f32d3e7 --- /dev/null +++ b/sentry-ruby/lib/sentry/debug_structured_logger.rb @@ -0,0 +1,94 @@ +# frozen_string_literal: true + +require "json" +require "fileutils" +require "pathname" +require "delegate" + +module Sentry + # DebugStructuredLogger is a logger that captures structured log events to a file for debugging purposes. + # + # It can optionally also send log events to Sentry via the normal structured logger if logging + # is enabled. + class DebugStructuredLogger < SimpleDelegator + DEFAULT_LOG_FILE_PATH = File.join("log", "sentry_debug_logs.log") + + attr_reader :log_file, :backend + + def initialize(configuration) + @log_file = initialize_log_file(configuration) + @backend = initialize_backend(configuration) + + super(@backend) + end + + # Override all log level methods to capture events + %i[trace debug info warn error fatal].each do |level| + define_method(level) do |message, parameters = [], **attributes| + log_event = capture_log_event(level, message, parameters, **attributes) + backend.public_send(level, message, parameters, **attributes) + log_event + end + end + + def log(level, message, parameters:, **attributes) + log_event = capture_log_event(level, message, parameters, **attributes) + backend.log(level, message, parameters: parameters, **attributes) + log_event + end + + def capture_log_event(level, message, parameters, **attributes) + log_event_json = { + timestamp: Time.now.utc.iso8601, + level: level.to_s, + message: message, + parameters: parameters, + attributes: attributes + } + + File.open(log_file, "a") { |file| file << JSON.dump(log_event_json) << "\n" } + log_event_json + end + + def logged_events + return [] unless File.exist?(log_file) + + File.readlines(log_file).map do |line| + JSON.parse(line) + end + end + + def clear + File.write(log_file, "") + if backend.respond_to?(:config) + backend.config.sdk_logger.debug("DebugStructuredLogger: Cleared events from #{log_file}") + end + end + + private + + def initialize_backend(configuration) + if configuration.enable_logs + StructuredLogger.new(configuration) + else + # Create a no-op logger if logging is disabled + NoOpLogger.new + end + end + + def initialize_log_file(configuration) + log_file = Pathname(configuration.sdk_debug_structured_logger_log_file || DEFAULT_LOG_FILE_PATH) + + FileUtils.mkdir_p(log_file.dirname) unless log_file.dirname.exist? + + log_file + end + + # No-op logger for when structured logging is disabled + class NoOpLogger + %i[trace debug info warn error fatal log].each do |method| + define_method(method) { |*args, **kwargs| nil } + end + end + end +end diff --git a/sentry-ruby/lib/sentry/test_helper.rb b/sentry-ruby/lib/sentry/test_helper.rb index 7fb313b57..39ee0dca2 100644 --- a/sentry-ruby/lib/sentry/test_helper.rb +++ b/sentry-ruby/lib/sentry/test_helper.rb @@ -2,6 +2,8 @@ module Sentry module TestHelper + module_function + DUMMY_DSN = "http://12345:67890@sentry.localdomain/sentry/42" # Not really real, but it will be resolved as a non-local for testing needs @@ -49,10 +51,7 @@ def setup_sentry_test(&block) def teardown_sentry_test return unless Sentry.initialized? - transport = Sentry.get_current_client&.transport - if transport.is_a?(Sentry::DebugTransport) - transport.clear - end + clear_sentry_events # pop testing layer created by `setup_sentry_test` # but keep the base layer to avoid nil-pointer errors @@ -63,6 +62,14 @@ def teardown_sentry_test Sentry::Scope.global_event_processors.clear end + def clear_sentry_events + if Sentry.initialized? && Sentry.configuration.enable_logs + [Sentry.get_current_client.transport, Sentry.logger].each do |obj| + obj.clear if obj.respond_to?(:clear) + end + end + end + # @return [Transport] def sentry_transport Sentry.get_current_client.transport diff --git a/sentry-ruby/spec/sentry/debug_structured_logger_spec.rb b/sentry-ruby/spec/sentry/debug_structured_logger_spec.rb new file mode 100644 index 000000000..df22230d9 --- /dev/null +++ b/sentry-ruby/spec/sentry/debug_structured_logger_spec.rb @@ -0,0 +1,136 @@ +# frozen_string_literal: true + +RSpec.describe Sentry::DebugStructuredLogger do + let(:configuration) do + config = Sentry::Configuration.new + config.enable_logs = true + config.dsn = Sentry::TestHelper::DUMMY_DSN + config + end + + let(:debug_logger) { described_class.new(configuration) } + + before do + debug_logger.clear + end + + after do + debug_logger.clear + end + + describe "#initialize" do + it "creates a debug logger with structured logger backend" do + expect(debug_logger.backend).to be_a(Sentry::StructuredLogger) + end + + it "creates a log file" do + expect(debug_logger.log_file).to be_a(Pathname) + end + + context "when logs are disabled" do + let(:configuration) do + config = Sentry::Configuration.new + config.enable_logs = false + config.dsn = Sentry::TestHelper::DUMMY_DSN + config + end + + it "creates a no-op logger backend" do + expect(debug_logger.backend).to be_a(Sentry::DebugStructuredLogger::NoOpLogger) + end + end + end + + describe "logging methods" do + %i[trace debug info warn error fatal].each do |level| + describe "##{level}" do + it "captures log events to file" do + debug_logger.public_send(level, "Test #{level} message", test_attr: "value") + + logged_events = debug_logger.logged_events + expect(logged_events).not_to be_empty + + log_event = logged_events.last + expect(log_event["level"]).to eq(level.to_s) + expect(log_event["message"]).to eq("Test #{level} message") + expect(log_event["attributes"]["test_attr"]).to eq("value") + expect(log_event["timestamp"]).to be_a(String) + end + + it "handles parameters correctly" do + debug_logger.public_send(level, "Test message", ["param1", "param2"], extra_attr: "extra") + + logged_events = debug_logger.logged_events + log_event = logged_events.last + + expect(log_event["parameters"]).to eq(["param1", "param2"]) + expect(log_event["attributes"]["extra_attr"]).to eq("extra") + end + end + end + end + + describe "#log" do + it "captures log events with specified level" do + debug_logger.log(:info, "Test log message", parameters: [], custom_attr: "custom_value") + + logged_events = debug_logger.logged_events + expect(logged_events).not_to be_empty + + log_event = logged_events.last + expect(log_event["level"]).to eq("info") + expect(log_event["message"]).to eq("Test log message") + expect(log_event["attributes"]["custom_attr"]).to eq("custom_value") + end + end + + describe "#logged_events" do + it "returns empty array when no events logged" do + expect(debug_logger.logged_events).to eq([]) + end + + it "returns all logged events" do + debug_logger.info("First message") + debug_logger.warn("Second message") + debug_logger.error("Third message") + + logged_events = debug_logger.logged_events + expect(logged_events.length).to eq(3) + + expect(logged_events[0]["message"]).to eq("First message") + expect(logged_events[1]["message"]).to eq("Second message") + expect(logged_events[2]["message"]).to eq("Third message") + end + end + + describe "#clear" do + it "clears logged events" do + debug_logger.info("Test message") + expect(debug_logger.logged_events).not_to be_empty + + debug_logger.clear + expect(debug_logger.logged_events).to be_empty + end + end + + describe "JSON serialization" do + it "handles complex data types" do + debug_logger.info("Complex data", + string: "text", + number: 42, + boolean: true, + array: [1, 2, 3], + hash: { nested: "value" } + ) + + logged_events = debug_logger.logged_events + log_event = logged_events.last + + expect(log_event["attributes"]["string"]).to eq("text") + expect(log_event["attributes"]["number"]).to eq(42) + expect(log_event["attributes"]["boolean"]).to eq(true) + expect(log_event["attributes"]["array"]).to eq([1, 2, 3]) + expect(log_event["attributes"]["hash"]).to eq({ "nested" => "value" }) + end + end +end diff --git a/spec/support/test_helper.rb b/spec/support/test_helper.rb index 002cd0d11..ebc66d2d3 100644 --- a/spec/support/test_helper.rb +++ b/spec/support/test_helper.rb @@ -39,6 +39,14 @@ def logged_envelopes Sentry.get_current_client.transport.logged_envelopes end + def logged_structured_events + if Sentry.logger.is_a?(Sentry::DebugStructuredLogger) + Sentry.logger.logged_events + else + [] + end + end + # TODO: move this to a shared helper for all gems def perform_basic_setup Sentry.init do |config| From f5ebedbfef4d71f03917276aa73af26f7545e53a Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 26 Aug 2025 07:23:25 +0000 Subject: [PATCH 03/21] [rails] introduce abstract log subscriber --- .../lib/sentry/rails/log_subscriber.rb | 70 +++++ .../rails/log_subscribers/parameter_filter.rb | 52 ++++ sentry-rails/spec/dummy/test_rails_app/app.rb | 11 + .../spec/sentry/rails/log_subscriber_spec.rb | 255 ++++++++++++++++++ .../shared_examples_for_parameter_filter.rb | 141 ++++++++++ 5 files changed, 529 insertions(+) create mode 100644 sentry-rails/lib/sentry/rails/log_subscriber.rb create mode 100644 sentry-rails/lib/sentry/rails/log_subscribers/parameter_filter.rb create mode 100644 sentry-rails/spec/sentry/rails/log_subscriber_spec.rb create mode 100644 sentry-rails/spec/support/shared_examples_for_parameter_filter.rb diff --git a/sentry-rails/lib/sentry/rails/log_subscriber.rb b/sentry-rails/lib/sentry/rails/log_subscriber.rb new file mode 100644 index 000000000..5de6cdf6e --- /dev/null +++ b/sentry-rails/lib/sentry/rails/log_subscriber.rb @@ -0,0 +1,70 @@ +# 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 + if ::Rails.version.to_f < 6.0 + # Rails 5.x does not provide detach_from + def detach_from(namespace, notifications = ActiveSupport::Notifications) + listeners = public_instance_methods(false) + .flat_map { |key| + notifications.notifier.listeners_for("#{key}.#{namespace}") + } + .select { |listener| listener.instance_variable_get(:@delegate).is_a?(self) } + + listeners.map do |listener| + notifications.notifier.unsubscribe(listener) + end + end + 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: {}) + 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 + + # 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 + end + end +end diff --git a/sentry-rails/lib/sentry/rails/log_subscribers/parameter_filter.rb b/sentry-rails/lib/sentry/rails/log_subscribers/parameter_filter.rb new file mode 100644 index 000000000..8f20cf3ed --- /dev/null +++ b/sentry-rails/lib/sentry/rails/log_subscribers/parameter_filter.rb @@ -0,0 +1,52 @@ +# frozen_string_literal: true + +module Sentry + module Rails + module LogSubscribers + # Shared utility module for filtering sensitive parameters in log subscribers. + # + # This module provides consistent parameter filtering across all Sentry Rails + # log subscribers, leveraging Rails' built-in parameter filtering when available. + # It automatically detects the correct Rails parameter filtering API based on + # the Rails version and includes the appropriate implementation module. + # + # @example Usage in a log subscriber + # class MySubscriber < Sentry::Rails::LogSubscriber + # include Sentry::Rails::LogSubscribers::ParameterFilter + # + # def my_event(event) + # if Sentry.configuration.send_default_pii && event.payload[:params] + # filtered_params = filter_sensitive_params(event.payload[:params]) + # attributes[:params] = filtered_params unless filtered_params.empty? + # end + # end + # end + module ParameterFilter + EMPTY_HASH = {}.freeze + + if ::Rails.version.to_f >= 6.0 + def self.backend + ActiveSupport::ParameterFilter + end + else + def self.backend + ActionDispatch::Http::ParameterFilter + end + end + + # Filter sensitive parameters from a hash, respecting Rails configuration. + # + # @param params [Hash] The parameters to filter + # @return [Hash] Filtered parameters with sensitive data removed + def filter_sensitive_params(params) + return EMPTY_HASH unless params.is_a?(Hash) + + filter_parameters = ::Rails.application.config.filter_parameters + parameter_filter = ParameterFilter.backend.new(filter_parameters) + + parameter_filter.filter(params) + end + end + end + end +end diff --git a/sentry-rails/spec/dummy/test_rails_app/app.rb b/sentry-rails/spec/dummy/test_rails_app/app.rb index 874b6d1ae..42f4d8d04 100644 --- a/sentry-rails/spec/dummy/test_rails_app/app.rb +++ b/sentry-rails/spec/dummy/test_rails_app/app.rb @@ -71,6 +71,17 @@ def self.name configure_app(app) + # Configure parameter filtering for consistent test behavior + app.config.filter_parameters.concat( + [:custom_secret, + :api_key, + :credit_card, + :authorization, + :password, + :token] + ) + app.config.filter_parameters.uniq! + app.routes.append do get "/exception", to: "hello#exception" get "/view_exception", to: "hello#view_exception" diff --git a/sentry-rails/spec/sentry/rails/log_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscriber_spec.rb new file mode 100644 index 000000000..a8fcc4fa4 --- /dev/null +++ b/sentry-rails/spec/sentry/rails/log_subscriber_spec.rb @@ -0,0 +1,255 @@ +# frozen_string_literal: true + +require "spec_helper" + +require "sentry/rails/log_subscriber" +require "sentry/rails/log_subscribers/parameter_filter" + +RSpec.describe Sentry::Rails::LogSubscriber, type: :request do + let!(:test_subscriber) { test_subscriber_class.new } + + after do + Sentry.logger.clear if Sentry.logger.respond_to?(:clear) + test_subscriber_class.detach_from(:test_component) + end + + context "with no parameter filtering" do + let(:test_subscriber_class) do + Class.new(described_class) do + attach_to :test_component + + def test_event(event) + log_structured_event( + message: "Test event occurred", + attributes: { + duration_ms: duration_ms(event), + test_data: event.payload[:test_data], + component: "test_component" + } + ) + end + + def error_test_event(event) + log_structured_event( + message: "Error test event", + level: :error, + attributes: { + duration_ms: duration_ms(event), + error_data: event.payload[:error_data] + } + ) + end + end + end + + before do + make_basic_app do |config| + config.enable_logs = true + config.structured_logger_class = Sentry::DebugStructuredLogger + end + end + + describe "ActiveSupport notifications integration" do + it "responds to real ActiveSupport notifications and logs structured events" do + ActiveSupport::Notifications.instrument("test_event.test_component", test_data: "sample_data") do + sleep(0.01) + end + + logged_events = Sentry.logger.logged_events + expect(logged_events).not_to be_empty + + log_event = logged_events.first + expect(log_event["level"]).to eq("info") + expect(log_event["message"]).to eq("Test event occurred") + expect(log_event["attributes"]["test_data"]).to eq("sample_data") + expect(log_event["attributes"]["component"]).to eq("test_component") + expect(log_event["attributes"]["duration_ms"]).to be_a(Float) + expect(log_event["attributes"]["duration_ms"]).to be > 0 + expect(log_event["timestamp"]).to be_a(String) + end + + it "uses appropriate log level based on duration thresholds" do + ActiveSupport::Notifications.instrument("test_event.test_component", test_data: "fast") do + sleep(0.1) + end + + logged_events = Sentry.logger.logged_events + expect(logged_events.size).to eq(1) + + log_event = logged_events.first + expect(log_event["level"]).to eq("info") + expect(log_event["attributes"]["test_data"]).to eq("fast") + expect(log_event["attributes"]["duration_ms"]).to be > 50 + end + + it "handles events with various payload data types" do + test_payloads = [ + { test_data: "string_value" }, + { test_data: { nested: "hash" } }, + { test_data: [1, 2, 3] }, + { test_data: nil } + ] + + expected_values = [ + "string_value", + { "nested" => "hash" }, + [1, 2, 3], + nil + ] + + test_payloads.each do |payload| + ActiveSupport::Notifications.instrument("test_event.test_component", payload) do + sleep 0.01 + end + end + + logged_events = Sentry.logger.logged_events + expect(logged_events.size).to eq(test_payloads.size) + + logged_events.each_with_index do |log_event, index| + expect(log_event["message"]).to eq("Test event occurred") + expect(log_event["attributes"]["test_data"]).to eq(expected_values[index]) + expect(log_event["level"]).to eq("info") + end + end + + it "calculates duration correctly from real events" do + ActiveSupport::Notifications.instrument("test_event.test_component", test_data: "duration_test") do + sleep(0.05) # 50ms + end + + logged_events = Sentry.logger.logged_events + log_event = logged_events.first + duration = log_event["attributes"]["duration_ms"] + + expect(duration).to be_a(Float) + expect(duration).to be >= 40.0 + expect(duration).to be < 100.0 + expect(duration.round(2)).to eq(duration) + end + end + + describe "error handling" do + it "handles logging errors gracefully and logs to sdk_logger" do + failing_logger = double("failing_logger") + + allow(failing_logger).to receive(:error).and_raise(StandardError.new("Logging failed")) + allow(Sentry).to receive(:logger).and_return(failing_logger) + + sdk_logger_output = StringIO.new + Sentry.configuration.sdk_logger = ::Logger.new(sdk_logger_output) + + expect { + ActiveSupport::Notifications.instrument("error_test_event.test_component", error_data: "error_test") do + sleep 0.01 + end + }.not_to raise_error + + sdk_output = sdk_logger_output.string + expect(sdk_output).to include("Failed to log structured event: Logging failed") + end + end + + describe "Rails version compatibility" do + context "when Rails version is less than 6.0", skip: Rails.version.to_f >= 6.0 ? "Rails 6.0+" : false do + it "provides custom detach_from implementation" do + temp_subscriber_class = Class.new(described_class) do + attach_to :temp_test + + def temp_event(event) + log_structured_event(message: "Temp event", attributes: { data: event.payload[:data] }) + end + end + + ActiveSupport::Notifications.instrument("temp_event.temp_test", data: "before_detach") do + sleep 0.01 + end + + initial_log_count = Sentry.logger.logged_events.size + expect(initial_log_count).to be > 0 + + temp_subscriber_class.detach_from(:temp_test) + + Sentry.logger.clear + + ActiveSupport::Notifications.instrument("temp_event.temp_test", data: "after_detach") do + sleep 0.01 + end + + expect(Sentry.logger.logged_events).to be_empty + end + end + + context "when Rails version is 6.0 or higher", skip: Rails.version.to_f < 6.0 ? "Rails 5.x" : false do + it "uses Rails built-in detach_from method" do + expect(described_class).to respond_to(:detach_from) + + temp_subscriber_class = Class.new(described_class) do + attach_to :temp_test_rails6 + + def temp_event(event) + log_structured_event(message: "Temp event Rails 6+", attributes: { data: event.payload[:data] }) + end + end + + ActiveSupport::Notifications.instrument("temp_event.temp_test_rails6", data: "test") do + sleep 0.01 + end + + initial_log_count = Sentry.logger.logged_events.size + expect(initial_log_count).to be > 0 + + temp_subscriber_class.detach_from(:temp_test_rails6) + + Sentry.logger.clear + + ActiveSupport::Notifications.instrument("temp_event.temp_test_rails6", data: "after_detach") do + sleep 0.01 + end + + expect(Sentry.logger.logged_events).to be_empty + end + end + end + end + + context "parameter filtering integration" do + let(:test_subscriber_class) do + Class.new(described_class) do + include Sentry::Rails::LogSubscribers::ParameterFilter + + attach_to :filtering_test + + def filtering_event(event) + attributes = { + duration_ms: duration_ms(event), + component: "filtering_test" + } + + if Sentry.configuration.send_default_pii && event.payload[:params] + filtered_params = filter_sensitive_params(event.payload[:params]) + attributes[:params] = filtered_params unless filtered_params.empty? + end + + log_structured_event( + message: "Filtering event occurred", + attributes: attributes + ) + end + end + end + + before do + make_basic_app do |config, app| + config.enable_logs = true + config.structured_logger_class = Sentry::DebugStructuredLogger + config.send_default_pii = true + app.config.filter_parameters += [:custom_secret, :api_key, :credit_card, :authorization] + end + end + + it_behaves_like "parameter filtering" do + let(:test_instance) { test_subscriber } + end + end +end diff --git a/sentry-rails/spec/support/shared_examples_for_parameter_filter.rb b/sentry-rails/spec/support/shared_examples_for_parameter_filter.rb new file mode 100644 index 000000000..ceafd7f9a --- /dev/null +++ b/sentry-rails/spec/support/shared_examples_for_parameter_filter.rb @@ -0,0 +1,141 @@ +# frozen_string_literal: true + +RSpec.shared_examples "parameter filtering" do |subscriber_class| + let(:test_instance) { subscriber_class.new } + + describe "#filter_sensitive_params" do + context "when params is not a hash" do + it "returns empty hash for nil" do + result = test_instance.filter_sensitive_params(nil) + expect(result).to eq({}) + end + + it "returns empty hash for non-hash objects" do + result = test_instance.filter_sensitive_params("not a hash") + expect(result).to eq({}) + end + + it "returns empty hash for arrays" do + result = test_instance.filter_sensitive_params([1, 2, 3]) + expect(result).to eq({}) + end + end + + context "when params is a valid hash" do + it "preserves non-sensitive parameters" do + params = { + "name" => "John Doe", + "email" => "john@example.com", + "age" => 30, + "preferences" => { "theme" => "dark" } + } + + result = test_instance.filter_sensitive_params(params) + + expect(result).to include("name" => "John Doe") + expect(result).to include("email" => "john@example.com") + expect(result).to include("age" => 30) + expect(result).to include("preferences" => { "theme" => "dark" }) + end + + it "filters default sensitive parameters" do + params = { + "name" => "John Doe", + "password" => "secret123", + "password_confirmation" => "secret123", + "normal_param" => "safe_value" + } + + result = test_instance.filter_sensitive_params(params) + + expect(result).to include("name" => "John Doe") + expect(result).to include("normal_param" => "safe_value") + expect(result).to include("password" => "[FILTERED]") + expect(result).to include("password_confirmation" => "[FILTERED]") + end + + it "filters custom configured sensitive parameters" do + params = { + "name" => "John Doe", + "custom_secret" => "top_secret", + "api_key" => "abc123xyz", + "credit_card" => "1234-5678-9012-3456", + "authorization" => "Bearer token123", + "normal_param" => "safe_value" + } + + result = test_instance.filter_sensitive_params(params) + + expect(result).to include("name" => "John Doe") + expect(result).to include("normal_param" => "safe_value") + expect(result).to include("custom_secret" => "[FILTERED]") + expect(result).to include("api_key" => "[FILTERED]") + expect(result).to include("credit_card" => "[FILTERED]") + expect(result).to include("authorization" => "[FILTERED]") + end + + it "handles mixed sensitive and non-sensitive parameters" do + params = { + "user_id" => 123, + "username" => "johndoe", + "password" => "secret", + "session_token" => "abc123", + "preferences" => { + "notifications" => true, + "api_key" => "sensitive_key" + } + } + + result = test_instance.filter_sensitive_params(params) + + expect(result).to include("user_id" => 123) + expect(result).to include("username" => "johndoe") + expect(result).to include("password" => "[FILTERED]") + expect(result).to include("session_token" => "[FILTERED]") + expect(result).to have_key("preferences") + end + + it "returns a new hash and doesn't modify the original" do + original_params = { + "name" => "John", + "password" => "secret" + } + original_copy = original_params.dup + + result = test_instance.filter_sensitive_params(original_params) + + expect(original_params).to eq(original_copy) + expect(result).not_to equal(original_params) + end + + it "handles empty hash" do + result = test_instance.filter_sensitive_params({}) + expect(result).to eq({}) + end + end + + context "with Rails filter_parameters configuration" do + it "respects dynamically added filter parameters" do + original_filter_params = Rails.application.config.filter_parameters.dup + + begin + Rails.application.config.filter_parameters += [:dynamic_secret] + + params = { + "name" => "John", + "dynamic_secret" => "should_be_filtered", + "normal_param" => "value" + } + + result = test_instance.filter_sensitive_params(params) + + expect(result).to include("name" => "John") + expect(result).to include("normal_param" => "value") + expect(result).to include("dynamic_secret" => "[FILTERED]") + ensure + Rails.application.config.filter_parameters = original_filter_params + end + end + end + end +end From af61e02b98ba9146c9fb9249a9e21920b630c1ce Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 26 Aug 2025 07:35:11 +0000 Subject: [PATCH 04/21] [rails] add structured logging config/activation --- sentry-rails/lib/sentry/rails.rb | 1 + .../lib/sentry/rails/configuration.rb | 35 +++++++++++++++ sentry-rails/lib/sentry/rails/railtie.rb | 7 +++ .../lib/sentry/rails/structured_logging.rb | 26 +++++++++++ .../spec/sentry/rails/configuration_spec.rb | 34 +++++++++++++++ .../sentry/rails/structured_logging_spec.rb | 43 +++++++++++++++++++ sentry-rails/spec/spec_helper.rb | 5 ++- 7 files changed, 150 insertions(+), 1 deletion(-) create mode 100644 sentry-rails/lib/sentry/rails/structured_logging.rb create mode 100644 sentry-rails/spec/sentry/rails/structured_logging_spec.rb diff --git a/sentry-rails/lib/sentry/rails.rb b/sentry-rails/lib/sentry/rails.rb index b4b79dd85..8af39f372 100644 --- a/sentry-rails/lib/sentry/rails.rb +++ b/sentry-rails/lib/sentry/rails.rb @@ -5,6 +5,7 @@ require "sentry/integrable" require "sentry/rails/tracing" require "sentry/rails/configuration" +require "sentry/rails/structured_logging" require "sentry/rails/engine" require "sentry/rails/railtie" diff --git a/sentry-rails/lib/sentry/rails/configuration.rb b/sentry-rails/lib/sentry/rails/configuration.rb index 2669a84a6..0d43fe3ab 100644 --- a/sentry-rails/lib/sentry/rails/configuration.rb +++ b/sentry-rails/lib/sentry/rails/configuration.rb @@ -159,6 +159,25 @@ class Configuration # Set this option to true if you want Sentry to capture each retry failure attr_accessor :active_job_report_on_retry_error + # Configuration for structured logging feature + # @return [StructuredLoggingConfiguration] + attr_reader :structured_logging + + # Allow setting structured_logging as a boolean for convenience + # @param value [Boolean, StructuredLoggingConfiguration] + def structured_logging=(value) + case value + when true + @structured_logging.enabled = true + when false + @structured_logging.enabled = false + when StructuredLoggingConfiguration + @structured_logging = value + else + raise ArgumentError, "structured_logging must be a boolean or StructuredLoggingConfiguration" + end + end + def initialize @register_error_subscriber = false @report_rescued_exceptions = true @@ -176,6 +195,22 @@ def initialize @db_query_source_threshold_ms = 100 @active_support_logger_subscription_items = Sentry::Rails::ACTIVE_SUPPORT_LOGGER_SUBSCRIPTION_ITEMS_DEFAULT.dup @active_job_report_on_retry_error = false + @structured_logging = StructuredLoggingConfiguration.new + end + end + + class StructuredLoggingConfiguration + # Enable or disable structured logging + # @return [Boolean] + attr_accessor :enabled + + # Hash of components to subscriber classes for structured logging + # @return [Hash] + attr_accessor :subscribers + + def initialize + @enabled = false + @subscribers = {} end end end diff --git a/sentry-rails/lib/sentry/rails/railtie.rb b/sentry-rails/lib/sentry/rails/railtie.rb index d2cf03d57..0691fa277 100644 --- a/sentry-rails/lib/sentry/rails/railtie.rb +++ b/sentry-rails/lib/sentry/rails/railtie.rb @@ -49,6 +49,7 @@ class Railtie < ::Rails::Railtie setup_backtrace_cleanup_callback inject_breadcrumbs_logger activate_tracing + activate_structured_logging register_error_subscriber(app) if ::Rails.version.to_f >= 7.0 && Sentry.configuration.rails.register_error_subscriber @@ -138,6 +139,12 @@ def activate_tracing end end + def activate_structured_logging + if Sentry.configuration.rails.structured_logging.enabled && Sentry.configuration.enable_logs + Sentry::Rails::StructuredLogging.attach(Sentry.configuration.rails.structured_logging) + end + end + def register_error_subscriber(app) require "sentry/rails/error_subscriber" app.executor.error_reporter.subscribe(Sentry::Rails::ErrorSubscriber.new) diff --git a/sentry-rails/lib/sentry/rails/structured_logging.rb b/sentry-rails/lib/sentry/rails/structured_logging.rb new file mode 100644 index 000000000..ee1246a22 --- /dev/null +++ b/sentry-rails/lib/sentry/rails/structured_logging.rb @@ -0,0 +1,26 @@ +# frozen_string_literal: true + +module Sentry + module Rails + module StructuredLogging + class << self + def attach(config) + config.subscribers.each do |component, subscriber_class| + subscriber_class.attach_to component + end + rescue => e + Sentry.configuration.sdk_logger.error("Failed to attach structured loggers: #{e.message}") + Sentry.configuration.sdk_logger.error(e.backtrace.join("\n")) + end + + def detach(config) + config.subscribers.each do |component, subscriber_class| + subscriber_class.detach_from component + end + rescue => e + Sentry.configuration.sdk_logger.debug("Error during detaching loggers: #{e.message}") + end + end + end + end +end diff --git a/sentry-rails/spec/sentry/rails/configuration_spec.rb b/sentry-rails/spec/sentry/rails/configuration_spec.rb index d008af92f..0a6dc9544 100644 --- a/sentry-rails/spec/sentry/rails/configuration_spec.rb +++ b/sentry-rails/spec/sentry/rails/configuration_spec.rb @@ -65,4 +65,38 @@ class MySubscriber; end expect(subject.active_job_report_on_retry_error).to be(false) end end + + describe "#structured_logging" do + let(:config) { Sentry.configuration.rails } + + it "allows enabling by setting to true" do + make_basic_app do |config| + config.rails.structured_logging = true + end + + expect(config.structured_logging.enabled).to be(true) + expect(config.structured_logging.subscribers).to be_a(Hash) + end + + it "allows disabling by setting to false" do + make_basic_app do |config| + config.rails.structured_logging = false + end + + expect(config.structured_logging.enabled).to be(false) + expect(config.structured_logging.subscribers).to be_a(Hash) + end + + it "allows customizing subscribers" do + class TestSubscriber; end + + make_basic_app do |config| + config.rails.structured_logging = true + config.rails.structured_logging.subscribers = { action_controller: TestSubscriber } + end + + expect(config.structured_logging.subscribers.keys).to eql([:action_controller]) + expect(config.structured_logging.subscribers[:action_controller]).to eq(TestSubscriber) + end + end end diff --git a/sentry-rails/spec/sentry/rails/structured_logging_spec.rb b/sentry-rails/spec/sentry/rails/structured_logging_spec.rb new file mode 100644 index 000000000..1c7ee1abd --- /dev/null +++ b/sentry-rails/spec/sentry/rails/structured_logging_spec.rb @@ -0,0 +1,43 @@ +# frozen_string_literal: true + +require "spec_helper" + +RSpec.describe Sentry::Rails::StructuredLogging, type: :request do + context "when sentry structured logging is disabled" do + before do + make_basic_app do |config| + config.enable_logs = false + config.rails.structured_logging = true + end + end + + it "does not capture structured logs" do + get "/posts" + + Post.first + + Sentry.get_current_client.flush + + expect(sentry_logs).to be_empty + end + end + + context "when rails structured logging is disabled" do + before do + make_basic_app do |config| + config.enable_logs = true + config.rails.structured_logging = false + end + end + + it "does not capture structured logs" do + get "/posts" + + Post.first + + Sentry.get_current_client.flush + + expect(sentry_logs).to be_empty + end + end +end diff --git a/sentry-rails/spec/spec_helper.rb b/sentry-rails/spec/spec_helper.rb index 4f1b8f5c0..4a8640f5f 100644 --- a/sentry-rails/spec/spec_helper.rb +++ b/sentry-rails/spec/spec_helper.rb @@ -54,7 +54,10 @@ expect(Sentry::Rails::Tracing.subscribed_tracing_events).to be_empty Sentry::Rails::Tracing.remove_active_support_notifications_patch - Sentry::TestHelper.clear_sentry_events + if Sentry.initialized? + Sentry::TestHelper.clear_sentry_events + Sentry::Rails::StructuredLogging.detach(Sentry.configuration.rails.structured_logging) + end if defined?(Sentry::Rails::ActiveJobExtensions) Sentry::Rails::ActiveJobExtensions::SentryReporter.detach_event_handlers From 8ede8d950d512c4a8f3419a6f7dddba55b789a6e Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 26 Aug 2025 07:45:02 +0000 Subject: [PATCH 05/21] [rails] add ActionController log subscriber --- .../action_controller_subscriber.rb | 114 +++++++++ .../action_controller_subscriber_spec.rb | 240 ++++++++++++++++++ 2 files changed, 354 insertions(+) create mode 100644 sentry-rails/lib/sentry/rails/log_subscribers/action_controller_subscriber.rb create mode 100644 sentry-rails/spec/sentry/rails/action_controller_subscriber_spec.rb 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 new file mode 100644 index 000000000..3496f71f5 --- /dev/null +++ b/sentry-rails/lib/sentry/rails/log_subscribers/action_controller_subscriber.rb @@ -0,0 +1,114 @@ +# frozen_string_literal: true + +require "sentry/rails/log_subscriber" +require "sentry/rails/log_subscribers/parameter_filter" + +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.subscribers = { action_controller: Sentry::Rails::LogSubscribers::ActionControllerSubscriber } + # end + class ActionControllerSubscriber < Sentry::Rails::LogSubscriber + include ParameterFilter + + # Handle process_action.action_controller events + # + # @param event [ActiveSupport::Notifications::Event] The controller action event + def process_action(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 + end + end + end +end diff --git a/sentry-rails/spec/sentry/rails/action_controller_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/action_controller_subscriber_spec.rb new file mode 100644 index 000000000..c417cb355 --- /dev/null +++ b/sentry-rails/spec/sentry/rails/action_controller_subscriber_spec.rb @@ -0,0 +1,240 @@ +# 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, app| + config.enable_logs = true + config.rails.structured_logging.enabled = true + config.rails.structured_logging.subscribers = { action_controller: Sentry::Rails::LogSubscribers::ActionControllerSubscriber } + app.config.filter_parameters += [:api_key, :credit_card, :authorization] + end + end + + describe "integration with ActiveSupport::Notifications" do + it "logs controller action events when requests are processed" do + get "/world" + + Sentry.get_current_client.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 + get "/not_found" + + Sentry.get_current_client.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 + get "/exception" + + Sentry.get_current_client.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 + get "/view" + + Sentry.get_current_client.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 + Post.create! + get "/posts" + + Sentry.get_current_client.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 + get "/world", params: { safe_param: "value", password: "secret" } + + Sentry.get_current_client.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]).to include("password" => "[FILTERED]") + end + + it "filters sensitive parameter names" do + get "/world", params: { + normal_param: "value", + password: "secret", + api_key: "key123", + credit_card: "1234567890", + authorization: "Bearer token" + } + + Sentry.get_current_client.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).to include("password" => "[FILTERED]") + expect(params).to include("api_key" => "[FILTERED]") + expect(params).to include("credit_card" => "[FILTERED]") + expect(params).to include("authorization" => "[FILTERED]") + end + + it "respects Rails filter_parameters configuration" do + original_filter_params = Rails.application.config.filter_parameters.dup + Rails.application.config.filter_parameters += [:custom_secret] + + get "/world", params: { + normal_param: "value", + custom_secret: "should_be_filtered", + another_param: "visible" + } + + Sentry.get_current_client.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).to include("another_param" => "visible") + expect(params).to include("custom_secret" => "[FILTERED]") + + Rails.application.config.filter_parameters = original_filter_params + end + + it "handles nested parameters correctly" do + get "/world", params: { + user: { + name: "John", + password: "secret123", + profile: { + api_key: "key456", + public_info: "visible" + } + }, + normal_param: "value" + } + + Sentry.get_current_client.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["user"]).to include("name" => "John") + expect(params["user"]).to include("password" => "[FILTERED]") + expect(params["user"]["profile"]).to include("api_key" => "[FILTERED]") + expect(params["user"]["profile"]).to include("public_info" => "visible") + 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.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.subscribers = { action_controller: Sentry::Rails::LogSubscribers::ActionControllerSubscriber } + 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.flush + end + + expect(sentry_logs.count).to eq(initial_log_count) + end + end + + describe "ParameterFilter functionality" do + include_examples "parameter filtering", described_class + end +end From 4c630fe6ee6d9598960e0db2f52e5366cc74a91e Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 26 Aug 2025 07:45:16 +0000 Subject: [PATCH 06/21] [rails] add ActiveRecord log subscriber --- .../active_record_subscriber.rb | 144 ++++++++++++++++ .../rails/active_record_subscriber_spec.rb | 154 ++++++++++++++++++ 2 files changed, 298 insertions(+) create mode 100644 sentry-rails/lib/sentry/rails/log_subscribers/active_record_subscriber.rb create mode 100644 sentry-rails/spec/sentry/rails/active_record_subscriber_spec.rb 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 new file mode 100644 index 000000000..3245025e3 --- /dev/null +++ b/sentry-rails/lib/sentry/rails/log_subscribers/active_record_subscriber.rb @@ -0,0 +1,144 @@ +# frozen_string_literal: true + +require "sentry/rails/log_subscriber" +require "sentry/rails/log_subscribers/parameter_filter" + +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.subscribers = { active_record: Sentry::Rails::LogSubscribers::ActiveRecordSubscriber } + # end + class ActiveRecordSubscriber < Sentry::Rails::LogSubscriber + include ParameterFilter + + EXCLUDED_NAMES = ["SCHEMA", "TRANSACTION"].freeze + + # Handle sql.active_record events + # + # @param event [ActiveSupport::Notifications::Event] The SQL event + def sql(event) + return if EXCLUDED_NAMES.include?(event.payload[:name]) + + 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 + + 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/active_record_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/active_record_subscriber_spec.rb new file mode 100644 index 000000000..c941a8274 --- /dev/null +++ b/sentry-rails/spec/sentry/rails/active_record_subscriber_spec.rb @@ -0,0 +1,154 @@ +# 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.subscribers = { active_record: Sentry::Rails::LogSubscribers::ActiveRecordSubscriber } + end + end + + describe "integration with ActiveSupport::Notifications" do + it "logs SQL events when database queries are executed" do + Post.create! + + Sentry.get_current_client.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.flush + sentry_transport.events.clear + sentry_transport.envelopes.clear + + Post.find(post.id) + + Sentry.get_current_client.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 + + if Rails.version.to_f > 5.1 + it "excludes SCHEMA events" do + ActiveSupport::Notifications.instrument("sql.active_record", + sql: "CREATE TABLE temp_test_table (id INTEGER)", + name: "SCHEMA", + connection: ActiveRecord::Base.connection + ) + + Sentry.get_current_client.flush + + schema_logs = sentry_logs.select { |log| log[:attributes]&.dig(:sql, :value)&.include?("CREATE TABLE") } + expect(schema_logs).to be_empty + end + end + end + + describe "database configuration extraction" do + it "includes database configuration in log attributes" do + Post.create! + + Sentry.get_current_client.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! + Post.find(post.id) + + Sentry.get_current_client.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.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.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.subscribers = { active_record: Sentry::Rails::LogSubscribers::ActiveRecordSubscriber } + end + end + + it "does not log events when logging is disabled" do + initial_log_count = sentry_logs.count + + Post.create! + + Sentry.get_current_client.flush + + expect(sentry_logs.count).to eq(initial_log_count) + end + end + + include_examples "parameter filtering", described_class +end From d5eae11544fa0335afdea334f6d5ae63f6ba67e3 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 26 Aug 2025 07:45:31 +0000 Subject: [PATCH 07/21] [rails] add ActiveJob log subscriber --- .../log_subscribers/active_job_subscriber.rb | 155 +++++++++ .../rails/active_job_subscriber_spec.rb | 310 ++++++++++++++++++ 2 files changed, 465 insertions(+) create mode 100644 sentry-rails/lib/sentry/rails/log_subscribers/active_job_subscriber.rb create mode 100644 sentry-rails/spec/sentry/rails/active_job_subscriber_spec.rb diff --git a/sentry-rails/lib/sentry/rails/log_subscribers/active_job_subscriber.rb b/sentry-rails/lib/sentry/rails/log_subscribers/active_job_subscriber.rb new file mode 100644 index 000000000..6dd348594 --- /dev/null +++ b/sentry-rails/lib/sentry/rails/log_subscribers/active_job_subscriber.rb @@ -0,0 +1,155 @@ +# frozen_string_literal: true + +require "sentry/rails/log_subscriber" +require "sentry/rails/log_subscribers/parameter_filter" + +module Sentry + module Rails + module LogSubscribers + # LogSubscriber for ActiveJob events that captures background job execution + # and logs them using Sentry's structured logging system. + # + # This subscriber captures various ActiveJob events including job execution, + # enqueueing, retries, and failures with relevant job information. + # + # @example Usage + # # Enable structured logging for ActiveJob + # Sentry.init do |config| + # config.enable_logs = true + # config.rails.structured_logging = true + # config.rails.structured_logging.subscribers = { active_job: Sentry::Rails::LogSubscribers::ActiveJobSubscriber } + # end + class ActiveJobSubscriber < Sentry::Rails::LogSubscriber + include ParameterFilter + + # Handle perform.active_job events + # + # @param event [ActiveSupport::Notifications::Event] The job performance event + def perform(event) + job = event.payload[:job] + duration = duration_ms(event) + + attributes = { + job_class: job.class.name, + job_id: job.job_id, + queue_name: job.queue_name, + duration_ms: duration, + executions: job.executions, + priority: job.priority + } + + attributes[:adapter] = job.class.queue_adapter.class.name if job.class.respond_to?(:queue_adapter) + + if job.scheduled_at + attributes[:scheduled_at] = job.scheduled_at.iso8601 + attributes[:delay_ms] = ((Time.current - job.scheduled_at) * 1000).round(2) + end + + if Sentry.configuration.send_default_pii && job.arguments.present? + filtered_args = filter_sensitive_arguments(job.arguments) + attributes[:arguments] = filtered_args unless filtered_args.empty? + end + + message = "Job performed: #{job.class.name}" + + log_structured_event( + message: message, + level: :info, + attributes: attributes + ) + end + + # Handle enqueue.active_job events + # + # @param event [ActiveSupport::Notifications::Event] The job enqueue event + def enqueue(event) + job = event.payload[:job] + + attributes = { + job_class: job.class.name, + job_id: job.job_id, + queue_name: job.queue_name, + priority: job.priority + } + + attributes[:adapter] = job.class.queue_adapter.class.name if job.class.respond_to?(:queue_adapter) + + if job.scheduled_at + attributes[:scheduled_at] = job.scheduled_at.iso8601 + attributes[:delay_seconds] = (job.scheduled_at - Time.current).round(2) + end + + message = "Job enqueued: #{job.class.name}" + + log_structured_event( + message: message, + level: :info, + attributes: attributes + ) + end + + def retry_stopped(event) + job = event.payload[:job] + error = event.payload[:error] + + attributes = { + job_class: job.class.name, + job_id: job.job_id, + queue_name: job.queue_name, + executions: job.executions, + error_class: error.class.name, + error_message: error.message + } + + message = "Job retry stopped: #{job.class.name}" + + log_structured_event( + message: message, + level: :error, + attributes: attributes + ) + end + + def discard(event) + job = event.payload[:job] + error = event.payload[:error] + + attributes = { + job_class: job.class.name, + job_id: job.job_id, + queue_name: job.queue_name, + executions: job.executions + } + + attributes[:error_class] = error.class.name if error + attributes[:error_message] = error.message if error + + message = "Job discarded: #{job.class.name}" + + log_structured_event( + message: message, + level: :warn, + attributes: attributes + ) + end + + private + + def filter_sensitive_arguments(arguments) + return [] unless arguments.is_a?(Array) + + arguments.map do |arg| + case arg + when Hash + filter_sensitive_params(arg) + when String + arg.length > 100 ? "[FILTERED: #{arg.length} chars]" : arg + else + arg + end + end + end + end + end + end +end diff --git a/sentry-rails/spec/sentry/rails/active_job_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/active_job_subscriber_spec.rb new file mode 100644 index 000000000..2c3e6f8c1 --- /dev/null +++ b/sentry-rails/spec/sentry/rails/active_job_subscriber_spec.rb @@ -0,0 +1,310 @@ +# frozen_string_literal: true + +require "spec_helper" +require "sentry/rails/log_subscribers/active_job_subscriber" + +require_relative "../../support/test_jobs" + +RSpec.describe Sentry::Rails::LogSubscribers::ActiveJobSubscriber, skip: Rails.version.to_f < 5.1 do + before do + make_basic_app do |config| + config.enable_logs = true + config.rails.structured_logging.enabled = true + config.rails.structured_logging.subscribers = { active_job: Sentry::Rails::LogSubscribers::ActiveJobSubscriber } + end + end + + describe "integration with ActiveSupport::Notifications" do + it "logs job perform events when jobs are executed" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + NormalJob.perform_now + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") && log[:body]&.include?("NormalJob") } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("info") + expect(log_event[:attributes][:job_class][:value]).to eq("NormalJob") + expect(log_event[:attributes][:duration_ms][:value]).to be > 0 + end + + it "logs job enqueue events when jobs are enqueued" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + NormalJob.perform_later + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job enqueued") && log[:body]&.include?("NormalJob") } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("info") + expect(log_event[:attributes][:job_class][:value]).to eq("NormalJob") + expect(log_event[:attributes][:job_id][:value]).to be_a(String) + expect(log_event[:attributes][:queue_name][:value]).to eq("default") + end + end + + describe "job attributes extraction" do + it "includes job attributes in log events" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + NormalJob.perform_now + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } + expect(log_event).not_to be_nil + + attributes = log_event[:attributes] + expect(attributes[:job_class][:value]).to eq("NormalJob") + expect(attributes[:job_id][:value]).to be_a(String) + expect(attributes[:queue_name][:value]).to eq("default") + expect(attributes[:executions][:value]).to eq(1) + expect(attributes[:priority][:value]).to be_a(Integer).or be_nil + end + + it "includes adapter information when available" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + NormalJob.perform_now + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } + expect(log_event).not_to be_nil + + attributes = log_event[:attributes] + expect(attributes[:adapter][:value]).to include("TestAdapter") + end + end + + describe "scheduled job handling" do + it "includes scheduling information for delayed jobs" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + # Simulate a scheduled job enqueue event + job = NormalJob.new + job.job_id = SecureRandom.uuid + job.queue_name = "default" + job.priority = nil + job.scheduled_at = 1.hour.from_now + + ActiveSupport::Notifications.instrument("enqueue.active_job", job: job) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job enqueued") } + expect(log_event).not_to be_nil + + attributes = log_event[:attributes] + expect(attributes[:scheduled_at][:value]).to be_a(String) + expect(attributes[:delay_seconds][:value]).to be > 0 + end + end + + describe "argument filtering" do + context "when send_default_pii is enabled" do + before do + make_basic_app do |config| + config.enable_logs = true + config.send_default_pii = true + config.rails.structured_logging.enabled = true + config.rails.structured_logging.subscribers = { active_job: Sentry::Rails::LogSubscribers::ActiveJobSubscriber } + end + end + + it "includes filtered job arguments" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + # Create a job class that doesn't raise an error + test_job_class = Class.new(ActiveJob::Base) do + def self.name + "TestJobWithArgs" + end + + def perform(*args, **kwargs) + # Job implementation that doesn't raise + end + end + + test_job_class.perform_now("safe_arg", integer: 42, post: Post.create!) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } + expect(log_event).not_to be_nil + + attributes = log_event[:attributes] + expect(attributes[:arguments][:value]).to be_a(Array) + expect(attributes[:arguments][:value]).to include("safe_arg") + end + + it "filters sensitive arguments" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + original_filter_params = Rails.application.config.filter_parameters.dup + Rails.application.config.filter_parameters += [:token] + + # Create a job class that accepts sensitive arguments + test_job_class = Class.new(ActiveJob::Base) do + def self.name + "TestJobWithSensitiveArgs" + end + + def perform(password:, token:, safe_data:) + # Job implementation + end + end + + test_job_class.perform_now(password: "secret123", token: "abc123", safe_data: "public") + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } + expect(log_event).not_to be_nil + + attributes = log_event[:attributes] + arguments = attributes[:arguments][:value] + + expect(arguments.first).to include(safe_data: "public") + expect(arguments.first).to include(password: "[FILTERED]") + expect(arguments.first).to include(token: "[FILTERED]") + + Rails.application.config.filter_parameters = original_filter_params + end + end + + context "when send_default_pii is disabled" do + it "does not include job arguments" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + # Create a job class that doesn't raise an error + test_job_class = Class.new(ActiveJob::Base) do + def self.name + "TestJobNoArgs" + end + + def perform(*args, **kwargs) + # Job implementation that doesn't raise + end + end + + test_job_class.perform_now("arg", integer: 42, post: Post.create!) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } + expect(log_event).not_to be_nil + + attributes = log_event[:attributes] + expect(attributes).not_to have_key(:arguments) + end + end + end + + describe "retry and error handling" do + it "logs retry_stopped events" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + # Simulate a retry_stopped event + job = FailedJob.new + error = StandardError.new("Test error") + + ActiveSupport::Notifications.instrument("retry_stopped.active_job", + job: job, + error: error + ) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job retry stopped") } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("error") + expect(log_event[:attributes][:job_class][:value]).to eq("FailedJob") + expect(log_event[:attributes][:error_class][:value]).to eq("StandardError") + expect(log_event[:attributes][:error_message][:value]).to eq("Test error") + end + + it "logs discard events" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + # Simulate a discard event + job = FailedJob.new + error = StandardError.new("Test error") + + ActiveSupport::Notifications.instrument("discard.active_job", + job: job, + error: error + ) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job discarded") } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("warn") + expect(log_event[:attributes][:job_class][:value]).to eq("FailedJob") + expect(log_event[:attributes][:error_class][:value]).to eq("StandardError") + expect(log_event[:attributes][:error_message][:value]).to eq("Test error") + end + + it "logs discard events without error" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + # Simulate a discard event without error + job = FailedJob.new + + ActiveSupport::Notifications.instrument("discard.active_job", + job: job, + error: nil + ) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job discarded") } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("warn") + expect(log_event[:attributes][:job_class][:value]).to eq("FailedJob") + expect(log_event[:attributes]).not_to have_key(:error_class) + expect(log_event[:attributes]).not_to have_key(:error_message) + 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.subscribers = { active_job: Sentry::Rails::LogSubscribers::ActiveJobSubscriber } + end + end + + it "does not log events when logging is disabled" do + initial_log_count = sentry_logs.count + + NormalJob.perform_now + + if Sentry.get_current_client&.log_event_buffer + Sentry.get_current_client.flush + end + + expect(sentry_logs.count).to eq(initial_log_count) + end + end + + # Test ParameterFilter functionality using shared examples + include_examples "parameter filtering", described_class +end From 338ef6c690a26a519faa8d00bc939435d8795ef8 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 26 Aug 2025 07:45:44 +0000 Subject: [PATCH 08/21] [rails] add ActionMailer log subscriber --- .../action_mailer_subscriber.rb | 88 ++++++++ .../rails/action_mailer_subscriber_spec.rb | 199 ++++++++++++++++++ 2 files changed, 287 insertions(+) create mode 100644 sentry-rails/lib/sentry/rails/log_subscribers/action_mailer_subscriber.rb create mode 100644 sentry-rails/spec/sentry/rails/action_mailer_subscriber_spec.rb diff --git a/sentry-rails/lib/sentry/rails/log_subscribers/action_mailer_subscriber.rb b/sentry-rails/lib/sentry/rails/log_subscribers/action_mailer_subscriber.rb new file mode 100644 index 000000000..e3ee41a15 --- /dev/null +++ b/sentry-rails/lib/sentry/rails/log_subscribers/action_mailer_subscriber.rb @@ -0,0 +1,88 @@ +# frozen_string_literal: true + +require "sentry/rails/log_subscriber" +require "sentry/rails/log_subscribers/parameter_filter" + +module Sentry + module Rails + module LogSubscribers + # LogSubscriber for ActionMailer events that captures email delivery + # and processing events using Sentry's structured logging system. + # + # This subscriber captures deliver.action_mailer and process.action_mailer events + # and formats them with relevant email information while respecting PII settings. + # + # @example Usage + # # Enable structured logging for ActionMailer + # Sentry.init do |config| + # config.enable_logs = true + # config.rails.structured_logging = true + # config.rails.structured_logging.subscribers = { action_mailer: Sentry::Rails::LogSubscribers::ActionMailerSubscriber } + # end + class ActionMailerSubscriber < Sentry::Rails::LogSubscriber + include ParameterFilter + + # Handle deliver.action_mailer events + # + # @param event [ActiveSupport::Notifications::Event] The email delivery event + def deliver(event) + payload = event.payload + mailer = payload[:mailer] + duration = duration_ms(event) + + attributes = { + mailer: mailer, + duration_ms: duration, + perform_deliveries: payload[:perform_deliveries] + } + + attributes[:delivery_method] = payload[:delivery_method] if payload[:delivery_method] + attributes[:date] = payload[:date].to_s if payload[:date] + + if Sentry.configuration.send_default_pii + attributes[:message_id] = payload[:message_id] if payload[:message_id] + end + + message = "Email delivered via #{mailer}" + + # Log the structured event + log_structured_event( + message: message, + level: :info, + attributes: attributes + ) + end + + # Handle process.action_mailer events + # + # @param event [ActiveSupport::Notifications::Event] The email processing event + def process(event) + payload = event.payload + + mailer = payload[:mailer] + action = payload[:action] + duration = duration_ms(event) + + attributes = { + mailer: mailer, + action: action, + duration_ms: duration + } + + if Sentry.configuration.send_default_pii && payload[:params] + filtered_params = filter_sensitive_params(payload[:params]) + attributes[:params] = filtered_params unless filtered_params.empty? + end + + message = "#{mailer}##{action}" + + log_structured_event( + message: message, + level: :info, + attributes: attributes + ) + end + end + end + end +end diff --git a/sentry-rails/spec/sentry/rails/action_mailer_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/action_mailer_subscriber_spec.rb new file mode 100644 index 000000000..3b1668344 --- /dev/null +++ b/sentry-rails/spec/sentry/rails/action_mailer_subscriber_spec.rb @@ -0,0 +1,199 @@ +# frozen_string_literal: true + +require "spec_helper" +require "sentry/rails/log_subscribers/action_mailer_subscriber" + +RSpec.describe Sentry::Rails::LogSubscribers::ActionMailerSubscriber do + before do + make_basic_app do |config| + config.enable_logs = true + config.rails.structured_logging.enabled = true + config.rails.structured_logging.subscribers = { action_mailer: Sentry::Rails::LogSubscribers::ActionMailerSubscriber } + end + end + + describe "integration with ActiveSupport::Notifications" do + it "logs deliver events when emails are sent" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + ActiveSupport::Notifications.instrument("deliver.action_mailer", + mailer: "UserMailer", + perform_deliveries: true, + delivery_method: :test, + date: Time.current, + message_id: "test@example.com" + ) do + sleep(0.01) + end + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "Email delivered via UserMailer" } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("info") + expect(log_event[:attributes][:mailer][:value]).to eq("UserMailer") + expect(log_event[:attributes][:duration_ms][:value]).to be > 0 + expect(log_event[:attributes][:perform_deliveries][:value]).to be true + expect(log_event[:attributes][:delivery_method][:value]).to eq(:test) + expect(log_event[:attributes][:date]).to be_present + end + + it "logs process events when mailer actions are processed" do + ActiveSupport::Notifications.instrument("process.action_mailer", + mailer: "UserMailer", + action: "welcome_email", + params: { user_id: 123, name: "John Doe" } + ) do + sleep(0.01) + end + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "UserMailer#welcome_email" } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("info") + expect(log_event[:attributes][:mailer][:value]).to eq("UserMailer") + expect(log_event[:attributes][:action][:value]).to eq("welcome_email") + expect(log_event[:attributes][:duration_ms][:value]).to be > 0 + end + + it "includes delivery method when available" do + ActiveSupport::Notifications.instrument("deliver.action_mailer", + mailer: "NotificationMailer", + perform_deliveries: true, + delivery_method: :smtp + ) + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "Email delivered via NotificationMailer" } + expect(log_event).not_to be_nil + expect(log_event[:attributes][:delivery_method][:value]).to eq(:smtp) + 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 message_id for deliver events" do + ActiveSupport::Notifications.instrument("deliver.action_mailer", + mailer: "UserMailer", + perform_deliveries: true, + message_id: "unique-message-id@example.com" + ) + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "Email delivered via UserMailer" } + expect(log_event).not_to be_nil + expect(log_event[:attributes][:message_id][:value]).to eq("unique-message-id@example.com") + end + + it "includes filtered parameters for process events" do + ActiveSupport::Notifications.instrument("process.action_mailer", + mailer: "UserMailer", + action: "welcome_email", + params: { + user_id: 123, + safe_param: "value", + password: "secret", + email_address: "user@example.com", + subject: "Welcome!", + api_key: "secret-key" + } + ) + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "UserMailer#welcome_email" } + expect(log_event).not_to be_nil + expect(log_event[:attributes][:params]).to be_present + + params = log_event[:attributes][:params][:value] + + expect(params).to include(user_id: 123, safe_param: "value") + expect(params[:password]).to eq("[FILTERED]") + expect(params[:api_key]).to eq("[FILTERED]") + expect(params).to include(email_address: "user@example.com", subject: "Welcome!") + end + end + + context "when send_default_pii is disabled" do + it "does not include message_id for deliver events" do + ActiveSupport::Notifications.instrument("deliver.action_mailer", + mailer: "UserMailer", + perform_deliveries: true, + message_id: "unique-message-id@example.com" + ) + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "Email delivered via UserMailer" } + expect(log_event).not_to be_nil + expect(log_event[:attributes]).not_to have_key(:message_id) + end + + it "does not include parameters for process events" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + ActiveSupport::Notifications.instrument("process.action_mailer", + mailer: "UserMailer", + action: "welcome_email", + params: { user_id: 123, name: "John Doe" } + ) + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "UserMailer#welcome_email" } + 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.subscribers = { action_mailer: Sentry::Rails::LogSubscribers::ActionMailerSubscriber } + end + end + + it "does not log events when logging is disabled" do + initial_log_count = sentry_logs.count + + ActiveSupport::Notifications.instrument("deliver.action_mailer", + mailer: "UserMailer", + perform_deliveries: true + ) + + Sentry.get_current_client.flush + + expect(sentry_logs.count).to eq(initial_log_count) + end + end + + include_examples "parameter filtering", described_class +end From ce7e3ef34929efe94d3cc016909c7e1513f381f1 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Mon, 11 Aug 2025 14:15:04 +0000 Subject: [PATCH 09/21] [rails] add e2e specs for rails structured logging --- .../lib/sentry/debug_structured_logger.rb | 2 - spec/apps/rails-mini/Gemfile | 5 + spec/apps/rails-mini/app.rb | 193 +++++++++++++++++- spec/features/structured_logging_spec.rb | 49 +++++ spec/spec_helper.rb | 9 +- spec/support/test_helper.rb | 30 ++- 6 files changed, 279 insertions(+), 9 deletions(-) create mode 100644 spec/features/structured_logging_spec.rb diff --git a/sentry-ruby/lib/sentry/debug_structured_logger.rb b/sentry-ruby/lib/sentry/debug_structured_logger.rb index 88f32d3e7..129822c4b 100644 --- a/sentry-ruby/lib/sentry/debug_structured_logger.rb +++ b/sentry-ruby/lib/sentry/debug_structured_logger.rb @@ -51,8 +51,6 @@ def capture_log_event(level, message, parameters, **attributes) end def logged_events - return [] unless File.exist?(log_file) - File.readlines(log_file).map do |line| JSON.parse(line) end diff --git a/spec/apps/rails-mini/Gemfile b/spec/apps/rails-mini/Gemfile index be4cf2082..30350e931 100644 --- a/spec/apps/rails-mini/Gemfile +++ b/spec/apps/rails-mini/Gemfile @@ -4,7 +4,12 @@ source 'https://rubygems.org' gem "rake" gem "puma" + gem 'railties' gem 'actionpack' +gem 'activerecord' +gem 'activejob' +gem 'sqlite3' + gem 'sentry-ruby', path: Pathname(__dir__).join("../../..").realpath gem 'sentry-rails', path: Pathname(__dir__).join("../../..").realpath diff --git a/spec/apps/rails-mini/app.rb b/spec/apps/rails-mini/app.rb index 0750c387b..184d9b4af 100644 --- a/spec/apps/rails-mini/app.rb +++ b/spec/apps/rails-mini/app.rb @@ -5,8 +5,11 @@ Bundler.require ENV["RAILS_ENV"] = "development" +ENV["DATABASE_URL"] = "sqlite3:tmp/rails_mini_development.sqlite3" -require "action_controller" +require "action_controller/railtie" +require "active_record/railtie" +require "active_job/railtie" class RailsMiniApp < Rails::Application config.hosts = nil @@ -39,7 +42,73 @@ def debug_log_path config.transport.transport_class = Sentry::DebugTransport config.sdk_debug_transport_log_file = debug_log_path.join("sentry_debug_events.log") config.background_worker_threads = 0 + + config.enable_logs = true + config.structured_logger_class = Sentry::DebugStructuredLogger + config.sdk_debug_structured_logger_log_file = debug_log_path.join("sentry_e2e_tests.log") + + config.rails.structured_logging.enabled = true + + config.rails.structured_logging.subscribers = { + active_record: Sentry::Rails::LogSubscribers::ActiveRecordSubscriber, + action_controller: Sentry::Rails::LogSubscribers::ActionControllerSubscriber, + active_job: Sentry::Rails::LogSubscribers::ActiveJobSubscriber + } + end + end +end + +class Post < ActiveRecord::Base +end + +class User < ActiveRecord::Base +end + +class ApplicationJob < ActiveJob::Base + retry_on ActiveRecord::Deadlocked + + discard_on ActiveJob::DeserializationError +end + +class SampleJob < ApplicationJob + queue_as :default + + def perform(message = "Hello from ActiveJob!") + Rails.logger.info("SampleJob executed with message: #{message}") + + Post.count + User.count + + message + end +end + +class DatabaseJob < ApplicationJob + queue_as :default + + def perform(post_title = "Test Post") + Rails.logger.info("DatabaseJob creating post: #{post_title}") + + post = Post.create!(title: post_title, content: "Content for #{post_title}") + found_post = Post.find(post.id) + + Rails.logger.info("DatabaseJob found post: #{found_post.title}") + + found_post + end +end + +class FailingJob < ApplicationJob + queue_as :default + + def perform(should_fail = true) + Rails.logger.info("FailingJob started") + + if should_fail + raise StandardError, "Intentional job failure for testing" end + + "Job completed successfully" end end @@ -97,12 +166,134 @@ def set_cors_headers end end +class PostsController < ActionController::Base + before_action :set_cors_headers + def index + posts = Post.all.to_a + + Sentry.logger.info("Posts index accessed", posts_count: posts.length) + + render json: { + posts: posts.map { |p| { id: p.id, title: p.title, content: p.content } } + } + end + + def create + post = Post.create!(post_params) + + Sentry.logger.info("Post created", post_id: post.id, title: post.title) + + render json: { post: { id: post.id, title: post.title, content: post.content } }, status: :created + rescue ActiveRecord::RecordInvalid => e + render json: { error: e.message }, status: :unprocessable_entity + end + + def show + post = Post.find(params[:id]) + render json: { post: { id: post.id, title: post.title, content: post.content } } + rescue ActiveRecord::RecordNotFound + render json: { error: "Post not found" }, status: :not_found + end + + private + + def post_params + params.require(:post).permit(:title, :content) + end + + def set_cors_headers + response.headers['Access-Control-Allow-Origin'] = '*' + response.headers['Access-Control-Allow-Methods'] = 'GET, POST, PUT, DELETE, OPTIONS' + response.headers['Access-Control-Allow-Headers'] = 'Content-Type, Authorization, sentry-trace, baggage' + end +end + +class JobsController < ActionController::Base + before_action :set_cors_headers + + def sample_job + job = SampleJob.perform_later("Hello from Rails mini app!") + + Sentry.logger.info("SampleJob enqueued", job_id: job.job_id) + + render json: { + message: "SampleJob enqueued successfully", + job_id: job.job_id, + job_class: job.class.name + } + end + + def database_job + title = params[:title] || "Test Post from Job" + job = DatabaseJob.perform_later(title) + + Sentry.logger.info("DatabaseJob enqueued", job_id: job.job_id, post_title: title) + + render json: { + message: "DatabaseJob enqueued successfully", + job_id: job.job_id, + job_class: job.class.name, + post_title: title + } + end + + def failing_job + should_fail = params[:should_fail] != "false" + job = FailingJob.perform_later(should_fail) + + Sentry.logger.info("FailingJob enqueued", job_id: job.job_id, should_fail: should_fail) + + render json: { + message: "FailingJob enqueued successfully", + job_id: job.job_id, + job_class: job.class.name, + should_fail: should_fail + } + end + + private + + def set_cors_headers + response.headers['Access-Control-Allow-Origin'] = '*' + response.headers['Access-Control-Allow-Methods'] = 'GET, POST, PUT, DELETE, OPTIONS' + response.headers['Access-Control-Allow-Headers'] = 'Content-Type, Authorization, sentry-trace, baggage' + end +end + RailsMiniApp.initialize! +ActiveRecord::Schema.define do + create_table :posts, force: true do |t| + t.string :title, null: false + t.text :content + t.timestamps + end + + create_table :users, force: true do |t| + t.string :name, null: false + t.string :email + t.timestamps + end +end + +Post.create!(title: "Welcome Post", content: "Welcome to the Rails mini app!") +Post.create!(title: "Sample Post", content: "This is a sample post for testing.") +User.create!(name: "Test User", email: "test@example.com") + RailsMiniApp.routes.draw do get '/health', to: 'events#health' get '/error', to: 'error#error' get '/trace_headers', to: 'events#trace_headers' + get '/logged_events', to: 'events#logged_events' + post '/clear_logged_events', to: 'events#clear_logged_events' + + get '/posts', to: 'posts#index' + post '/posts', to: 'posts#create' + get '/posts/:id', to: 'posts#show' + + post '/jobs/sample', to: 'jobs#sample_job' + post '/jobs/database', to: 'jobs#database_job' + post '/jobs/failing', to: 'jobs#failing_job' match '*path', to: proc { |env| [200, { diff --git a/spec/features/structured_logging_spec.rb b/spec/features/structured_logging_spec.rb new file mode 100644 index 000000000..9e67e00c4 --- /dev/null +++ b/spec/features/structured_logging_spec.rb @@ -0,0 +1,49 @@ +# frozen_string_literal: true + +RSpec.describe "Structured Logging", type: :e2e do + it "captures Rails application logs using structured logging" do + response = make_request("/posts") + expect(response.code).to eq("200") + + logged_events = Sentry.logger.logged_events + expect(logged_events).not_to be_empty + + log_event = logged_events.first + expect(log_event).to have_key("timestamp") + expect(log_event).to have_key("level") + expect(log_event).to have_key("message") + expect(log_event).to have_key("attributes") + expect(log_event["timestamp"]).to be_a(String) + end + + it "captures logs from Rails mini app" do + response = make_request("/posts") + expect(response.code).to eq("200") + + logged_events = Sentry.logger.logged_events + expect(logged_events).not_to be_empty + + posts_log = logged_events.find { |log| log["message"] == "Posts index accessed" } + expect(posts_log).not_to be_nil + expect(posts_log["level"]).to eq("info") + expect(posts_log["attributes"]["posts_count"]).to eq(2) + end + + it "captures structured logs with proper format" do + response = make_request("/posts") + expect(response.code).to eq("200") + + logged_events = Sentry.logger.logged_events + expect(logged_events).not_to be_empty + + log_event = logged_events.first + expect(log_event).to have_key("timestamp") + expect(log_event).to have_key("level") + expect(log_event).to have_key("message") + expect(log_event).to have_key("attributes") + expect(log_event["timestamp"]).to be_a(String) + expect(log_event["level"]).to be_a(String) + expect(log_event["message"]).to be_a(String) + expect(log_event["attributes"]).to be_a(Hash) + end +end diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index c52c47664..6329d91c7 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -7,6 +7,7 @@ require "capybara" require "capybara/rspec" +require "debug" require_relative "support/test_helper" @@ -31,12 +32,14 @@ RSpec.configure do |config| config.include(Capybara::DSL, type: :e2e) - config.include(Test::Helper) config.before(:suite) do Test::Helper.perform_basic_setup do |config| config.transport.transport_class = Sentry::DebugTransport + config.structured_logger_class = Sentry::DebugStructuredLogger + config.sdk_debug_structured_logger_log_file = Test::Helper.debug_log_path.join("sentry_e2e_tests.log") + config.enable_logs = true end Test::Helper.clear_logged_events @@ -45,4 +48,8 @@ config.after(:each) do Test::Helper.clear_logged_events end + + config.after(:each) do + Test::Helper.clear_logs + end end diff --git a/spec/support/test_helper.rb b/spec/support/test_helper.rb index ebc66d2d3..4cceef141 100644 --- a/spec/support/test_helper.rb +++ b/spec/support/test_helper.rb @@ -1,9 +1,20 @@ # frozen_string_literal: true +require 'net/http' +require 'uri' + module Test module Helper module_function + def rails_app_url + ENV.fetch("SENTRY_E2E_RAILS_APP_URL") + end + + def make_request(path) + Net::HTTP.get_response(URI("#{rails_app_url}#{path}")) + end + def logged_events @logged_events ||= begin extracted_events = [] @@ -40,11 +51,7 @@ def logged_envelopes end def logged_structured_events - if Sentry.logger.is_a?(Sentry::DebugStructuredLogger) - Sentry.logger.logged_events - else - [] - end + Sentry.logger.logged_events end # TODO: move this to a shared helper for all gems @@ -58,5 +65,18 @@ def perform_basic_setup yield(config) if block_given? end end + + def debug_log_path + @log_path ||= begin + path = Pathname(__dir__).join("../../log") + FileUtils.mkdir_p(path) unless path.exist? + path.realpath + end + end + + def clear_logs + Sentry.get_current_client.transport.clear + Sentry.logger.clear + end end end From 0ac50225c602e424e13e67e7ce97df99536ace49 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Wed, 27 Aug 2025 11:06:15 +0000 Subject: [PATCH 10/21] [rails] move specs --- .../action_controller_subscriber_spec.rb | 0 .../action_mailer_subscriber_spec.rb | 0 .../active_job_subscriber_spec.rb | 11 ----------- .../active_record_subscriber_spec.rb | 0 4 files changed, 11 deletions(-) rename sentry-rails/spec/sentry/rails/{ => log_subscribers}/action_controller_subscriber_spec.rb (100%) rename sentry-rails/spec/sentry/rails/{ => log_subscribers}/action_mailer_subscriber_spec.rb (100%) rename sentry-rails/spec/sentry/rails/{ => log_subscribers}/active_job_subscriber_spec.rb (94%) rename sentry-rails/spec/sentry/rails/{ => log_subscribers}/active_record_subscriber_spec.rb (100%) diff --git a/sentry-rails/spec/sentry/rails/action_controller_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/action_controller_subscriber_spec.rb similarity index 100% rename from sentry-rails/spec/sentry/rails/action_controller_subscriber_spec.rb rename to sentry-rails/spec/sentry/rails/log_subscribers/action_controller_subscriber_spec.rb diff --git a/sentry-rails/spec/sentry/rails/action_mailer_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb similarity index 100% rename from sentry-rails/spec/sentry/rails/action_mailer_subscriber_spec.rb rename to sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb diff --git a/sentry-rails/spec/sentry/rails/active_job_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb similarity index 94% rename from sentry-rails/spec/sentry/rails/active_job_subscriber_spec.rb rename to sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb index 2c3e6f8c1..732ae9cfa 100644 --- a/sentry-rails/spec/sentry/rails/active_job_subscriber_spec.rb +++ b/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb @@ -90,7 +90,6 @@ sentry_transport.events.clear sentry_transport.envelopes.clear - # Simulate a scheduled job enqueue event job = NormalJob.new job.job_id = SecureRandom.uuid job.queue_name = "default" @@ -125,14 +124,12 @@ sentry_transport.events.clear sentry_transport.envelopes.clear - # Create a job class that doesn't raise an error test_job_class = Class.new(ActiveJob::Base) do def self.name "TestJobWithArgs" end def perform(*args, **kwargs) - # Job implementation that doesn't raise end end @@ -155,14 +152,12 @@ def perform(*args, **kwargs) original_filter_params = Rails.application.config.filter_parameters.dup Rails.application.config.filter_parameters += [:token] - # Create a job class that accepts sensitive arguments test_job_class = Class.new(ActiveJob::Base) do def self.name "TestJobWithSensitiveArgs" end def perform(password:, token:, safe_data:) - # Job implementation end end @@ -189,14 +184,12 @@ def perform(password:, token:, safe_data:) sentry_transport.events.clear sentry_transport.envelopes.clear - # Create a job class that doesn't raise an error test_job_class = Class.new(ActiveJob::Base) do def self.name "TestJobNoArgs" end def perform(*args, **kwargs) - # Job implementation that doesn't raise end end @@ -218,7 +211,6 @@ def perform(*args, **kwargs) sentry_transport.events.clear sentry_transport.envelopes.clear - # Simulate a retry_stopped event job = FailedJob.new error = StandardError.new("Test error") @@ -241,7 +233,6 @@ def perform(*args, **kwargs) sentry_transport.events.clear sentry_transport.envelopes.clear - # Simulate a discard event job = FailedJob.new error = StandardError.new("Test error") @@ -264,7 +255,6 @@ def perform(*args, **kwargs) sentry_transport.events.clear sentry_transport.envelopes.clear - # Simulate a discard event without error job = FailedJob.new ActiveSupport::Notifications.instrument("discard.active_job", @@ -305,6 +295,5 @@ def perform(*args, **kwargs) end end - # Test ParameterFilter functionality using shared examples include_examples "parameter filtering", described_class end diff --git a/sentry-rails/spec/sentry/rails/active_record_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/active_record_subscriber_spec.rb similarity index 100% rename from sentry-rails/spec/sentry/rails/active_record_subscriber_spec.rb rename to sentry-rails/spec/sentry/rails/log_subscribers/active_record_subscriber_spec.rb From cf91d44d79bd4890ce0e75fd101c4d0d68745451 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Wed, 27 Aug 2025 15:01:16 +0000 Subject: [PATCH 11/21] [rails] add requires --- sentry-rails/lib/sentry/rails/structured_logging.rb | 6 ++++++ .../log_subscribers/action_controller_subscriber_spec.rb | 2 -- .../rails/log_subscribers/action_mailer_subscriber_spec.rb | 1 - .../rails/log_subscribers/active_job_subscriber_spec.rb | 3 --- .../rails/log_subscribers/active_record_subscriber_spec.rb | 1 - 5 files changed, 6 insertions(+), 7 deletions(-) diff --git a/sentry-rails/lib/sentry/rails/structured_logging.rb b/sentry-rails/lib/sentry/rails/structured_logging.rb index ee1246a22..d184c519c 100644 --- a/sentry-rails/lib/sentry/rails/structured_logging.rb +++ b/sentry-rails/lib/sentry/rails/structured_logging.rb @@ -1,5 +1,11 @@ # frozen_string_literal: true +require "sentry/rails/log_subscriber" +require "sentry/rails/log_subscribers/action_controller_subscriber" +require "sentry/rails/log_subscribers/active_record_subscriber" +require "sentry/rails/log_subscribers/active_job_subscriber" +require "sentry/rails/log_subscribers/action_mailer_subscriber" + module Sentry module Rails module StructuredLogging 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 index c417cb355..5e95351fa 100644 --- 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 @@ -1,7 +1,6 @@ # 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 @@ -9,7 +8,6 @@ config.enable_logs = true config.rails.structured_logging.enabled = true config.rails.structured_logging.subscribers = { action_controller: Sentry::Rails::LogSubscribers::ActionControllerSubscriber } - app.config.filter_parameters += [:api_key, :credit_card, :authorization] end end diff --git a/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb index 3b1668344..158439c41 100644 --- a/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb +++ b/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb @@ -1,7 +1,6 @@ # frozen_string_literal: true require "spec_helper" -require "sentry/rails/log_subscribers/action_mailer_subscriber" RSpec.describe Sentry::Rails::LogSubscribers::ActionMailerSubscriber do before do diff --git a/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb index 732ae9cfa..8a691a9fa 100644 --- a/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb +++ b/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb @@ -1,9 +1,6 @@ # frozen_string_literal: true require "spec_helper" -require "sentry/rails/log_subscribers/active_job_subscriber" - -require_relative "../../support/test_jobs" RSpec.describe Sentry::Rails::LogSubscribers::ActiveJobSubscriber, skip: Rails.version.to_f < 5.1 do before do 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 index c941a8274..deaf7500e 100644 --- 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 @@ -1,7 +1,6 @@ # frozen_string_literal: true require "spec_helper" -require "sentry/rails/log_subscribers/active_record_subscriber" RSpec.describe Sentry::Rails::LogSubscribers::ActiveRecordSubscriber do before do From be038276097e50e652615d731c1d5b4e34b0f898 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 26 Aug 2025 15:32:10 +0000 Subject: [PATCH 12/21] Update CHANGELOG --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 4c9f8d319..f367036db 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,8 @@ ### Feature - Propagated sampling rates as specified in [Traces](https://develop.sentry.dev/sdk/telemetry/traces/#propagated-random-value) docs ([#2671](https://github.com/getsentry/sentry-ruby/pull/2671)) +- Support for Rails ActiveSupport log subscribers ([#2690](https://github.com/getsentry/sentry-ruby/pull/2690)) +- Support for defining custom Rails log subscribers that work with Sentry Structured Logging ([#2689](https://github.com/getsentry/sentry-ruby/pull/2689)) ### Internal From 1c63745f224ce72516e7fd05a1c98d672ebb6754 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Mon, 1 Sep 2025 16:09:35 +0000 Subject: [PATCH 13/21] Simplify config --- sentry-rails/lib/sentry/rails/configuration.rb | 15 --------------- .../spec/sentry/rails/configuration_spec.rb | 10 +++++----- .../spec/sentry/rails/structured_logging_spec.rb | 4 ++-- 3 files changed, 7 insertions(+), 22 deletions(-) diff --git a/sentry-rails/lib/sentry/rails/configuration.rb b/sentry-rails/lib/sentry/rails/configuration.rb index 0d43fe3ab..cd7d29360 100644 --- a/sentry-rails/lib/sentry/rails/configuration.rb +++ b/sentry-rails/lib/sentry/rails/configuration.rb @@ -163,21 +163,6 @@ class Configuration # @return [StructuredLoggingConfiguration] attr_reader :structured_logging - # Allow setting structured_logging as a boolean for convenience - # @param value [Boolean, StructuredLoggingConfiguration] - def structured_logging=(value) - case value - when true - @structured_logging.enabled = true - when false - @structured_logging.enabled = false - when StructuredLoggingConfiguration - @structured_logging = value - else - raise ArgumentError, "structured_logging must be a boolean or StructuredLoggingConfiguration" - end - end - def initialize @register_error_subscriber = false @report_rescued_exceptions = true diff --git a/sentry-rails/spec/sentry/rails/configuration_spec.rb b/sentry-rails/spec/sentry/rails/configuration_spec.rb index 0a6dc9544..adf08a635 100644 --- a/sentry-rails/spec/sentry/rails/configuration_spec.rb +++ b/sentry-rails/spec/sentry/rails/configuration_spec.rb @@ -69,18 +69,18 @@ class MySubscriber; end describe "#structured_logging" do let(:config) { Sentry.configuration.rails } - it "allows enabling by setting to true" do + it "allows enabling by setting enabled to true" do make_basic_app do |config| - config.rails.structured_logging = true + config.rails.structured_logging.enabled = true end expect(config.structured_logging.enabled).to be(true) expect(config.structured_logging.subscribers).to be_a(Hash) end - it "allows disabling by setting to false" do + it "allows disabling by setting enabled to false" do make_basic_app do |config| - config.rails.structured_logging = false + config.rails.structured_logging.enabled = false end expect(config.structured_logging.enabled).to be(false) @@ -91,7 +91,7 @@ class MySubscriber; end class TestSubscriber; end make_basic_app do |config| - config.rails.structured_logging = true + config.rails.structured_logging.enabled = true config.rails.structured_logging.subscribers = { action_controller: TestSubscriber } end diff --git a/sentry-rails/spec/sentry/rails/structured_logging_spec.rb b/sentry-rails/spec/sentry/rails/structured_logging_spec.rb index 1c7ee1abd..b414d86e0 100644 --- a/sentry-rails/spec/sentry/rails/structured_logging_spec.rb +++ b/sentry-rails/spec/sentry/rails/structured_logging_spec.rb @@ -7,7 +7,7 @@ before do make_basic_app do |config| config.enable_logs = false - config.rails.structured_logging = true + config.rails.structured_logging.enabled = true end end @@ -26,7 +26,7 @@ before do make_basic_app do |config| config.enable_logs = true - config.rails.structured_logging = false + config.rails.structured_logging.enabled = false end end From 0256acc46d86241ea11102ed9cfe4860e4cf96c2 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Mon, 1 Sep 2025 19:28:33 +0000 Subject: [PATCH 14/21] Fix debug transport clean up --- sentry-ruby/lib/sentry/test_helper.rb | 15 +++++++++++---- 1 file changed, 11 insertions(+), 4 deletions(-) diff --git a/sentry-ruby/lib/sentry/test_helper.rb b/sentry-ruby/lib/sentry/test_helper.rb index 39ee0dca2..bcee3d9df 100644 --- a/sentry-ruby/lib/sentry/test_helper.rb +++ b/sentry-ruby/lib/sentry/test_helper.rb @@ -63,13 +63,20 @@ def teardown_sentry_test end def clear_sentry_events - if Sentry.initialized? && Sentry.configuration.enable_logs - [Sentry.get_current_client.transport, Sentry.logger].each do |obj| - obj.clear if obj.respond_to?(:clear) - end + return unless Sentry.initialized? + + sentry_transport.clear if sentry_transport.respond_to?(:clear) + + if Sentry.configuration.enable_logs && sentry_logger.respond_to?(:clear) + sentry_logger.clear end end + # @return [Sentry::StructuredLogger, Sentry::DebugStructuredLogger] + def sentry_logger + Sentry.logger + end + # @return [Transport] def sentry_transport Sentry.get_current_client.transport From 1424ecd895b68adf66268f63f5383872a9cab495 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 2 Sep 2025 08:44:30 +0000 Subject: [PATCH 15/21] Skip including db attributes if connection is not in the payload --- .../active_record_subscriber.rb | 9 ------- .../active_record_subscriber_spec.rb | 26 ++++++++++--------- 2 files changed, 14 insertions(+), 21 deletions(-) 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 index 3245025e3..6abdf5f0b 100644 --- a/sentry-rails/lib/sentry/rails/log_subscribers/active_record_subscriber.rb +++ b/sentry-rails/lib/sentry/rails/log_subscribers/active_record_subscriber.rb @@ -74,18 +74,9 @@ def build_log_message(statement_name) 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) 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 index deaf7500e..b59e31563 100644 --- 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 @@ -59,22 +59,24 @@ end end - describe "database configuration extraction" do - it "includes database configuration in log attributes" do - Post.create! + if Rails.version.to_f >= 7.2 + describe "database configuration extraction" do + it "includes database configuration in log attributes" do + Post.create! - Sentry.get_current_client.flush + Sentry.get_current_client.flush - log_event = sentry_logs.find do |log| - log[:body]&.include?("Database query") && - log[:attributes]&.dig(:sql, :value)&.include?("INSERT") - end + 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 + 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") + attributes = log_event[:attributes] + expect(attributes[:db_system][:value]).to eq("sqlite3") + expect(attributes[:db_name][:value]).to eq("db") + end end end From 352385cb3676516bb61a3d65fc04c3e43e7cfc9f Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 2 Sep 2025 08:07:14 +0000 Subject: [PATCH 16/21] Fix handling of duration --- .../rails/log_subscribers/action_controller_subscriber.rb | 2 +- .../log_subscribers/action_controller_subscriber_spec.rb | 6 +++++- 2 files changed, 6 insertions(+), 2 deletions(-) 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 index 3496f71f5..482d4efd3 100644 --- a/sentry-rails/lib/sentry/rails/log_subscribers/action_controller_subscriber.rb +++ b/sentry-rails/lib/sentry/rails/log_subscribers/action_controller_subscriber.rb @@ -28,7 +28,7 @@ class ActionControllerSubscriber < Sentry::Rails::LogSubscriber # @param event [ActiveSupport::Notifications::Event] The controller action event def process_action(event) payload = event.payload - duration = event.time.round(2) + duration = event.duration.round(2) controller = payload[:controller] action = payload[:action] 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 index 5e95351fa..b62d08cde 100644 --- 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 @@ -25,7 +25,11 @@ 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 + + duration = log_event[:attributes][:duration_ms][:value] + expect(duration).to be_a(Float) + expect(duration).to be_in(0.01..30.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) From 741eea35156b199cb26feca17fa6ada44a02ffae Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 2 Sep 2025 08:12:10 +0000 Subject: [PATCH 17/21] Set action controller and active record as default log subscribers --- sentry-rails/lib/sentry/rails/configuration.rb | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/sentry-rails/lib/sentry/rails/configuration.rb b/sentry-rails/lib/sentry/rails/configuration.rb index cd7d29360..70f975cf7 100644 --- a/sentry-rails/lib/sentry/rails/configuration.rb +++ b/sentry-rails/lib/sentry/rails/configuration.rb @@ -6,6 +6,9 @@ require "sentry/rails/tracing/active_storage_subscriber" require "sentry/rails/tracing/active_support_subscriber" +require "sentry/rails/log_subscribers/active_record_subscriber" +require "sentry/rails/log_subscribers/action_controller_subscriber" + module Sentry class Configuration attr_reader :rails @@ -193,9 +196,14 @@ class StructuredLoggingConfiguration # @return [Hash] attr_accessor :subscribers + DEFAULT_SUBSCRIBERS = { + active_record: Sentry::Rails::LogSubscribers::ActiveRecordSubscriber, + action_controller: Sentry::Rails::LogSubscribers::ActionControllerSubscriber + }.freeze + def initialize @enabled = false - @subscribers = {} + @subscribers = DEFAULT_SUBSCRIBERS.dup end end end From 2a78399e2319169cbfe5646e23fbfa233b819ab3 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 2 Sep 2025 08:28:02 +0000 Subject: [PATCH 18/21] Update CHANGELOG --- CHANGELOG.md | 65 ++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 65 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index f367036db..77bb76e75 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,71 @@ - Support for Rails ActiveSupport log subscribers ([#2690](https://github.com/getsentry/sentry-ruby/pull/2690)) - Support for defining custom Rails log subscribers that work with Sentry Structured Logging ([#2689](https://github.com/getsentry/sentry-ruby/pull/2689)) + Rails applications can now define custom log subscribers that integrate with Sentry's structured logging system. The feature includes built-in subscribers for ActionController, ActiveRecord, ActiveJob, and ActionMailer events, with automatic parameter filtering that respects Rails' `config.filter_parameters` configuration. + + To enable structured logging with Rails log subscribers: + + ```ruby + Sentry.init do |config| + # ... your setup ... + + # Make sure structured logging is enabled + config.enable_logs = true + + # Enable default Rails log subscribers (ActionController and ActiveRecord) + config.rails.structured_logging.enabled = true + end + ``` + + To configure all subscribers: + + ```ruby + Sentry.init do |config| + # ... your setup ... + + # Make sure structured logging is enabled + config.enable_logs = true + + # Enable Rails log subscribers + config.rails.structured_logging.enabled = true + + # Add ActionMailer and ActiveJob subscribers + config.rails.structured_logging.subscribers.update( + action_mailer: Sentry::Rails::LogSubscribers::ActionMailerSubscriber, + active_job: Sentry::Rails::LogSubscribers::ActiveJobSubscriber + ) + end + ``` + + You can also define custom log subscribers by extending the base class: + + ```ruby + class MyCustomSubscriber < Sentry::Rails::LogSubscriber + attach_to :my_component + + def my_event(event) + log_structured_event( + message: "Custom event occurred", + level: :info, + attributes: { duration_ms: event.duration } + ) + end + end + + Sentry.init do |config| + # ... your setup ... + + # Make sure structured logging is enabled + config.enable_logs = true + + # Enable Rails log subscribers + config.rails.structured_logging.enabled = true + + # Add custom subscriber + config.rails.structured_logging.subscribers[:my_component] = MyCustomSubscriber + end + ``` + ### Internal - Factor out do_request in HTTP transport ([#2662](https://github.com/getsentry/sentry-ruby/pull/2662)) From 7ff156aa818e01da95ad25ae8246cf119ee366c6 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 2 Sep 2025 08:59:09 +0000 Subject: [PATCH 19/21] Use duration_ms helper --- .../rails/log_subscribers/action_controller_subscriber.rb | 3 +-- .../sentry/rails/log_subscribers/action_mailer_subscriber.rb | 4 ++-- .../sentry/rails/log_subscribers/active_record_subscriber.rb | 3 +-- 3 files changed, 4 insertions(+), 6 deletions(-) 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 index 482d4efd3..eaacb8ff2 100644 --- a/sentry-rails/lib/sentry/rails/log_subscribers/action_controller_subscriber.rb +++ b/sentry-rails/lib/sentry/rails/log_subscribers/action_controller_subscriber.rb @@ -28,7 +28,6 @@ class ActionControllerSubscriber < Sentry::Rails::LogSubscriber # @param event [ActiveSupport::Notifications::Event] The controller action event def process_action(event) payload = event.payload - duration = event.duration.round(2) controller = payload[:controller] action = payload[:action] @@ -39,7 +38,7 @@ def process_action(event) controller: controller, action: action, status: status, - duration_ms: duration, + duration_ms: duration_ms(event), method: payload[:method], path: payload[:path], format: payload[:format] diff --git a/sentry-rails/lib/sentry/rails/log_subscribers/action_mailer_subscriber.rb b/sentry-rails/lib/sentry/rails/log_subscribers/action_mailer_subscriber.rb index e3ee41a15..63f16e41f 100644 --- a/sentry-rails/lib/sentry/rails/log_subscribers/action_mailer_subscriber.rb +++ b/sentry-rails/lib/sentry/rails/log_subscribers/action_mailer_subscriber.rb @@ -27,12 +27,12 @@ class ActionMailerSubscriber < Sentry::Rails::LogSubscriber # @param event [ActiveSupport::Notifications::Event] The email delivery event def deliver(event) payload = event.payload + mailer = payload[:mailer] - duration = duration_ms(event) attributes = { mailer: mailer, - duration_ms: duration, + duration_ms: duration_ms(event), perform_deliveries: payload[:perform_deliveries] } 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 index 6abdf5f0b..c159e2423 100644 --- a/sentry-rails/lib/sentry/rails/log_subscribers/active_record_subscriber.rb +++ b/sentry-rails/lib/sentry/rails/log_subscribers/active_record_subscriber.rb @@ -37,13 +37,12 @@ def sql(event) # 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, + duration_ms: duration_ms(event), cached: cached } From 01ae4cb7a46143cae9dd6a39240f4d23b3095ed1 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Tue, 2 Sep 2025 09:20:29 +0000 Subject: [PATCH 20/21] Clean up specs organization This avoids double-setup of test rails apps which makes specs faster and fixes warnings --- .../spec/sentry/rails/log_subscriber_spec.rb | 3 +- .../action_controller_subscriber_spec.rb | 294 +++++++------- .../action_mailer_subscriber_spec.rb | 247 ++++++------ .../active_job_subscriber_spec.rb | 368 ++++++++---------- .../active_record_subscriber_spec.rb | 183 ++++----- .../shared_examples_for_parameter_filter.rb | 13 + 6 files changed, 536 insertions(+), 572 deletions(-) diff --git a/sentry-rails/spec/sentry/rails/log_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscriber_spec.rb index a8fcc4fa4..10135859c 100644 --- a/sentry-rails/spec/sentry/rails/log_subscriber_spec.rb +++ b/sentry-rails/spec/sentry/rails/log_subscriber_spec.rb @@ -9,7 +9,6 @@ let!(:test_subscriber) { test_subscriber_class.new } after do - Sentry.logger.clear if Sentry.logger.respond_to?(:clear) test_subscriber_class.detach_from(:test_component) end @@ -242,9 +241,9 @@ def filtering_event(event) before do make_basic_app do |config, app| config.enable_logs = true + config.structured_logger_class = Sentry::DebugStructuredLogger config.send_default_pii = true - app.config.filter_parameters += [:custom_secret, :api_key, :credit_card, :authorization] 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 index b62d08cde..b815e4aee 100644 --- 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 @@ -3,221 +3,197 @@ require "spec_helper" RSpec.describe Sentry::Rails::LogSubscribers::ActionControllerSubscriber, type: :request do - before do - make_basic_app do |config, app| - config.enable_logs = true - config.rails.structured_logging.enabled = true - config.rails.structured_logging.subscribers = { action_controller: Sentry::Rails::LogSubscribers::ActionControllerSubscriber } - end - end - - describe "integration with ActiveSupport::Notifications" do - it "logs controller action events when requests are processed" do - get "/world" - - Sentry.get_current_client.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) - - duration = log_event[:attributes][:duration_ms][:value] - expect(duration).to be_a(Float) - expect(duration).to be_in(0.01..30.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 - get "/not_found" - - Sentry.get_current_client.flush - - expect(sentry_logs).not_to be_empty + context "when logging is enabled" do + before do + make_basic_app do |config, app| + config.enable_logs = true - 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) + config.rails.structured_logging.enabled = true + config.rails.structured_logging.subscribers = { action_controller: Sentry::Rails::LogSubscribers::ActionControllerSubscriber } + end end - it "logs error status codes with error level" do - get "/exception" + describe "integration with ActiveSupport::Notifications" do + it "logs controller action events when requests are processed" do + get "/world" - Sentry.get_current_client.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 - get "/view" + Sentry.get_current_client.flush - Sentry.get_current_client.flush + expect(sentry_logs).not_to be_empty - 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) + + duration = log_event[:attributes][:duration_ms][:value] + expect(duration).to be_a(Float) + expect(duration).to be_in(0.01..30.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 - 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 "logs bad requests appropriately" do + get "/not_found" - it "includes database runtime when available" do - Post.create! - get "/posts" + Sentry.get_current_client.flush - Sentry.get_current_client.flush + expect(sentry_logs).not_to be_empty - 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 - log_event = sentry_logs.find { |log| log[:body] == "PostsController#index" } - expect(log_event).not_to be_nil + it "logs error status codes with error level" do + get "/exception" - 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 + Sentry.get_current_client.flush - context "when send_default_pii is enabled" do - before do - Sentry.configuration.send_default_pii = true - end + expect(sentry_logs).not_to be_empty - after do - Sentry.configuration.send_default_pii = false + 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 filtered request parameters" do - get "/world", params: { safe_param: "value", password: "secret" } + it "includes view runtime when available" do + get "/view" Sentry.get_current_client.flush expect(sentry_logs).not_to be_empty - log_event = sentry_logs.find { |log| log[:body] == "HelloController#world" } + log_event = sentry_logs.find { |log| log[:body] == "HelloController#view" } 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]).to include("password" => "[FILTERED]") + expect(log_event[:attributes][:view_runtime_ms]).to be_present + expect(log_event[:attributes][:view_runtime_ms][:value]).to be >= 0 end - it "filters sensitive parameter names" do - get "/world", params: { - normal_param: "value", - password: "secret", - api_key: "key123", - credit_card: "1234567890", - authorization: "Bearer token" - } + it "includes database runtime when available" do + Post.create! + get "/posts" Sentry.get_current_client.flush expect(sentry_logs).not_to be_empty - log_event = sentry_logs.find { |log| log[:body] == "HelloController#world" } + log_event = sentry_logs.find { |log| log[:body] == "PostsController#index" } expect(log_event).not_to be_nil - params = log_event[:attributes][:params][:value] - expect(params).to include("normal_param" => "value") - expect(params).to include("password" => "[FILTERED]") - expect(params).to include("api_key" => "[FILTERED]") - expect(params).to include("credit_card" => "[FILTERED]") - expect(params).to include("authorization" => "[FILTERED]") + 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 - it "respects Rails filter_parameters configuration" do - original_filter_params = Rails.application.config.filter_parameters.dup - Rails.application.config.filter_parameters += [:custom_secret] + context "when send_default_pii is enabled" do + before do + Sentry.configuration.send_default_pii = true + end - get "/world", params: { - normal_param: "value", - custom_secret: "should_be_filtered", - another_param: "visible" - } + after do + Sentry.configuration.send_default_pii = false + end - Sentry.get_current_client.flush + it "includes filtered request parameters" do + get "/world", params: { safe_param: "value", password: "secret" } - expect(sentry_logs).not_to be_empty + Sentry.get_current_client.flush - log_event = sentry_logs.find { |log| log[:body] == "HelloController#world" } - expect(log_event).not_to be_nil + expect(sentry_logs).not_to be_empty - params = log_event[:attributes][:params][:value] - expect(params).to include("normal_param" => "value") - expect(params).to include("another_param" => "visible") - expect(params).to include("custom_secret" => "[FILTERED]") + 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]).to include("password" => "[FILTERED]") + end - Rails.application.config.filter_parameters = original_filter_params - end + it "filters sensitive parameter names" do + get "/world", params: { + normal_param: "value", + password: "secret", + api_key: "key123", + credit_card: "1234567890", + authorization: "Bearer token" + } - it "handles nested parameters correctly" do - get "/world", params: { - user: { - name: "John", - password: "secret123", - profile: { - api_key: "key456", - public_info: "visible" - } - }, - normal_param: "value" - } + Sentry.get_current_client.flush - Sentry.get_current_client.flush + expect(sentry_logs).not_to be_empty - expect(sentry_logs).not_to be_empty + log_event = sentry_logs.find { |log| log[:body] == "HelloController#world" } + expect(log_event).not_to be_nil - 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).to include("password" => "[FILTERED]") + expect(params).to include("api_key" => "[FILTERED]") + expect(params).to include("credit_card" => "[FILTERED]") + expect(params).to include("authorization" => "[FILTERED]") + end - params = log_event[:attributes][:params][:value] - expect(params).to include("normal_param" => "value") - expect(params["user"]).to include("name" => "John") - expect(params["user"]).to include("password" => "[FILTERED]") - expect(params["user"]["profile"]).to include("api_key" => "[FILTERED]") - expect(params["user"]["profile"]).to include("public_info" => "visible") + it "handles nested parameters correctly" do + get "/world", params: { + user: { + name: "John", + password: "secret123", + profile: { + api_key: "key456", + public_info: "visible" + } + }, + normal_param: "value" + } + + Sentry.get_current_client.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["user"]).to include("name" => "John") + expect(params["user"]).to include("password" => "[FILTERED]") + expect(params["user"]["profile"]).to include("api_key" => "[FILTERED]") + expect(params["user"]["profile"]).to include("public_info" => "visible") + end 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" } + context "when send_default_pii is disabled" do + it "does not include request parameters" do + get "/world", params: { param: "value" } - Sentry.get_current_client.flush + Sentry.get_current_client.flush - expect(sentry_logs).not_to be_empty + 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) + 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 end - describe "when logging is disabled" do + context "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.subscribers = { action_controller: Sentry::Rails::LogSubscribers::ActionControllerSubscriber } end diff --git a/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb index 158439c41..66d700e2f 100644 --- a/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb +++ b/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb @@ -3,95 +3,29 @@ require "spec_helper" RSpec.describe Sentry::Rails::LogSubscribers::ActionMailerSubscriber do - before do - make_basic_app do |config| - config.enable_logs = true - config.rails.structured_logging.enabled = true - config.rails.structured_logging.subscribers = { action_mailer: Sentry::Rails::LogSubscribers::ActionMailerSubscriber } - end - end - - describe "integration with ActiveSupport::Notifications" do - it "logs deliver events when emails are sent" do - sentry_transport.events.clear - sentry_transport.envelopes.clear - - ActiveSupport::Notifications.instrument("deliver.action_mailer", - mailer: "UserMailer", - perform_deliveries: true, - delivery_method: :test, - date: Time.current, - message_id: "test@example.com" - ) do - sleep(0.01) - end - - Sentry.get_current_client.flush - - expect(sentry_logs).not_to be_empty - - log_event = sentry_logs.find { |log| log[:body] == "Email delivered via UserMailer" } - expect(log_event).not_to be_nil - expect(log_event[:level]).to eq("info") - expect(log_event[:attributes][:mailer][:value]).to eq("UserMailer") - expect(log_event[:attributes][:duration_ms][:value]).to be > 0 - expect(log_event[:attributes][:perform_deliveries][:value]).to be true - expect(log_event[:attributes][:delivery_method][:value]).to eq(:test) - expect(log_event[:attributes][:date]).to be_present - end + context "when logging is enabled" do + before do + make_basic_app do |config| + config.enable_logs = true - it "logs process events when mailer actions are processed" do - ActiveSupport::Notifications.instrument("process.action_mailer", - mailer: "UserMailer", - action: "welcome_email", - params: { user_id: 123, name: "John Doe" } - ) do - sleep(0.01) + config.rails.structured_logging.enabled = true + config.rails.structured_logging.subscribers = { action_mailer: Sentry::Rails::LogSubscribers::ActionMailerSubscriber } end - - Sentry.get_current_client.flush - - expect(sentry_logs).not_to be_empty - - log_event = sentry_logs.find { |log| log[:body] == "UserMailer#welcome_email" } - expect(log_event).not_to be_nil - expect(log_event[:level]).to eq("info") - expect(log_event[:attributes][:mailer][:value]).to eq("UserMailer") - expect(log_event[:attributes][:action][:value]).to eq("welcome_email") - expect(log_event[:attributes][:duration_ms][:value]).to be > 0 end + describe "integration with ActiveSupport::Notifications" do + it "logs deliver events when emails are sent" do + sentry_transport.events.clear + sentry_transport.envelopes.clear - it "includes delivery method when available" do - ActiveSupport::Notifications.instrument("deliver.action_mailer", - mailer: "NotificationMailer", - perform_deliveries: true, - delivery_method: :smtp - ) - - Sentry.get_current_client.flush - - expect(sentry_logs).not_to be_empty - - log_event = sentry_logs.find { |log| log[:body] == "Email delivered via NotificationMailer" } - expect(log_event).not_to be_nil - expect(log_event[:attributes][:delivery_method][:value]).to eq(:smtp) - 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 message_id for deliver events" do ActiveSupport::Notifications.instrument("deliver.action_mailer", mailer: "UserMailer", perform_deliveries: true, - message_id: "unique-message-id@example.com" - ) + delivery_method: :test, + date: Time.current, + message_id: "test@example.com" + ) do + sleep(0.01) + end Sentry.get_current_client.flush @@ -99,22 +33,22 @@ log_event = sentry_logs.find { |log| log[:body] == "Email delivered via UserMailer" } expect(log_event).not_to be_nil - expect(log_event[:attributes][:message_id][:value]).to eq("unique-message-id@example.com") + expect(log_event[:level]).to eq("info") + expect(log_event[:attributes][:mailer][:value]).to eq("UserMailer") + expect(log_event[:attributes][:duration_ms][:value]).to be > 0 + expect(log_event[:attributes][:perform_deliveries][:value]).to be true + expect(log_event[:attributes][:delivery_method][:value]).to eq(:test) + expect(log_event[:attributes][:date]).to be_present end - it "includes filtered parameters for process events" do + it "logs process events when mailer actions are processed" do ActiveSupport::Notifications.instrument("process.action_mailer", mailer: "UserMailer", action: "welcome_email", - params: { - user_id: 123, - safe_param: "value", - password: "secret", - email_address: "user@example.com", - subject: "Welcome!", - api_key: "secret-key" - } - ) + params: { user_id: 123, name: "John Doe" } + ) do + sleep(0.01) + end Sentry.get_current_client.flush @@ -122,59 +56,128 @@ log_event = sentry_logs.find { |log| log[:body] == "UserMailer#welcome_email" } expect(log_event).not_to be_nil - expect(log_event[:attributes][:params]).to be_present - - params = log_event[:attributes][:params][:value] - - expect(params).to include(user_id: 123, safe_param: "value") - expect(params[:password]).to eq("[FILTERED]") - expect(params[:api_key]).to eq("[FILTERED]") - expect(params).to include(email_address: "user@example.com", subject: "Welcome!") + expect(log_event[:level]).to eq("info") + expect(log_event[:attributes][:mailer][:value]).to eq("UserMailer") + expect(log_event[:attributes][:action][:value]).to eq("welcome_email") + expect(log_event[:attributes][:duration_ms][:value]).to be > 0 end - end - context "when send_default_pii is disabled" do - it "does not include message_id for deliver events" do + it "includes delivery method when available" do ActiveSupport::Notifications.instrument("deliver.action_mailer", - mailer: "UserMailer", + mailer: "NotificationMailer", perform_deliveries: true, - message_id: "unique-message-id@example.com" + delivery_method: :smtp ) Sentry.get_current_client.flush expect(sentry_logs).not_to be_empty - log_event = sentry_logs.find { |log| log[:body] == "Email delivered via UserMailer" } + log_event = sentry_logs.find { |log| log[:body] == "Email delivered via NotificationMailer" } expect(log_event).not_to be_nil - expect(log_event[:attributes]).not_to have_key(:message_id) + expect(log_event[:attributes][:delivery_method][:value]).to eq(:smtp) end - it "does not include parameters for process events" do - sentry_transport.events.clear - sentry_transport.envelopes.clear + 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 message_id for deliver events" do + ActiveSupport::Notifications.instrument("deliver.action_mailer", + mailer: "UserMailer", + perform_deliveries: true, + message_id: "unique-message-id@example.com" + ) + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "Email delivered via UserMailer" } + expect(log_event).not_to be_nil + expect(log_event[:attributes][:message_id][:value]).to eq("unique-message-id@example.com") + end + + it "includes filtered parameters for process events" do + ActiveSupport::Notifications.instrument("process.action_mailer", + mailer: "UserMailer", + action: "welcome_email", + params: { + user_id: 123, + safe_param: "value", + password: "secret", + email_address: "user@example.com", + subject: "Welcome!", + api_key: "secret-key" + } + ) + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "UserMailer#welcome_email" } + expect(log_event).not_to be_nil + expect(log_event[:attributes][:params]).to be_present + + params = log_event[:attributes][:params][:value] + + expect(params).to include(user_id: 123, safe_param: "value") + expect(params[:password]).to eq("[FILTERED]") + expect(params[:api_key]).to eq("[FILTERED]") + expect(params).to include(email_address: "user@example.com", subject: "Welcome!") + end + end - ActiveSupport::Notifications.instrument("process.action_mailer", - mailer: "UserMailer", - action: "welcome_email", - params: { user_id: 123, name: "John Doe" } - ) + context "when send_default_pii is disabled" do + it "does not include message_id for deliver events" do + ActiveSupport::Notifications.instrument("deliver.action_mailer", + mailer: "UserMailer", + perform_deliveries: true, + message_id: "unique-message-id@example.com" + ) - Sentry.get_current_client.flush + Sentry.get_current_client.flush - expect(sentry_logs).not_to be_empty + expect(sentry_logs).not_to be_empty - log_event = sentry_logs.find { |log| log[:body] == "UserMailer#welcome_email" } - expect(log_event).not_to be_nil - expect(log_event[:attributes]).not_to have_key(:params) + log_event = sentry_logs.find { |log| log[:body] == "Email delivered via UserMailer" } + expect(log_event).not_to be_nil + expect(log_event[:attributes]).not_to have_key(:message_id) + end + + it "does not include parameters for process events" do + sentry_transport.events.clear + sentry_transport.envelopes.clear + + ActiveSupport::Notifications.instrument("process.action_mailer", + mailer: "UserMailer", + action: "welcome_email", + params: { user_id: 123, name: "John Doe" } + ) + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "UserMailer#welcome_email" } + expect(log_event).not_to be_nil + expect(log_event[:attributes]).not_to have_key(:params) + end end end end - describe "when logging is disabled" do + context "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.subscribers = { action_mailer: Sentry::Rails::LogSubscribers::ActionMailerSubscriber } end diff --git a/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb index 8a691a9fa..25b099bd9 100644 --- a/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb +++ b/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb @@ -3,277 +3,247 @@ require "spec_helper" RSpec.describe Sentry::Rails::LogSubscribers::ActiveJobSubscriber, skip: Rails.version.to_f < 5.1 do - before do - make_basic_app do |config| - config.enable_logs = true - config.rails.structured_logging.enabled = true - config.rails.structured_logging.subscribers = { active_job: Sentry::Rails::LogSubscribers::ActiveJobSubscriber } - end - end + context "when logging is enabled" do + before do + make_basic_app do |config| + config.enable_logs = true - describe "integration with ActiveSupport::Notifications" do - it "logs job perform events when jobs are executed" do - sentry_transport.events.clear - sentry_transport.envelopes.clear + config.rails.structured_logging.enabled = true + config.rails.structured_logging.subscribers = { active_job: Sentry::Rails::LogSubscribers::ActiveJobSubscriber } + end + end - NormalJob.perform_now + describe "integration with ActiveSupport::Notifications" do + it "logs job perform events when jobs are executed" do + NormalJob.perform_now - Sentry.get_current_client.flush + Sentry.get_current_client.flush - expect(sentry_logs).not_to be_empty + expect(sentry_logs).not_to be_empty - log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") && log[:body]&.include?("NormalJob") } - expect(log_event).not_to be_nil - expect(log_event[:level]).to eq("info") - expect(log_event[:attributes][:job_class][:value]).to eq("NormalJob") - expect(log_event[:attributes][:duration_ms][:value]).to be > 0 - end - - it "logs job enqueue events when jobs are enqueued" do - sentry_transport.events.clear - sentry_transport.envelopes.clear + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") && log[:body]&.include?("NormalJob") } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("info") + expect(log_event[:attributes][:job_class][:value]).to eq("NormalJob") + expect(log_event[:attributes][:duration_ms][:value]).to be > 0 + end - NormalJob.perform_later + it "logs job enqueue events when jobs are enqueued" do + NormalJob.perform_later - Sentry.get_current_client.flush + Sentry.get_current_client.flush - log_event = sentry_logs.find { |log| log[:body]&.include?("Job enqueued") && log[:body]&.include?("NormalJob") } - expect(log_event).not_to be_nil - expect(log_event[:level]).to eq("info") - expect(log_event[:attributes][:job_class][:value]).to eq("NormalJob") - expect(log_event[:attributes][:job_id][:value]).to be_a(String) - expect(log_event[:attributes][:queue_name][:value]).to eq("default") + log_event = sentry_logs.find { |log| log[:body]&.include?("Job enqueued") && log[:body]&.include?("NormalJob") } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("info") + expect(log_event[:attributes][:job_class][:value]).to eq("NormalJob") + expect(log_event[:attributes][:job_id][:value]).to be_a(String) + expect(log_event[:attributes][:queue_name][:value]).to eq("default") + end end - end - - describe "job attributes extraction" do - it "includes job attributes in log events" do - sentry_transport.events.clear - sentry_transport.envelopes.clear - - NormalJob.perform_now - Sentry.get_current_client.flush + describe "job attributes extraction" do + it "includes job attributes in log events" do + NormalJob.perform_now - log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } - expect(log_event).not_to be_nil + Sentry.get_current_client.flush - attributes = log_event[:attributes] - expect(attributes[:job_class][:value]).to eq("NormalJob") - expect(attributes[:job_id][:value]).to be_a(String) - expect(attributes[:queue_name][:value]).to eq("default") - expect(attributes[:executions][:value]).to eq(1) - expect(attributes[:priority][:value]).to be_a(Integer).or be_nil - end + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } + expect(log_event).not_to be_nil - it "includes adapter information when available" do - sentry_transport.events.clear - sentry_transport.envelopes.clear + attributes = log_event[:attributes] + expect(attributes[:job_class][:value]).to eq("NormalJob") + expect(attributes[:job_id][:value]).to be_a(String) + expect(attributes[:queue_name][:value]).to eq("default") + expect(attributes[:executions][:value]).to eq(1) + expect(attributes[:priority][:value]).to be_a(Integer).or be_nil + end - NormalJob.perform_now + it "includes adapter information when available" do + NormalJob.perform_now - Sentry.get_current_client.flush + Sentry.get_current_client.flush - log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } - expect(log_event).not_to be_nil + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } + expect(log_event).not_to be_nil - attributes = log_event[:attributes] - expect(attributes[:adapter][:value]).to include("TestAdapter") + attributes = log_event[:attributes] + expect(attributes[:adapter][:value]).to include("TestAdapter") + end end - end - - describe "scheduled job handling" do - it "includes scheduling information for delayed jobs" do - sentry_transport.events.clear - sentry_transport.envelopes.clear - job = NormalJob.new - job.job_id = SecureRandom.uuid - job.queue_name = "default" - job.priority = nil - job.scheduled_at = 1.hour.from_now + describe "scheduled job handling" do + it "includes scheduling information for delayed jobs" do + job = NormalJob.new + job.job_id = SecureRandom.uuid + job.queue_name = "default" + job.priority = nil + job.scheduled_at = 1.hour.from_now - ActiveSupport::Notifications.instrument("enqueue.active_job", job: job) + ActiveSupport::Notifications.instrument("enqueue.active_job", job: job) - Sentry.get_current_client.flush + Sentry.get_current_client.flush - log_event = sentry_logs.find { |log| log[:body]&.include?("Job enqueued") } - expect(log_event).not_to be_nil + log_event = sentry_logs.find { |log| log[:body]&.include?("Job enqueued") } + expect(log_event).not_to be_nil - attributes = log_event[:attributes] - expect(attributes[:scheduled_at][:value]).to be_a(String) - expect(attributes[:delay_seconds][:value]).to be > 0 + attributes = log_event[:attributes] + expect(attributes[:scheduled_at][:value]).to be_a(String) + expect(attributes[:delay_seconds][:value]).to be > 0 + end end - end - describe "argument filtering" do - context "when send_default_pii is enabled" do - before do - make_basic_app do |config| - config.enable_logs = true - config.send_default_pii = true - config.rails.structured_logging.enabled = true - config.rails.structured_logging.subscribers = { active_job: Sentry::Rails::LogSubscribers::ActiveJobSubscriber } + describe "argument filtering" do + context "when send_default_pii is enabled" do + before do + Sentry.configuration.send_default_pii = true end - end - it "includes filtered job arguments" do - sentry_transport.events.clear - sentry_transport.envelopes.clear + after do + Sentry.configuration.send_default_pii = false + end - test_job_class = Class.new(ActiveJob::Base) do - def self.name - "TestJobWithArgs" - end + it "includes filtered job arguments" do + test_job_class = Class.new(ActiveJob::Base) do + def self.name + "TestJobWithArgs" + end - def perform(*args, **kwargs) + def perform(*args, **kwargs) + end end - end - test_job_class.perform_now("safe_arg", integer: 42, post: Post.create!) + test_job_class.perform_now("safe_arg", integer: 42, post: Post.create!) - Sentry.get_current_client.flush + Sentry.get_current_client.flush - log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } - expect(log_event).not_to be_nil + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } + expect(log_event).not_to be_nil - attributes = log_event[:attributes] - expect(attributes[:arguments][:value]).to be_a(Array) - expect(attributes[:arguments][:value]).to include("safe_arg") - end + attributes = log_event[:attributes] + expect(attributes[:arguments][:value]).to be_a(Array) + expect(attributes[:arguments][:value]).to include("safe_arg") + end - it "filters sensitive arguments" do - sentry_transport.events.clear - sentry_transport.envelopes.clear + it "filters sensitive arguments" do + original_filter_params = Rails.application.config.filter_parameters.dup + Rails.application.config.filter_parameters += [:token] - original_filter_params = Rails.application.config.filter_parameters.dup - Rails.application.config.filter_parameters += [:token] + test_job_class = Class.new(ActiveJob::Base) do + def self.name + "TestJobWithSensitiveArgs" + end - test_job_class = Class.new(ActiveJob::Base) do - def self.name - "TestJobWithSensitiveArgs" + def perform(password:, token:, safe_data:) + end end - def perform(password:, token:, safe_data:) - end - end + test_job_class.perform_now(password: "secret123", token: "abc123", safe_data: "public") - test_job_class.perform_now(password: "secret123", token: "abc123", safe_data: "public") + Sentry.get_current_client.flush - Sentry.get_current_client.flush + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } + expect(log_event).not_to be_nil - log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } - expect(log_event).not_to be_nil + attributes = log_event[:attributes] + arguments = attributes[:arguments][:value] - attributes = log_event[:attributes] - arguments = attributes[:arguments][:value] + expect(arguments.first).to include(safe_data: "public") + expect(arguments.first).to include(password: "[FILTERED]") + expect(arguments.first).to include(token: "[FILTERED]") - expect(arguments.first).to include(safe_data: "public") - expect(arguments.first).to include(password: "[FILTERED]") - expect(arguments.first).to include(token: "[FILTERED]") - - Rails.application.config.filter_parameters = original_filter_params + Rails.application.config.filter_parameters = original_filter_params + end end - end - context "when send_default_pii is disabled" do - it "does not include job arguments" do - sentry_transport.events.clear - sentry_transport.envelopes.clear + context "when send_default_pii is disabled" do + it "does not include job arguments" do + test_job_class = Class.new(ActiveJob::Base) do + def self.name + "TestJobNoArgs" + end - test_job_class = Class.new(ActiveJob::Base) do - def self.name - "TestJobNoArgs" + def perform(*args, **kwargs) + end end - def perform(*args, **kwargs) - end - end + test_job_class.perform_now("arg", integer: 42, post: Post.create!) - test_job_class.perform_now("arg", integer: 42, post: Post.create!) + Sentry.get_current_client.flush - Sentry.get_current_client.flush + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } + expect(log_event).not_to be_nil - log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } - expect(log_event).not_to be_nil - - attributes = log_event[:attributes] - expect(attributes).not_to have_key(:arguments) + attributes = log_event[:attributes] + expect(attributes).not_to have_key(:arguments) + end end end - end - describe "retry and error handling" do - it "logs retry_stopped events" do - sentry_transport.events.clear - sentry_transport.envelopes.clear + describe "retry and error handling" do + it "logs retry_stopped events" do + job = FailedJob.new + error = StandardError.new("Test error") - job = FailedJob.new - error = StandardError.new("Test error") + ActiveSupport::Notifications.instrument("retry_stopped.active_job", + job: job, + error: error + ) - ActiveSupport::Notifications.instrument("retry_stopped.active_job", - job: job, - error: error - ) - - Sentry.get_current_client.flush - - log_event = sentry_logs.find { |log| log[:body]&.include?("Job retry stopped") } - expect(log_event).not_to be_nil - expect(log_event[:level]).to eq("error") - expect(log_event[:attributes][:job_class][:value]).to eq("FailedJob") - expect(log_event[:attributes][:error_class][:value]).to eq("StandardError") - expect(log_event[:attributes][:error_message][:value]).to eq("Test error") - end - - it "logs discard events" do - sentry_transport.events.clear - sentry_transport.envelopes.clear + Sentry.get_current_client.flush - job = FailedJob.new - error = StandardError.new("Test error") + log_event = sentry_logs.find { |log| log[:body]&.include?("Job retry stopped") } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("error") + expect(log_event[:attributes][:job_class][:value]).to eq("FailedJob") + expect(log_event[:attributes][:error_class][:value]).to eq("StandardError") + expect(log_event[:attributes][:error_message][:value]).to eq("Test error") + end - ActiveSupport::Notifications.instrument("discard.active_job", - job: job, - error: error - ) + it "logs discard events" do + job = FailedJob.new + error = StandardError.new("Test error") - Sentry.get_current_client.flush + ActiveSupport::Notifications.instrument("discard.active_job", + job: job, + error: error + ) - log_event = sentry_logs.find { |log| log[:body]&.include?("Job discarded") } - expect(log_event).not_to be_nil - expect(log_event[:level]).to eq("warn") - expect(log_event[:attributes][:job_class][:value]).to eq("FailedJob") - expect(log_event[:attributes][:error_class][:value]).to eq("StandardError") - expect(log_event[:attributes][:error_message][:value]).to eq("Test error") - end + Sentry.get_current_client.flush - it "logs discard events without error" do - sentry_transport.events.clear - sentry_transport.envelopes.clear + log_event = sentry_logs.find { |log| log[:body]&.include?("Job discarded") } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("warn") + expect(log_event[:attributes][:job_class][:value]).to eq("FailedJob") + expect(log_event[:attributes][:error_class][:value]).to eq("StandardError") + expect(log_event[:attributes][:error_message][:value]).to eq("Test error") + end - job = FailedJob.new + it "logs discard events without error" do + job = FailedJob.new - ActiveSupport::Notifications.instrument("discard.active_job", - job: job, - error: nil - ) + ActiveSupport::Notifications.instrument("discard.active_job", + job: job, + error: nil + ) - Sentry.get_current_client.flush + Sentry.get_current_client.flush - log_event = sentry_logs.find { |log| log[:body]&.include?("Job discarded") } - expect(log_event).not_to be_nil - expect(log_event[:level]).to eq("warn") - expect(log_event[:attributes][:job_class][:value]).to eq("FailedJob") - expect(log_event[:attributes]).not_to have_key(:error_class) - expect(log_event[:attributes]).not_to have_key(:error_message) + log_event = sentry_logs.find { |log| log[:body]&.include?("Job discarded") } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("warn") + expect(log_event[:attributes][:job_class][:value]).to eq("FailedJob") + expect(log_event[:attributes]).not_to have_key(:error_class) + expect(log_event[:attributes]).not_to have_key(:error_message) + end end end - describe "when logging is disabled" do + context "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.subscribers = { active_job: Sentry::Rails::LogSubscribers::ActiveJobSubscriber } 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 index b59e31563..81824af30 100644 --- 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 @@ -3,138 +3,141 @@ require "spec_helper" 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.subscribers = { active_record: Sentry::Rails::LogSubscribers::ActiveRecordSubscriber } - end - end + context "when logging is enabled" do + before do + make_basic_app do |config| + config.enable_logs = true - describe "integration with ActiveSupport::Notifications" do - it "logs SQL events when database queries are executed" do - Post.create! + config.rails.structured_logging.enabled = true + config.rails.structured_logging.subscribers = { active_record: Sentry::Rails::LogSubscribers::ActiveRecordSubscriber } + end + end + describe "integration with ActiveSupport::Notifications" do + it "logs SQL events when database queries are executed" do + Post.create! - Sentry.get_current_client.flush + Sentry.get_current_client.flush - expect(sentry_logs).not_to be_empty + 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 + 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! + it "logs SELECT queries with proper attributes" do + post = Post.create! - Sentry.get_current_client.flush - sentry_transport.events.clear - sentry_transport.envelopes.clear + Sentry.get_current_client.flush + sentry_transport.events.clear + sentry_transport.envelopes.clear - Post.find(post.id) + Post.find(post.id) - Sentry.get_current_client.flush + Sentry.get_current_client.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 + 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 - if Rails.version.to_f > 5.1 - it "excludes SCHEMA events" do - ActiveSupport::Notifications.instrument("sql.active_record", - sql: "CREATE TABLE temp_test_table (id INTEGER)", - name: "SCHEMA", - connection: ActiveRecord::Base.connection - ) + if Rails.version.to_f > 5.1 + it "excludes SCHEMA events" do + ActiveSupport::Notifications.instrument("sql.active_record", + sql: "CREATE TABLE temp_test_table (id INTEGER)", + name: "SCHEMA", + connection: ActiveRecord::Base.connection + ) - Sentry.get_current_client.flush + Sentry.get_current_client.flush - schema_logs = sentry_logs.select { |log| log[:attributes]&.dig(:sql, :value)&.include?("CREATE TABLE") } - expect(schema_logs).to be_empty + schema_logs = sentry_logs.select { |log| log[:attributes]&.dig(:sql, :value)&.include?("CREATE TABLE") } + expect(schema_logs).to be_empty + end end end - end - if Rails.version.to_f >= 7.2 - describe "database configuration extraction" do - it "includes database configuration in log attributes" do - Post.create! + if Rails.version.to_f >= 7.2 + describe "database configuration extraction" do + it "includes database configuration in log attributes" do + Post.create! - Sentry.get_current_client.flush + Sentry.get_current_client.flush - log_event = sentry_logs.find do |log| - log[:body]&.include?("Database query") && - log[:attributes]&.dig(:sql, :value)&.include?("INSERT") - end + 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 + 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") + attributes = log_event[:attributes] + expect(attributes[:db_system][:value]).to eq("sqlite3") + expect(attributes[:db_name][:value]).to eq("db") + end end end - end - describe "statement name handling" do - it "includes statement name in log message when available" do - post = Post.create! - Post.find(post.id) + describe "statement name handling" do + it "includes statement name in log message when available" do + post = Post.create! + Post.find(post.id) - Sentry.get_current_client.flush + Sentry.get_current_client.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") + 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 - 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 + it "handles queries without specific statement names" do + sentry_transport.events.clear + sentry_transport.envelopes.clear - ActiveRecord::Base.connection.execute("SELECT 1") + ActiveRecord::Base.connection.execute("SELECT 1") - Sentry.get_current_client.flush + Sentry.get_current_client.flush - log_event = sentry_logs.find do |log| - log[:body] == "Database query" && - log[:attributes]&.dig(:sql, :value) == "SELECT 1" + 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 - 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 + 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) + Post.find(post.id) + Post.find(post.id) - Sentry.get_current_client.flush + Sentry.get_current_client.flush - cached_log = sentry_logs.find { |log| log[:attributes]&.dig(:cached, :value) == true } - expect(cached_log).not_to be_nil + cached_log = sentry_logs.find { |log| log[:attributes]&.dig(:cached, :value) == true } + expect(cached_log).not_to be_nil + end end end end - describe "when logging is disabled" do + context "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.subscribers = { active_record: Sentry::Rails::LogSubscribers::ActiveRecordSubscriber } end diff --git a/sentry-rails/spec/support/shared_examples_for_parameter_filter.rb b/sentry-rails/spec/support/shared_examples_for_parameter_filter.rb index ceafd7f9a..52f3f9d13 100644 --- a/sentry-rails/spec/support/shared_examples_for_parameter_filter.rb +++ b/sentry-rails/spec/support/shared_examples_for_parameter_filter.rb @@ -4,6 +4,19 @@ let(:test_instance) { subscriber_class.new } describe "#filter_sensitive_params" do + around do |example| + original_filter_params = Rails.application.config.filter_parameters.dup + + Rails.application.config.filter_parameters.concat([ + :password, :secret, :custom_secret, :api_key, + :credit_card, :authorization, :token, :session_token + ]).uniq! + + example.run + + Rails.application.config.filter_parameters = original_filter_params + end + context "when params is not a hash" do it "returns empty hash for nil" do result = test_instance.filter_sensitive_params(nil) From b87ad68adc5970c8873a7d9103eb51e2d66d0be7 Mon Sep 17 00:00:00 2001 From: Peter Solnica Date: Wed, 3 Sep 2025 07:54:01 +0000 Subject: [PATCH 21/21] More coverage --- .../action_controller_subscriber.rb | 5 +- .../log_subscribers/active_job_subscriber.rb | 2 +- .../action_controller_subscriber_spec.rb | 185 ++++++++++++++++++ .../action_mailer_subscriber_spec.rb | 53 +++++ .../active_job_subscriber_spec.rb | 85 ++++++++ .../active_record_subscriber_spec.rb | 48 ++++- 6 files changed, 371 insertions(+), 7 deletions(-) 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 index eaacb8ff2..94a804cf8 100644 --- a/sentry-rails/lib/sentry/rails/log_subscribers/action_controller_subscriber.rb +++ b/sentry-rails/lib/sentry/rails/log_subscribers/action_controller_subscriber.rb @@ -37,13 +37,14 @@ def process_action(event) attributes = { controller: controller, action: action, - status: status, duration_ms: duration_ms(event), method: payload[:method], path: payload[:path], format: payload[:format] } + attributes[:status] = status if status + if payload[:view_runtime] attributes[:view_runtime_ms] = payload[:view_runtime].round(2) end @@ -97,6 +98,8 @@ def level_for_request(payload) else :error end + elsif status.nil? + :info elsif status >= 200 && status < 400 :info elsif status >= 400 && status < 500 diff --git a/sentry-rails/lib/sentry/rails/log_subscribers/active_job_subscriber.rb b/sentry-rails/lib/sentry/rails/log_subscribers/active_job_subscriber.rb index 6dd348594..e0181ee8a 100644 --- a/sentry-rails/lib/sentry/rails/log_subscribers/active_job_subscriber.rb +++ b/sentry-rails/lib/sentry/rails/log_subscribers/active_job_subscriber.rb @@ -38,7 +38,7 @@ def perform(event) priority: job.priority } - attributes[:adapter] = job.class.queue_adapter.class.name if job.class.respond_to?(:queue_adapter) + attributes[:adapter] = job.class.queue_adapter.class.name if job.scheduled_at attributes[:scheduled_at] = job.scheduled_at.iso8601 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 index b815e4aee..98dd588cb 100644 --- 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 @@ -97,6 +97,164 @@ end end + it "handles missing payload fields gracefully" do + event = ActiveSupport::Notifications::Event.new( + "process_action.action_controller", + Time.current, + Time.current + 0.1, + "unique_id", + { + controller: "TestController", + action: "test" + } + ) + + subscriber = described_class.new + expect { subscriber.process_action(event) }.not_to raise_error + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body] == "TestController#test" } + expect(log_event).not_to be_nil + expect(log_event[:attributes][:controller][:value]).to eq("TestController") + expect(log_event[:attributes][:action][:value]).to eq("test") + expect(log_event[:attributes]).not_to have_key(:status) + end + + it "includes status when explicitly provided" do + event = ActiveSupport::Notifications::Event.new( + "process_action.action_controller", + Time.current, + Time.current + 0.1, + "unique_id", + { + controller: "TestController", + action: "test", + status: 201, + method: "POST", + path: "/test", + format: :json + } + ) + + subscriber = described_class.new + subscriber.process_action(event) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body] == "TestController#test" } + expect(log_event).not_to be_nil + expect(log_event[:attributes][:status][:value]).to eq(201) + end + + it "handles custom status codes correctly" do + event = ActiveSupport::Notifications::Event.new( + "process_action.action_controller", + Time.current, + Time.current + 0.1, + "unique_id", + { + controller: "TestController", + action: "test", + status: 418, # I'm a teapot + method: "GET", + path: "/test", + format: :json + } + ) + + subscriber = described_class.new + subscriber.process_action(event) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body] == "TestController#test" } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("warn") + expect(log_event[:attributes][:status][:value]).to eq(418) + end + + it "handles ActionController::RoutingError exceptions" do + event = ActiveSupport::Notifications::Event.new( + "process_action.action_controller", + Time.current, + Time.current + 0.1, + "unique_id", + { + controller: "TestController", + action: "test", + exception: ["ActionController::RoutingError", "No route matches"], + method: "GET", + path: "/nonexistent", + format: :html + } + ) + + subscriber = described_class.new + subscriber.process_action(event) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body] == "TestController#test" } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("warn") + expect(log_event[:attributes][:status][:value]).to eq(404) + end + + it "handles ActionController::BadRequest exceptions" do + event = ActiveSupport::Notifications::Event.new( + "process_action.action_controller", + Time.current, + Time.current + 0.1, + "unique_id", + { + controller: "TestController", + action: "test", + exception: ["ActionController::BadRequest", "Bad request"], + method: "POST", + path: "/test", + format: :json + } + ) + + subscriber = described_class.new + subscriber.process_action(event) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body] == "TestController#test" } + 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 "handles other exceptions with error level" do + event = ActiveSupport::Notifications::Event.new( + "process_action.action_controller", + Time.current, + Time.current + 0.1, + "unique_id", + { + controller: "TestController", + action: "test", + exception: ["StandardError", "Something went wrong"], + method: "POST", + path: "/test", + format: :json + } + ) + + subscriber = described_class.new + subscriber.process_action(event) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body] == "TestController#test" } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("error") + expect(log_event[:attributes][:status][:value]).to eq(500) + end + context "when send_default_pii is enabled" do before do Sentry.configuration.send_default_pii = true @@ -171,6 +329,33 @@ expect(params["user"]["profile"]).to include("api_key" => "[FILTERED]") expect(params["user"]["profile"]).to include("public_info" => "visible") end + + it "handles malformed parameters gracefully" do + event = ActiveSupport::Notifications::Event.new( + "process_action.action_controller", + Time.current, + Time.current + 0.1, + "unique_id", + { + controller: "TestController", + action: "test", + status: 200, + method: "POST", + path: "/test", + format: :json, + params: "not_a_hash" + } + ) + + subscriber = described_class.new + expect { subscriber.process_action(event) }.not_to raise_error + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body] == "TestController#test" } + expect(log_event).not_to be_nil + expect(log_event[:attributes]).not_to have_key(:params) + end end context "when send_default_pii is disabled" do diff --git a/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb index 66d700e2f..df55048c4 100644 --- a/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb +++ b/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb @@ -78,6 +78,59 @@ expect(log_event[:attributes][:delivery_method][:value]).to eq(:smtp) end + it "includes date when available" do + test_date = Time.current + ActiveSupport::Notifications.instrument("deliver.action_mailer", + mailer: "NotificationMailer", + perform_deliveries: true, + date: test_date + ) + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "Email delivered via NotificationMailer" } + expect(log_event).not_to be_nil + expect(log_event[:attributes][:date][:value]).to eq(test_date.to_s) + end + + it "handles missing optional fields gracefully" do + ActiveSupport::Notifications.instrument("deliver.action_mailer", + mailer: "MinimalMailer", + perform_deliveries: false + ) + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "Email delivered via MinimalMailer" } + expect(log_event).not_to be_nil + expect(log_event[:attributes][:mailer][:value]).to eq("MinimalMailer") + expect(log_event[:attributes][:perform_deliveries][:value]).to be false + expect(log_event[:attributes]).not_to have_key(:delivery_method) + expect(log_event[:attributes]).not_to have_key(:date) + expect(log_event[:attributes]).not_to have_key(:message_id) + end + + it "handles process events with missing params gracefully" do + ActiveSupport::Notifications.instrument("process.action_mailer", + mailer: "UserMailer", + action: "welcome_email" + ) + + Sentry.get_current_client.flush + + expect(sentry_logs).not_to be_empty + + log_event = sentry_logs.find { |log| log[:body] == "UserMailer#welcome_email" } + expect(log_event).not_to be_nil + expect(log_event[:attributes][:mailer][:value]).to eq("UserMailer") + expect(log_event[:attributes][:action][:value]).to eq("welcome_email") + expect(log_event[:attributes]).not_to have_key(:params) + end + context "when send_default_pii is enabled" do before do Sentry.configuration.send_default_pii = true diff --git a/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb index 25b099bd9..49a4573c5 100644 --- a/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb +++ b/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb @@ -154,6 +154,72 @@ def perform(password:, token:, safe_data:) Rails.application.config.filter_parameters = original_filter_params end + + it "filters long string arguments" do + test_job_class = Class.new(ActiveJob::Base) do + def self.name + "TestJobWithLongString" + end + + def perform(short_string, long_string) + end + end + + long_string = "a" * 150 + test_job_class.perform_now("short", long_string) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } + expect(log_event).not_to be_nil + + attributes = log_event[:attributes] + arguments = attributes[:arguments][:value] + + expect(arguments).to include("short") + expect(arguments).to include("[FILTERED: 150 chars]") + end + + it "handles mixed argument types" do + test_job_class = Class.new(ActiveJob::Base) do + def self.name + "TestJobWithMixedArgs" + end + + def perform(string_arg, hash_arg, number_arg, array_arg) + end + end + + test_job_class.perform_now( + "string_value", + { safe_key: "value", password: "secret" }, + 42, + [1, 2, 3] + ) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job performed") } + expect(log_event).not_to be_nil + + attributes = log_event[:attributes] + arguments = attributes[:arguments][:value] + + expect(arguments[0]).to eq("string_value") + expect(arguments[1]).to include(safe_key: "value") + expect(arguments[1]).to include(password: "[FILTERED]") + expect(arguments[2]).to eq(42) + expect(arguments[3]).to eq([1, 2, 3]) + end + + it "handles non-array arguments gracefully" do + subscriber = described_class.new + result = subscriber.send(:filter_sensitive_arguments, "not_an_array") + expect(result).to eq([]) + + result = subscriber.send(:filter_sensitive_arguments, nil) + expect(result).to eq([]) + end end context "when send_default_pii is disabled" do @@ -236,6 +302,25 @@ def perform(*args, **kwargs) expect(log_event[:attributes]).not_to have_key(:error_class) expect(log_event[:attributes]).not_to have_key(:error_message) end + + it "logs discard events with custom discard reason" do + job = FailedJob.new + error = StandardError.new("Custom discard reason") + + ActiveSupport::Notifications.instrument("discard.active_job", + job: job, + error: error + ) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:body]&.include?("Job discarded") } + expect(log_event).not_to be_nil + expect(log_event[:level]).to eq("warn") + expect(log_event[:attributes][:job_class][:value]).to eq("FailedJob") + expect(log_event[:attributes][:error_class][:value]).to eq("StandardError") + expect(log_event[:attributes][:error_message][:value]).to eq("Custom discard reason") + 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 index 81824af30..316a4c74d 100644 --- 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 @@ -57,6 +57,49 @@ schema_logs = sentry_logs.select { |log| log[:attributes]&.dig(:sql, :value)&.include?("CREATE TABLE") } expect(schema_logs).to be_empty end + + it "excludes TRANSACTION events" do + ActiveSupport::Notifications.instrument("sql.active_record", + sql: "BEGIN", + name: "TRANSACTION", + connection: ActiveRecord::Base.connection + ) + + Sentry.get_current_client.flush + + transaction_logs = sentry_logs.select { |log| log[:attributes]&.dig(:sql, :value) == "BEGIN" } + expect(transaction_logs).to be_empty + end + end + + it "handles events with missing connection gracefully" do + ActiveSupport::Notifications.instrument("sql.active_record", + sql: "SELECT 1", + name: "SQL" + ) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:attributes]&.dig(:sql, :value) == "SELECT 1" } + expect(log_event).not_to be_nil + expect(log_event[:attributes][:sql][:value]).to eq("SELECT 1") + expect(log_event[:attributes]).not_to have_key(:db_system) + expect(log_event[:attributes]).not_to have_key(:db_name) + end + + it "handles events with missing connection_id gracefully" do + ActiveSupport::Notifications.instrument("sql.active_record", + sql: "SELECT 2", + name: "SQL", + connection: ActiveRecord::Base.connection + ) + + Sentry.get_current_client.flush + + log_event = sentry_logs.find { |log| log[:attributes]&.dig(:sql, :value) == "SELECT 2" } + expect(log_event).not_to be_nil + expect(log_event[:attributes][:sql][:value]).to eq("SELECT 2") + expect(log_event[:attributes]).not_to have_key(:connection_id) end end @@ -98,9 +141,6 @@ 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.flush @@ -118,8 +158,6 @@ 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)