Railsのデバッグ

http://guides.rubyonrails.org/debugging_rails_applications.html

このガイドでは、Ruby on Railsアプリケーションをデバッグするためのテクニックを紹介します。このガイドを読むことで、次の事が学べるはずです。

デバッグの目的
テストだけでは不十分なアプリケーションの問題と課題を探しだす方法
様々なデバッグ方法
スタックトレースを分析する方法

1. デバッグのためのビューヘルパー
2. Logger
3. デバッグ用のGemを使ったデバッグ
4. メモリーリークのデバッグ
5. デバッグのためのプラグイン
6. リファレンス

1. デバッグのためのビューヘルパー

デバッグ全般に共通する事の1つに変数の中身を調べることがあります。 Railsでは、下記の3つのメソッドによってそれを行います。

debug
to_yaml
inspect

1.1 debug

debugヘルパーは、YAMLフォーマットを使ったオブジェクトを描画した<pre>タグを返します。オブジェクトから人にとって読みやすいデータを生成します。例えば、下記のようなコードであった場合、

<%= debug @post %>
<p>
  <b>Title:</b>
  <%= @post.title %>
</p>

次のように出力されます。

--- !ruby/object:Post
attributes:
  updated_at: 2008-09-05 22:55:47
  body: It's a very helpful guide for debugging your Rails app.
  title: Rails debugging guide
  published: t
  id: "1"
  created_at: 2008-09-05 22:55:47
attributes_cache: {}


Title: Rails debugging guide

1.2 to_yaml

下記の方法で、インスタンス変数、オブジェクト、メソッドなどをYAMLフォーマットで出力します。

<%= simple_format @post.to_yaml %>
<p>
  <b>Title:</b>
  <%= @post.title %>
</p>

to_yamlは、メソッドを読みやすいYAMLフォーマットに変換し、 simple_formatヘルパーはコンソール上の各行に描画するのに使用されます。

--- !ruby/object:Post
attributes:
updated_at: 2008-09-05 22:55:47
body: It's a very helpful guide for debugging your Rails app.
title: Rails debugging guide
published: t
id: "1"
created_at: 2008-09-05 22:55:47
attributes_cache: {}

Title: Rails debugging guide

1.3 inspect

他にオブジェクトの値を表示するのに便利なメソッドにinspectがあります。特に配列やハッシュで非常に便利です。これは、オブジェクトの値を文字列として出力します。例えば下記の場合、

<%= [1, 2, 3, 4, 5].inspect %>
<p>
  <b>Title:</b>
  <%= @post.title %>
</p>

次のように出力します。

[1, 2, 3, 4, 5]

Title: Rails debugging guide

2. Logger

また、実行時にログファイルに情報を保存することもデバッグにとって有用な事です。 Railsは各実行環境によってログファイルを別にして保存します。

2.1 Loggerとは何か?

Railsはログ情報の書き込みに、ActiveSupport::Loggerクラスを使用します。代わりにLog4rのような別のLoggerを使用することも可能です。

environment.rb、または環境設定ファイルで、使用するLoggerの切り替えを指定することが出来ます。

Rails.logger = Logger.new(STDOUT)
Rails.logger = Log4r::Logger.new("Application Log")

または、Initializer部分に、下記のように追記します。

config.logger = Logger.new(STDOUT)
config.logger = Log4r::Logger.new("Application Log")

デフォルトでは、各ログはRails.root/log/フォルダに作成され、ログファイル名は、(環境変数名).logになります。

2.2 Logレベル

設定されたログレベルと、メッセージのログレベルが等しいまたは高い場合にのみ、ログが出力されます。もし、現在設定されているログレベルが知りたい場合は、Rails.logger.levelメソッドを使用して確かめる事が出来ます。

利用可能なログレベルは、:debug、:info、:warn、:error、:fatal、 :unknownがあり、ログレベルの数値は0～5になります。デフォルトのログレベルを変更するには、下記のようにします。

config.log_level = :warn # 各環境の初期化時に行う場合の指定
Rails.logger.level = 0   # 環境に関係なく常にこのレベルを指定

ログ出力は、開発・ステージング環境下で便利ですが、通常は本環境(production)下で不必要なログ情報によって溢れさせたくないと考えるはずです。

デフォルトでのRailsのログレベルは、本環境(production)ではinfoで、開発(development)・テスト(test)環境下ではdebugです。

2.3 メッセージの送信

logger.(debug|info|warn|error|fatal)メソッドを使用して、コントローラー、モデル、メーラーからログファイルに書き込みを行います。

logger.debug "Person attributes hash: #{@person.attributes.inspect}"
logger.info "Processing the request..."
logger.fatal "Terminating application, raised unrecoverable error!!!"

下記はログ出力によるメソッドの動作確認の例です。

class PostsController < ApplicationController
  # ...

  def create
    @post = Post.new(params[:post])
    logger.debug "New post: #{@post.attributes.inspect}"
    logger.debug "Post should be valid: #{@post.valid?}"

    if @post.save
      flash[:notice] = 'Post was successfully created.'
      logger.debug "The post was saved and now the user is going to be redirected..."
      redirect_to(@post)
    else
      render action: "new"
    end
  end

  # ...
end

下記は上記のコントローラーのアクションが実行された際に出力されるログの出力例です。

Processing PostsController#create (for 127.0.0.1 at 2008-09-08 11:52:54) [POST]
  Session ID: BAh7BzoMY3NyZl9pZCIlMDY5MWU1M2I1ZDRjODBlMzkyMWI1OTg2NWQyNzViZjYiCmZsYXNoSUM6J0FjdGl
vbkNvbnRyb2xsZXI6OkZsYXNoOjpGbGFzaEhhc2h7AAY6CkB1c2VkewA=--b18cd92fba90eacf8137e5f6b3b06c4d724596a4
  Parameters: {"commit"=>"Create", "post"=>{"title"=>"Debugging Rails",
 "body"=>"I'm learning how to print in logs!!!", "published"=>"0"},
 "authenticity_token"=>"2059c1286e93402e389127b1153204e0d1e275dd", "action"=>"create", "controller"=>"posts"}
New post: {"updated_at"=>nil, "title"=>"Debugging Rails", "body"=>"I'm learning how to print in logs!!!",
 "published"=>false, "created_at"=>nil}
Post should be valid: true
  Post Create (0.000443)   INSERT INTO "posts" ("updated_at", "title", "body", "published",
 "created_at") VALUES('2008-09-08 14:52:54', 'Debugging Rails',
 'I''m learning how to print in logs!!!', 'f', '2008-09-08 14:52:54')
The post was saved and now the user is going to be redirected...
Redirected to #<Post:0x20af760>
Completed in 0.01224 (81 reqs/sec) | DB: 0.00044 (3%) | 302 Found [http://localhost/posts]

このようなログ出力を追加することで、異常や期待しない動作をしていないかを確認しやすくなります。また、このようなログ出力を追加する場合は、ログレベルを適切に使い分けて本環境(production)でのログが溢れないように、注意しましょう。

ログ出力のタグ付け

複数のユーザー、アプリケーションの複数アカウントが実行されている場合、カスタムルールに従ってログをフィルタリング出来ると便利な場合があります。 ActieサポートのTaggedLoggingは、そのような機能をログ出力行にサブドメイン、レクエストID、その他デバッグに役立つ情報を付け加えてくれます。

logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
logger.tagged("BCX") { logger.info "Stuff" }                            # Logs "[BCX] Stuff"
logger.tagged("BCX", "Jason") { logger.info "Stuff" }                   # Logs "[BCX] [Jason] Stuff"
logger.tagged("BCX") { logger.tagged("Jason") { logger.info "Stuff" } } # Logs "[BCX] [Jason] Stuff"

3. デバッグ用のGemを使ったデバッグ

コードが期待しているのとは異なる動きをする場合、ログ、またはコンソールにその問題を調べるためのログ出力を行う事が可能ですが、残念ながら、問題の原因の根本を見つけ出すのに効果的ではない事がよくあります。ソースコードの実行の過程を正確に知ることが必要な場合、debuggerはその助けとなってくれるでしょう。

また、debuggerはRailsのソースコードについて学びたいが、どこから始めればよいか分からない場合にも助けとなってくれます。このガイドを参考にアプリケーションのリクエストをデバッグし、自分で書いたコードがどのようにしてRailsコードの深い部分で動作しているかを学ぶ事が出来ます。

3.1 Setup

debugger gemを使用して、ブレイクポイントを設定し、Rails上の動作中のコードを辿ることが出来るようになります。次のようにインストルーを行って下さい。

$ gem install debugger

Railsは、2.0から組み込みのデバッグ機能がサポートされています。 Railsアプリケーション内で、debuggerメソッドの呼び出しによってdebuggerを起動することが出来ます。

下記はその例になります。

class PeopleController < ApplicationController
  def new
    debugger
    @person = Person.new
  end
end

もし、次のようなメッセージがコンソールかログで確認された場合、

***** Debugger requested, but was not available: Start server with --debugger to enable *****

Webサーバーをオプション--debugger付きで起動してください。

$ rails server --debugger
=> Booting WEBrick
=> Rails 3.2.13 application starting on http://0.0.0.0:3000
=> Debugger enabled
...

開発(development)環境の場合、--debugger未指定であってもサーバを再起動せずに直接debuggerを要求することが可能です。(翻訳に自信無し)

3.2 シェル

debuggerメソッドを呼び出して間もなく、debuggerはアプリケーションサーバー上のターミナルウインドウ内でdebuggerシェルを開始し、プロンプトが表示されます。(rdb:n) このnは、スレッド番号です。また、このプロンプトは実行待ちになっている次の行のコードを表示してくれます。

もし、これに対しブラウザでリクエストを行うと、そのブラウザのタブはdebuggerが完了し、全リクエストのプロセスが完了するまでハングします。

例えば、

@posts = Post.all
(rdb:7)

上記のようなアプリケーション上でデバッグ状態であったとします。ここでhelpと打ち込んでみましょう。

(rdb:7) help
ruby-debug help v0.10.2
Type 'help <command-name>' for help on a specific command

Available commands:
backtrace  delete   enable  help    next  quit     show    trace
break      disable  eval    info    p     reload   source  undisplay
catch      display  exit    irb     pp    restart  step    up
condition  down     finish  list    ps    save     thread  var
continue   edit     frame   method  putl  set      tmate   where

debuggerプロンプトで、help <command-name>として、使用出来るhelpコマンドのメニューを表示してくれます。例えば、help varのようにして使用します。

次に特に便利なコマンドの1つである、listについて学びます。他のコマンドと識別が十分できるアルファベットを指定することで、コマンドを省略することが可能です。例えば、lをlistコマンドとして使用することが出来ます。

このコマンドは、現在のコードを中心とした10行のコードを表示してくれます。また、現在の行が特定できるように、このケースでは6行目に=>の記号が表示されます。

(rdb:7) list
[1, 10] in /PathTo/project/app/controllers/posts_controller.rb
   1  class PostsController < ApplicationController
   2    # GET /posts
   3    # GET /posts.json
   4    def index
   5      debugger
=> 6      @posts = Post.all
   7
   8      respond_to do |format|
   9        format.html # index.html.erb
   10        format.json { render :json => @posts }

listコマンドを繰り返す(このケースではlを使用)と、次の10行が表示されます。

(rdb:7) l
[11, 20] in /PathTo/project/app/controllers/posts_controller.rb
   11      end
   12    end
   13
   14    # GET /posts/1
   15    # GET /posts/1.json
   16    def show
   17      @post = Post.find(params[:id])
   18
   19      respond_to do |format|
   20        format.html # show.html.erb

ファイルの終端まで繰り返すことが出来ます。終端に達すると、ファイルの先頭に移動して再び終端に向かって同じことを繰り返します。

また、前の10行を確認したい場合は、list-(または、l-)を使用します。

(rdb:7) l-
[1, 10] in /PathTo/project/app/controllers/posts_controller.rb
   1  class PostsController < ApplicationController
   2    # GET /posts
   3    # GET /posts.json
   4    def index
   5      debugger
   6      @posts = Post.all
   7
   8      respond_to do |format|
   9        format.html # index.html.erb
   10        format.json { render :json => @posts }

この方法で、ファイル内を移動してdebuggerを追加したコードの前後を確認することが出来ます。 list=とすることで、再度コードの何処にいるのかを確認します。

(rdb:7) list=
[1, 10] in /PathTo/project/app/controllers/posts_controller.rb
   1  class PostsController < ApplicationController
   2    # GET /posts
   3    # GET /posts.json
   4    def index
   5      debugger
=> 6      @posts = Post.all
   7
   8      respond_to do |format|
   9        format.html # index.html.erb
   10        format.json { render :json => @posts }

3.3 コンテキスト

デバッグを開始すると、メソッドなどを通して別のコンテキストに移動することがあると思います。

The debugger creates a context when a stopping point or an event is reached. The context has information about the suspended program which enables a debugger to inspect the frame stack, evaluate variables from the perspective(透視、眺める) of the debugged program, and contains information about the place where the debugged program is stopped.

At any time you can call the backtrace command (or its alias where) to print the backtrace of the application. This can be very helpful to know how you got where you are. If you ever wondered about how you got somewhere in your code, then backtrace will supply the answer.

(rdb:5) where
    #0 PostsController.index
       at line /PathTo/project/app/controllers/posts_controller.rb:6
    #1 Kernel.send
       at line /PathTo/project/vendor/rails/actionpack/lib/action_controller/base.rb:1175
    #2 ActionController::Base.perform_action_without_filters
       at line /PathTo/project/vendor/rails/actionpack/lib/action_controller/base.rb:1175
    #3 ActionController::Filters::InstanceMethods.call_filters(chain#ActionController::Fil...,...)
       at line /PathTo/project/vendor/rails/actionpack/lib/action_controller/filters.rb:617
...

You move anywhere you want in this trace (thus changing the context) by using the frame _n_ command, where n is the specified frame number.

(rdb:5) frame 2
#2 ActionController::Base.perform_action_without_filters
       at line /PathTo/project/vendor/rails/actionpack/lib/action_controller/base.rb:1175

The available variables are the same as if you were running the code line by line. After all, that's what debugging is.