diff --git a/docs/app/docs/filtering-sensitive-data/page.tsx b/docs/app/docs/filtering-sensitive-data/page.tsx index cfcb3b7b..8c61c4c5 100644 --- a/docs/app/docs/filtering-sensitive-data/page.tsx +++ b/docs/app/docs/filtering-sensitive-data/page.tsx @@ -24,6 +24,14 @@ export default function FilteringSensitiveDataPage() { other structured data based on key names. When a sensitive key is detected, the actual value is replaced with metadata instead.

+

+ Mail delivery jobs (deliver_later) are logged with only the mailer, the mail + and the delivery method as their arguments. A mail's own arguments can be secrets with + no key to filter on, such as the tokens Devise passes to its confirmation, password reset + and invitation emails. This applies while the ActiveJob integration is on and the delivery + job is ActionMailer::MailDeliveryJob or a subclass of it. With the integration + off, Rails' own job logs include the arguments. +

How Parameter Filtering Works diff --git a/docs/lib/integration-helpers.ts b/docs/lib/integration-helpers.ts index 3ac7ce7b..2db28ea5 100644 --- a/docs/lib/integration-helpers.ts +++ b/docs/lib/integration-helpers.ts @@ -146,7 +146,7 @@ export function getEventsForLogType(logType: LogType): Event[] { case LogType.ACTIVESTORAGE: return [Event.Upload, Event.Download, Event.Delete, Event.Metadata, Event.Exist, Event.Url]; case LogType.ACTIONMAILER: - return [Event.Delivery, Event.Delivered]; + return [Event.Delivery, Event.Delivered, Event.Error]; case LogType.CARRIERWAVE: return [Event.Upload, Event.Delete]; case LogType.GOODJOB: diff --git a/lib/log_struct/concerns/error_handling.rb b/lib/log_struct/concerns/error_handling.rb index f2e68b44..9ffbc151 100644 --- a/lib/log_struct/concerns/error_handling.rb +++ b/lib/log_struct/concerns/error_handling.rb @@ -42,10 +42,16 @@ def log_error(error, source:, context: nil) LogStruct.error(error_log) end - # Report an error using the configured handler or MultiErrorReporter + # Log an error and report it using the configured handler or MultiErrorReporter sig { params(error: StandardError, source: Source, context: T.nilable(T::Hash[Symbol, T.untyped])).void } def log_and_report_error(error, source:, context: nil) log_error(error, source: source, context: context) + report_error(error, source: source, context: context) + end + + # Report an error using the configured handler or MultiErrorReporter, without logging it + sig { params(error: StandardError, source: Source, context: T.nilable(T::Hash[Symbol, T.untyped])).void } + def report_error(error, source:, context: nil) error_handler = LogStruct.config.error_reporting_handler if error_handler # Use the configured handler @@ -56,9 +62,10 @@ def log_and_report_error(error, source:, context: nil) end end - # Handle an error according to the configured error handling mode (log, report, raise, etc) - sig { params(error: StandardError, source: Source, context: T.nilable(T::Hash[Symbol, T.untyped])).void } - def handle_exception(error, source:, context: nil) + # Handle an error according to the configured error handling mode (log, report, raise, etc). + # Pass `log: false` when the caller has already logged the error in its own structured line. + sig { params(error: StandardError, source: Source, context: T.nilable(T::Hash[Symbol, T.untyped]), log: T::Boolean).void } + def handle_exception(error, source:, context: nil, log: true) mode = error_handling_mode_for(source) # Log / report in production, raise locally (dev/test) @@ -74,10 +81,11 @@ def handle_exception(error, source:, context: nil) raise(error) when ErrorHandlingMode::Log, ErrorHandlingMode::LogProduction - log_error(error, source: source, context: context) + log_error(error, source: source, context: context) if log when ErrorHandlingMode::Report, ErrorHandlingMode::ReportProduction - log_and_report_error(error, source: source, context: context) + log_error(error, source: source, context: context) if log + report_error(error, source: source, context: context) else # Ensures the case statement is exhaustive diff --git a/lib/log_struct/integrations/action_mailer/error_handling.rb b/lib/log_struct/integrations/action_mailer/error_handling.rb index 35320fe5..39469bc0 100644 --- a/lib/log_struct/integrations/action_mailer/error_handling.rb +++ b/lib/log_struct/integrations/action_mailer/error_handling.rb @@ -15,6 +15,58 @@ module ErrorHandling extend T::Sig extend ActiveSupport::Concern + # ActionMailer::MailDeliveryJob passes errors to the mailer class (`handle_exception`), which + # looks the rescue_from handlers up on the class, so the handlers are defined there too. + # (ActiveSupport::Concern extends the class with ClassMethods when it's included or prepended.) + module ClassMethods + extend T::Sig + + # Just log the error without reporting or retrying + sig { params(ex: StandardError).void } + def log_and_ignore_error(ex) + ErrorHandling.handle_mailer_class_error(self, ex, report: false, reraise: false) + end + + # Log and report to error service, but doesn't reraise + sig { params(ex: StandardError).void } + def log_and_report_error(ex) + ErrorHandling.handle_mailer_class_error(self, ex, report: true, reraise: false) + end + + # Log, report to error service, and reraise for retry + sig { params(ex: StandardError).void } + def log_and_reraise_error(ex) + ErrorHandling.handle_mailer_class_error(self, ex, report: true, reraise: true) + end + end + + # An error that reaches the class handler from the delivery itself was logged (and reported) + # by the mailer's handler, which let it through: it re-raised it for the job to retry, or + # LogStruct.handle_exception raised it (Raise mode). It's raised again, without logging it + # twice, so the job fails as deliver_now would. + sig { params(mailer_class: T.untyped, error: StandardError, report: T::Boolean, reraise: T::Boolean).void } + def self.handle_mailer_class_error(mailer_class, error, report:, reraise:) + Kernel.raise error if LogStruct::LoggedErrors.logged?(error) + + message = if reraise + "#{error.class}: Email delivery error, will retry. Error message: #{error.message}" + else + "#{error.class}: Cannot send email. Error message: #{error.message}" + end + LogStruct.error(Log::ActionMailer::Error.new( + mailer_class: mailer_class.to_s, + error_class: error.class, + message: message, + backtrace: error.backtrace, + level: Level::Error + )) + if report + LogStruct.handle_exception(error, source: Source::Mailer, context: {mailer_class: mailer_class.to_s}, log: false) + end + + Kernel.raise error if reraise + end + sig { returns(T.nilable(T::Boolean)) } attr_accessor :logstruct_mail_failed @@ -127,6 +179,9 @@ def log_email_delivery_error(error, notify: false, report: true, reraise: true) # Use structured error logging log_structured_error(self, error, message) + # The mailer class handler gets the error if it's raised from here (re-raised, or raised by + # LogStruct.handle_exception in Raise mode), and mustn't log or report it again + LogStruct::LoggedErrors.mark(error) # Handle notifications and reporting handle_error_notifications(error, notify, report, reraise) @@ -148,21 +203,14 @@ def handle_error_notifications(error, notify, report, reraise) # Log a notification event if requested log_notification_event(error) if notify - # Report to error reporting service if requested + # Report to error reporting service if requested. The structured error line is already logged. if report - context_data = {recipients: recipients(error)} - exception_data = build_exception_data(error, Level::Error, context_data) - - # Log the exception with structured data - LogStruct.error(exception_data) - - # Call the error handler with flat context for compatibility context = { mailer_class: self.class.to_s, mailer_action: respond_to?(:action_name) ? action_name : nil, recipients: recipients(error) } - LogStruct.handle_exception(error, source: Source::Mailer, context: context) + LogStruct.handle_exception(error, source: Source::Mailer, context: context, log: false) end # Re-raise the error if requested diff --git a/lib/log_struct/integrations/active_job/log_subscriber.rb b/lib/log_struct/integrations/active_job/log_subscriber.rb index a5176679..d5369f52 100644 --- a/lib/log_struct/integrations/active_job/log_subscriber.rb +++ b/lib/log_struct/integrations/active_job/log_subscriber.rb @@ -85,10 +85,21 @@ def build_base_fields(job) executions: job.executions, # Backends use Strings or Integers (SolidQueue uses its job row ID) provider_job_id: job.provider_job_id&.to_s, - arguments: ((job.class.respond_to?(:log_arguments?) && job.class.log_arguments?) ? job.arguments : nil) + arguments: logged_arguments(job) ) end + # ActionMailer's delivery job carries the mail's own arguments, which can be secrets: Devise passes its + # confirmation, password reset and invitation tokens as plain strings, which no key-based filter can find. + # For a mail, log the mailer, the mail and the delivery method only. + sig { params(job: ::ActiveJob::Base).returns(T.nilable(T::Array[T.untyped])) } + def logged_arguments(job) + return nil unless job.class.respond_to?(:log_arguments?) && job.class.log_arguments? + return job.arguments.first(3) if defined?(::ActionMailer::MailDeliveryJob) && job.is_a?(::ActionMailer::MailDeliveryJob) + + job.arguments + end + # perform_now lets any Exception through, not only StandardErrors sig { params(exception: Exception, job: ::ActiveJob::Base, _event: ::ActiveSupport::Notifications::Event).void } def log_exception(exception, job, _event) diff --git a/test/log_struct/error_handling_test.rb b/test/log_struct/error_handling_test.rb index df1e6fc3..84e6241a 100644 --- a/test/log_struct/error_handling_test.rb +++ b/test/log_struct/error_handling_test.rb @@ -93,4 +93,31 @@ def test_handle_exception_log_production_logs_in_production assert_equal 1, logged.length end + + def test_handle_exception_report_without_logging + LogStruct.config.error_handling_modes.standard_errors = LogStruct::ErrorHandlingMode::Report + error = RuntimeError.new("already logged") + logged = [] + reported = [] + + LogStruct.stub(:error, ->(log) { logged << log }) do + LogStruct::MultiErrorReporter.stub(:report_error, ->(err, _ctx) { reported << err }) do + LogStruct.handle_exception(error, source: LogStruct::Source::App, log: false) + end + end + + assert_empty logged + assert_equal [error], reported + end + + def test_handle_exception_log_mode_without_logging_does_nothing + LogStruct.config.error_handling_modes.standard_errors = LogStruct::ErrorHandlingMode::Log + logged = [] + + LogStruct.stub(:error, ->(log) { logged << log }) do + LogStruct.handle_exception(RuntimeError.new("already logged"), source: LogStruct::Source::App, log: false) + end + + assert_empty logged + end end diff --git a/test/log_struct/integrations/action_mailer/error_handling_test.rb b/test/log_struct/integrations/action_mailer/error_handling_test.rb new file mode 100644 index 00000000..2e521b24 --- /dev/null +++ b/test/log_struct/integrations/action_mailer/error_handling_test.rb @@ -0,0 +1,180 @@ +# typed: true +# frozen_string_literal: true + +require "test_helper" +require "action_mailer" + +class ActionMailerErrorHandlingTest < ActiveSupport::TestCase + class DeliveryFailed < StandardError; end + + # Fails like an email provider rejecting the email + class FailingDelivery + def initialize(_settings) + end + + def deliver!(_mail) + raise DeliveryFailed, "Invalid 'From' address" + end + end + + # LogStruct prepends ErrorHandling to ActionMailer::Base, and apps' mailers inherit it + class BaseMailer < ActionMailer::Base + prepend LogStruct::Integrations::ActionMailer::ErrorHandling + + add_delivery_method :logstruct_failing, FailingDelivery + self.delivery_method = :logstruct_failing + end + + class FailingMailer < BaseMailer + def notice + mail(to: "user@example.com", from: "app@example.com", subject: "Notice", body: "Hello") + end + end + + class IgnoringMailer < FailingMailer + rescue_from DeliveryFailed, with: :log_and_ignore_error + end + + class ReportingMailer < FailingMailer + rescue_from DeliveryFailed, with: :log_and_report_error + end + + setup do + @orig_logger = ::Rails.logger + @buf = StringIO.new + logger = ::Logger.new(@buf) + logger.formatter = LogStruct::Formatter.new + ::Rails.logger = logger + @reported = [] + @orig_standard_errors = LogStruct.config.error_handling_modes.standard_errors + end + + teardown do + ::Rails.logger = @orig_logger + LogStruct.config.error_handling_modes.standard_errors = @orig_standard_errors + end + + test "a failed delivery is one error line" do + with_reports_recorded do + assert_raises(DeliveryFailed) { ActionMailer::MessageDelivery.new(FailingMailer, :notice).deliver_now } + end + + assert_equal 1, error_lines.size + assert_equal 1, @reported.size + end + + # Raise is the default mode for standard errors: LogStruct raises the error instead of reporting it, and the app's + # error reporter gets it from the job or the request + test "in Raise mode, a failed delivery in MailDeliveryJob is one error line from the mailer" do + LogStruct.config.error_handling_modes.standard_errors = LogStruct::ErrorHandlingMode::Raise + + assert_raises(DeliveryFailed) { deliver_through_job(FailingMailer) } + + assert_equal [[FailingMailer.name, "notice"]], error_lines.map { |line| [line["mailer"], line["mailer_action"]] } + end + + test "in Report mode, a failed delivery in MailDeliveryJob is logged and reported once" do + LogStruct.config.error_handling_modes.standard_errors = LogStruct::ErrorHandlingMode::Report + reported = [] + + LogStruct::MultiErrorReporter.stub(:report_error, ->(error, _context) { reported << error }) do + assert_raises(DeliveryFailed) { deliver_through_job(FailingMailer) } + end + + assert_equal 1, error_lines.size + assert_equal 1, reported.size + end + + test "in Report mode, the mailer class logs and reports an error once" do + LogStruct.config.error_handling_modes.standard_errors = LogStruct::ErrorHandlingMode::Report + error = DeliveryFailed.new("Couldn't load the email's record") + reported = [] + + LogStruct::MultiErrorReporter.stub(:report_error, ->(e, _context) { reported << e }) do + assert_raises(DeliveryFailed) { FailingMailer.handle_exception(error) } + end + + assert_equal 1, error_lines.size + assert_equal [error], reported + end + + test "a failed delivery in MailDeliveryJob raises the delivery error, logged and reported only by the mailer" do + with_reports_recorded do + assert_raises(DeliveryFailed) { ActionMailer::MessageDelivery.new(FailingMailer, :notice).deliver_now } + end + lines_from_mailer = error_lines.size + reports_from_mailer = @reported.size + @buf.truncate(0) + @buf.rewind + @reported.clear + + error = with_reports_recorded do + assert_raises(DeliveryFailed) { deliver_through_job(FailingMailer) } + end + + assert_equal "Invalid 'From' address", error.message + assert_equal lines_from_mailer, error_lines.size, "The mailer class logged the error again" + assert_equal reports_from_mailer, @reported.size, "The mailer class reported the error again" + end + + test "a mailer's own rescue_from handler works in MailDeliveryJob" do + with_reports_recorded { deliver_through_job(IgnoringMailer) } + + assert_empty @reported + assert_equal [[IgnoringMailer.name, "notice"]], error_lines.map { |line| [line["mailer"], line["mailer_action"]] } + end + + test "the mailer class logs, reports and re-raises an error its mailer didn't handle" do + error = DeliveryFailed.new("Couldn't load the email's record") + + with_reports_recorded do + assert_raises(DeliveryFailed) { FailingMailer.handle_exception(error) } + end + + assert_equal [error], @reported + assert_equal 1, error_lines.size + assert_match(/FailingMailer\z/, error_lines.first["mailer"]) + end + + test "the mailer class logs an error its rescue_from handler ignores, without raising" do + with_reports_recorded { IgnoringMailer.handle_exception(DeliveryFailed.new("Couldn't load the email's record")) } + + assert_empty @reported + assert_equal 1, error_lines.size + end + + # In Raise mode handle_exception raises, so log_and_report_error lets the error through. The job + # must fail as deliver_now does, not swallow it at the mailer class. + test "in Raise mode, log_and_report_error fails a delivery job as deliver_now raises" do + LogStruct.config.error_handling_modes.standard_errors = LogStruct::ErrorHandlingMode::Raise + + assert_raises(DeliveryFailed) { ActionMailer::MessageDelivery.new(ReportingMailer, :notice).deliver_now } + assert_raises(DeliveryFailed) { deliver_through_job(ReportingMailer) } + + assert_equal 2, error_lines.size, "One line per delivery" + end + + # Only the mailer's own handler marks an error for the class handler to raise again + test "the class handler ignores an error each time it's given it" do + error = DeliveryFailed.new("Couldn't load the email's record") + + 2.times { IgnoringMailer.handle_exception(error) } + + assert_equal 2, error_lines.size + end + + private + + def deliver_through_job(mailer_class) + ActionMailer::MailDeliveryJob.perform_now(mailer_class.name, "notice", "deliver_now", args: []) + end + + # LogStruct.handle_exception raises in tests; record what it would report in production + def with_reports_recorded(&block) + LogStruct.stub(:handle_exception, ->(error, source:, context: nil, log: true) { @reported << error }, &block) + end + + def error_lines + @buf.string.lines.map { |line| JSON.parse(line) }.select { |line| line["src"] == "mailer" && line["evt"] == "error" } + end +end diff --git a/test/log_struct/integrations/active_job/log_subscriber_test.rb b/test/log_struct/integrations/active_job/log_subscriber_test.rb index 3ea35a85..f5dc6007 100644 --- a/test/log_struct/integrations/active_job/log_subscriber_test.rb +++ b/test/log_struct/integrations/active_job/log_subscriber_test.rb @@ -15,6 +15,9 @@ def perform end end + class TestMailer < ::ActionMailer::Base + end + setup do @original_logger = ::ActiveJob::Base.logger @log_output = setup_isolated_logger @@ -88,6 +91,42 @@ def perform assert_equal %w[job error NotImplementedError], log.values_at("src", "evt", "error_class") end + test "logs only the mailer, the mail and the delivery method for a mail delivery job" do + clear_log_buffer(@log_output) + + # Devise's deliver_later passes the raw token as a plain string + mailer = TestMailer.name + job = ::ActionMailer::MailDeliveryJob.new( + mailer, + "reset_password_instructions", + "deliver_now", + args: ["gid://app/User/1", "raw-reset-password-token", {}] + ) + start_time = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) + @subscriber.perform_start(build_event("perform_start.active_job", start_time, start_time, {job: job})) + @subscriber.perform(build_event("perform.active_job", start_time, start_time + 0.1, {job: job})) + ::SemanticLogger.flush + + logs = @log_output.string.lines.select { |line| line.strip.start_with?("{") }.map { |line| JSON.parse(line) } + + assert_equal 2, logs.size + logs.each do |log| + assert_equal [mailer, "reset_password_instructions", "deliver_now"], log["arguments"] + end + refute_includes @log_output.string, "raw-reset-password-token" + end + + test "logs other jobs' arguments" do + clear_log_buffer(@log_output) + + job = TestActiveJob.new("report", 42) + start_time = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) + @subscriber.perform(build_event("perform.active_job", start_time, start_time + 0.1, {job: job})) + ::SemanticLogger.flush + + assert_equal ["report", 42], parse_first_log(@log_output)["arguments"] + end + private def build_event(name, start_time, finish_time, payload) diff --git a/test/test_helper.rb b/test/test_helper.rb index 4c3fc057..fded5a69 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -114,16 +114,33 @@ class ActiveSupport::TestCase setup do TEST_LOG_IO.truncate(0) TEST_LOG_IO.rewind - @saved_filter_keys = T.let(LogStruct.config.filters.filter_keys.dup, T.nilable(T::Array[Symbol])) - @saved_filter_matchers = T.let(LogStruct.config.filters.filter_matchers.dup, - T.nilable(T::Array[LogStruct::ConfigStruct::FilterMatcher])) + # Each test gets its own copy of the configuration: tests change filters in place and set + # handlers, scrubbers, salts and error handling modes (the code examples do), which later + # tests would otherwise see + @saved_configuration = T.let(LogStruct.configuration, T.nilable(LogStruct::Configuration)) + LogStruct.configuration = deep_copy_configuration(LogStruct.configuration) end - # Tests change the filters in place, so later tests would see them. Runs after each test - # class's own teardown has put back the configuration it replaced. + # Runs after each test class's own teardown has put back the configuration it replaced teardown do - LogStruct.config.filters.filter_keys = T.must(@saved_filter_keys) - LogStruct.config.filters.filter_matchers = T.must(@saved_filter_matchers) + LogStruct.configuration = T.must(@saved_configuration) + end + + sig { params(value: T.untyped).returns(T.untyped) } + def deep_copy_configuration(value) + case value + when T::Struct + copy = value.dup + value.class.props.each_key do |name| + ivar = :"@#{name}" + copy.instance_variable_set(ivar, deep_copy_configuration(value.instance_variable_get(ivar))) + end + copy + when Array then value.map { |item| deep_copy_configuration(item) } + when Hash then value.to_h { |key, item| [key, deep_copy_configuration(item)] } + when String then value.dup + else value + end end # Helper method for tests that need to capture and parse log output