Rails5 の or クエリがバグを誘発しそうで超怖い

Rails5 になって ActiveRecord に or クエリが導入されました。早速、既存のコードを書き換えようとしたんですが、かなり慎重に使わないと結合順序のワナに嵌ってバグりそうで怖いです。

このような（間の抜けた）コードがあったとします。

Country.
  where(id: 1).
  where("id = ? OR id = ?", 1, 2).
  pluck(:id)

生成される SQL はこうで、

SELECT "countries"."id" FROM "countries" WHERE
"countries"."id" = $1 AND (id = 1 OR id = 2)  [["id", 1]]

実行結果はこう。

[
    [0] 1
]

これを、or クエリを用いて素直に書き換えてみます。

Country.
  where(id: 1).
  where(id: 1).or(Country.where(id: 2)).
  pluck(:id)

生成される SQL はこうで、

SELECT "countries"."id" FROM "countries" WHERE
("countries"."id" = $1 AND "countries"."id" = $2 OR "countries"."id" = $3)  [["id", 1], ["id", 1], ["id", 2]]

実行結果はこう。て、さっきと違うやないかい！？

[
    [0] 1,
    [1] 2
]

最初のケースでは A AND (B OR C) のように OR 句のまわりが明示的にカッコで囲まれていたのに対し、 or クエリを使ったケースでは A AND B OR C とカッコがなく、結果的に (A AND B) OR C と評価されたためです。

最初のケースと同様の結果を得るには、or クエリを使った行を最初に持ってくるといいようです。

Country.
  where(id: 1).or(Country.where(id: 2)). # この行と
  where(id: 1).                          # この行を入れ替えた
  pluck(:id)

生成される SQL はこうなり、

SELECT "countries"."id" FROM "countries" WHERE
("countries"."id" = $1 OR "countries"."id" = $2) AND "countries"."id" = $3  [["id", 1], ["id", 2], ["id", 1]]

実行結果は最初と等しくなりました。

[
    [0] 1
]

(B OR C) AND A のように OR 句のまわりがカッコで囲まれて、最初のケースの A AND (B OR C) と等価になっています。

or クエリ、怖いですねえ。

この挙動をしっかり理解した上でコードを書いたとしても、チームの別のエンジニアが（あるいは将来の自分が）無自覚に where 句を追加したり順番を入れ替えたりして、予期せぬバグが生まれたりしたら…。

慎重に使ったほうがよさそうです。

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.hour と DateTime.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 で囲みました。これでセーフ。

気をつけましょう。