Railsで、Action Mailerの callback・interceptor・observer の実行タイミングを調べてみた

Rails Ruby

RailsのAction Mailerには

などのフィルターやフックがあります。

ただ、これらの実行タイミングが分からなかったため、調べた時のメモです。

なお、今回は

  • メール送信が同期/非同期
  • メールサーバへの送信が成功/失敗

を組み合わせた4パターンで調べてみます。

　
目次

　

環境

  • Rails 6.1.4
  • letter opener 1.7.0
  • delayed_job_active_record 4.1.6
    • メールを非同期で送信するために、Active Jobのバックエンドとして利用

　

Action Mailerを使うアプリの準備

今回は

  • /hook/now にアクセスすると、メールを同期送信
  • /hook/later にアクセスすると、メールを非同期送信

とします。

また、メールサーバへの通信は

  • letter_opener を使うことで、メールサーバへの通信が成功したとみなせる
  • デフォルトのSMTP設定を使うことで、メールサーバへの通信が失敗しなとみなせる
    • デフォルトでは正しいSMTP設定になっていないため

として、 config/environments/development.rb へ設定することとします。

　

Railsアプリの生成とgem追加

Railsアプリを作成します。

% bundle exec rails new rails_mailer_app --skip-javascript --skip-turbolinks --skip-sprockets --skip-test

今回使うものをGemfileに追加します。

group :development do
  gem 'letter_opener'
end

gem 'delayed_job_active_record'

　

Delayed Jobのセットアップ

Delayed JobのREADMEに従ってセットアップします。
collectiveidea/delayed_job: Database based asynchronous priority queue system -- Extracted from Shopify

% bin/rails generate delayed_job:active_record
Running via Spring preloader in process 83213
      create  bin/delayed_job
       chmod  bin/delayed_job
      create  db/migrate/20210723085718_create_delayed_jobs.rb


% bin/rails db:migrate
== 20210723085718 CreateDelayedJobs: migrating ================================
-- create_table(:delayed_jobs)
   -> 0.0033s
-- add_index(:delayed_jobs, [:priority, :run_at], {:name=>"delayed_jobs_priority"})
   -> 0.0008s
== 20210723085718 CreateDelayedJobs: migrated (0.0043s) =======================

　

Mailerのセットアップ

Mailerを生成します。

% bin/rails g mailer MyMailer hello

　
生成されたMailerに対し、

  • before_action
  • after_action

を追加します。

　
今回は動作したことを確認するため、 logger.info を使ってログへ出力します。

Mailerなので、 logger で動作します。
2.3 メッセージ送信 | Rails アプリケーションのデバッグ - Railsガイド

class MyMailer < ApplicationMailer
  before_action :log_at_before_action
  after_action :log_at_after_action

  def hello
    @greeting = 'Hi'

    mail to: 'to@example.org'

   logger.info('<====== [Run hello] =======>')
  end

  private

  def log_at_before_action
   logger.info('======= [Before] =======>')
  end

  def log_at_after_action
   logger.info('<====== [After] ========')
  end
end

　

Controllerのセットアップ

Mailerができたので、Controllerを生成します。

% bin/rails g controller hook now later --no-helper --no-assets

　
Controllerの中でMailerを起動します。

now アクションは同期送信、laterアクションは非同期送信としています。

class HookController < ApplicationController
  def now
    MyMailer.hello.deliver_now
  end

  def later
    MyMailer.hello.deliver_later
  end
end

　

Interceptorの作成

app/mailers/my_mailer_interceptor.rb として作成します。

Interceptorとして動作するよう、クラスメソッド delivering_email を定義し、その中でログを出力しています。

class MyMailerInterceptor
  def self.delivering_email(mail)
    Rails.logger.info('<====== [Interceptor] =======>')
  end
end

　

Observerの作成

app/mailers/my_mailer_observer.rb として作成します。

こちらもクラスメソッド delivered_email を定義します。

なお、引数 message のクラス名も確認できるよう、ログに出力します。

class MyMailerObserver
  def self.delivered_email(message)
    Rails.logger.info('======= [Observer] =======>')
    Rails.logger.info(message.class.to_s)
    Rails.logger.info('<====== [Observer] ========')
  end
end

　

config/environments/development.rb への追記

メールまわりの設定を追記します。

なお、パターンごとの設定はコメントアウトしておき、動作確認する時にアンコメントしていきます。

# 追加
# メールの動作確認
# interceptorは常に実行
config.action_mailer.interceptors = ['MyMailerInterceptor']
# observerは常に実行
config.action_mailer.observers = ['MyMailerObserver']
# メール送信時のエラーは無視しない
config.action_mailer.raise_delivery_errors = true
# メール配信を行う
config.action_mailer.perform_deliveries = true

# パターン1. 同期送信、letter_openerを使用
# config.action_mailer.delivery_method = :letter_opener

# パターン2. 同期送信、存在しないSMTPサーバを使用
# config.action_mailer.delivery_method = :smtp

# パターン3. 非同期送信、letter openerの設定
# config.active_job.queue_adapter = :delayed_job
# config.action_mailer.delivery_method = :letter_opener

# パターン4. 非同期送信、存在しないSMTPサーバ
# config.active_job.queue_adapter = :delayed_job
# config.action_mailer.delivery_method = :smtp

　
以上で、確認するための準備ができました。

　

パターン1. 同期送信、letter_openerを使用

config/environments/development.rb で

config.action_mailer.delivery_method = :letter_opener

を有効にして実行すると、

Started GET "/hook/now" for 127.0.0.1 at 2021-07-23 20:53:17 +0900
Processing by HookController#now as HTML
======= [Before] =======>
  Rendered layout layouts/mailer.text.erb (Duration: 0.1ms | Allocations: 118)
<====== [Run hello] =======>
<====== [After] ========
MyMailer#hello: processed outbound mail in 5.2ms
<====== [Interceptor] =======>
Delivered mail 60faadad696f5_15d7e43e41150@...
======= [Observer] =======>
Mail::Message
<====== [Observer] ========

と、

  1. before_action
  2. Mailerのhelloメソッド
  3. after_action
  4. interceptor
  5. observer

の順で実行されました。

　

パターン2. 同期送信、存在しないSMTPサーバを使用

config/environments/development.rb で

config.action_mailer.delivery_method = :smtp

を有効にして実行すると、画面に Connection refused - connect(2) for "localhost" port 25 エラーが表示されました。

また、ログには

Started GET "/hook/now" for 127.0.0.1 at 2021-07-23 20:58:06 +0900
======= [Before] =======>
  Rendered layout layouts/mailer.text.erb (Duration: 0.5ms | Allocations: 287)
<====== [Run hello] =======>
<====== [After] ========
MyMailer#hello: processed outbound mail in 12.9ms
<====== [Interceptor] =======>
Delivered mail 60faaece837ed_16bcd2a30984@...
...
Completed 500 Internal Server Error in 75ms (ActiveRecord: 0.0ms | Allocations: 42200)

Errno::ECONNREFUSED (Connection refused - connect(2) for "localhost" port 25):

と出力されました。

  1. before_action
  2. Mailerのhelloメソッド
  3. after_action
  4. interceptor

までは実行されたものの、 observer は実行されませんでした。

　

パターン3. 非同期送信、letter openerを使用

config/environments/development.rb で

config.active_job.queue_adapter = :delayed_job
config.action_mailer.delivery_method = :letter_opener

を有効にして hook/later にアクセスした時は

Started GET "/hook/later" for 127.0.0.1 at 2021-07-23 21:02:34 +0900
...
[ActiveJob] Enqueued ActionMailer::MailDeliveryJob (Job ID: 922d375d-04eb-4f3e-bd9c-f9340ddce72f) to DelayedJob(default) with arguments: "MyMailer", "hello", "deliver_now", {:args=>[]}

と、Mailerまわりのログが出力されませんでした。

その後、

% bin/rails jobs:work

を実行したところ

[ActiveJob] [ActionMailer::MailDeliveryJob] [...] ======= [Before] =======>
[ActiveJob] [ActionMailer::MailDeliveryJob] [...]   Rendered layout layouts/mailer.text.erb (Duration: 0.4ms | Allocations: 242)
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] <====== [Run hello] =======>
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] <====== [After] ========
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] MyMailer#hello: processed outbound mail in 23.9ms
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] <====== [Interceptor] =======>
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] Delivered mail 60fab03938356_16f61e247966d@
...
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] ======= [Observer] =======>
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] Mail::Message
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] <====== [Observer] ========
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] Performed ActionMailer::MailDeliveryJob (Job ID: 922d375d-04eb-4f3e-bd9c-f9340ddce72f) from DelayedJob(default) in 101.14ms

と、Active Jobの方で

  1. before_action
  2. Mailerのhelloメソッド
  3. after_action
  4. interceptor
  5. observer

の順に実行されました。

　

パターン4. 非同期送信、存在しないSMTPサーバを使用

config/environments/development.rb で

config.active_job.queue_adapter = :delayed_job
config.action_mailer.delivery_method = :smtp

を有効にして hook/later にアクセスした時は

Started GET "/hook/later" for 127.0.0.1 at 2021-07-23 21:12:48 +0900
...
[ActiveJob] Enqueued ActionMailer::MailDeliveryJob (Job ID: a73c673e-63e6-412b-802d-59108998efd6) to DelayedJob(default) with arguments: "MyMailer", "hello", "deliver_now", {:args=>[]}

と、Mailerまわりのログが出力されませんでした。

その後、

% bin/rails jobs:work

を実行したところ、ジョブのログに

[Worker(host:*** pid:95801)] 1 jobs processed at 22.9310 j/s, 1 failed

と出力されました。

また、サーバのログにも

2021-07-23T21:14:40+0900: [Worker(host:*** pid:95801)] Starting job worker
...
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] Performing ActionMailer::MailDeliveryJob (Job ID: 28ee4556-11de-4f8e-bf39-6caa02f56533) from DelayedJob(default) enqueued at 2021-07-23T12:14:27Z with arguments: "MyMailer", "hello", "deliver_now", {:args=>[]}
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] ======= [Before] =======>
...
[ActiveJob] [ActionMailer::MailDeliveryJob] [...]   Rendered layout layouts/mailer.text.erb (Duration: 0.6ms | Allocations: 243)
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] <====== [Run hello] =======>
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] <====== [After] ========
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] MyMailer#hello: processed outbound mail in 32.0ms
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] <====== [Interceptor] =======>
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] Delivered mail 60fab2b0b41fc_17639e2445447@
...
[ActiveJob] [ActionMailer::MailDeliveryJob] [...] Error performing ActionMailer::MailDeliveryJob (Job ID: 28ee4556-11de-4f8e-bf39-6caa02f56533) from DelayedJob(default) in 107.6ms: Errno::ECONNREFUSED (Connection refused - connect(2) for "localhost" port 25):

と、

  1. before_action
  2. Mailerのhelloメソッド
  3. after_action
  4. interceptor

までは実行されたものの、 observer は実行されませんでした。

　

ソースコード

Githubに上げました。
https://github.com/thinkAmi-sandbox/rails_mailer_app

関係するプルリクはこちらです。
https://github.com/thinkAmi-sandbox/rails_mailer_app/pull/1