はじめに

プログラムをしていく中で、不具合は避けて通れないものです。

文法間違いなどであれば、例外が発生してプログラムが停止し、その状況を教えてくれますので、そこから修正することになるでしょう。

しかし、例外が発生するわけではなく問題なく動作しているが、想定外の動き（仕様と違う動き）をしてしまうということもあります。

その場合は、なぜそのような動きになっているのかを、プログラムコードを解析し、正しく（仕様通りに）動くように修正しなければいけません。

このプログラムコードの解析には、プログラムコードを眺めて頭の中で動かして確認する方法と、実際に動かしながら確認する方法の2種類があります。

今回は、後者の「動かしながら確認する」デバッグ方法を支援するRailsの標準機能、「logger」について、詳しく解説いたします。

loggerの使い方

loggerは、Railsに標準で搭載している機能で、任意の箇所に挿入することで、メッセージや変数の内容を表示することができるようなものです。

「必要な処理が行われているか」や、「どういった流れで処理されているか」、「例外が発生する直前の変数の内容」など、デバッグでの応用範囲が広い機能といえるでしょう。

ただし、手軽に使える分、検討した上で使わなければ、ログを追加（ログを仕込むと呼びます）しすぎて必要なログが見つけられなかったり、必要なところに仕込めなかったりということがありますので、注意しなければいけません。

そんなlogger機能の使い方を、実際に動かしながら説明していきましょう。

環境構築

まずは、以下のコマンドでテスト環境を作ります。

[bash]
rails new logger_test
cd logger_test
rails generate scaffold User name:string age:integer
rake db:migrate
rails c
User.create(name:”Ryosuke”,age:18)
User.create(name:”Daigo”,age:23)
User.create(name:”Hiroshi”,age:35)
exit
[/bash]

ログを仕込むためのメソッドと、そのメソッドを呼び出すコードは、以下です。
（app/models/user.rb）

class User < ApplicationRecord
# logger test
def self.log_test
loop_count = 0
count = 10

count.times do
count -= 1
loop_count += 1
end
if loop_count &amp;gt; 0
puts loop_count
else
puts count
end
end
end

（app/controllers/users_controller.rb）

:
def index
ret = User.log_test # call log_test
puts ret # print log_test return
@users = User.all
end
:

サーバを起動して、「localhost:3000/users」にアクセスすると、コマンドプロンプトに以下の結果が表示されます。

[bash]
Started GET “/users” for 127.0.0.1 at 2018-11-04 14:03:45 +0900
Processing by UsersController#index as HTML
10

Rendering users/index.html.erb within layouts/application
:
[/bash]

※ブラウザではUserテーブルのリストが表示されています

ここで表示されている「10」が、log_testメソッドの処理結果です。

ただし、このプログラムには、以下の2点の問題があります。

・出力されている「10」がloop_countとcountのどちらなのか分からない
・不要な空行が表示されている

ログを仕込んで、デバッグしてみましょう。

https://web-camp.io/magazine/archives/12654

ログ出力の方法

ログを仕込むための構文は、以下です。

ログ名.ログレベル(出力内容)

Viewファイルの場合は以下のようになります。

「ログ名」のデフォルトは「logger」ですので、そのままloggerを使えば良いでしょう。（自分で生成（後述）した場合は、生成したログ名を使用します）

「ログレベル」はそのログを出力する緊急度や必要度などを考慮して設定するもので、以下の6種類があります（詳しくは後述）

ログレベル	説明
unknown	不明なエラー：あり得ない不具合であるため、必ず出力する
fatal	重大なエラー：システムに影響があり、プログラムを継続することが不可能なエラー
error	想定内のエラー：織り込み済みのエラーで処理可能、処理すべきエラー
warn	警告：そのままでも影響がないが、処理しておいた方が良いエラー
info	通知：システムの管理上役に立つ情報
debug	デバッグ情報：開発時の出力情報

「出力内容」は、基本的には文字列で、展開記法も利用できます。

ログを仕込んでみる

まずは、1つめのデバッグです。

表示されている「10」が、loop_countなのか、countなのかが分岐しているのは、「if loop_count > 0」の部分です。つまり、このif式の直前のloop_countにどんな値が入っているのかが分かれば、解決します。

そのため、「if式の直前」にログを仕込んで確認してみましょう。念のため、countの内容も見ておきます。
（app/models/user.rb）

class User < ApplicationRecord # logger test def self.log_test loop_count = 0 count = 10 count.times do count -= 1 loop_count += 1 end logger.debug(“loop_count=#{loop_count}”) # log(1) logger.debug(“count =#{count}”) # log(2) if loop_count > 0
puts loop_count
else
puts count
end
end
end

※デバッグでの解析ですので、debugレベルにしています

（実行結果）

[bash]
Started GET “/users” for 127.0.0.1 at 2018-11-04 15:06:18 +0900
Processing by UsersController#index as HTML
loop_count=10
count =0
10

Rendering users/index.html.erb within layouts/application
:
[/bash]

この結果を見れば、loop_countが表示されているのは明らかです。

loggerの出力をカスタマイズする

2つめの問題のデバッグをする前に、出力される内容をカスタマイズしてみましょう。

ログの出力については、以下の内容をカスタマイズすることができます。

1．環境（本番環境/開発環境/テスト環境）ごとのログ作成
2．出力内容
3．出力先
4．出力レベル

それぞれ、説明しましょう。

1．環境ごとのログ作成

開発環境だけで出力するログなど、環境ごとのログを作成するには、config/environmentsディレクトリにある、環境用の設定ファイルに定義することで行います。

ファイル	環境
config/environments/production.rb	本番環境
config/environments/development.rb	開発環境
config/environments/test.rb	テスト環境

以下の構文で設定します。

config.ログ名 = Logger.new(出力先[, ローテート周期])

※ローテート周期については、最後に説明します

例えば、開発環境でだけ出力したいログ「dev_log」は、config/environments/development.rbに以下のように設定します。
（config/environments/development.rb）

config.dev_log = Logger.new(STDOUT)

なお、ログ名に「logger」と設定した場合は、標準搭載されているログの設定変更となります。loggerログの使用については、「rails.application.config」は不要です。

また、新たに作ったログを使用する場合の使い方はデフォルトのloggerを違いはありませんが、以下のように指定して利用する必要がありますので、気を付けましょう。
（app/models/user.rb）

Rails.application.config.dev_log.debug(“dev_log”)

ただし、本番環境に定義したログを開発環境で使用しようとすると、例外が発生します。もし、すべての環境で使用する新たなログを作成する場合は、「config/application.rb」のApplicationクラスに定義してください。
※loggerの定義は、サーバを再起動しなければ反映されませんので、注意してください

2．出力内容

log_devログの出力内容は、loggerの出力内容に比べて日時などの情報が追加されています。
（loggerのログ）

[bash]
loop_count=10
count=0
[/bash]

（dev_logのログ）

[bash]
D, [2018-11-04T16:32:10.777447 #1740] DEBUG — : dev_log
:
[/bash]

この出力内容は、じつのところ、loggerの方が簡略化されており、新たに作ったdev_logの方が標準的なものなのです。

出力内容の詳細は、以下のようになっています。

[bash]
ログレベル, [出力日時 #プロセルID] ログレベル — : 出力内容
[/bash]

もし、loggerでも同じ出力が必要であれば、適切な設定ファイルに、以下の一文を追加してください。

config.log_formatter = ::Logger::Formatter.new

また、出力フォーマットをカスタマイズすることも可能です。その場合の構文は、以下のようになっています。

config.log_formatter = proc do |severity, datetime, progname, msg|
出力内容
end

出力内容は文字列だけでも構いませんが、ブロック引数も活用するのが一般的でしょう。

ブロック引数	説明
severity	ログレベル
datetime	ログの出力日時
progname	cofig.logger.progname = ○○で定義したプログラム名 定義していなければnil
msg	ログ出力時に設定した表示内容

3．出力先

これまで、ログ出力はコマンドプロンプトで確認していました。

新たに追加したdev_logログについても、コマンドプロンプトにてログが出力されています。

じつは、コマンドプロンプトに表示されていたログはすべて「log/production.log」「log/development.log」「log/test.log」にも、実行している環境ごとに出力されているのです。

前述のdev_logログの定義で出力先として指定した「STDOUT」がそれにあたります。

この「STDOUT」の代わりにファイル名を記載することで、ログの保存先を変更することができます。

例えば、先ほどのdev_logログの出力先を「log/development.log」から「log/dev_log.log」へ変更してみましょう。
（config/environments/development.rb）

config.dev_log = Logger.new(‘log/dev_log.log’)

サーバを再起動して実行してみると、logディレクトリにdev_log.logが生成されて、コマンドプロンプトに表示されていたdev_logログの出力結果が記載されています。

ただし、コマンドプロンプトには表示されていません。これは、不便に思えるかもしれませんが、プログラムを実行し続ける場合などに、定期的な状態確認のためのログ出力を行う場合は、余計な出力を行わないという意味で好都合なのです。

また、ファイルを分ければ、必要なログしか出力されませんので、解析が容易になります。（log/development.logとlog/dev_log.logを見比べてみましょう）

4．出力レベル

上述しているように、ログには、ログの重要度や緊急度を表すログレベルがあります。

それはつまり、「常に表示して知らせなければいけないもの」、「場合によって表示しなくても良いもの」という分け方ということにもなるでしょう。

例えば、開発中であれば、すべて表示するべきかもしれません。しかし、開発の終盤であれば、リリースへ向けて重大なバグだけに絞り込んだ方が効率が良いでしょう。

そのため、以下の一文を追記することで、「ログレベルによって出力されるログを制御する」ことができるようになっています。

config.log_level = ログレベル

「ログレベル」に、表示したい最低レベルのログレベルを記載します。

ログレベル	説明	設定値
unknown	不明なエラー：あり得ない不具合であるため、必ず出力する	「:unknown」or「5」
fatal	重大なエラー：システムに影響があり、プログラムを継続することが不可能なエラー	「:fatal」or「4」
error	想定内のエラー：織り込み済みのエラーで処理可能、処理すべきエラー	「:error」or「3」
warn	警告：そのままでも影響がないが、処理しておいた方が良いエラー	「:warn」or「2」
info	通知：システムの管理上役に立つ情報	「:info」or「1」
debug	デバッグ情報：開発時の出力情報	「:debug」or「0」

例えば、以下の場合はfatalとunknownのログのみが出力されます。

Rails.logger.level = :fatal

なお、開発環境とテスト環境は、なにも設定しなければ「:debug」になっています（すべて出力される）が、本番環境では「:info」になっていますので、注意しましょう。

“未経験”でもたった1ヶ月で営業からエンジニアとして転職！『WebCamp』受講者インタビュー

プログラムの流れを追う

前述で紹介したログを利用することで、プログラムがどう動いているのかを確認することができます。

残っているもう1つの問題を解析しながら、説明していきましょう。

プログラムのコードを眺めて動きを追っていくという作業は、とても勉強になりますが、時間がかかってしまうものです。そのため、デバッグ作業といった時間との闘いとなる作業を行う場合は、最後の手段としてとっておくべきでしょう。

しかし、プログラムがどう動いているかを確認しなければ、修正箇所を特定しにくい不具合も存在しています。（例えば、プログラムが停止しているのがどこかを確認するなど）

そんなときには、ログを仕込んだプログラムを動かして、処理の流れを掴むという解析方法は非常に有効な手法です。

ログの仕込み方

プログラムの流れを確認するためのログを仕込む場合、ざっくりと処理の分かれ目にログを仕込み、その後、原因箇所を絞り込んでいくようにするのが、常套手段です。

（app/models/user.rb）

class User < ApplicationRecord # logger test def self.log_test logger.debug(“1 log_test start”) # log loop_count = 0 count = 10 count.times do count -= 1 loop_count += 1 end logger.debug(“2 loop finished”) # log if loop_count > 0
logger.debug(“3 log_test > loop_count end”) # log
puts loop_count
else
logger.debug(“4 log_test > count end”) # log
puts count
end
end
end

メソッドの開始直後と終了直前にログを仕込むことで、メソッドが開始、終了することが分かります。また、繰り返し処理の直後にログを仕込めば、無限ループに陥っていないことも分かるでしょう。

※なお、ここではlog_testメソッドの最終行にログを仕込んでいません。これは、Rubyの仕様で「最終処理結果が戻り値になる」ことを考慮し、log_testの最終行にログを仕込んでしまうと戻り値が変わってしまうことを防ぐためです

（app/controllers/users_controller.rb）

:
def index
logger.debug(“1 calling log_test”) # log
ret = User.log_test # call log_test
logger.debug(“2 called log_test”) # log
puts ret # print log_test return
@users = User.all
end
:

呼び出し元のコントローラで、メソッドの前後にログを仕込むことで、メソッドを呼び出して、返ってきたことが分かります。

（実行結果）

[bash]
Started GET “/users” for 127.0.0.1 at 2018-11-04 19:50:06 +0900
Processing by UsersController#index as HTML
1 calling log_test
1 log_test start
2 loop finished
3 log_test > loop_count end
10
2 called log_test

Rendering users/index.html.erb within layouts/application
:
[/bash]

コントローラでのlog_testメソッドの呼び出し（1 calling log_test）、log_testメソッドの開始（1 log_test start）から繰り返し処理を抜けて（2 loop finished）、loop_count側の処理を通って（3 log_test > loop_count end）、「10」と表示しています。

つまり、最初に確認した1つめの問題（どちらの10を表示しているのか分からない）という問題も、この方法で解析できるということです。

その後、コントローラへ戻ってきたログ（2 called log_test）を出力した後、改行が出力されています。

つまり、改行は「2 called log_test」を出力したログの後に表示されているわけです。

それは、「puts ret # print log_test return」となります。

すでにlog_testメソッド内で結果を表示していますので、コントローラで戻り値を表示しているこの行は不要でしょう。

なにより、putsの戻り値ですので、log_testメソッドの戻り値はnilになっており、空行が表示されてしまう不具合につながってしまっているわけです。

この場合の修正方法は、以下のどちらかになるでしょう。

・「puts ret」と「ret = User.log_test」の「ret = 」を削除してretを使わなくする
・log_testメソッドでputsを使わなくして、countかloop_countの値を戻り値にする

以上のように、ログを仕込むことでプログラムの流れが手に取るように分かります。今回は単純なプログラムでしたが、大きなプログラムであれば、この進め方で不具合箇所を絞り込んでいくことができるのです。

https://web-camp.io/magazine/archives/12481

長時間ログ出力時のローテート

最後に、通常運用時のログ出力について、説明します。

ログ出力は、なにも開発環境で不具合解析を行うためだけに行うものではありません。

Webアプリケーションの運用段階で、日々の状況を監視するためにも、ログはとても重要な役割を担っています。

しかし、延々とログを出力していると、ログファイルは長大になって、日時を入れているにしても、いざというときに解析の手間がかかってしまいます。

そのため、ログファイルを定期的に分割した方が都合が良い場合があります。

そんなときに、便利なのがログファイル出力のローテート設定です。

ローテート設定というのは、毎日や週に1度、ファイルサイズなどの制限を設けて、自動的にログファイルを新たに作って記録していってくれるものです。

こうすれば一定量ごとにログファイルが分割されますので、いざというときに確認する範囲を特定でき、解析時間の短縮を図れます。

設定方法は、ログの設定時の第2引数です。第2引数に、以下のいずれかを設定することで、指定のローテートを行うことができます。

設定値	説明
daily	1日ごとに新たなファイルを作る
weekly	1週ごとに新たなファイルを作る
monthly	1ヶ月ごとに新たなファイルを作る
ファイル数, サイズ （引数を2つ追加します）	サイズ(bit単位)を超えた場合、新たなファイルを作る。ただし、ログファイルがファイル数を超えると、古いファイルから削除する

まとめ

Railsのlogger機能について、解説しました。

logger機能は、開発をしていく上でとてもよく使う機能です。

もちろん、デバッグにはもっと高機能なツールやgemなども存在していますが、基本となるログでの解析が行えなければ、その恩恵も余り実感できませんし、基本となるものがなければ活用も難しいでしょう。

最初は慣れないかもしれませんが、使っていて慣れていただくことをおすすめします。

・loggerを使うことで、プログラム上の任意の箇所でメッセージを出力できる
・標準では、コマンドプロンプトとlog/xxxxxx.logファイルに出力される（xxxxxxは環境による）
・環境ごとの設定ファイル（config/environments/xxxxxx.rb）に設定することでカスタマイズや新たなログを作成可能（xxxxxxは環境による）
・config/application.rbのApplicationクラスに設定すれば、すべての環境で利用できる設定が可能
・ログ出力するファイルは変更可能
・ログ出力する内容をカスタマイズできる
・ログ出力のファイルを一定期間やサイズごとにローテートする設定が可能
・ログで変数の内容を出力できる
・ログを使って処理の流れを見えるようにできる

＼プログラミングスクールを比較／