RailsのAction Mailerには
- callback
- interceptor
- observer
などのフィルターやフックがあります。
ただ、これらの実行タイミングが分からなかったため、調べた時のメモです。
なお、今回は
- メール送信が同期/非同期
- メールサーバへの送信が成功/失敗
を組み合わせた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 への追記
メールまわりの設定を追記します。
なお、パターンごとの設定はコメントアウトしておき、動作確認する時にアンコメントしていきます。
config.action_mailer.interceptors = ['MyMailerInterceptor']
config.action_mailer.observers = ['MyMailerObserver']
config.action_mailer.raise_delivery_errors = true
config.action_mailer.perform_deliveries = true
以上で、確認するための準備ができました。
パターン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] ========
と、
- before_action
- Mailerのhelloメソッド
- after_action
- interceptor
- 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):
と出力されました。
- before_action
- Mailerのhelloメソッド
- after_action
- 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の方で
- before_action
- Mailerのhelloメソッド
- after_action
- interceptor
- 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):
と、
- before_action
- Mailerのhelloメソッド
- after_action
- interceptor
までは実行されたものの、 observer
は実行されませんでした。
Githubに上げました。
https://github.com/thinkAmi-sandbox/rails_mailer_app
関係するプルリクはこちらです。
https://github.com/thinkAmi-sandbox/rails_mailer_app/pull/1