アプリケーション動作ログ、ERRORで出すか? WARNで出すか? 〜 岡山城で話してきました #cmdevio2019

旬の生魚おじさん、都元です。旬かどうかは分かりませんが、最新数週間連続でマテ貝を売っているのにお目にかかりました。これはもう、酒蒸しですよ。最高ですよ。あ、魚じゃなかった。生でもなかった…。

さて先週末。2019-04-06 にDevelopers.IO 2019 at 岡山城を開催し、そこで「アプリケーション動作ログ、ERRORで出すか? WARNで出すか?」と題しましてお話をさせていただきました。そのレポートをお送りします。

スライドとセッション概要

アプリケーションのログ、出してますか？ 欲しい情報が出てますか？ 要らない情報いっぱい出てませんか？ 出すか出さないかの判断は、何に基づいて決めていますか？ そもそも何のためにログ出してますか？ そこでログが出るのは正しいですか？ ここでログが出ないのは正しいですか？ そのログは INFO で出すべきものですか？ それとも DEBUG ですか？ 異常発生なので ERROR でログを出しますか？ では異常とはなんですか？ 404は異常ですか？ 直感に任せて雑にやってますか？ 雑にやってうまくいっていますか？ ガイドラインほしくないですか？ 忙しいですか？ 救ってもらっていいですか？

クラウドネイティブ、コンテナ、DeepRacer という今を時めくキーワードが並ぶ中、動作ログｗｗｗｗ しかもこんなセッション概要ｗｗｗ という状況でご清聴いただきましたみなさま、どうもありがとうございました。

ともあれ。ログは大事と言われつつ、じゃあどのように出したらいいのか、というのはなかなかじっくりと議論されないテーマであると思います。私のこれまでの経験では、直感で書いてみて多ければ削り足りなければ増やす、といったアドホックなやりかたしかありませんでした。

まぁいくら考えたところで「多ければ削り足りなければ増やす」方針には変わりないと思いますが、それでもこうやって書いて行こう！という一定の方向性があるとみんな幸せかもしれない、という想いでガイドラインを作ってみました。

ログを出す目的

まず、なぜログを出すんでしたっけ？ 考えてみました。

ログはアプリケーションの開発・運用に必要な情報の 1 つであり、障害調査時に重要な役割を果たします。 ログは障害からの素早い復帰を可能にし、また不具合の原因究明によるアプリケーションの改善等に役立ちます。

• 【運用】 アラート (通知) により、障害を事前に予測する
• 【運用】 アラート (通知) により、障害の発生を事後検知する
• 【運用】 発生した障害の根本的な原因究明をする
• 【運用】 障害により消失・欠損したデータをリカバリーする
• 【開発】 システムの動作を把握しやすくし、開発の効率を上げる

おおむね、こんなところかと思います。

契約プログラミング

で、突然ですが。本ガイドラインは契約プログラミングという考え方から、少しヒントをもらいました。ということで、読み進めるにあたって前提として知っておいていただきたいことをまとめます。

まず本稿では、メソッドやサブルーチンの呼び出しにおいて、呼び出す側を caller と呼びます。 一方で、呼び出される側を callee と呼びます。

caller および callee は、それぞれの責任で満たすべき条件があり、これらを次の 3 つに分類します。

事前条件 (precondition)

事前条件とは、メソッド呼び出し前に満たすべき条件であり、 違反時に Java では IllegalArgumentException や IllegalStateException 等が発生します。

• メソッド呼び出し前に callee の状態 (フィールド) が満たすべき条件 (ex. 特定のフィールドにあらかじめ値を入れておくこと、など)
• メソッド呼び出しの引数が満たすべき条件 (ex. null ではないこと、など)

事前条件は caller が保証すべき条件であり、callee にはそれを検証する責務があります。 callee は事前条件違反を認識した場合、違反内容をメッセージに含む例外を投げる必要があります。

事後条件 (postcondition)

事後条件とは、(事前条件を満たすことを前提として) メソッド呼び出し後に callee が保証すべき条件であり、違反時に Java では Error が発生します。

• メソッド呼び出し後、callee 自身や callee が引数で受け取ったオブジェクトの状態 (フィールド) が満たすべき条件 (ex. 特定の値が更新されていること、など)
• メソッドの戻り値が満たすべき条件 (ex. null ではない処理結果を返すこと、など)

事後条件は callee が保証すべき条件であり、callee 自身にそれを検証する責務があります。 callee は事後条件違反を認識した場合、違反内容をメッセージに含む Error を投げる必要があります。

不変条件 (invariant)

不変条件は、メソッドの実行有無にかかわらず、callee が常に満たすべきオブジェクトの状態についての条件です。

• callee の状態が常に満たすべき条件 (ex. 自然数クラスであれば値が 0 よりも大きいこと、など)

不変条件は callee が保証すべき条件であり、callee 自身にそれを検証する責務があります。 callee は不変条件違反を認識した場合、違反内容をメッセージに含む Error を投げる必要があります。

異常ログ

さて、ログの話に戻ります。

異常とはなにか

まず、何はともあれ異常発生時にはログが出ていて欲しいと思うのはみんなの共通の願いでしょう。ただそうすると、異常とはなにかを積極的に考えていく必要があります。

• ミクロな視点では極小さな想定内のエラーが発生していて、マクロな視点ではそのエラーを受けてデフォルト処理でリカバリーをしている場合。これは異常が発生したと言えるか？
• 404 Not Found を返す場合。これは異常が発生したと言えるか？

ただ、上記のように少し回答に迷うような状況もあります。

契約プログラミングから着想を得た異常の分類

そう、十把一絡げに「異常」と呼んでしまうからもやもやするのだ、と考えた俺たちは。 契約プログラミングから着想を得て、例えばある処理を実行中に異常が発生したことを考え、次の視点で整理しました。

• その異常は、事前条件違反なのか事後条件違反なのか
• その異常が起こった直接的なキッカケはどこにあったのか。呼んだ側 caller / 呼ばれた側 callee / その他

この表は、状況が上に行くほど「好転」した、下に行くほど「悪化」したと判断します。

ただし、この判断はあくまでも現在実行中のオブジェクトによる主観的なものであり、 呼び出し元に処理を戻した時に呼び出し元としては別の判断をする可能性もあることに注意してください。

状況評価が変化した時に ERROR / WARN を出す

悪化は、もともとは正常や違反であったが状況が、失敗に変わった場合などが該当します。 この時は速やかに (悪化を認識した発生地点からもっとも近い自分たちのコード上で) ERROR レベルのログを出力します。

逆に、状況評価を悪い状況からより良い状況に再評価した場合を好転と呼び、この時は速やかに WARN レベルのログを出力します。 例えば、違反が発生したものの、デフォルト値などを利用して、つまり正常として処理を継続する場合等が該当します。 他にも、失敗が発生したが、リトライする、つまり正常として処理をやり直す場合もこれに該当します。

このように ERROR および WARN のログレベル選択は、発生した異常の重大さ (日常的 / 致命的) で決めるのではなく、 状況が悪化・好転したかどうかで選択する、というのが本ガイドラインにおける異常ログのキモです。

正常ログ

さて、ここまでの指針では、何事もなくリクエストを完遂した場合はログが1行も出ない場合があります。しかし、正常に処理を行った時にも、何らかの痕跡は必要です。ということで、正常時のログとして、成功ログと境界ログを定義します。

成功ログ

先程の異常ログでは、状況が悪化したときに ERROR を出すと決めました。成功ログはそれと対になるログです。

つまり、状況悪化の可能性を考慮した (ERROR ログ出力のコードを書いた) が、実際には悪化が起こらずに何事もなく成功した場合、INFO を出すことを必須とします。

関数型プログラミングで if 式 (≠ if 文) をご存知の方はすんなりイメージできるかもしれません。異常時には ERROR が出るのであれば、正常時には INFO を出します。ERRORが出る可能性があったのに、正常時には何も出力しないような状況を回避します。

これを成功ログと呼びます。

境界ログ

普段から、各メソッドの最初の行と return の直前にログを書いたりすることがあると思います。これを境界ログと呼びます。

特に MVC で Web アプリケーションを書いている場合においては、コントローラーのリクエストハンドラが呼ばれたタイミングで、処理開始の境界ログを出力を必須としておきましょう。それ以降のサービスクラス等のエントリー時にログを出すことも構いませんが、こちらは任意としておきます。

ちなみに、処理終了の境界ログ (return 直前) については、前述の「成功ログ」及び「悪化ログ」としてかならずどちらかが出力されるように、既になっているはずです。

開発ログ

最後に開発ログについて少しだけ。今まで見てきた ERROR, WARN, INFO は本番環境で出力するログレベルです。それ以下、例えば DEBUG, TRACE レベルについては本番環境では出力しない、開発ログとして扱います。

本番ログは色々細かいこと言いましたが、開発ログは開発に不都合がない限り、好きにしていいです。

まとめ

まとめると、次のとおりです。

もちろん、このガイドラインが全てではありません。実際、細かいところで発生した違反をいちいち ERROR としてログ出力するとなると、だいぶウルサイ感じがするのは確かだと思います。なので、状況に応じて「違反時、即座に例外を投げる場合は異常ログを省略してもかまわない」というルールも、いい感じに働くかな、などという肌感覚もあったりします。この辺りは、私自身もガイドラインを運用しながら、今後も調整していきたいところです。