【Rails初学者向け】Railsサーバーのログが読めないので分解して読み解いてみた

Last updated at 2026-11-02Posted at 2026-11-02

はじめに

RUNTEQにてプログラミングを学習中のイリエイです。
デバッグの学習でRailsサーバーのログを確認したとき、ターミナルに並ぶ英語やSQLがどの処理を表しているのか、全く理解できず読み取れませんでした。

実務でアプリが想定どおりに動かないとき、どこまで処理が進んだのかを知る手掛かりの一つがログです。そのログを読めないのはまずくないか？というある種の危機感を感じました。原因を自分で調べられるようになるには、学習中の今からログを読む力を身につけたほうが絶対良いはずです。そんな思いで、本記事を書くに至りました。

対象読者🔰

本記事は、Railsを学び始めた方の中でも、私と同じようにサーバーのログを読むことに苦手意識がある方に向けて書きました。私自身もRailsの基礎を学んでいる途中なので、説明が行き届かないところもあるかと思います。

ログを1行ずつ読みながら、どのページにアクセスし、そのときRailsがどんな処理をしたのかをたどります。「どこから読めばいいのだろう」と迷ったときに、この読み方が手掛かりになれば幸いです。

1. そもそもログには何が書かれているの？？

ログは、アプリが処理中に残す記録です。エラーの内容だけでなく、実行した処理やDB（データベース）への問い合わせも記録されます。

たとえば、ブラウザでIDが7の本のページを開くとします。Railsはデータベースからその本の情報を取り出し、タイトルを載せたページを作ってブラウザに返します。

ブラウザ：「IDが7の本のページを見せて」
  → Railsがリクエストを受け取る
  → 本の詳細を表示するために、BooksControllerのshowを呼び出す
  → DBから本の情報を取得する
  → 表示するHTMLを作る
  → ブラウザへ返す

ブラウザからの要求がリクエスト、サーバーからの応答がレスポンスです。ログを読むと、この途中で何が起きたかを追えます。Railsガイド「Action Controller の概要」

まず、ログを開いてみる！

開発中は、Railsサーバーを起動したターミナルでログを確認できます。標準的なファイル出力では、プロジェクト内のlog/development.logにも保存されます。出力先は設定によって変わります。Railsガイド「ロガー」

log/development.logに出力されていれば、プロジェクトのディレクトリで別のターミナルを開き、次のコマンドでも確認できます。

tail -f log/development.log

この状態で画面を操作すると、追加されたログが順に表示されます。見るのをやめるときは、このターミナルでCtrl + Cを押します。

2. 目印となる3つのログを確認してみる

ブラウザで http://localhost:3000/books/7 を開くとします。Bookモデルにはtitle属性があり、データベースにはIDが7の本が1冊ある想定です。

この例の前提　記事中のログとコードは、読み方を説明するために作成した想定例です。実行による採取・検証はしていません。SQLはPostgreSQLを想定し、ログは解説する行と項目に絞っています。時刻・所要時間・行番号も説明用です。実際の表示はバージョンや設定によって変わります。

Started GET "/books/7" for 127.0.0.1 at 2026-10-30 10:00:00 +0900
Processing by BooksController#show as HTML
  Parameters: {"id"=>"7"}
  Book Load (0.6ms)  SELECT "books".* FROM "books" WHERE "books"."id" = $1 LIMIT $2  [["id", 7], ["LIMIT", 1]]
  ↳ app/controllers/books_controller.rb:12:in 'show'
  Rendered books/show.html.erb within layouts/application (Duration: 4.8ms)
Completed 200 OK in 21ms (Views: 6.2ms | ActiveRecord: 0.6ms)

まず、次の3行を見てみましょう。

目印	知りたいこと	この例で読めること
`Started`	どこにアクセスした？	ブラウザで開いた `/books/7` にGETリクエストが来た
`Processing by`	どのコードが担当した？	`BooksController`の`show`が担当した
`Completed`	どんな結果で終わった？	`200 OK`で処理が終わった

これで長いSQLを読む前に、アクセス先・担当・結果が掴めました。では、URLの末尾にあった 7 はどこで使われたのでしょうか。今度は同じログを上からたどります。

3. ログを分解し1行ずつ読み解く

① Started：どこへのアクセスが始まった？

Started GET "/books/7" for 127.0.0.1 at 2026-10-30 10:00:00 +0900

最初に目を留めたいのは、ブラウザで開いたのと同じ/books/7です。その前後に、アクセスの方法や接続元、日時が並んでいます。

部分	意味
`Started`	リクエストの処理を開始した
`GET`	情報の取得を要求するHTTPメソッド
`"/books/7"`	アクセス先のパス
`for 127.0.0.1`	アクセス元として記録されたIPアドレス
`at ... +0900`	日時。末尾はUTCより9時間進んでいることを示す

HTTPメソッドは「何をしたいか」を表します。GETはページなどの情報を取得するときに使います。127.0.0.1は自分自身を指すアドレスで、ローカル開発でよく見かけます。GETの仕様／ループバックアドレスの仕様

最初に、自分が開いたURLと操作した時刻が合っているかを確認します。違っていたら、別の操作のログかもしれません。

② Processing by：どのコードが処理する？

Processing by BooksController#show as HTML

この行は、Processing by／BooksController#show／as HTMLの3つに区切ると読みやすくなります。

Processing byの後ろにあるのが、処理を担当するコントローラとアクションです。今回はBooksControllerのshow。末尾のas HTMLは、HTML形式のリクエストとして扱っていることを示します。

コントローラはリクエストに応じた処理を担当し、アクションはその中で呼び出されるメソッドです。BooksController#showは「BooksControllerのshow」と読みます。

/books/7とshowを対応させているのが、ルーティングです。たとえば、次のように設定します。

# config/routes.rb の例
Rails.application.routes.draw do
  get "books/:id", to: "books#show"
end

この設定では、GETで/books/7にアクセスすると、BooksControllerのshowが呼ばれます。resources :booksでも、このshow用のルートが作られます。Railsガイド「Rails のルーティング」

ここまで読めれば、次に開くコードが決まります。app/controllers/books_controller.rbのshowを見てみます。Railsガイド「コントローラを作成する」

③ Parameters：どの値を受け取った？

Parameters: {"id"=>"7"}

ここにも7が出てきました。idという名前のパラメータで、文字列の"7"を受け取っています。

先ほどのルートの:idに、URLの7が入ります。コントローラでは、この値をparams[:id]で取り出せます。

# BooksController内のshowアクションの例
def show
  @book = Book.find(params[:id])
end

URLから受け取った"7"をparams[:id]で取り出し、Book.findに渡しています。ここで探しているのが、IDが7の本です。

パラメータには、URLの値のほかに、フォームの入力や検索条件なども入ります。フォーム送信のログでも、Parametersに値が出たことだけでは、DBに保存できたかは判断できません。Railsガイド「パラメータ」

④ Book Load：DBに何を問い合わせた？

Book Load (0.6ms)  SELECT "books".* FROM "books" WHERE "books"."id" = $1 LIMIT $2  [["id", 7], ["LIMIT", 1]]

ここが7行の中でいちばん長いですね。内容は、booksテーブルからIDが7のデータを最大1件取得する問い合わせです。

さっきのコードはBook.find(params[:id])というRubyだったのに、ログには別の書き方で出ています。

DBに問い合わせるための言語がSQLです。RailsのActive RecordがRubyで書いた検索処理をSQLに変換しているので、コードとログでは見た目が違います。部分ごとに読むと、検索するIDも確認できます。

部分	この例での意味
`Book Load`	`Book`のレコードを探すため、DBに問い合わせた
`(0.6ms)`	問い合わせにかかった時間。1,000msが1秒
`SELECT "books".* FROM "books"`	booksテーブルの全カラムを取得する
`WHERE "books"."id" = $1`	IDが指定した値に一致するものを探す
`LIMIT $2`	取得する件数の上限を指定する

$1と$2には、末尾に表示された7と1が対応します。カラムは、IDやタイトルといった項目のこと。*は「全カラム」で、全件を取得するという意味ではありません。今回はWHEREとLIMITで対象を絞っています。

検索条件は読み取れますが、検索結果が0件だったか1件だったかは、この行だけでは分かりません。Railsガイド「Active Record クエリインターフェイス」

⑤ `↳`　そのSQLはどこから呼ばれた？

↳ app/controllers/books_controller.rb:12:in 'show'

矢印の後ろは、直前のSQLがどこから呼ばれたかを示しています。この例の12行目にあるのが、③で見た @book = Book.find(params[:id]) です。自分のアプリなら、手元のログが指すファイルと行をエディタで開いてみます。

この表示はverbose_query_logsという機能によるもので、開発環境では標準で有効です。Railsガイド「詳細なクエリログ」

⑥ Rendered：どのビューでHTMLを作った？

Rendered books/show.html.erb within layouts/application (Duration: 4.8ms)

先ほどのshowには、ビューのファイル名を書いていません。この例では、Railsがコントローラ名とアクション名に対応するapp/views/books/show.html.erbを自動で選んで描画します。

books/show.html.erbを、applicationレイアウトの中で描画した記録です。この描画には4.8msかかっています。

HTMLはWebページの構造を記述する言語です。Railsでは、ビューというテンプレートを使ってHTMLを作ります。たとえば、詳細画面のビューに次のコードがあるとします。

<!-- app/views/books/show.html.erb の例 -->
<h1><%= @book.title %></h1>

さっきBook.findで取得して@bookに入れた本を、ここで使います。<%= @book.title %>の部分に入るのは、その本のタイトルです。

ログにあるlayouts/applicationは、ヘッダーなど複数の画面で共通する部分をまとめたレイアウトを指します。

モデル・ビュー・コントローラという名前だけだと分かりにくいので、今回のコードをMVCの役割に当てはめておきます。

役割	今回の例
Model：データや業務処理を扱う	`Book`
View：表示内容を組み立てる	`books/show.html.erb`
Controller：リクエストに応じて処理を進める	`BooksController#show`

Renderedはサーバー側でHTMLを作った記録です。ブラウザが画面を表示し終えた、という意味ではありません。Railsガイド「レイアウトとレンダリング」

⑦ Completed：どんな結果で終わった？

Completed 200 OK in 21ms (Views: 6.2ms | ActiveRecord: 0.6ms)

最後は処理の結果です。200 OKはリクエストの成功、in 21msはアクションの処理にかかった時間を表します。

Viewsはビュー処理、ActiveRecordはDB関連の時間の目安です。ほかの処理もあるため、2つの合計が処理全体の時間と一致するとは限りません。

また、21msはブラウザへの通信やブラウザの描画まで含めた「画面が表示し終わるまでの時間」ではありません。

HTTPステータスコードは、リクエストに対する結果を表す3桁の数字です。よく見るものをまとめます。

コード	意味と、次に見るところ
`200`	成功。画面の内容も期待どおりか確認する
`302`・`303`	別のURLへの移動を案内している。移動先のリクエストも見る
`404`	対象が見つからない。URL・ルート・対象データを確認する
`422`	内容は理解できても処理できない。入力値やエラーの詳細を確認する
`500`	サーバー側で予期しない問題が起きた。例外の内容を見る

302や303は正常な画面遷移でも使います。422も、入力値のバリデーションエラーとは限りません。原因を調べるには、ステータスコードとあわせて前後のログやコードを確認します。HTTPステータスの仕様

4. 7行を通して読んでみる

最初の7行に戻って、日本語で言い直してみます。

/books/7へのリクエストが来た。
BooksControllerのshowが担当し、IDとして7を受け取った。
Bookを通じてDBに問い合わせ、詳細用のビューを描画。
ステータス200で処理を終えた。

最初に拾った3行から分かったのは、詳細画面へのリクエストが成功したことでした。間の行を読むと、URLの7がparams[:id]を経由してSQLの検索条件に使われたところまで、コードと対応づけられます。

5. エラーが出たら、何を手掛かりにする？

同じ詳細画面で、今度はIDが999の本を開くとします。このIDの本はDBに存在しない想定です。先ほどのshowから2か所変えて、検索にはfind_byを使い、タイトルもコントローラ内で読み取ることにします。

def show
  @book = Book.find_by(id: params[:id]) # 12行目
  @title = @book.title                  # 13行目
end

先ほどのfindは、対象の本が見つからなければ、その場でActiveRecord::RecordNotFoundという例外を送出します。一方、ここで使うfind_byは、見つからないとnilを返し、処理は次の行に進みます。この違いを踏まえて、想定ログを読んでみます。Railsガイド「単一のオブジェクトを取り出す」

Started GET "/books/999" for 127.0.0.1 at 2026-10-30 10:01:00 +0900
Processing by BooksController#show as HTML
  Parameters: {"id"=>"999"}
  Book Load (0.5ms)  SELECT "books".* FROM "books" WHERE "books"."id" = $1 LIMIT $2  [["id", 999], ["LIMIT", 1]]
  ↳ app/controllers/books_controller.rb:12:in 'show'
Completed 500 Internal Server Error in 11ms

NoMethodError (undefined method 'title' for nil):
app/controllers/books_controller.rb:13:in 'show'

まず同じ3行を拾うと、「/books/999にアクセスし、BooksController#showが担当し、結果は500だった」と読めます。では、showのどこで止まったのでしょうか。

ここで注目したいのは、同じファイルの12行目と13行目が、別々の理由で出ていることです。

ログの手掛かり	コードと照らして分かること
SQLの下の `↳ ...:12`	12行目の`find_by`から、IDが`999`の本を探すSQLが呼ばれた
`undefined method 'title' for nil`	`title`を呼び出した相手が`nil`だった
例外の下の `...:13:in 'show'`	13行目は`@book.title`。エラーメッセージと照らし合わせると、`nil`だったのは`@book`だと分かる

「本のタイトルが空だった」のと「本が見つからなかった」のとでは、確認する場所が違います。エラーメッセージの for nil が指すのは、ドットの左側にある@bookです。そこで@bookに値を入れた12行目へ戻ります。ParametersとSQLの両方に999が出ているので、次に確かめたいのは「そのIDの本が開発用のDBにあるか」です。Rubyリファレンス「NoMethodError」

6. 自分のアプリで読むときの手順

次は自分のアプリでも読めるように、試す順番をメモしておきます。練習には、開発環境で正常に表示できる画面を1つ選びます。

ログを表示して、画面を1回開く。
URLと時刻から、その操作に対応するログを探す。
Started・Processing by・Completedを探し、「どこにアクセスし、誰が担当し、どう終わったか」をひとことで言い直す。
知りたいことを1つ選ぶ。受け取ったIDならParameters、検索に使ったIDならSQL、検索を書いた場所ならその下の↳を見る。
ログが指したファイルを開く。エラーが出ていたら、例外メッセージと該当行を照らし合わせる。

調べるときは、分からない部分を検索語にします。たとえば、通常のログならRails Processing by 意味、今回のエラーならRuby undefined method for nilです。自分のファイル名や行番号を外すと、共通する表現で探せます。

見つかった説明は公式ガイドでも確認し、次のようにメモしておきます。

取り上げた行：
分からなかったこと：
調べた結果と参照先：
自分の言葉で言い直すと：

補足：ログの追加・[FILTERED]・リクエストID

自分でもログを足せる

たとえば「showの処理まで来ているのか」を確認したいときは、showの先頭に次の1行を追加します。

Rails.logger.debug { "[log_practice] showに入りました" }

debugのログが出る設定なら、この行を通ったときに次のメッセージが表示されます。日時などが付くかどうかは設定によります。

[log_practice] showに入りました

debugはログレベルです。出力する詳しさを決める設定で、infoに設定されているとdebugのメッセージは出ません。「出ないから処理が通っていない」と判断する前に、ログレベルも確認します。練習用に追加した行は、確認後に取り除きます。Railsガイド「ログの出力レベル」

[FILTERED]は、値を隠している印

パラメータに[FILTERED]と出たら、ログに残さないよう設定された値です。送信されなかったという意味ではありません。自分で書くログに秘密情報を直接入れたり、実際のログを記事にそのまま貼ったりしないよう、内容を確認します。Railsガイド「パラメータをフィルタする」

リクエストIDがあると追いやすい

リクエストIDは、1つのリクエストを追跡するための識別子です。ログに付いている環境では、同じIDの行を追うと、混ざったログを整理しやすくなります。公式API：RequestId

まとめ

ログを塊としてみるのではなく分解することで何を意味しているのか掴めてきたように感じます。
ネット上で調べやすくなりますし、再度動かしたときのログの変化にも気づきやすいです。
ログを読み解くには時間を要しているのですがなんとなくアタリをつけられるように日々の学習で理解を深めていけたらと思っております！

今回は以上になります。
最後まで読んでいただき、ありがとうございました。

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up