rails runner と NoMethodError - 使い回すスクリプトは rake task にしよう

People Tribe / Backend Squad の @izumin5210 です。Advent Calendar の担当日に追われる12月、みなさまいかがお過ごしでしょうか。

この記事は Ruby on Rails Advent Calendar 2019 12日目の記事です。穴が空いたので埋めさせていただきました🙏

人の穴埋めてる場合じゃないという話はある。

TL;DR

• `rails runner` は一部のエラーを rescue するので、エラーが起きてもエラー収集ツールをすり抜けるかも
• 複数回実行しうるスクリプトであれば、なるべく rake タスクを定義しそれを使うほうが良さそう
• • rake は eager load されないので、そこだけ注意！

定期実行タスク

Wantedly では Rails アプリケーションで定期実行したい処理がある場合、Kubernetes の CronJob を利用し rake タスクを実行しています。

apiVersion: batch/v1beta1
kind: CronJob
metadata:
  # ...
spec:
  schedule: "0 3 * * 0" # Execute at every Sunday 12:00 o'clock
  # ...
  jobTemplate:
    metadata:
      # ...
    spec:
      # ...
      template:
        metadata:
          # ...
        spec:
          # ...
          containers:
          - # ...
            command: ["bundle", "exec", "rake", "scheduler:send_awesome_email"]

普通は上のように、専用の rake task を用意して、それを呼び出すように cronjob をセットアップしています（ちなみに、この CronJob マニフェストは kube という社内ツールをつかえばコマンド一発で生成できます。便利ですね。）

しかし一部のリポジトリでは~~横着して~~ rails runner で直接アプリケーションコードを実行していました。

command: ["bundle", "exec", "rails", "r", "SendAwesomeEmailService.new.perform"

実はこのrails runnerを使う方法には思わぬ落とし穴があります。今回はこれでハマった話をしたいと思います。

発端

事のはじまりは、ある定期的なプッシュ通知が送られていないという報告でした。Wantedlyでは発生した未知のエラーを Honeybadger というサービスに送って監視しているので、何らかのエラーでプッシュ通知が送られていないのであれば本来気付けるはずです。ところが今回の事案では、当該ジョブに関するエラーは報告されていませんでした。

実験

Honeybadgerを見てもわからないので、ログを調べました。すると、 NoMethodError でジョブが停止していたことがわかりました。エラーの原因自体は単純なタイプミスによるもので、簡単に修正することができました。

問題はここからです。なぜエラーが発生しているのに Honeybadger には報告されていないのでしょうか。軽く実験してみましょう。

# Honeybadger は `rails r` 対応してない？
rails r 'raise StandardError'  # => 通知される（なので、対応してそう）


# `NoMethodError` と `rails r` 
rails r '[].foo' # => 通知されない

# Honeybadger が NoMethodError を受け取っているのは見たことあるので割愛

NoMethodError と rails r の相性が悪そうですね。

Honeybadger の実装

そもそも、 rails r で起きたエラーを Honeybadger はどうやって捕まえているのでしょう？

答えはシンプルで、 at_exit 内で $! を参照しています。$! には最後に発生した Exception が入っているので、これを終了時に投げているんですね。

# https://github.com/honeybadger-io/honeybadger-ruby/blob/v4.5.4/lib/honeybadger/singleton.rb#L67-L76

# @api private
def install_at_exit_callback
at_exit do
if $! && !ignored_exception?($!) && Honeybadger.config[:'exceptions.notify_at_exit']
Honeybadger.notify($!, component: 'at_exit', sync: true)
end


Honeybadger.stop if Honeybadger.config[:'send_data_at_exit']
end
end

と、いうことは、rails runner の実装のどこかで NoMethodError もしくはそのサブクラスが rescue されている場合、Honeybadger に飛ばないことになります。

（sentry-raven gem でもだいたい同じような実装なので、Honeybadger に限った話ではないでしょう）

rails/rails の実装

rails runner が怪しいということがわかりました。とりあえず、rails/rails に怪しいコードがないか見てみましょう。Rails コマンドは railties/lib 以下なので、そこで grep します。

rails/rails / - v6.0.2^0
:) % rg -e 'rescue(.*(NameError|NoMethodError).*)?$' railties/lib
railties/lib/rails/tasks/zeitwerk.rake
48:    rescue NameError => e

railties/lib/rails/application/configuration.rb
267:            rescue NameError

railties/lib/rails/generators/resource_helpers.rb
70:            rescue NameError

railties/lib/rails/commands/runner/runner_command.rb
46:          rescue SyntaxError, NameError => e

railties/lib/rails/commands/server/server_command.rb
47:    rescue LoadError, NameError

下から2つめ、runner_command.rb で NameError が rescue されてますね。怪しい。実際のコードを見てみましょう。

# https://github.com/rails/rails/blob/v6.0.2/railties/lib/rails/commands/runner/runner_command.rb#L44-L52

begin
eval(code_or_file, TOPLEVEL_BINDING, __FILE__, __LINE__)
rescue SyntaxError, NameError => e
error "Please specify a valid ruby command or the path of a script to run."
error "Run '#{self.class.executable} -h' for help."
error ""
error e
exit 1
end

なるほどー。

ちなみに、この変更は Rails 5 付近で入ったようです。変な入力を入れてしまった場合にわかりやすいエラーメッセージとともに help へ案内するらしい。なるほど。

難しい問題だなあ。

補足とか

バッチジョブは rails 経由で起動しなくていいのでは？

Rails.env や Honeybadger, New Relic など、確実に有効化したいものはいくつか存在するため、そういうものがもれないように rails アプリケーションの起動を伴う rails runner を利用していました。

rake にしないの？

元々 rails runner を使っていたのは単なる横着なので、基本的にはrake taskにしたほうがいいはずです。ただ、実はrake taskへの移行にはひとつ落とし穴があります。それが以下のissueです。

この issue に書かれているように、現在の Rails は rake task 内では eager load を無効にしてしまいます。autoload は最近までスレッドセーフではなかったので、複数スレッドで動くようなタスクを rake task に移行すると問題が発生する可能性があります。

しかし、時代は Zeitwerk。Wantedly People の主要サービスはすべて Rails 6 かつ Zeitwerk 移行済みなので、心置きなく rake への置き換えができます。やったね！

（この Zeitwerk 移行については誰かがそのうちブログに書いてくれるでしょう）

Zeitwerk に移行しきれていない場合や eager load 絶対されててほしい場合については、特定 namespace に含まれる task を Rails.application.eager_load! するように enhance するとかでもいい感じになるかもしれない。誰か試してほしい。

まとめ

rails runner はいい感じに Rails アプリケーション化で任意のスクリプトを動かせるので便利ですが、実は SyntaxError, NameError とそのサブクラスを rescue してしまいます。その場合、一般的なエラー収集ツールをすり抜けていくでしょう。

なので、たまに実行するようなスクリプトを rails runner で動かしている場合、rake タスクなどへの置き換えを検討するといいかもしれません。

Photo by Nathan Dumlao on Unsplash