【Rails】Railsのログの読み方

はじめに

Railsのログについて、実装の過程で出てきたログをもとに読み方をまとめてみた。

ログの格納場所

Railsは実行環境ごとに異なるログファイルを出力される。
ログの格納場所は、デフォルトでRails.root/log/となっており、ログのファイル名は、アプリケーションが実行されるときの環境が使用される。

＜具体例＞
development環境　→　development.log
test環境　　　　　→　test.log
production環境　　→　production.oog

ログの内容

正常処理時

基本となるGET、POST、PATCH、DELETE別に解析してみた。

一覧表示【GET】

Started GET "/users" for 127.0.0.1 at 2017-06-06 00:03:08 +0900
Processing by UsersController#index as HTML
  Rendering users/index.html.erb within layouts/application
  [1m[36mUser Load (0.2ms)[0m  [1m[34mSELECT "users".* FROM "users"[0m
  Rendered users/index.html.erb within layouts/application (9.2ms)
Completed 200 OK in 1069ms (Views: 1050.6ms | ActiveRecord: 1.7ms)

1行目

Started [メソッド] [アクセス先] for [アクセス元IP] at [時間]
→ いつ、どこから、どのメソッドでどんなアクセスがされたか

2行目

Processing by [コントローラ名#メソッド名] as HTML
→ 処理が行われたコントローラとメソッド名と取得した形式

3行目

Rendering [レンダリングされたビューファイル名] within layouts/application
→ レンダリングの内容

4行目

[1m[36mUser Load (0.2ms)[0m [1m[34mSELECT “users”.* FROM “users”[0m
→ [1m[36とか謎の文字列がある。これは、

ANSI shell color codes というものらしく、以下のstackoverflowに情報があった。 stackoverflow.com

上記を取り除くと mUser Load (0.2ms) SELECT “users”.* FROM “users”
となり、mUserが読み込まれ、ログにあるようなSQLが流れたことを示す。0.2msはかかった時間。

5行目

Rendered users/index.html.erb within layouts/application (9.2ms)
→ layouts/application内でusers/index.html.erbがレンダリングされた。

6行目

Completed 200 OK in 1069ms (Views: 1050.6ms | ActiveRecord: 1.7ms)
→ HTTPステータスコードと処理にかかった時間が表示される。
　（ちなみに「200 OK」は、リクエスト成功時に返すレスポンスコード）

データの作成【POST】

Started POST "/users" for 127.0.0.1 at 2017-06-06 06:33:30 +0900
Processing by UsersController#create as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"YyULtXbbHrvd0PtDCocKrWIHSBGfbYJ/xD8V0TyWlWnRiEvFAP0Vu7Aaf/3V9t2FijWXRyLWKiMfbWxIPmjI6A==", "user"=>{"name"=>"aba", "text"=>"a"}, "commit"=>"Create User"}
  [1m[35m (0.1ms)[0m  [1m[36mbegin transaction[0m
  [1m[35mSQL (1.0ms)[0m  [1m[32mINSERT INTO "users" ("name", "text", "created_at", "updated_at") VALUES (?, ?, ?, ?)[0m  [["name", "aba"], ["text", "a"], ["created_at", "2017-06-05 21:33:30.094146"], ["updated_at", "2017-06-05 21:33:30.094146"]]
  [1m[35m (0.9ms)[0m  [1m[36mcommit transaction[0m
Redirected to http://0.0.0.0:3000/users/2
Completed 302 Found in 7ms (ActiveRecord: 2.1ms)

（重複したログは省略）

3行目

Parameters: [パラメータの内容] パラメータの内容。ちなみにパスワードなどはログに書き込まれたくないので、
config/initializers/filter_parameter_logging.rb

Rails.application.config.filter_parameters += [:password]

で、フィルタをかける項目の定義が行える。なお、フィルタの項目は、ログでは[FILTERED]に置き換えられる。

4行目

begin transaction
→ トランザクションの開始

5行目

実行されたSQL

6行目

commit transaction
→ トランザクションのコミット

7行目

Redirected to [リダイレクト先のURL]
→ 記載のURLにリダイレクトされた

データの更新【PATCH】

Started PATCH "/users/2" for 127.0.0.1 at 2017-06-06 06:33:39 +0900
Processing by UsersController#update as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"c6CWUAYKwBihYJh+GCoOZv1XMgALdnzrA6mC9nqVa1bz1gajw3KZ696HEUg28xh00SIriwfZDIktPesXZymLyA==", "user"=>{"name"=>"abad", "text"=>"ad"}, "commit"=>"Update User", "id"=>"2"}
  [1m[36mUser Load (0.2ms)[0m  [1m[34mSELECT  "users".* FROM "users" WHERE "users"."id" = ? LIMIT ?[0m  [["id", 2], ["LIMIT", 1]]
  [1m[35m (0.1ms)[0m  [1m[36mbegin transaction[0m
  [1m[35mSQL (0.6ms)[0m  [1m[33mUPDATE "users" SET "name" = ?, "text" = ?, "updated_at" = ? WHERE "users"."id" = ?[0m  [["name", "abad"], ["text", "ad"], ["updated_at", "2017-06-05 21:33:39.981554"], ["id", 2]]
  [1m[35m (0.9ms)[0m  [1m[36mcommit transaction[0m
Redirected to http://0.0.0.0:3000/users/2
Completed 302 Found in 8ms (ActiveRecord: 1.8ms)

目新しいログは無し

データの削除【DELETE】

Started DELETE "/users/1" for 127.0.0.1 at 2017-06-06 06:33:26 +0900
Processing by UsersController#destroy as HTML
  Parameters: {"authenticity_token"=>"vMMe9vhpLIjJ+6/krjCuflIVGEJ15gxwEAbQ0FBZiJNchaAIqXiX52Ntps6ZM94rVyg6NLNXxkTBP7ec4qFMRg==", "id"=>"1"}
  [1m[36mUser Load (0.3ms)[0m  [1m[34mSELECT  "users".* FROM "users" WHERE "users"."id" = ? LIMIT ?[0m  [["id", 1], ["LIMIT", 1]]
  [1m[35m (0.1ms)[0m  [1m[36mbegin transaction[0m
  [1m[35mSQL (0.6ms)[0m  [1m[31mDELETE FROM "users" WHERE "users"."id" = ?[0m  [["id", 1]]
  [1m[35m (0.9ms)[0m  [1m[36mcommit transaction[0m
Redirected to http://0.0.0.0:3000/users
Completed 302 Found in 8ms (ActiveRecord: 2.0ms)

こちらも目新しいログは無し

エラー発生時

Started GET "/users/new" for 127.0.0.1 at 2017-06-06 06:07:05 +0900
Processing by UsersController#new as HTML
  Rendering users/new.html.erb within layouts/application
  Rendered users/_form.html.haml (6.0ms)
  Rendered users/new.html.erb within layouts/application (10.3ms)
Completed 500 Internal Server Error in 44ms (ActiveRecord: 1.8ms)

ActionView::Template::Error (Illegal nesting: nesting within plain text is illegal.):
     6:
     7:       %ul
     8:         user.errors.full_messages.each do |message|
     9:           %li = message
    10:         end
    11:
    12:   %div{ class: "field" }

この時は、ビューでエラーを出してしまった。６行目で「500 Internal Server Error」の記述の後、具体的な内容がログに出ている。

おまけ

ログファイルをクリアするコマンド

rake log:clear

おわりに

ほんの一例ではあるが、まずはログの場所と大まかな内容の理解ができた。

Reinvent Yourself

技術メモや日々思っていることなど