🐈

[Rails]エラーの内容をログに出力したい ~ログレベルとloggerについて。また、例外処理との合わせ技も

2023/02/04に公開
4

はじめに - この記事の内容はどんなときに役立つか

アプリケーション上に表示されるエラー文が抽象的すぎてどうしてエラーが起きているのかわからない、しかもログを見てもエラー内容がわからない、なんてことはないでしょうか?
実装者にすぐ確認ができれば良いのですが実装者がすでにチームを去っているなんてことは度々ありますし、そもそもこういうエラーは実装者が想定していなかったりします。テストちゃんと書けよとか思ったりしますが
私が仕事上でそういう事案にぶつかった際にログに出力する方法を教えていただいて解決できたので、その方法を残しておきます

前提知識 - ログレベルについて

Rubyのログにはログレベルがあります

ログレベル(数字) ログレベル 意味
5 unknown 常に記録されるべき不明なエラー
4 fatal プログラムをクラッシュさせるような制御不可能なエラー
3 error 制御可能なエラー
2 warn 警告
1 info 一般的な情報
0 debug 低レベルの情報

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

ログは設定しているログレベル以上のものが出力されます
ex) warn(2)で設定すれば、warn(2),error(3),fatal(4),unknown(5)のものがログに出力されます

ログレベルの設定方法(2023/02/05追記)

ログレベルはconfig/environments配下のファイルで、環境ごとに設定することができます。
1つ例を出しましょう

config/environments/development.rb
config.log_level = :info # 数値で表せば1

このような記述があれば、development環境のログにはログレベルはinfo(1)以上のものが出力されます。

ログレベルの設定はconfig.log_level = :ログレベルで行うことが可能です
また、デフォルトの設定はdebug(0)となっており、全てのログが出力されます

加えて、config/application.rbconfig.log_level = :ログレベルと記述すれば、環境を問わず ログレベルが設定されます。

config/application.rb
config.log_level = :warn # 数値で表せば2

このような記述をすれば、全ての環境でログレベル2以上のものが出力されるように設定されます。

また、Rails.logger.levelを使うことでもログレベルの設定ができますが、こちらは私の理解が及んでいないため、正しく理解でき次第追記します。

ログに情報を出力する(2023/02/05追記)

ログに出力したい情報を出力するには、loggerを使います

hoge_controller.rb
def index
  logger.info("indexメソッドだよ")
  # 処理
end

このように記述すれば、hoge_controller.rbindexメソッドを実行した際に、ログレベルinfo(1)でindexメソッドだよと出力されます。

I,[yyyy-mm-dd ~省略~ ]INFO -- :indexメソッドだよ

のような出力になります

ログレベルと出力されるログについて練習しましょ〜(2023/02/05追記)

以下の場合、development環境のログにhoge fuga piyoがそれぞれ出力されるか考えてみましょう。

config/environments/development.rb
config.log_level = :error # 数字で表すと3
hogehoge_controller.rb
def index
  logger.info("hoge")
  logger.fatal("fuga")
  logger.error("piyo")
end

解説と答え

この問題でのdevelopment環境のログはログレベルがerror(3) 以上 の情報が出力されます。
hogeはログレベルinfo(1)の情報です => 出力されません
fugaはログレベルfatal(4)の情報です => 出力されます
piyoはログレベルerror(3)の情報です => 出力されます
したがって、以下のような出力になります

F,[yyyy-mm-dd ~省略~ ]FATAL -- :fuga
E,[yyyy-mm-dd ~省略~ ]ERROR -- :piyo

本題に戻ります

ローカル環境のログレベルは大抵debug(0)に設定されている = 全ての情報がログに出力される状態になっているかと思います。
しかし、本番環境のログレベルはinfo(1)に設定されていたりします。そのためバグ調査をしようにも調べようがない。。。なんてことも起き得ます

そんなわけで、エラー内容を強制的に出力させましょう

ログレベルの設定がinfo(1)のアプリケーションで、新しい情報を登録する処理中によくわからないエラーが起きたと想定しましょう
アプリケーション上でもログでもわからないのでソースコードを見にいきます

def create
  # 処理
rescue
  flash.now[:alert] = '不正だよ'
  render(:new)
end

例外処理が行われていることしかわかりません。まあ場合によってはバリデーションエラーかな?みたいな推測は立ちますが、推測の域を出ないかと思います。
こんなフラッシュ出されても意味ねえだろと殺意を覚える方もいらっしゃるかもしれませんが、まあそこはユーザーに見せられないのかもしれないと許しましょう。

はい、そんなわけで(?)ログにエラー内容を出力されます

def create
  # 処理
rescue => e
  logger.error(e.message) # ログレベル3で出力する
  flash.now[:alert] = '不正だよ'
  render(:new)
end

このように記述することで、ログレベルerror(3)でエラー内容を出すことができます
このアプリケーションのログレベルはinfo(1)に設定されていますので、無事にエラー内容がログに出力されることになります

E,[yyyy-mm-dd ~省略~ ]ERROR -- :Userを入力してください。

このようなログが出力されれば、Userの入力に問題があることがわかりますね

仕組み

rescue => e

この行でエラー内容をeに格納します

logger.error(e.message)

続いて、こちらの行でeに格納されたエラー内容をログに出力します
分解していきましょう
logger.ログレベル(hoge)で指定のログレベルでhogeを出力します
e.messageeに格納されているエラーメッセージです
つまり、この行での処理は
ログレベルerror(3)でエラーメッセージを出力してね
ということになります

まとめ

ログに関する基本的な知識と、例外処理に関する基本的な知識の合わせ技ですが、まあ使える場面はままあるかなと。
e.messageをアプリケーション上に出力することの方が多い気がせんこともないですが。。。
私は今回紹介した方法でエラー内容がわかり修正パッチのリリースができたので、私みたいな状況に陥ったよわよわエンジニア(私のなかーま!)が助かったらいいな〜ぐらいの気持ちで残しておきます。

参考文献

Discussion

Junichi ItoJunichi Ito

こうのさん、こんにちは。
ログレベルとログ出力メソッドの関係はたしかに最初は理解しづらいかもしれませんね。
いい着眼点だと思います👍

僕の登壇を聞いてこの投稿をされたと思うので、「こうするとさらにわかりやすくなりそう」というポイントを書いておきますね。

  • ログレベルはどこでどのように設定するのか、具体例を示す
  • logger.error(e.message)を呼ぶと、こんなふうにログ出力されます(またはされません)」というように、具体的な出力例を見せるとさらに理解しやすい
  • ログレベルとログ出力メソッドをいろいろ切り替えながら、「これは出力される」「これは出力されない」といくつかのパターンを見せるとさらに理解しやすい(以下はその例)
    • ログレベルがinfoでlogger.info→出力される
    • ログレベルがinfoでlogger.debug→ 出力されない
    • ログレベルがdebugでlogger.info→出力される
    • ログレベルがdebugでlogger.debug→ 出力される

ちなみに、本題とは無関係ですが、controller内でrescueを書くのは、その多くがアンチパターンです。
業務エラーは例外ではなく、条件分岐で処理していく方がいいですね。
もちろん、既存のコードが全部こうなってたので、同じように書かざるを得なかった、ということもよくありますが・・・😅

詳しくは以下の記事をご確認ください〜。

Railsアプリケーションにおけるエラー処理(例外設計)の考え方 - Qiita

こうのこうの

伊藤様、コメントありがとうございます。
また、先日のウェビナー非常に勉強になりました。ありがとうございました。

ログレベルとログ出力メソッドの関係はたしかに最初は理解しづらいかもしれませんね。
いい着眼点だと思います👍

ありがとうございます。正直、私自身もちゃんと理解できているか不安が残っている箇所ですので、今後の自身のためにとも思い、記事にしました。

ログレベルはどこでどのように設定するのか、具体例を示す

確かに、これがないと自身の環境ログレベルがどのようになっているのか確認できないですね。追記します。

logger.error(e.message)を呼ぶと、こんなふうにログ出力されます(またはされません)」というように、具体的な出力例を見せるとさらに理解しやすい

なるほど。私自身もあまり出力例を見ていない状態ですので、自身が関わっているプロダクトで色々なケースを試し、追記しようと思います。

ログレベルとログ出力メソッドをいろいろ切り替えながら、「これは出力される」「これは出力されない」といくつかのパターンを見せるとさらに理解しやすい(以下はその例)

わかりやすさを追求するとはこういうことなのですね。実例を示していただきありがとうございます。こちらも教えていただいた例を参考に、追記させていただきます。

controller内でrescueを書くのは、その多くがアンチパターンです。
業務エラーは例外ではなく、条件分岐で処理していく方がいいですね。

教えてくださりありがとうございます。私が関わっているプロダクトでこのような実装があったので、「このように実装していいんだ」と思っておりました。
添付してくださったリンク先の記事を読んで勉強させていただきます。

Junichi ItoJunichi Ito

修正ありがとうございます!かなりわかりやすくなりました👍

そのうえでいくつかコメントさせてください。

数字よりシンボルの方が読みやすい

ログレベルの設定は数値でもシンボルでも大丈夫ですが、シンボルの方が可読性が高いと思います。その上で、数字も併記してあげるとより親切ですね。

# infoは数値で言うと1
Rails.logger.level = :info

Rubyのコメントはシャープ

// 処理 とありますが、Rubyの場合は # 処理 ですね。

以下の記事も参考にしてみてください。

https://qiita.com/jnchito/items/da33f793de2e29e470f4

ログレベルを変更したときの有効範囲がおかしい?

また、「このcontrollerのこのメソッドのときだけログレベル0の情報はいらない」といった場合、Rails.logger.levelを使うことで実現できます

この点ですが、「このメソッドのときだけ」というわけではなく、そのあともその変更が引き継がれませんか?
以下は僕のローカル環境で実験した結果です。

この点はもうちょっと深掘りが必要になりそうですね!

こうのこうの

伊藤さま、さらなるご指摘ありがとうございます!

ログレベルの設定は数値でもシンボルでも大丈夫ですが、シンボルの方が可読性が高いと思います。その上で、数字も併記してあげるとより親切ですね。

どちらでの表記の方が良いか悩んでいたのですが、併記すると良いのですね。修正します

// 処理 とありますが、Rubyの場合は # 処理 ですね。

全くもってご指摘のとおりです。おそらく過去に投稿した技術記事でも同様の記載をしてしまっていると思うので、過去のもの含めて修正します。
また、参考となる記事のリンクを添付してくださり、ありがとうございます

「このメソッドのときだけ」というわけではなく、そのあともその変更が引き継がれませんか?

こちら、私の理解が及んでいませんでした。
不正確な情報となっているので、こちらに関する記載は一度削除して、正しく理解できてから再度追記します。

ログインするとコメントできます