diff --git a/CHANGELOG.md b/CHANGELOG.md index 4c9f8d319..77bb76e75 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,73 @@ ### 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)) + + 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 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..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 @@ -159,6 +162,10 @@ 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 + def initialize @register_error_subscriber = false @report_rescued_exceptions = true @@ -176,6 +183,27 @@ 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 + + DEFAULT_SUBSCRIBERS = { + active_record: Sentry::Rails::LogSubscribers::ActiveRecordSubscriber, + action_controller: Sentry::Rails::LogSubscribers::ActionControllerSubscriber + }.freeze + + def initialize + @enabled = false + @subscribers = DEFAULT_SUBSCRIBERS.dup end end end 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/action_controller_subscriber.rb b/sentry-rails/lib/sentry/rails/log_subscribers/action_controller_subscriber.rb new file mode 100644 index 000000000..94a804cf8 --- /dev/null +++ b/sentry-rails/lib/sentry/rails/log_subscribers/action_controller_subscriber.rb @@ -0,0 +1,116 @@ +# 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 + + controller = payload[:controller] + action = payload[:action] + + status = extract_status(payload) + + attributes = { + controller: controller, + action: action, + 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 + + 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.nil? + :info + 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/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..63f16e41f --- /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] + + attributes = { + mailer: mailer, + duration_ms: duration_ms(event), + 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/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..e0181ee8a --- /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.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/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..c159e2423 --- /dev/null +++ b/sentry-rails/lib/sentry/rails/log_subscribers/active_record_subscriber.rb @@ -0,0 +1,134 @@ +# 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] + + db_config = extract_db_config(event.payload) + + attributes = { + sql: sql, + duration_ms: duration_ms(event), + 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] + + return unless connection + + extract_db_config_from_connection(connection) + 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/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/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..d184c519c --- /dev/null +++ b/sentry-rails/lib/sentry/rails/structured_logging.rb @@ -0,0 +1,32 @@ +# 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 + 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/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/configuration_spec.rb b/sentry-rails/spec/sentry/rails/configuration_spec.rb index d008af92f..adf08a635 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 enabled to true" do + make_basic_app do |config| + 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 enabled to false" do + make_basic_app do |config| + config.rails.structured_logging.enabled = 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.enabled = 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/log_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscriber_spec.rb new file mode 100644 index 000000000..10135859c --- /dev/null +++ b/sentry-rails/spec/sentry/rails/log_subscriber_spec.rb @@ -0,0 +1,254 @@ +# 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 + 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 + end + end + + it_behaves_like "parameter filtering" do + let(:test_instance) { test_subscriber } + end + end +end diff --git a/sentry-rails/spec/sentry/rails/log_subscribers/action_controller_subscriber_spec.rb b/sentry-rails/spec/sentry/rails/log_subscribers/action_controller_subscriber_spec.rb new file mode 100644 index 000000000..98dd588cb --- /dev/null +++ b/sentry-rails/spec/sentry/rails/log_subscribers/action_controller_subscriber_spec.rb @@ -0,0 +1,403 @@ +# frozen_string_literal: true + +require "spec_helper" + +RSpec.describe Sentry::Rails::LogSubscribers::ActionControllerSubscriber, type: :request do + context "when logging is enabled" 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 + + 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 + + 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 + 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 "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 + + 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 + it "does not include request parameters" do + 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 + end + + 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 + 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 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 new file mode 100644 index 000000000..df55048c4 --- /dev/null +++ b/sentry-rails/spec/sentry/rails/log_subscribers/action_mailer_subscriber_spec.rb @@ -0,0 +1,254 @@ +# frozen_string_literal: true + +require "spec_helper" + +RSpec.describe Sentry::Rails::LogSubscribers::ActionMailerSubscriber do + context "when logging is enabled" 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 + + 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 + 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 + end + + 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 + 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 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 new file mode 100644 index 000000000..49a4573c5 --- /dev/null +++ b/sentry-rails/spec/sentry/rails/log_subscribers/active_job_subscriber_spec.rb @@ -0,0 +1,351 @@ +# frozen_string_literal: true + +require "spec_helper" + +RSpec.describe Sentry::Rails::LogSubscribers::ActiveJobSubscriber, skip: Rails.version.to_f < 5.1 do + context "when logging is enabled" 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 + 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 + 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 + 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 + 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 + 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 + Sentry.configuration.send_default_pii = true + end + + after do + Sentry.configuration.send_default_pii = false + end + + it "includes filtered job arguments" do + test_job_class = Class.new(ActiveJob::Base) do + def self.name + "TestJobWithArgs" + end + + def perform(*args, **kwargs) + 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 + 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 + + def perform(password:, token:, safe_data:) + 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 + + 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 + it "does not include job arguments" do + test_job_class = Class.new(ActiveJob::Base) do + def self.name + "TestJobNoArgs" + end + + def perform(*args, **kwargs) + 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 + 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 + 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 + 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 + + 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 + + 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 + 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 + + include_examples "parameter filtering", described_class +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 new file mode 100644 index 000000000..316a4c74d --- /dev/null +++ b/sentry-rails/spec/sentry/rails/log_subscribers/active_record_subscriber_spec.rb @@ -0,0 +1,196 @@ +# frozen_string_literal: true + +require "spec_helper" + +RSpec.describe Sentry::Rails::LogSubscribers::ActiveRecordSubscriber do + context "when logging is enabled" 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 + + 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 + + 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 + + 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 + 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 + 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! + + 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 + end + + 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 + 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 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..b414d86e0 --- /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.enabled = 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.enabled = 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 e3accdf98..4a8640f5f 100644 --- a/sentry-rails/spec/spec_helper.rb +++ b/sentry-rails/spec/spec_helper.rb @@ -54,6 +54,11 @@ expect(Sentry::Rails::Tracing.subscribed_tracing_events).to be_empty Sentry::Rails::Tracing.remove_active_support_notifications_patch + 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 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..52f3f9d13 --- /dev/null +++ b/sentry-rails/spec/support/shared_examples_for_parameter_filter.rb @@ -0,0 +1,154 @@ +# frozen_string_literal: true + +RSpec.shared_examples "parameter filtering" do |subscriber_class| + 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) + 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 diff --git a/sentry-ruby/lib/sentry-ruby.rb b/sentry-ruby/lib/sentry-ruby.rb index 986e6d1a8..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,13 +640,16 @@ 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. Use Sentry.configuration.sdk_logger for SDK-specific logging needs." + + Caller: #{caller.first} STR configuration.sdk_logger 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..129822c4b --- /dev/null +++ b/sentry-ruby/lib/sentry/debug_structured_logger.rb @@ -0,0 +1,92 @@ +# 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 + 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..bcee3d9df 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,21 @@ def teardown_sentry_test Sentry::Scope.global_event_processors.clear end + def clear_sentry_events + 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 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/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 002cd0d11..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 = [] @@ -39,6 +50,10 @@ def logged_envelopes Sentry.get_current_client.transport.logged_envelopes end + def logged_structured_events + Sentry.logger.logged_events + end + # TODO: move this to a shared helper for all gems def perform_basic_setup Sentry.init do |config| @@ -50,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