モンモンブログ

技術的な話など

DelayedJob による非同期処理の失敗を exception_notification でエラー通知させる

delayed_jobs による非同期処理時に、exception_notification によるエラー通知メール送信を行う - Qiita

こちらの記事を参考に DelayedJob のエラー通知を実装していたんですが、 Rails5 で alias_method_chain が Deprecated になってしまったので Module.prepend を使って書き直しました。

config/initializers/delayed_job.rb

module NotifyWhenDelayedJobFailed
  def handle_failed_job(job, error)
    # オリジナルの Delayed::Worker#handle_failed_job を実行
    super
    # 追加処理としてメール通知を行う
    ExceptionNotifier.notify_exception(error)
  end
end

class Delayed::Worker
  # 定義したモジュールを prepend
  prepend NotifyWhenDelayedJobFailed
end

Module.prepend については

» Ruby2.0のModule#prependは如何にしてalias_method_chainを撲滅するのか!? TECHSCORE BLOG

こちらが分かりやすかったです。

Rubyで2項演算子が単項演算子に化けて悪さする話

DateTime.now + 1.hourDateTime.now +1.hour は異なる値を返します。

何を言ってるのかわからねーと思うがこの実行結果を見てくれ。こいつをどう思う?

[10] pry(main)> DateTime.now + 1.hour
Fri, 29 Jan 2016 11:38:52 +0900         # こっちだと 11:38
[11] pry(main)> DateTime.now +1.hour
Fri, 29 Jan 2016 10:38:52 +0900         # こうすると 10:38。あれれ?

すごく・・・バグりそうです・・・///

なんでか

DateTime.now + 1.hour

DateTime.now() + 1.hour

と解釈されるのに対し、

DateTime.now +1.hour

DateTime.now(+1.hour)

と解釈されるためです。

前者では二項演算子だった + 演算子が、後者では単項演算子に化けてますね。

ちなみに Time.now の場合はこの問題は起こりません。Time.now は引数を取らないので ArgumentError となるため。

[15] pry(main)> Time.now +1.hour
ArgumentError: wrong number of arguments (given 1, expected 0)
from /Users/monmon/.rbenv/versions/2.3.0/lib/ruby/gems/2.3.0/gems/delorean-2.1.0/lib/delorean.rb:11:in `now'

ちなみにちなみに 1.hour は1時間分の秒数 = 3600 を返すもんだと思ってくれい。ActiveSupport が追加するメソッドだ。rails 使いなら常識だ。

どんな場合に起こるか?

以下のような場合に、この問題が起こるんだと思います。

  • 数値(っぽい)型のデフォルト値つきの引数1つを取り、数値(っぽい)型の値を返すメソッドがある
  • + または - 演算子の左側にこのメソッドの括弧なし呼び出し、右側に数値(っぽい値)が現れる
  • 演算子と右側の値の間にスペースがない

「数値っぽい」と表現したのは、+- 演算子で計算出来るものであれば多分なんでもよさげなので。

実験してみましょう。こんなメソッドを作って、

def hoge(n = 1)
  n
end

+ 演算子の前後のスペースを変えながら実行してみると、

hoge + 1    # 2 ✓
hoge+1      # 2 ✓
hoge+ 1     # 2 ✓
hoge +1     # 1 ×

このとおり、結果がおかしくなる場合がありました。

- 演算子でも同様です。

hoge - 1    # 0 ✓
hoge-1      # 0 ✓
hoge- 1     # 0 ✓
hoge -1     # -1 ×

こわいですね。

弊社サービスもこれが原因でバグってたことがあるのはみんなには内緒だよ。
雑なエンジニアは死滅すればいいのに。

教訓

スペースにもちゃんと気を配ってコード書きましょうねというお話でした。

ActionMailerのメール本文がログに出力されるのを抑制

メール本文がログに出力されるとログ容量を圧迫するので(あとウザいので)出力を抑制しました。

環境

$ ruby -v
ruby 2.3.0p0 (2015-12-25 revision 53290) [x86_64-darwin13]
$ rails -v
Rails 4.2.5

事象

メーラーでメールを送信すると、デフォルトでメール本文がログに記録されます。

...
  Rendered notifier/order_received.jp.html.erb within layouts/mailer (3.9ms)
  Rendered notifier/order_received.jp.text.erb within layouts/mailer (31.2ms)
Notifier#order_received: processed outbound mail in 69.6ms
Sent mail to hoehoe@hoe.com (148.1ms)
Date: Thu, 28 Jan 2016 04:25:52 +0000
From: noreply@skimatalk.com
To: hoehoe@hoe.com
Message-ID: <56a99850628a8_e3fe3d690d13056190@812fa40a-c82a-4968-83bf-a9b4df09e732.mail>
Subject: hoehoe
Mime-Version: 1.0
Content-Type: multipart/alternative;
 boundary="--==_mimepart_56a998505d1bb_e3fe3d690d130560ea";
 charset=UTF-8
Content-Transfer-Encoding: 7bit
----==_mimepart_56a998505d1bb_e3fe3d690d130560ea
Content-Type: text/plain;
 charset=UTF-8
Content-Transfer-Encoding: base64
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
...

例では XXXX... で表現してますが、base64 エンコードされたメール本文がこのように長々と出力されます。こんなのログに残っても対して役に立たない上にうっとうしいです。

解決策1

メーラーのロガーを nil に設定するだけでもOK。

environments/production.rb

    config.action_mailer.logger = nil

ただしこれだと、メーラーのログが一切出なくなり、それもちょっとどうかなあという感じ。(メールのテンプレートレンダリングのログは残ります。先ほどの例でいうと Rendered notifier/order_received.jp.html.erb within layouts/mailer (3.9ms) などの行。ERB のレンダリングメーラーの仕事じゃないからででしょうか。)

解決策2

メーラーのロガーを設定して、ロガーのログレベルを INFO レベルにしてやります。

environments/production.rb

    config.action_mailer.logger = Logger.new(config.paths["log"].first)
    config.action_mailer.logger.level = Logger::INFO

ログはこんな感じになりました。

...
  Rendered admin_mailer/test.jp.text.erb (0.9ms)
  Rendered admin_mailer/test.jp.html.erb (1.7ms)
I, [2016-01-28T07:14:51.945455 #17]  INFO -- :
Completed 302 Found in 670ms (ActiveRecord: 0.0ms)
Sent mail to hoehoe@hoe.com (367.3ms) ←
...

Sent mail to hoehoe@hoe.com (367.3ms) というメーラーのログは残しつつ、うっとうしいメール本文は消すことが出来ました。

ActiveRecordのscope,validatorでの意図せぬキャッシュに要注意

クリティカルなバグの原因になりえます(なりました)。

環境

少々古いです。activerecord の最近のバージョンでは未確認です。

ruby 1.9.3p547 (2014-05-14 revision 45962) [x86_64-darwin13.3.0]
rails-3.2.11
activerecord-3.2.11
MacOSX Mavericks

現象

ActieRecord の named scope の条件文や、 validator のエラーメッセージなどは自動でキャッシュされちゃいます。そのため、

  scope :upcoming, where('start_at > ?', Time.now)

のように scope の where 句で時刻比較したり、

  validates :start_at, presence: { message: I18n.t(:start_at_is_required) }

のように validation のエラーメッセージを I18n で国際化したりすると、1回目に実行した時点での時刻やロケール文字列がキャッシュされてしまい、

  • 時間が経過しても古い時刻での検索結果が返されたり
  • 日本語ロケールを指定してるのに英語でメッセージが出力されたり

しちゃいます。怖いですね。

対策

Proc で囲むことで回避できます。lambda でも可。

named scope ならこう。

  # クエリ全体を Proc.new で囲む
  scope :upcoming, Proc.new {
    where('start_at > ?', Time.now)
  }

validator ならこう。

  # I18n 呼んでる部分を Proc.new で囲む
  validates :start_at, presence: { message: Proc.new{ I18n.t(:start_at_is_required) } }
end

named scope から別の named scope を使ってる場合は更に注意が必要です。

時刻比較等の動的な操作を行う named scope (scope A) を、別の named scope (scope B) から使う場合、scope A のみならず scope B も Proc.new で囲む必要があるんです。

  # (scope A) 時刻比較する "upcoming" scope。Proc.new で囲んで対策済み
  scope :upcoming, Proc.new {
    where('start_at > ?', Time.now)
  }

  # (scope B) "upcoming" scope を利用。Proc.new で囲んでない
  scope :available, upcoming.where(status: 1)

これはアウト。"available" scope の評価結果がキャッシュされ、時刻が変化しません。

  # (scope A) こちらを Proc.new で囲む必要があるのはもちろん、
  scope :upcoming, Proc.new {
    where('start_at > ?', Time.now)
  }

  # (scope B) "upcoming" scope を利用するこちらも Proc.new で囲まないといけない
  scope :available, Proc.new {
    upcoming.where(state: :open)
  }

両方 Proc.new で囲みました。これでセーフ。

気をつけましょう。

Action Mailerのマルチパートメールでファイル形式の優先順位が変わっちゃう件

Action Mailer でマルチパートメールを送るようにしていて、かつ mail メソッドにブロックを渡す場合は注意が必要です。html 版、text 版の優先順位が意図せず変わってしまう場合があります。

環境

MacOSX Mavericks
ruby 1.9.3p547 (2014-05-14 revision 45962) [x86_64-darwin13.3.0]
rails-3.2.11
actionmailer-3.2.11

そもそもマルチパートメールって?

1通のメール中に複数の形式のメール本文を含められる機能です。

例えば html 形式と text 形式、両方のメール本文を含めれば、html 対応のメール表示ソフトではリッチな html 形式で表示させ、そうでなければ text 形式で表示させる、てことが可能です。

マルチパートメール on Rails

rails でマルチパートメールを送るのは超簡単。mailer のテンプレートとして複数の形式のファイルを用意しておくだけです。

app/views/user_mailer/password_reset.html.erb    # html版
app/views/user_mailer/password_reset.text.erb   # text版

あとは普通にメールを送信するだけ。

UserMailer.password_reset(user).deliver

送信されるメールの内容はこんな感じ。1本のメールに複数の形式が含まれてるのが分かると思います。

Sent mail to xxxx@skimatalk.com (1786ms)         # メールヘッダ
Date: Mon, 02 Feb 2015 11:09:00 +0900
From: noreply@skimatalk.com
To: xxxx@skimatalk.com
Message-ID: <xxxx>
Subject: xxxx
Mime-Version: 1.0
Content-Type: multipart/alternative;            # Content Type でマルチパート指定
 boundary="--==_mimepart_54cedc31b283f";        # 各パートの境界となる文字列を定義
 charset=UTF-8
Content-Transfer-Encoding: 7bit



----==_mimepart_54cedc31b283f                   # パート境界1 (text版ここから)
Date: Mon, 02 Feb 2015 11:09:00 +0900           # text版メールヘッダ
Mime-Version: 1.0
Content-Type: text/plain;
 charset=UTF-8
Content-Transfer-Encoding: base64
Content-ID: <xxxx>

44G744GS44G744GS44G744GS44G744GS44G744GS44G7    # text版メール本文 (base64 encoded)
44GS44G744GS44G744GS44G744GS44G744GS44G744GS
44G744GS44G744GS44G744GS44G744GS44G744GS44G7
44GS44G744GS44G744GS44G744GS44G744GS44G744GS

----==_mimepart_54cedc31b283f                   # パート境界2 (html版ここから)
Date: Mon, 02 Feb 2015 11:09:00 +0900           # html版メールヘッダ
Mime-Version: 1.0
Content-Type: text/html;
 charset=UTF-8
Content-Transfer-Encoding: base64
Content-ID: <xxxx>

44G744GS44G744GS44G744GS44G744GS44G744GS44G7    # html版メール本文 (base64 encoded)
44GS44G744GS44G744GS44G744GS44G744GS44G744GS
44G744GS44G744GS44G744GS44G744GS44G744GS44G7
44GS44G744GS44G744GS44G744GS44G744GS44G744GS

----==_mimepart_54cedc31b283f--                 # パート境界3 (メール末尾)

各形式の優先順位は ActionMailer::Basedefault メソッドparts_order の値をセットすることで指定出来ます。この値はデフォルトで ["text/plain", "text/enriched", "text/html"] となってます(参考)。各形式の内容はこの順番で出力されます(先ほどの例も然り)。

class UserMailer < ActionMailer::Base
  default parts_order: ["text/plain", "text/enriched", "text/html"]
  
  def password_reset(user)
    ...
  end
end

この順番だと、一番上に出力される text/plain 形式の内容が最優先で表示されそうですが、違います。 RFCに、表示の際の優先順位は逆順とするように定められており、この場合、一番下の text/html が最優先となります。

この理由もRFCにありました。もっともシンプルな形式を一番上に出力するようにしておけば、MIME非対応のメール表示ソフトであっても読みやすいよね、ということのようです。なるほどちゃん。

placing the plainest alternative first is the friendliest possible option when mutlipart/alternative entities are viewed using a non-MIME- compliant mail reader.

mail メソッドにブロックを渡すと parts_order 指定が無視されちゃう

mail メソッドにはブロックを渡すことが出来ます。下記のように、ファイル形式ごとにレイアウトを指定出来たりします。

class UserMailer < ActionMailer::Base
  default parts_order: ["text/plain", "text/enriched", "text/html"]
  
  def password_reset(user)
    mail to: 'xx@skimatalk.com', subject: 'hello!' do |format|
      format.text { render layout: 'mailer' }
      format.html { render layout: 'mailer' }
    end
  end
end

これで、

app/views/layouts/mailer.text.erb
app/views/layouts/mailer.html.erb

がメールのレイアウトとして使われるって寸法。

が、ここに落とし穴があります。

      format.text { render layout: 'mailer' }
      format.html { render layout: 'mailer' } # html形式が後

この順番を逆にして

      format.html { render layout: 'mailer' }
      format.text { render layout: 'mailer' } # text形式が後

ってしちゃうと、parts_order での指定を無視して、html 形式が先、text 形式が後に出力されます。 すると RFC のルール通り、text 版の方が優先して表示されちゃいます。html 版は決して表示されなくなります。なんと。

ActionMailer::Base のドキュメントを読んでもそんなこと書いてないですねえ。(該当箇所は "If you want to explicitly render only certain templates..." らへんから)

参考

ActionMailer overrides header[:parts_order] when a block is passed to #mail · Issue #7978 · rails/rails