Railsのログを理解する-ログの基礎知識- #Ruby

Railsにおけるログの出力方法について理解が浅く、勘違いをしていた。
自分と同じような人が１０人くらいはそうなので、基礎知識から簡単な表示方法をまとめる。

環境

Ruby 2.6.3
Rails 5.2.3

ログと標準出力

今回大きな間違えをしていたのが、ログと標準出力を混同してしまっていたこと。
pなどで変数情報を表示する際に、pumaの出力(以下のようなrails sを立ち上げた際の画面)に表示されるものは、ログファイルに保存されるものと同じだと勘違いしていた。

Processing by SamplesController#index as HTML
  "-----デバッグ情報------"
  Rendering samples/index.html.erb within layouts/application
  Rendered samples/index.html.erb within layouts/application (1.3ms)
Completed 200 OK in 18ms (Views: 16.5ms | ActiveRecord: 0.0ms)

今回分かったことは

上の画面はあくまでもpumaの標準出力であるため、pやputsといったrubyの標準出力メソッドの結果が表示される
ログファイルはRailsが必要とする情報を、必要な形で記録する
もし標準出力が必要であればログに記録させることもできる(ログの内容はカスタム可能)

Railsにおけるログの取り扱い

ログファイルの保存場所

Railsでは環境(production, development, test)ごとに、Rails.root/log/（環境）.logというログファイルが生成される(例：log/production.log)

ログレベルについて

Railsが生成するログには以下の５段階のレベルというものが存在する。
ログレベルは情報の必要度が低→高の順で、0→5の数値が充てられている。

ログレベル	名称	内容
0	debug	デバッグ情報など
1	info	一般的な情報
2	warn	警告
3	error	制御可能なエラー
4	fatal	プログラムをクラッシュさせるような制御不可能なエラー
5	unknown	常に記録されるべき不明なエラー

https://docs.ruby-lang.org/ja/latest/library/logger.html

設定したログレベル以上のもののみファイルに保存される。（例：設定したログレベルが3の場合は3,4,5が保存される）

Railsのデフォルトのログレベルは0となっており、何も変更しなければ全てのログが上記のファイルに保存される。

デフォルトのログ出力レベルを変更する

config/環境/設定ファイルでconfig.log_levelを指定することにより、環境ごとに標準で保存するログレベルを変更できる。
config.log_levelをシンボル型の名称(:debug, :fatal)で指定する。

これにより、development環境では全てのログを表示するが、production環境ではエラーログのみ保存するなどと言ったことができる。

config/environments/production.rb

# production環境ではログレベルがerror以上（error|fatal|unknown）のみ保存される
config.log_level = :error

config/environments/development.rb

# development環境では全てのログレベルを保存する
# ※デフォルトがdebug=レベル0になっているため、実際にはlog_level = :debugを設定する必要はない
config.log_level = :debug

ログへの書き込み

コード内でログへの書き込みを行う

コードの中で任意のログを書き込みたい場合には以下のようにRails.loggerか省略形のloggerを使用する。コントローラー、モデルいずれの場所でも使用可。

logger.(ログレベルの名称)の引数にメッセージを渡すことで、そのログレベルを持ったメッセージを保存することができる。

class ArticlesController < ApplicationController
  # ...

  def create
    @article = Article.new(article_params)
    # ログレベルがdebugのメッセージを保存する
    logger.debug "新しい記事: #{@article.attributes.inspect}"
    logger.debug "記事が正しいかどうか: #{@article.valid?}"  

    if @article.save
      flash[:notice] = 'Article was successfully created.'
      logger.debug "記事は正常に保存され、ユーザーをリダイレクト中..."
      redirect_to @article, notice: '記事は正常に作成されました。'
    else
      logger.warn "記事の保存に失敗しました。" 
      render :new
    end
  end

  # ...
end

https://railsguides.jp/debugging_rails_applications.html

任意の場所でログレベルを変更する

保存するログレベルは、configだけでなく、他のコードの中でも変更することができる。
デフォルトではerrorのみを保存し、特定の箇所のみデバッグ情報を表示するなどと言ったことが可能。
ログレベルの変更はlogger(Rails.logger).leverで設定変更が可能。これは場所を問わない。

config/environments/production.rb

# ここではデフォルトでdebugは表示されないように設定
config.log_level = :error

class ArticlesController < ApplicationController
  # ...

  def create
    # ここでlogレベルを変更することにより、この処理ではデバッグログを保存することができる。
    Rails.logger.level = 0
    @article = Article.new(article_params)
    logger.debug "新しい記事: #{@article.attributes.inspect}"
    logger.debug "記事が正しいかどうか: #{@article.valid?}"  

    if @article.save
      flash[:notice] =  'Article was successfully created.'
      logger.debug "記事は正常に保存され、ユーザーをリダイレクト中..."
      redirect_to @article, notice: '記事は正常に作成されました。'
    else
      logger.warn 
      render :new
    end
  end

  # ...
end

豆知識：パフォーマンスへの影響

以下ような基本的なログ書き方は、比較的動作が重いStringオブジェクトのインスタンス化と、実行に時間のかかる変数の式展開 (interpolation) が行われるため、大量に呼び出された場合にはパフォーマンスに影響が出る。

そして、これはログの出力レベルがdebugを含んでいなかった場合でも評価されてしまうため、本番環境でログレベルを1（=info）以上にしていた場合にも処理時間に影響を与えることになる。

logger.debug "Person attributes hash: #{@person.attributes.inspect}"

これを書き換えて、ブロックの処理とすることにより、ブロックの評価は出力レベルが設定レベル以上になった場合のみ行われるので、無駄な処理時間を減らすことができる。

logger.debug {"Person attributes hash: #{@person.attributes.inspect}"}

Railsのログを理解する-ログの基礎知識-

環境

目次