忙しい人のための Rails デバッグ方法まとめ

ざっくりと書いたので、何かの参考にどうぞ

Rails の問題かどうか、ログを調べる

あなたのRails アプリが、例えばブラウザからのリクエストに対して何か応答する場合、リクエスト情報はRails のアプリケーションプログラムに到達する前にHTTP サーバのプログラムを通ります。

ブラウザ -> (色々) -> HTTP server(unicorn等) -> Railsアプリケーション

ですので、HTTP サーバがRails にリクエスト情報を渡さなかった場合、もしくはリクエストがHTTP サーバにすら到達しなかった場合は、当然Rails プログラムは動きません。

ということでまずは、リクエストがRails に到達しているかをログから調べましょう。

ログ

デフォルトでは、development 環境の Rails のログは log/development.log に出ます。
ログ見るときの基本的なことですが、tail コマンドの f オプションで、追加行が随時流れてくるようにしてみましょう

$ tail -f log/development.log

ここでログが更新されているようであれば、Railsには到達していると考えていいと思います。

※ブラウザじゃなくて何かのバックグラウンドプロセスからアクセスされることがある場合は、何のアクセスによってログが動いているかきちんと見るようにしましょう ¹

(Railsアプリケーションに到達していない時の話は後述)

デバッグコードの実行方法

print debug

Rails.logger

上記の標準のログに出力するためには、 Rails.logger を使います。デバッグなので debug レベルの例にします

Rails.logger.debug "出力したい内容"

ちゃんとしたところで書けば、省略して logger.debug と書けます

Rails.logger の使い方には、こちらの記事 https://qiita.com/sobameshi0901/items/b963e7046e2ae8b8e813 に詳しく書いてありましたので、参考にしてください

puts

puts を使って出力しようとすると、ログには出ません。http リクエストの場合は、HTTP サーバの標準出力に出力されるので、rails server をforeground で実行している人は、puts を使えばforegroundを見ていれば出てくると思います（多分）

後述の rails console の場合は puts で console の中に出力したほうが便利だと思います。

Ruby のコードを実行する

rails console

ライブラリ（というかgem）と自分たちのruby コードをロードした状態のconsole が立ち上がります。ここで好きな ruby コードを書いてデバッグ作業することができます。

$ rails console
Loading staging environment (Rails 6.0.3.4)

[1] pry(main)> u = User.new
[2] pry(main)> u.birthday = Date.today
[3] pry(main)> u.save

frontend もFooBarController.new みたいにインスタンスを作れば実行できますが、リクエストパラメータを再現するのは割と面倒なので、必要なデータだけ用意して、コードを1行ずつ入力するのが良いと思います。

Shoryuken のworkerを rails console から実行する方法は、以前自分が書いた<Shoryuken の worker を Rails console で実行>をご参照ください

byebug

byebug は、コード実行中にpromptを立ち上げることができるものです。

有名なのは pry-byebug という pry(便利な対話的Ruby実行ツール)のプラグインで、コード中に binding.pry と書いて使います。

class UserController
  def index
    @users = User.all.limit(20)
    binding.pry
  end
end

これは、先ほど書いた puts と同様、HTTPサーバの標準出力でpromptが立ち上がります。（自分は、最近 docker とかを使っているうちに標準出力の捕まえ方がよく分からなくなったので使っていません...

binding.pry と書いた地点でコードを実行できるので、変数とかの状態が変わっており rails console よりも便利です

デバッグで何を見るか

オブジェクトの中身を見る (inspect)

オブジェクトの dump をしたいときは inspect メソッドを使うと良いです

Rails.logger.debug @user.inspect

ただし、inspect することにより挙動が変わる可能性もあります。例えばActiveRecord では、データベースからデータを取ってくる関連の機能でいわゆる遅延ロードが実装されていますが、inspect するとinspect した時点でデータがロードされることになるケースがあります。

コードの存在場所

Ruby の話ですが、Method#source_location で、method がどのファイルのどこで定義されているのか調べることができます。

[4] pry(main)> ActiveRecord::Base.method(:where).source_location
=> ["/usr/local/bundle/gems/activerecord-6.0.3.4/lib/active_record/querying.rb", 21]

Method オブジェクトを得るために、 .method(:メソッド名) するところがポイントです

stacktrace

これもRuby の話ですが、調べたいコードがどういう経路で実行に至ったか知りたい場合、stacktrace を知りたいことがあります。そのときは Thread.current.backtrace が使えます。

[5] pry(main)> puts Thread.current.backtrace.join("\n")

使える method 名を調べる

Ruby の話ですが、インスタンスに対してmethodsメソッドを使うことで、そのインスタンスをレシーバーとして呼べるメソッド一覧を取れます。

@user.methods

メソッド名の一部が分かっているときは、 select で絞ってあげましょう。自分はこういう使い方をよくします

irb(main):001:0> @user.methods.select(&/^save/.method(:=~))
=> [:saved_change_to_id?, :saved_change_to_id, :saved_change_to_name?, :saved_change_to_name, :saved_change_to_created_at?, :saved_change_to_created_at, :saved_change_to_updated_at?, :saved_change_to_updated_at, :save, :save!, :saved_change_to_attribute?, :saved_change_to_attribute, :saved_changes?, :saved_changes]

(save_ から始まるメソッド一覧の例)

ちょっとうまく出力するコツ

文字列を短く切るには String#truncate

irb(main):018:0> "abcdefghijklmnopqrstuvwxyz".truncate(16)
=> "abcdefghijklm..."

配列を短く切るには Array#slice

irb(main):023:0> puts Thread.current.backtrace.slice(0, 16).join("\n")
(irb):23:in `backtrace'
(irb):23:in `irb_binding'
/usr/local/lib/ruby/2.5.0/irb/workspace.rb:85:in `eval'
/usr/local/lib/ruby/2.5.0/irb/workspace.rb:85:in `evaluate'
/usr/local/lib/ruby/2.5.0/irb/context.rb:380:in `evaluate'
/usr/local/lib/ruby/2.5.0/irb.rb:491:in `block (2 levels) in eval_input'
/usr/local/lib/ruby/2.5.0/irb.rb:621:in `signal_status'
/usr/local/lib/ruby/2.5.0/irb.rb:488:in `block in eval_input'
/usr/local/lib/ruby/2.5.0/irb/ruby-lex.rb:246:in `block (2 levels) in each_top_level_statement'
/usr/local/lib/ruby/2.5.0/irb/ruby-lex.rb:232:in `loop'
/usr/local/lib/ruby/2.5.0/irb/ruby-lex.rb:232:in `block in each_top_level_statement'
/usr/local/lib/ruby/2.5.0/irb/ruby-lex.rb:231:in `catch'
/usr/local/lib/ruby/2.5.0/irb/ruby-lex.rb:231:in `each_top_level_statement'
/usr/local/lib/ruby/2.5.0/irb.rb:487:in `eval_input'
/usr/local/lib/ruby/2.5.0/irb.rb:428:in `block in run'
/usr/local/lib/ruby/2.5.0/irb.rb:427:in `catch'
=> nil

その他

Database を見る

dbconsole を使うと、database client が立ち上がって、DB名も勝手に合わせてくれます。

rails dbconsole -p development

p オプションで環境名を指定するとパスワードを config から取ってきてくれます。²

Rails に到達してない場合

HTTP サーバは、rails の場合、unicorn, puma, webrick, passenger などが代表的かと思います。unicorn の場合は config/unicorn.rb の stderr_path とかにログファイルの場所が書いてあるので、そこを見れば unicorn まで到達しているかが分かるはずです。
また、HTTP サーバの前にリバースプロキシが立っているかも知れません。リバースプロキシサーバとして有名なnginxだと、access log とerror logが出るようになっていることが多いと思います。

HTTP サーバ以外だと、Sidekiq や Shoryuken などの非同期ジョブワーカーによってコードが実行しようとしている場合があり、どちらも実行ログがあると思います。

アプリケーションを動かしたつもりでもログが出なければ、各ソフトウェアのプロセスが生きているか、docker を使っている場合はコンテナが生きているか、調べましょう。
正直かなり大雑把に書いてしまっていますが、この辺りは使っているミドルウェアや設定によって変わることが多いと思うので、誰か詳しい人が詳しい記事を書いてくれることを期待します。

なお、自分が遭遇するBest3は

• rails アプリ動かすdocker コンテナが立ち上がっていなかった
• gem が更新されてなくてbundler が読み込めない
• docker コンテナと Mac のファイル共有のところがうまく動かなくなってコードが反映されない

です。

1. リクエスト届いていると思ったら、外部アクセスを想定した docker コンテナが動いていて、見たいログではなかったということがありました。 ↩

2. 環境名は分かっているはずなのに、なんで指定が必要なんでしょうね ↩