From 989676c0926f603458a80d510751e4d1fa843247 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 18:51:35 +1300 Subject: [PATCH 1/4] Define the mailer error handlers on the mailer class too ActionMailer::MailDeliveryJob passes a delivery error to the mailer class (handle_exception), and Rails looks the rescue_from handler up on the class. LogStruct's handlers (log_and_reraise_error, and the log_and_ignore_error / log_and_report_error that apps use in their own rescue_from lines) were only instance methods, so every email that failed to send in a delivery job raised "NameError: undefined method 'log_and_reraise_error' for class", with the real error as its cause. Define them on the class as well. An error the mailer's own handler already logged and re-raised is marked, so the class handler re-raises it without logging or reporting it twice. --- .../action_mailer/error_handling.rb | 56 ++++++++- .../action_mailer/error_handling_test.rb | 110 ++++++++++++++++++ 2 files changed, 165 insertions(+), 1 deletion(-) create mode 100644 test/log_struct/integrations/action_mailer/error_handling_test.rb diff --git a/lib/log_struct/integrations/action_mailer/error_handling.rb b/lib/log_struct/integrations/action_mailer/error_handling.rb index 35320fe5..7d18628d 100644 --- a/lib/log_struct/integrations/action_mailer/error_handling.rb +++ b/lib/log_struct/integrations/action_mailer/error_handling.rb @@ -15,6 +15,57 @@ module ErrorHandling extend T::Sig extend ActiveSupport::Concern + # Marks an error the mailer's handler logged and re-raised, so the class handler doesn't log it again + LOGGED_ERROR_IVAR = :@_logstruct_mailer_error_logged + + # 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 + + # Errors that reach the class handler from the delivery itself were logged (and reported) + # by the mailer's handler before it re-raised them for the job to retry + 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:) + unless error.instance_variable_get(LOGGED_ERROR_IVAR) + 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 + )) + LogStruct.handle_exception(error, source: Source::Mailer, context: {mailer_class: mailer_class.to_s}) if report + end + + Kernel.raise error if reraise + end + sig { returns(T.nilable(T::Boolean)) } attr_accessor :logstruct_mail_failed @@ -166,7 +217,10 @@ def handle_error_notifications(error, notify, report, reraise) end # Re-raise the error if requested - Kernel.raise error if reraise + if reraise + error.instance_variable_set(LOGGED_ERROR_IVAR, true) unless error.frozen? + Kernel.raise error + end end # Log a notification event that can be picked up by external systems 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..a217c98a --- /dev/null +++ b/test/log_struct/integrations/action_mailer/error_handling_test.rb @@ -0,0 +1,110 @@ +# 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 + + setup do + @orig_logger = ::Rails.logger + @buf = StringIO.new + logger = ::Logger.new(@buf) + logger.formatter = LogStruct::Formatter.new + ::Rails.logger = logger + @reported = [] + end + + teardown do + ::Rails.logger = @orig_logger + 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 + + 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) { @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 From f87e463a651ae7b14b6bf02a75e3597884edb0f0 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 15:08:34 +1300 Subject: [PATCH 2/4] Log only the mailer, mail and delivery method for mail delivery jobs A MailDeliveryJob's arguments include the mail's own arguments, which can be secrets with no key to filter on: Devise passes its confirmation, password reset and invitation tokens to the mailer, and deliver_later puts them in the job. ActiveJob lines logged them on enqueue, start and finish. --- .../docs/filtering-sensitive-data/page.tsx | 6 +++ .../integrations/active_job/log_subscriber.rb | 13 ++++++- .../active_job/log_subscriber_test.rb | 39 +++++++++++++++++++ 3 files changed, 57 insertions(+), 1 deletion(-) diff --git a/docs/app/docs/filtering-sensitive-data/page.tsx b/docs/app/docs/filtering-sensitive-data/page.tsx index cfcb3b7b..eb4ee219 100644 --- a/docs/app/docs/filtering-sensitive-data/page.tsx +++ b/docs/app/docs/filtering-sensitive-data/page.tsx @@ -24,6 +24,12 @@ 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. +

How Parameter Filtering Works 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/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) From aaf8239bd7a2e70972a8354ca30d2b310be2ad87 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 15:21:52 +1300 Subject: [PATCH 3/4] Log a failed email once The mailer's handler logged a failed delivery twice: its structured line, then the same struct again before reporting. In Log and Report modes handle_exception logged it a third time. In Raise mode (the default for standard errors) handle_exception raised before the error was marked as logged, so when it reached the mailer class (MailDeliveryJob) the class handler logged it again. handle_exception takes log: false for callers that have already logged the error, and the mailer marks the error as logged straight after its structured line. --- docs/lib/integration-helpers.ts | 2 +- lib/log_struct/concerns/error_handling.rb | 20 +++++--- .../action_mailer/error_handling.rb | 23 ++++----- test/log_struct/error_handling_test.rb | 27 +++++++++++ .../action_mailer/error_handling_test.rb | 48 ++++++++++++++++++- test/test_helper.rb | 8 +++- 6 files changed, 104 insertions(+), 24 deletions(-) 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 7d18628d..939f2b6f 100644 --- a/lib/log_struct/integrations/action_mailer/error_handling.rb +++ b/lib/log_struct/integrations/action_mailer/error_handling.rb @@ -60,7 +60,9 @@ def self.handle_mailer_class_error(mailer_class, error, report:, reraise:) backtrace: error.backtrace, level: Level::Error )) - LogStruct.handle_exception(error, source: Source::Mailer, context: {mailer_class: mailer_class.to_s}) if report + if report + LogStruct.handle_exception(error, source: Source::Mailer, context: {mailer_class: mailer_class.to_s}, log: false) + end end Kernel.raise error if reraise @@ -178,6 +180,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 + error.instance_variable_set(LOGGED_ERROR_IVAR, true) unless error.frozen? # Handle notifications and reporting handle_error_notifications(error, notify, report, reraise) @@ -199,28 +204,18 @@ 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 - if reraise - error.instance_variable_set(LOGGED_ERROR_IVAR, true) unless error.frozen? - Kernel.raise error - end + Kernel.raise error if reraise end # Log a notification event that can be picked up by external systems 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 index a217c98a..c0ee2478 100644 --- a/test/log_struct/integrations/action_mailer/error_handling_test.rb +++ b/test/log_struct/integrations/action_mailer/error_handling_test.rb @@ -42,10 +42,56 @@ class IgnoringMailer < FailingMailer 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 @@ -101,7 +147,7 @@ def deliver_through_job(mailer_class) # 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) { @reported << error }, &block) + LogStruct.stub(:handle_exception, ->(error, source:, context: nil, log: true) { @reported << error }, &block) end def error_lines diff --git a/test/test_helper.rb b/test/test_helper.rb index 4c3fc057..6aede2c9 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -117,13 +117,17 @@ class ActiveSupport::TestCase @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])) + @saved_error_reporting_handler = T.let(LogStruct.config.error_reporting_handler, + T.nilable(LogStruct::Handlers::ErrorReporter)) 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. + # Tests change the filters in place and set error reporting handlers (the code examples do), so + # later tests would see them. 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.config.error_reporting_handler = @saved_error_reporting_handler end # Helper method for tests that need to capture and parse log output From 9dad347439c59cb0788d1667e562bdae162a6bd1 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 21:09:59 +1300 Subject: [PATCH 4/4] Fail a delivery job when the mailer's handler lets the error through In Raise mode (the default for standard errors), a mailer whose rescue_from calls log_and_report_error has handle_exception raise the error. In a delivery job the error then reached the mailer class's handler, which saw that it was already logged and returned without raising, so the job succeeded and the error was never reported. The class handler now raises an error the mailer already logged, as deliver_now does, without logging it again. The marks use LogStruct::LoggedErrors instead of an instance variable on the error. The tests now give each test its own copy of the whole configuration. The code examples left string scrubbers, lograge options, salts, filter settings and the LogStruct error handling mode set for later tests. The docs say the mail argument filtering applies while the ActiveJob integration is on. --- .../docs/filtering-sensitive-data/page.tsx | 4 +- .../action_mailer/error_handling.rb | 43 +++++++++---------- .../action_mailer/error_handling_test.rb | 24 +++++++++++ test/test_helper.rb | 35 ++++++++++----- 4 files changed, 72 insertions(+), 34 deletions(-) diff --git a/docs/app/docs/filtering-sensitive-data/page.tsx b/docs/app/docs/filtering-sensitive-data/page.tsx index eb4ee219..8c61c4c5 100644 --- a/docs/app/docs/filtering-sensitive-data/page.tsx +++ b/docs/app/docs/filtering-sensitive-data/page.tsx @@ -28,7 +28,9 @@ export default function FilteringSensitiveDataPage() { 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. + 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.

diff --git a/lib/log_struct/integrations/action_mailer/error_handling.rb b/lib/log_struct/integrations/action_mailer/error_handling.rb index 939f2b6f..39469bc0 100644 --- a/lib/log_struct/integrations/action_mailer/error_handling.rb +++ b/lib/log_struct/integrations/action_mailer/error_handling.rb @@ -15,9 +15,6 @@ module ErrorHandling extend T::Sig extend ActiveSupport::Concern - # Marks an error the mailer's handler logged and re-raised, so the class handler doesn't log it again - LOGGED_ERROR_IVAR = :@_logstruct_mailer_error_logged - # 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.) @@ -43,26 +40,28 @@ def log_and_reraise_error(ex) end end - # Errors that reach the class handler from the delivery itself were logged (and reported) - # by the mailer's handler before it re-raised them for the job to retry + # 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:) - unless error.instance_variable_get(LOGGED_ERROR_IVAR) - 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 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 @@ -182,7 +181,7 @@ def log_email_delivery_error(error, notify: false, report: true, reraise: true) 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 - error.instance_variable_set(LOGGED_ERROR_IVAR, true) unless error.frozen? + LogStruct::LoggedErrors.mark(error) # Handle notifications and reporting handle_error_notifications(error, notify, report, reraise) diff --git a/test/log_struct/integrations/action_mailer/error_handling_test.rb b/test/log_struct/integrations/action_mailer/error_handling_test.rb index c0ee2478..2e521b24 100644 --- a/test/log_struct/integrations/action_mailer/error_handling_test.rb +++ b/test/log_struct/integrations/action_mailer/error_handling_test.rb @@ -35,6 +35,10 @@ 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 @@ -139,6 +143,26 @@ class IgnoringMailer < FailingMailer 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) diff --git a/test/test_helper.rb b/test/test_helper.rb index 6aede2c9..fded5a69 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -114,20 +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])) - @saved_error_reporting_handler = T.let(LogStruct.config.error_reporting_handler, - T.nilable(LogStruct::Handlers::ErrorReporter)) + # 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 and set error reporting handlers (the code examples do), 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.config.error_reporting_handler = @saved_error_reporting_handler + 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