67:トラブル解決に役立つログを出力しよう¶
プログラミング迷子: ログ出力は何のため？
後輩W：ログ出力って要りますか？
先輩T：要るね。ログ出力は開発者をトラブルから守ってくれる大事な武器だよ。
後輩W：そうなんですか。トラブルが起きてもログが役立ったことがなかったんで実感がないんですけど……。
先輩T：ん？ たとえばどんなログが出力されてたの？
後輩W：今運用しているシステムでは、ログファイルに処理の開始と終了を出力してます。でも、それを見ても「購入できない」という問い合わせの原因を調べる役には立ちませんでした。
先輩T：なるほど。それなら、「購入できない」状況を詳しくログ出力すれば良いんじゃないかな。
後輩W：稼働してるシステムにログ出力を追加するんですか？ 予算がなくてできないって言われちゃいませんか？
先輩T：あとからでも追加したほうが良いね。そうしないと、トラブルのたびに問い合わせ対応や調査でお金も時間もかかっちゃうよ。
ログ出力（ロギング）を実装しているかどうかで、システムの保守性やトラブルシューティングにかかる時間は格段に変わってきます。 ただし、処理の開始と終了しかロギングしていなかったり、処理フローで重要な値をロギングしていないようでは、トラブルの解決にはほとんど役立ちません。 トラブルシューティングに時間がかかれば、お金と時間を浪費するだけでなく、サービス自体の機会損失にもつながってしまいます。
具体的な失敗¶
たとえば、以下のようなログ出力では困ります。
INFO: 購入処理開始
INFO: 在庫確認API呼び出し
INFO: 在庫引き当てNG
INFO: 購入処理開始
INFO: 在庫確認API呼び出し
INFO: 在庫引き当てOK
INFO: 購入完了
このログには各行の日時情報がなく、「誰がどの商品をいくつ購入しようとしているのか」といった購入処理フローの重要な値も出力されていません。 「在庫引き当てNG」というログからは在庫不足のようにも見えますが、在庫確認API呼び出しでエラーが起きていてそのエラーが出力されていないのかもしれません。 このようにログ出力が不足していると、トラブルシューティングに苦しむことになります。 特に外部システムとの結合テストや本番リリース後の調査では、問題発生時に素早く、正確に状況を把握することが重要です。 状況を正確に把握できなければ、エラー原因の可能性は無数にありえますし、解決までの暫定的な対策も検討できません。
ベストプラクティス¶
トラブル解決に役立つログを出力しましょう。 問題発生時に状況を正確に把握できるロギングを実装するには、ログ出力の内容からプログラムの動作を把握できるようにすることが大事です。 状況を正確に把握できれば、どうやって問題を解決するかに集中できますし、根本解決に時間がかかるとしても暫定的な対策を検討できます。
たとえば、以下のようなログ出力であれば、先ほどの例よりも状況が正確に把握できます。
[19/Jan/2020 07:38:41] INFO: user=1234 購入処理開始: 購入トランザクション=2345, 商品id 111(1個),222(2個)
[19/Jan/2020 07:38:41] INFO: user=1234 在庫引き当てAPI: POST /inventory/allocate params=...
[19/Jan/2020 07:38:42] INFO: user=1234 在庫引き当てAPI: status=200, body=""
[19/Jan/2020 07:38:42] ERROR: user=1234 在庫システムAPIでエラーのため、担当者へ連絡してください
Traceback (most recent call last):
File "/var/www/hanbai/apps/inventry/service.py", line 162, in allocate
return r.json()
...
File "/usr/lib64/python3.6/json/decoder.py", line 357, in raw_decode
raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
[19/Jan/2020 07:38:42] INFO: user=1234 購入NG status=500
[19/Jan/2020 07:40:07] INFO: user=5432 購入処理開始: 購入トランザクション=2346, 商品id 222(3個),333(1個)
[19/Jan/2020 07:40:07] INFO: user=5432 在庫引き当てAPI: POST /inventory/allocate params=...
[19/Jan/2020 07:40:08] INFO: user=5432 在庫引き当てAPI: status=200, body="{...}"
[19/Jan/2020 07:40:08] INFO: user=5432 在庫引き当てOK: 商品id 222(3個),333(1個)
[19/Jan/2020 07:40:09] INFO: user=5432 購入確定: 購入トランザクション=2346
[19/Jan/2020 07:40:10] INFO: user=5432 購入完了 status=200
（中略）詳細は書籍 自走プログラマー をご参照ください
