たごもりすメモ

コードとかその他の話とか。

#java_ja で例外とロギングについて勉強会をやるというのでいってきた＆飛び込みLTやった＆運用の視点から見たアプリケーションのログについて

LOG.debug("nice catch!") - connpass
2012/06/27 java-ja 『LOG.debug("nice catch!")』#java_ja #javaja - Togetterまとめ

blogエントリを書くまでがjava-jaだと聞いたのでとりあえず書く。超まとまってません。各スピーカーの話の内容については他の人のblogに(たぶん)書いてあるのでそっちを見るとかTogetterを眺めるとかすればよいのではないでしょうか。

主催のみなさま、および会場提供のGREEさま、ありがとうございました。そういえばGREEでの勉強会って初めて参加した気がする。六本木ヒルズの入館、だいぶ簡単になりましたね。

いってきた

どっちかというとアプリケーションのコード書く人が多かったんですかね。という感じで、アプリケーションコードからいかにして例外を投げるか、それをどのようにログに残すか、という視点の話が多かった。
アプリケーションのビジネスロジック層がどのようにログを残すべきかというのはあまり問題のは感じない*1んで問題意識のズレがあって、自分には何が問題視されてるんだっけ、というのがいまいちわかってなくて、割とぼんやり聞いてた印象がある。うーん？

@t_wada さんの「TDDをやっているとログ出力を忘れる」という発言が極めて印象に残っているが、要するにうまくいくなら別にログ要らんのだと思うんだよね。……という話はあとでもうすこし詳しく書く。
あとで食べ物とりながら少し話した内容なんだけど、エラーというのはだいたいモジュールとモジュールの間、システムとシステムの間、Webアプリケーションとバックエンドの間で起きる、ので、そういうところについて手厚くデータのチェックと(怪しげな状態についての)詳細なロギングをやっておけばいいんじゃないかなあ。「境界」はログ出力において重要である、というのがそういえば話にありましたね。あれは本当にそうだと思う。

ところで @t_wada さんの紹介されていた「水色レンガ本」、あとでちらっと見せていただいたんだけどだいぶ良さそうな本だった。きちんと思考の過程や設計指針の前提条件を議論した上で設計をどのようにすべきか、のように整然と構成が組まれてる感がある。本文をチラ見した限りでは議論の組み立ても各章で簡潔に独立した記述になっているようだったので、気になった章だけ拾って読むにもよさそうに感じた。あれは買うつもり。*2

Amazon.co.jp： オブジェクト指向入門 第2版 原則・コンセプト (IT Architect’Archive クラシックモダン・コンピューティング): バートランド・メイヤー, 酒匂 寛: 本

しゃべってきた

「ログを残す方法としてこういうものを使う方法もあります」と太一こと @ryushi さんが紹介していたのがたいへん気になったので、最後に飛び込みでLTやってきた。資料無しで適当にブラウザにタブをいくつか開いて表示させておいてしゃべるスタイル。
話の内容は以下の通り。

  • logrotateマジちゃんとやんないと悲劇が起きる
  • scribedというものがあるがネットに基本的に情報は無い
  • scribedのインストールは大変
  • scribedのインストールはマジ大変
  • scribedはいろいろ大変過ぎるので避けたほうがよい
  • というようなことが こちらのエントリ に書いてあるので興味があれば読むのもよいでしょう
  • fluentdイイヨ！

このような話をしたところ心ない感想が(非参加者から)寄せられました。ひどい！

マジレスすると、いちおう同じ話は二度しないように気をつけているんだよ実は。「scribedひどい」って話はまだどこでもしていなかったはず！

運用の視点から、ログの話

状態が怪しげなときはwarnを出せるだけ出せばいいと思うしerrorを出さない奴はxxxxだ！みたいなのはまあいい*3として、infoレベルのログについて。

前者が会場からのツッコミ( @yoshiori さんだったかな)、後者はそれに対しての @ryushi さんの返答だったと思う。これについては自分も完全に同意です。で、そのあたりの詳しい話。
なおプロダクション環境の話です。開発時は開発者が好きにやればいいと思います。

まず基本的に、運用者が普段からINFOログを見ることは無いと思う。ひとつのサービス専属の運用担当でかつ毎日ヒマしてるとかならともかく、他に優先順位高いものがいくらでもあるので、まず見ない。見てるって人いる？

なので「INFOログを見てそれが正しい状況なのかどうかを判断することは普通はできない」んですね。無理。たとえば行われるべき重要な処理がひとつ飛ばされていてその分のINFOログが出てなくても、まず気付けない。どころか「この処理はスキップしてこっちに行くよ」というINFOログが出ていてもそれを読んで異常*4だと判断するのは不可能だ。*5

また何らかのトラブル時にINFOログを出していることで何か助かるかというと、何も助からない。正しくWARN/ERRORが出力されている状況ならログファイルはWARN/ERRORに溢れていて、そこから根本的な原因をたどるだけで精一杯だ。複数のモジュールが組合さって構成されている通常のアプリケーションの場合は問題を起こしているモジュール以外からも大量のエラーログが出てくるので、どこが実際に問題になっているのかを調べるだけでもひと苦労。
で、そこにINFOログが大量に溢れてても見てられない。むしろフィルタの手間が増えるだけなのでたいていは邪魔かな。問題の原因について大枠で見当がついた場合には、そこから詳細を見るのにINFOログが役に立つ場合があるけど、それよりアプリケーションのソースをエラーメッセージでgrepしたほうが解決が早い場合が多いんじゃないでしょうか。前述した通り、INFOログは「どういう出ているのが正しいかを知っていないと役には立たない」から。トラブル時にそんなの調べてらんないでしょ。

自分の感覚としては、(当然アクセスログや行動ログは別として)アプリケーションログは「何もなければ何も出ない」のがいちばん自然だし、何も出てなければ「ああ、何事も無いんだな」と判断する。
ということで、自分は WARN/ERROR だけ出てればいいや派です。むしろINFOのこと考えるヒマがあったらWARNを手厚くしてほしい。

運用の視点から、バッチ処理の話

なお会場で上記の話題に関連して以下のような話が出てた。

「INFOログ出して、たとえば定期的に起動してないと困るバッチの開始と終了のログを運用の人に監視してもらうとか」

いや、ないだろ。それはない。絶対ない。そんなことアプリ書く人が言いだしたら、誰かから椅子投げられても、しょうがないなーとにこやかに見守るレベル。ないない。

ジョブの起動と停止の制御というのはバッチ処理そのものの中心的な機能のひとつで、またアプリケーションの要件として決めるべき重要な要素でもある。5分に1回起動するジョブ、というものがあるとして、その起動と停止には以下のように様々な要素をアプリケーション要件として決めておく必要がある。

  • 1ジョブが5分を超えた(あるいは超えそうになった)とき、そのジョブはそのまま継続すべきか、停止すべきか？
    • またこの状況は正常状態か、異常状態か？
  • 前のジョブが異常状態だったとき、次のジョブは起動してしまっても良いか？
  • 前のジョブが5分を超えて走っているとき、次のジョブはどうすべきか？
    • 前のジョブのことは気にせずそのまま開始すべき？
    • 前のジョブが完了するまで待機し、それから動作を開始すべき？
    • 前のジョブをkillして自分は開始すべき？
    • 自分は開始しない(黙って終了する)べき？
    • で、その状態は異常状態？ 正常状態？

極めて簡単なところを挙げるだけでこれらのバリエーションがあり、またこれらはすべてアプリケーションの要求によって決まる。条件としては他にも「最後にデータが更新されてから30分いかなるジョブによっても更新がなければ異常」のようにデータドリブンでの監視が必要なケースもある。
また「前のジョブ」「次のジョブ」はサーバをまたいで存在する可能性があることにも注意する必要があるため、当然トランザクショナルな制御を必要とすることも多い。

ということで、バッチ処理が正常に走ったかどうかをINFOログを用いて監視するとか言語道断。そのようなことには全く意味がない。
アプリケーション開発者でなんらかのバッチ処理を書くことになった人はこのことをきちんと念頭に置いて、実行履歴をきちんとRDBMSなりなんなりで管理し、その情報をきちんとアプリケーションの要件に従って正常/異常を判定するプログラムを書いて、その実行結果を監視ツールに突っ込みましょう。

*1:無くてもいいんじゃね、というか、必要なデータならそれはアプリケーションが記録する他のデータと同じように残せばいいんじゃね、と思う

*2:とはいえ全部通して読むとかさすがにしないだろうなあ。サンプルコードにAdaが出てくるのを見て、あーAdaの仕様書ってアホみたいに分厚いって話を聞いたことがあるなー、みたいに思ってた。

*3:ログの容量について……という話があったけど、そもそもlogrotateをちゃんとやっていれば問題にならない。保存期間とかも言われてたけど、他所にバックアップしてそこで保存期間は考えろよ、じゃないとサーバ飛んだら終わりだぞ、と思う。

*4:あるいは異常に近い何らかの状況

*5:そのようなケースでそこに注意してほしいのであれば、それはINFOではなくWARNなりERRORなりで出すべき。