ログの話

はじめに

ログについては様々な文化があり、それぞれの色が一番出やすいところだと思います。
賛否両論あると思いますが、以降は個人的な見解です。

ある日、気づいた

このインシデント、原因不明すぎてわからない。。。
これ、ログを書いたら気づけたかもしれない！ログを書くぞ！！
ログの書き方ってこれでいいんだっけ・・・
ログってどう扱えば良いんだっけ
そもそもログってなんだっけ・・・

ログとは

コンピュータにおけるデータログでは、障害などが発生したとき、何が起きたのかを説明できるようにするためにプログラムが自動的にある範囲のイベントを記録する。

データログ-Wikipediaより引用

なるほど、言いたいことはわかる。

なぜログをとるのか

まずログが「なぜ必要か」という事が根底にある（はず）

• いつ
• どこで
• だれが
• なにをして
• どうなったか

さらに、以下の情報も欲しくなってくる

• 誰宛のログか
• なぜ起きたか
• どうすればよいか

例）アクセスログ

なぜ必要か
利用者のアクセスを記憶しておくため

いつ
発生時のタイムスタンプ

どこで
URL

だれが
クライアントのIP、ユーザID、ユーザエージェント、Cookieなど

何をして
GET、POSTなど

どうなった
HTTPステータスが正常/異常
レスポンスタイムが小さい/大きい

例）デバッグログ

なぜ必要か
アプリケーションの動作確認のため

いつ
発生時のタイムスタンプ

どこで
サーバのIP、クラス名、メソッド名、行数

だれが
スレッドのID、プロセスID、トランザクションID、セッションID、ユーザIDなど

何をして
関数などを呼び出した結果

どうなった
例外が発生した（stacktrace出力）
想定通り or 想定と異なる結果

ログをどうするのか

問題が起こったことを検知する
異常終了の検知、不正アクセスの検知

問題が起きた時に役立てる
ログから原因を推察 → 調査・原因を特定 → 対策を提示

持続してログをとることで役立てる
持続的な監視で問題を見つける
週次・月次のレポート

ログに関する問題

ログの出力先どこにする問題
ログローテーションはどうする問題
ログ多すぎ・少なすぎ問題
人の目じゃないと解析できない問題
機密情報をログ出力問題
パフォーマンス低下問題
行き過ぎた共通化でログ見ても原因がわからない問題
ライブラリが勝手にエラーログ出力する問題
別システムのWebAPIの不備なのに証拠がなくてこちらが責められる問題

ログに対する心構え

ログ保存先はどうするか
ログはいつまで保持しなければならないか
ログの量はどれぐらいになるか
機密情報をログに出してないか
出力されるログから原因が推測できるか
ログは誰が見るか、分ける必要はあるか
ログレベルをどうするか
ログフォーマットをどうするか
ログへコードを採番するか
パフォーマンス低下を招くようなログを出してないか
ライブラリのログ出力は適切か
クライアントサイドで発生したイベントについてログをとるか
時間がかかる処理について進捗ログを出しているか

ログ保存先はどうするか

基本はファイル
お手軽だし、あまり困らない
Linuxなら ”/var/log/アプリケーション名/各種ログ” に書く。

ログサーバ (Syslog,Elasticsearch,AWS S3等)
システムのログを1か所に集約する場合(クラウドを使うなら)
解析に使いたい場合(ログフォーマットも統一しやすい)
改ざんを防止したい場合

リレーショナルデータベース
ちゃんと設計して

ログの量はどれぐらいになるか

どこかのタイミングで見積もっておく
(例) 1日当たりのログ量 = 1リクエストあたりのログ量 * 秒間リクエスト数 * 24時間
面倒であればとりあえず1日1Gとかで出しておけば。。。

最近、あるシステムがDisk fullで死んだのを見たのでどこかで1回は見ておきたい。

ログはいつまで保持しなければならないか

最大日数を求め、そこから30日~365日の間で決める
最大日数 = ログ出力先のディスク空き容量 ÷ 1日のログ出力量(前ページ参照)
(ログサーバ使うなら考えなくて良いはず)

ファイルサイズや世代で残すのは微妙
日にちなど、意味がある単位で区切るほうが良い。
ただし、とてつもなく大きくなる、ファイルシステム制約に引っかかる場合はやむをえない

機密情報をログに出してないか

何が機密情報かは業務による。よく検討しておく。
例えば、パスワード、クレジットカード情報とか。
ログは誰が見るかわからないので、漏れたらマズそうな情報を残さないようにする。
(もしくはハッシュ化して元の値がわからないようにしたりするなど。なお、この方法は入力が普段と違うといった事に気付ける。)
機械的にログを出してる場合、特に注意する。(JavaならReflection,AOPなど)

新しいプロジェクトに入ったら一度は考えたほうが良い

出力されるログから原因が推測できるか

推測が困難なケース

1. ログが少なすぎて何が起きたかわからない
2. エラーになったのはわかるが何でそうなったかわからない
3. 共通化が進むと、同じようなエラー文言だが導線や根本原因が全く違う事がある。(2に行き着く)

原因が推測できるログとは?
周辺のログと処理内容から原因を推測できるログ

推測可能というのはどうやって判断する?
問題の度合いによるので何とも言えない気がする

どうするか
メソッドを呼び出す前に引数を出しておくとか、わかる範囲で情報を集めてしっかりログに書き残す努力をするしかないのでは...
例えば「Logger.error(...)」と書いたときそれが「なぜ起きたか?」を考え、説明できるような情報を集める。SQLExceptionならどういうクエリを投げたか、どういう例外が起きたかなど。

ただ、毎回きっちり書いてたら開発時間が足りなくなると思う・・・
いろいろ考えた結果、デバッグレベルのログをカジュアルに書いて、デバッグレベルで運用するのが手っ取り早いのでは・・・と思い始めてる

ログは誰に見せるか、分ける必要があるか

そのログは「誰に(Whom)」見せるか
● 開発者?
● 運用者?
● 監視システム?(人とは限らない)
開発者向けのログは他にとっては情報が多すぎて辛い。
なので、目的に合わせてログファイルを分けたり、識別子(タグ)を含める。

誰かに見られるとマズイか
マズイ場合、アクセス制御はしっかり行う(chmod 0600 や umask 0077 をしておく)
利用者からは不正アクセスされないような実装を行う。

ログレベルをどうするか

そもそもログレベルはログ出力時点での問題の重要度を示す事しかできない。
呼び出し元はさほど気にしてないかもしれないし、そもそもそのerrorに対して**「原因やこの後どうすればよいか」をログやレスポンスに書くべきでは。。
おそらく統一的なフォーマットでそれ**を書くのが面倒だからか、ログレベルに意味を持たせて使っている・・・という印象。(fatalなら即時対応！とか)

ログレベルに疲弊する前に代替案
Webアプリケーションなら、HTTPステータスコードで返し、アクセスログを監視。
付加情報をつけたいなら、レスポンスヘッダで。（コード値を採番しているならココ）

##ログフォーマットをどうするか
出力形式
ファイルに出す場合、1ログ1行出力を守ると解析の時に幸せになれる。
デバッグログなど人の目でしか見ないなら適当に書いてよさそう。
一貫性があると読みやすい。
また、アクセスログやAPI連携などログでより高度な解析を行いたい場合は、JSONやLTSVなどプログラムで処理しやすいフォーマットを使う
(jqやperlで処理できたり、後でログサーバに突っ込むといった運用がしやすくなる。)

##ログへコードを採番するか
「E1000」といったコードを採番しログに含める
メリット
表記ゆれがなくなる
運用や利用側がコードと事象を紐づけられる
「このコード値が出たらXXXを行う」というフローを組みやすくなる

デメリット
コード値の管理が面倒
複数人で開発するとコンフリクトが起きやすい部分になる

管理し続ける強い意思が必要。コード体系もしっかり決める

##パフォーマンス低下を招くようなログを出してないか
その前にシステム要件を満たしているか確認する

Webアプリなら必ず秒間nリクエストを処理することを定めておく。
ログ関連のパフォーマンスチューニングは後でも良いが、最初に決めておくと手
戻りがない。(満たしてるなら、考えなくてよい。)
ログ出力はコストがかかる

##ライブラリのログ出力は適切か
利用しているロガーやライブラリ毎に設定が異なるので注意する

平気でErrorレベルのログを出す(辛い)
ライブラリで必要な情報を出している箇所がDebugレベル(辛い)
そもそもロガーを使っていない(辛い)
必要になりそうな情報はとりあえず出しておく
ORMライブラリならSQLを出す
HTTP通信を行うライブラリならHTTPのヘッダなどのダンプを出す
ライブラリのロガー設定で出すか、アテにせず自前で出すようにするか考えておく

##クライアントサイドで発生したイベントについて
必要そうであれば入れる
ajax連携結果、JavaScript実行エラーは環境依存の問題を潰すために集めたくなる
他システム不備の証拠集めとして
マウスのクリックイベント、フォーカスイベントなどもA/Bテストで欲しい

WebAPI連携のログをとりたいなら、自前のサーバを中継させるのも手では
APIの利用状況のログを確実に取れる
より業務に合うレスポンスを返せる
しかし、二度手間感はある

##時間がかかる処理について進捗ログを出しているか
とりあえず出す
安心感が得られるため
バッチ処理のときは100～10000件単位で処理したときに「N件処理しました」と出す。
可能なら全体の何%終わったかも出す。
可能ならあと何秒でバッチ処理が終わる見込みか出す。
うまくいかなかったとき、その対象が特定できる情報(IDとか)を出す。

#我々は結局どうすればよいのか
ログのことを考えると面倒なので、簡単な方針として・・・
開発者がみるデバッグログは積極的に出す
機密情報は絶対に出さない
後は欲しい情報やプロジェクトのポリシーに従って、よしなに