Improve logging in e-mail receiver processing

Previously there was little visibility in Service Desk and
reply-by-email processing. Now we add more JSON logging when mails are
successfully processed and when they fail.

To do this, we needed to refactor:

1. `Email::Receiver` and `Email::ServiceDeskReceiver` to make it
possible to extract the metadata from the mail.

2. `EmailReceiverWorker` so that`ServiceDeskEmailReceiverWorker` can
better reuse the code.

Relates to https://gitlab.com/gitlab-org/gitlab/-/issues/118594

Changelog: added

app/workers/email_receiver_worker.rb

@@ -9,21 +9,80 @@ class EmailReceiverWorker # rubocop:disable Scalability/IdempotentWorker
   urgency :high
   weight 2
 
+  attr_accessor :raw
+
   def perform(raw)
-    return unless Gitlab::IncomingEmail.enabled?
+    return unless should_perform?
 
-    begin
-      Gitlab::Email::Receiver.new(raw).execute
-    rescue StandardError => e
-      handle_failure(raw, e)
-    end
+    @raw = raw
+    execute_receiver
+  end
+
+  def should_perform?
+    Gitlab::IncomingEmail.enabled?
   end
 
   private
 
-  def handle_failure(raw, error)
-    Gitlab::AppLogger.warn("Email can not be processed: #{error}\n\n#{raw}")
+  def execute_receiver
+    receiver.execute
+    log_success
+  rescue StandardError => e
+    log_error(e)
+    handle_failure(e)
+  end
+
+  def receiver
+    @receiver ||= Gitlab::Email::Receiver.new(raw)
+  end
+
+  def logger
+    Sidekiq.logger
+  end
+
+  def log_success
+    logger.info(build_message('Successfully processed message', receiver.mail_metadata))
+  end
+
+  def log_error(error)
+    payload =
+      case error
+      # Unparsable e-mails don't have metadata we can use
+      when Gitlab::Email::EmailUnparsableError, Gitlab::Email::EmptyEmailError
+        {}
+      else
+        mail_metadata
+      end
+
+    # We don't need the backtrace and more details if the e-mail couldn't be processed
+    if error.is_a?(Gitlab::Email::ProcessingError)
+      payload['exception.class'] = error.class.name
+    else
+      Gitlab::ExceptionLogFormatter.format!(error, payload)
+      Gitlab::ErrorTracking.track_exception(error)
+    end
+
+    logger.error(build_message('Error processing message', payload))
+  end
+
+  def build_message(message, params = {})
+    {
+      class: self.class.name,
+      Labkit::Correlation::CorrelationId::LOG_KEY => Labkit::Correlation::CorrelationId.current_id,
+      message: message
+    }.merge(params)
+  end
+
+  def mail_metadata
+    receiver.mail_metadata
+  rescue StandardError => e
+    # We should never get here as long as we check EmailUnparsableError, but
+    # let's be defensive in case we did something wrong.
+    Gitlab::ErrorTracking.track_exception(e)
+    {}
+  end
 
+  def handle_failure(error)
     return unless raw.present?
 
     can_retry = false

app/workers/service_desk_email_receiver_worker.rb

@@ -5,13 +5,11 @@ class ServiceDeskEmailReceiverWorker < EmailReceiverWorker # rubocop:disable Sca
 
   sidekiq_options retry: 3
 
-  def perform(raw)
-    return unless ::Gitlab::ServiceDeskEmail.enabled?
+  def should_perform?
+    ::Gitlab::ServiceDeskEmail.enabled?
+  end
 
-    begin
-      Gitlab::Email::ServiceDeskReceiver.new(raw).execute
-    rescue StandardError => e
-      handle_failure(raw, e)
-    end
+  def receiver
+    @receiver ||= Gitlab::Email::ServiceDeskReceiver.new(raw)
   end
 end

changelogs/unreleased/sh-improve-email-receiver-logging.yml

+---
+title: Improve logging in e-mail receiver processing
+merge_request: 60692
+author:
+type: added

lib/gitlab/email/receiver.rb

@@ -6,6 +6,8 @@ require_dependency 'gitlab/email/handler'
 module Gitlab
   module Email
     class Receiver
+      include Gitlab::Utils::StrongMemoize
+
       def initialize(raw)
         @raw = raw
       end
@@ -13,11 +15,7 @@ module Gitlab
       def execute
         raise EmptyEmailError if @raw.blank?
 
-        mail = build_mail
-
-        ignore_auto_reply!(mail)
-
-        handler = find_handler(mail)
+        ignore_auto_reply!
 
         raise UnknownIncomingEmail unless handler
 
@@ -26,13 +24,33 @@ module Gitlab
         end
       end
 
+      def mail_metadata
+        {
+          message_id: mail.message_id,
+          from_address: mail.from,
+          to_address: mail.to,
+          mail_key: mail_key,
+          references: Array(mail.references),
+          delivered_to: delivered_to.map(&:value),
+          envelope_to: envelope_to.map(&:value),
+          x_envelope_to: x_envelope_to.map(&:value)
+        }
+      end
+
       private
 
-      def find_handler(mail)
-        mail_key = extract_mail_key(mail)
+      def handler
+        strong_memoize(:handler) { find_handler }
+      end
+
+      def find_handler
         Handler.for(mail, mail_key)
       end
 
+      def mail
+        strong_memoize(:mail) { build_mail }
+      end
+
       def build_mail
         Mail::Message.new(@raw)
       rescue Encoding::UndefinedConversionError,
@@ -40,22 +58,24 @@ module Gitlab
         raise EmailUnparsableError, e
       end
 
-      def extract_mail_key(mail)
-        key_from_to_header(mail) || key_from_additional_headers(mail)
+      def mail_key
+        strong_memoize(:mail_key) do
+          key_from_to_header || key_from_additional_headers
+        end
       end
 
-      def key_from_to_header(mail)
+      def key_from_to_header
         mail.to.find do |address|
           key = Gitlab::IncomingEmail.key_from_address(address)
           break key if key
         end
       end
 
-      def key_from_additional_headers(mail)
-        find_key_from_references(mail) ||
-          find_key_from_delivered_to_header(mail) ||
-          find_key_from_envelope_to_header(mail) ||
-          find_key_from_x_envelope_to_header(mail)
+      def key_from_additional_headers
+        find_key_from_references ||
+          find_key_from_delivered_to_header ||
+          find_key_from_envelope_to_header ||
+          find_key_from_x_envelope_to_header
       end
 
       def ensure_references_array(references)
@@ -71,41 +91,53 @@ module Gitlab
         end
       end
 
-      def find_key_from_references(mail)
+      def find_key_from_references
         ensure_references_array(mail.references).find do |mail_id|
           key = Gitlab::IncomingEmail.key_from_fallback_message_id(mail_id)
           break key if key
         end
       end
 
-      def find_key_from_delivered_to_header(mail)
-        Array(mail[:delivered_to]).find do |header|
+      def delivered_to
+        Array(mail[:delivered_to])
+      end
+
+      def envelope_to
+        Array(mail[:envelope_to])
+      end
+
+      def x_envelope_to
+        Array(mail[:x_envelope_to])
+      end
+
+      def find_key_from_delivered_to_header
+        delivered_to.find do |header|
           key = Gitlab::IncomingEmail.key_from_address(header.value)
           break key if key
         end
       end
 
-      def find_key_from_envelope_to_header(mail)
-        Array(mail[:envelope_to]).find do |header|
+      def find_key_from_envelope_to_header
+        envelope_to.find do |header|
           key = Gitlab::IncomingEmail.key_from_address(header.value)
           break key if key
         end
       end
 
-      def find_key_from_x_envelope_to_header(mail)
-        Array(mail[:x_envelope_to]).find do |header|
+      def find_key_from_x_envelope_to_header
+        x_envelope_to.find do |header|
           key = Gitlab::IncomingEmail.key_from_address(header.value)
           break key if key
         end
       end
 
-      def ignore_auto_reply!(mail)
-        if auto_submitted?(mail) || auto_replied?(mail)
+      def ignore_auto_reply!
+        if auto_submitted? || auto_replied?
           raise AutoGeneratedEmailError
         end
       end
 
-      def auto_submitted?(mail)
+      def auto_submitted?
         # Mail::Header#[] is case-insensitive
         auto_submitted = mail.header['Auto-Submitted']&.value
 
@@ -114,7 +146,7 @@ module Gitlab
         auto_submitted && auto_submitted != 'no'
       end
 
-      def auto_replied?(mail)
+      def auto_replied?
         autoreply = mail.header['X-Autoreply']&.value
 
         autoreply && autoreply == 'yes'

lib/gitlab/email/service_desk_receiver.rb

@@ -5,14 +5,19 @@ module Gitlab
     class ServiceDeskReceiver < Receiver
       private
 
-      def find_handler(mail)
-        key = service_desk_key(mail)
-        return unless key
+      def find_handler
+        return unless service_desk_key
 
-        Gitlab::Email::Handler::ServiceDeskHandler.new(mail, nil, service_desk_key: key)
+        Gitlab::Email::Handler::ServiceDeskHandler.new(mail, nil, service_desk_key: service_desk_key)
       end
 
-      def service_desk_key(mail)
+      def service_desk_key
+        strong_memoize(:service_desk_key) do
+          find_service_desk_key
+        end
+      end
+
+      def find_service_desk_key
         mail.to.find do |address|
           key = ::Gitlab::ServiceDeskEmail.key_from_address(address)
           break key if key

spec/lib/gitlab/email/receiver_spec.rb

@@ -15,6 +15,7 @@ RSpec.describe Gitlab::Email::Receiver do
 
   context 'when the email contains a valid email address in a header' do
     let(:handler) { double(:handler) }
+    let(:metadata) { receiver.mail_metadata }
 
     before do
       allow(handler).to receive(:execute)
@@ -22,24 +23,38 @@ RSpec.describe Gitlab::Email::Receiver do
       allow(handler).to receive(:metrics_event)
 
       stub_incoming_email_setting(enabled: true, address: "incoming+%{key}@appmail.example.com")
+
+      expect(receiver.mail_metadata.keys).to match_array(%i(message_id from_address to_address mail_key references delivered_to envelope_to x_envelope_to))
     end
 
     context 'when in a Delivered-To header' do
       let(:email_raw) { fixture_file('emails/forwarded_new_issue.eml') }
 
       it_behaves_like 'correctly finds the mail key'
+
+      it 'parses the metadata' do
+        expect(metadata[:delivered_to]). to eq(["incoming+gitlabhq/gitlabhq+auth_token@appmail.example.com", "support@example.com"])
+      end
     end
 
     context 'when in an Envelope-To header' do
       let(:email_raw) { fixture_file('emails/envelope_to_header.eml') }
 
       it_behaves_like 'correctly finds the mail key'
+
+      it 'parses the metadata' do
+        expect(metadata[:envelope_to]). to eq(["incoming+gitlabhq/gitlabhq+auth_token@appmail.example.com"])
+      end
     end
 
     context 'when in an X-Envelope-To header' do
       let(:email_raw) { fixture_file('emails/x_envelope_to_header.eml') }
 
       it_behaves_like 'correctly finds the mail key'
+
+      it 'parses the metadata' do
+        expect(metadata[:x_envelope_to]). to eq(["incoming+gitlabhq/gitlabhq+auth_token@appmail.example.com"])
+      end
     end
 
     context 'when enclosed with angle brackets in an Envelope-To header' do

spec/workers/email_receiver_worker_spec.rb

@@ -13,6 +13,7 @@ RSpec.describe EmailReceiverWorker, :mailer do
     it "calls the email receiver" do
       expect(Gitlab::Email::Receiver).to receive(:new).with(raw_message).and_call_original
       expect_any_instance_of(Gitlab::Email::Receiver).to receive(:execute)
+      expect(Sidekiq.logger).to receive(:info).with(hash_including(message: "Successfully processed message")).and_call_original
 
       described_class.new.perform(raw_message)
     end
@@ -20,10 +21,11 @@ RSpec.describe EmailReceiverWorker, :mailer do
     context "when an error occurs" do
       before do
         allow_any_instance_of(Gitlab::Email::Receiver).to receive(:execute).and_raise(error)
+        expect(Sidekiq.logger).to receive(:error).with(hash_including('exception.class' => error.class.name)).and_call_original
       end
 
       context 'when the error is Gitlab::Email::EmptyEmailError' do
-        let(:error) { Gitlab::Email::EmptyEmailError }
+        let(:error) { Gitlab::Email::EmptyEmailError.new }
 
         it 'sends out a rejection email' do
           perform_enqueued_jobs do
@@ -38,7 +40,7 @@ RSpec.describe EmailReceiverWorker, :mailer do
       end
 
       context 'when the error is Gitlab::Email::AutoGeneratedEmailError' do
-        let(:error) { Gitlab::Email::AutoGeneratedEmailError }
+        let(:error) { Gitlab::Email::AutoGeneratedEmailError.new }
 
         it 'does not send out any rejection email' do
           perform_enqueued_jobs do
@@ -63,6 +65,21 @@ RSpec.describe EmailReceiverWorker, :mailer do
           expect(email.body.parts.last.to_s).to include("Could not deal with that")
         end
       end
+
+      context 'when the error is ActiveRecord::StatementTimeout' do
+        let(:error) { ActiveRecord::StatementTimeout.new("Statement timeout") }
+
+        it 'does not report the error to the sender' do
+          expect(Gitlab::ErrorTracking).to receive(:track_exception).with(error).and_call_original
+
+          perform_enqueued_jobs do
+            described_class.new.perform(raw_message)
+          end
+
+          email = ActionMailer::Base.deliveries.last
+          expect(email).to be_nil
+        end
+      end
     end
   end
 

spec/workers/service_desk_email_receiver_worker_spec.rb

@@ -9,11 +9,12 @@ RSpec.describe ServiceDeskEmailReceiverWorker, :mailer do
 
     context 'when service_desk_email config is enabled' do
       before do
-        stub_service_desk_email_setting(enabled: true, address: 'foo')
+        stub_service_desk_email_setting(enabled: true, address: 'support+%{key}@example.com')
       end
 
       it 'does not ignore the email' do
-        expect(Gitlab::Email::ServiceDeskReceiver).to receive(:new)
+        expect(Gitlab::Email::ServiceDeskReceiver).to receive(:new).and_call_original
+        expect(Sidekiq.logger).to receive(:error).with(hash_including('exception.class' => Gitlab::Email::ProjectNotFound.to_s)).and_call_original
 
         worker.perform(email)
       end
@@ -23,6 +24,7 @@ RSpec.describe ServiceDeskEmailReceiverWorker, :mailer do
           allow_next_instance_of(Gitlab::Email::ServiceDeskReceiver) do |receiver|
             allow(receiver).to receive(:find_handler).and_return(nil)
           end
+          expect(Sidekiq.logger).to receive(:error).with(hash_including('exception.class' => Gitlab::Email::UnknownIncomingEmail.to_s)).and_call_original
         end
 
         it 'sends a rejection email' do