Logging sensitive data

[tomas-stefano]

Context

I am working on an application where the email subject contains sensitive information, such as usernames. I have implemented a custom log formatter to redact sensitive information from logs. While the custom log formatter works correctly for web application logs, it does not seem to be applied to logs generated by background workers (Sidekiq jobs).

# config/initializer/semantic_logger.rg
  return unless defined? SemanticLogger
  require_dependency Rails.root.join('app/lib/custom_log_formatter')

  Clockwork.configure { |config| config[:logger] = SemanticLogger[Clockwork] if defined?(Clockwork) }
  SemanticLogger.add_appender(
    io: STDOUT,
    level: Rails.application.config.log_level,
    formatter: CustomLogFormatter.new,
  )

Then the CustomLogFormatter definition (I added a puts to check if is called - you can read the code):

# app/lib/custom_log_formatter
class CustomLogFormatter < SemanticLogger::Formatters::Raw
  REDACTED = '[REDACTED]'.freeze

  def call(log, logger)
    super

    add_custom_fields
    sanitize_payload_fields
    remove_post_params
    filter_skipping_email_message

    # rubocop:disable Rails/Output
    puts '-' * 80
    puts "Hash: #{hash}"
    puts '-' * 80
    # rubocop:enable Rails/Output
    hash.to_json
  end

private

  def add_custom_fields
    hash[:domain] = HostingEnvironment.hostname
    hash[:environment] = HostingEnvironment.environment_name
    hash[:hosting_environment] = HostingEnvironment.environment_name

    if (job_id = Thread.current[:job_id])
      hash[:job_id] = job_id
    end
    if (job_queue = Thread.current[:job_queue])
      hash[:job_queue] = job_queue
    end

    tid = Thread.current[:sidekiq_tid]
    if tid.present?
      ctx = Sidekiq::Context.current
      hash[:tid] = tid
      hash[:ctx] = ctx
    end
  end

  def sanitize_payload_fields
    if hash[:payload].present?
      hash[:payload].reject! { |key, _| SANITIZED_REQUEST_PARAMS.map(&:to_s).include?(key) }
      sanitize_mailer_subject_and_to
    end
  end

  def sanitize_mailer_subject_and_to
    if hash.dig(:payload, :subject).present?
      hash[:payload][:subject] = REDACTED
    end

    if hash.dig(:payload, :to).present?
      hash[:payload][:to] = REDACTED
    end
  end

  def filter_skipping_email_message
    if hash[:message]&.include?('Skipping email')
      hash[:message] = "Skipping email to #{REDACTED}"
    end
  end

  def remove_post_params
    return unless method_is_post_or_put_or_patch? && hash.dig(:payload, :params).present?

    hash[:payload][:params].clear
  end

  def method_is_post_or_put_or_patch?
    hash.dig(:payload, :method).in? %w[PUT POST PATCH]
  end
end

I can see this custom log working as expected although is does not work for the worker when they finish the job.

I can see the Custom log working for the web app and the logs working:

Hash: ... { [REDACTED] ... }

But on the worker after the mail is delivered / or skipped (even the puts is not even being called and the custom log leaks sensitive information):

[my-app-secondary-worker-1234] 2024-07-19 15:57:48.493654 I [1:processor] 
[ActionMailer::MailDeliveryJob] [c8a3facc-c8f0-45c1-b741-16e3e1198563] {jid: 51e96bc022d50913e3fb0ff1, queue: mailers} ActionMailer::Base -- Delivered mail 111@my-app-secondary-worker-85b9f59ff8-5l5gt.mail (97.3ms) -- 
{:event_name=>"deliver.action_mailer", 
:mailer=>"SomeMailer", 
:action=>nil, 
:message_id=>"111@myapp-secondary-worker-85b9f59ff8-5l5gt.mail", :perform_deliveries=>true, 
:subject=>"[REVIEW] John Doe did something", 
:to=>["john.doe@test.co.uk"], 
:from=>nil, :bcc=>nil, :cc=>nil, :date=>2024-07-19 14:57:48 UTC, :duration=>97.35, :args=>nil}

the subject and the to should be redacted and most important, the custom logger (and the puts) also should have being called but apparently it is not.

It the perform deliveries not using tha appenders to call the custom log?

Am I missing something?

[tomas-stefano]

My PR where I am working on this issue:

DFE-Digital/apply-for-teacher-training#9502