運用を支えるためのログを出すにはどうするか？ #jjug_ccc #ccc_m3

JJUG CCC 2019 Fallで話した時のスライドです。

Transcript

1. 運用を支えるための ログを出すには どうするか？ 斎藤将也
2. 自己紹介 • 無職 • 前職ではアプリケーションエンジニア ◦ SaaSとして動くSpring Bootで書かれたサーバーサイドの開発と運用 • 仕事で使ってたツール ◦ Spring Boot/Spring MVC ◦ Slf4j + Logback ◦ AWS, CloudWatch Logs ◦ Docker, AWS ECS 2
3. アジェンダ • なぜログを出力するか • どこでログを出力するか • どのようなログを出力するか • ログでなにを出力するか • ログ以外の手段 • まとめ 3
4. なぜログを出力するのか 4
5. 運用では色々なことが起きる 5
6. 運用では色々なことが起きる 6 ユーザからの問い合わせ エラー/バグ パフォーマンスダウン
7. 運用では色々なことが起きる • 色々なことが起きる ◦ バグ ◦ 問い合わせ ◦ パフォーマンス劣化 • 障害は必ず起きる ◦ 100%の可用性はありえない • でも出来る限りサービスを提供したい ◦ 障害の調査時間・復旧時間を短くして機会損失を減らす 7
8. じゃあどうするか • 高い信頼性を持つアプリケーションを作る • モニタリングで調査・復旧時間を短くする 8
9. じゃあどうするか • 高い信頼性を持つアプリケーションを作る • モニタリングで調査・復旧時間を短くする 今日の話 • 調査・復旧時間を減らすためにログにどんな工夫をするべきか 9
10. そもそもログってなんだっけ • 「いつ」を示すタイムスタンプを持つ • 「その時どういう動作を行ったか」を示す ◦ 「17時、決済サービスとの通信は正常に終了した」 ◦ 「18時、決済サービスがダウンしている」 • 当時の動作からシステムがどういう状態だったかが分かる 10
11. どんな場面でログを読むのか • 障害発生時 • ユーザサポート • 開発・テスト などなど 11
12. ログを出力するのは誰かに読んでもらうため • ログを読む人はシステムによって様々 ◦ 自分以外の開発者 ◦ 運用してる人 ◦ ユーザサポート ◦ 半年後の自分 • 意図の伝わるログを出力しよう 12
13. どんなログがいいか？ • 5W1Hがわかるログが良い ◦ 「いつ」「だれが」「なぜ」「何が起きて」「何をすれば良いのか」 ◦ 特にエラーログ • アプリケーションの特性・要件・コンテキストに合わせて トラブルシューティングなどで必要なログを書こう ◦ 「ユーザID 〇〇のユーザの注文を〇〇 Payで決済した」 ◦ 「ユーザがログインに失敗した」 13
14. 運用を支えるログとは • 「運用を支える」 ◦ 復旧時間や調査時間を出来るだけ短くする • ログ ◦ ある時点でのシステムの状態 運用を支えるログとは ➔ システムで起きた問題や状況を 運用している人間が 調査に掛かる時間を短くするログ 14
15. どこでログを出力するか 15
16. 関数の最初でログを出力しない • やりがち • どうしてもほしいならDEBUGレベルで • 関数の最後に、どういう結果になったかをログに吐く方がいい ◦ 最初に吐くより情報量が多い ◦ 関数の最初: 「ユーザを作成しようとしています。」 ◦ 関数の最後:「◦◦というユーザIDのユーザを作成しました」 • AOPで出力するログはオススメしない ◦ ログ量が多くなってノイズになりがち ◦ 業務的な情報がないログが出がち ◦ 個人情報がログに出てしまったりも・・・ 16
17. 関数の最初でログを出力しない おすすめしない例 17
18. 関数の最初でログを出力しない おすすめしない例 18
19. 関数の最初でログを出力しない まだマシ例 19
20. 関数の最初でログを出力しない 良い例 20
21. AOPで出力するログって？ • Aspect指向プログラミング（AOP）で出力するログ ◦ サンプルでよく見るやつ • 出すなら何か見たいものだけに絞る必要がある 21
22. ログは多すぎてはいけない • Ex. ◦ 繰り返し回数の多いループ内でのログ ◦ そもそも単純に吐いてるログが多い • ログが多いと読むのに時間がかかる • ディスクを食いつぶしたり・・・ ◦ 別の障害に繋がる可能性も・・・？ • ログを保持するコストに跳ね返る 22
23. システム間通信の結果はログに なぜ • システム間通信をする部分には障害が起きやすい • どういう依存があるかもログから分かる • 外部システム起因の障害の切り分けに使える 23
24. システム間通信の結果はログに • INFOレベルで出力する • 次のような内容が書かれていると良い ◦ どういうAPIを呼び出したか？ ◦ どういうステータスコードが帰ってきたか？ ◦ どの程度処理時間がかかったか？ 24
25. システム間通信の結果はログに • 通信ライブラリのインターセプタなどで書く ◦ Ex. okhttp-logging-interceptor 25
26. システム間通信の結果はログに • 通信ライブラリのインターセプタなどで書く ◦ Ex. okhttp-logging-interceptor • 通信結果の記録にリクエストIDを出力しておくと便利 ◦ リクエストIDについては後述 ◦ どう便利なのかについても後述 26
27. 通信の結果をログに吐くだけでいい？ 通信を行ったビジネスロジック側にもログは必要 なぜ • 通信ライブラリのログ出力部分では ERRORなのかINFOなのか判断できない • ビジネスロジック側ならもっと情報が出力できる ◦ 「◦◦というユーザのポイントの発行に失敗しました」 27
28. どのようなログを出力するか 28
29. ログレベルを使い分ける ログレベル周りでありがちなこと • ログレベルと出力している内容が合ってない ◦ すぐに対応が必要なログも見逃してしまう ◦ 障害時の初期対応はエラーログだけ見たいのに・・・ • フレームワークのDEBUGログが出ている 本当は状況に合わせて必要なログを読みたい 29
30. ログレベルを使い分ける • 適切にログレベルを選ぶ • 基本出力するログレベルはINFOレベル以上にする ◦ DEBUG以下はフレームワークのログとかも出てしまう • INFOで出力する例 ◦ ビジネスロジックで発生したイベントの結果 ◦ 外部通信の結果 ◦ バッチ処理の周期的なサマリ ▪ 「何件処理しました。そのうち何件は失敗しました」 ◦ など 30
31. ログレベルを使い分ける • ERROR ◦ 運用の継続が困難な問題が発生した時 ◦ 人の介入が必要な場合は出力する ▪ Ex. データベースの名前解決に失敗 • WARN ◦ 一時的な問題が発生した時や予期せぬ状態 ▪ Ex. リトライ可能な問題, 一時的なキャパシティ不足 • INFO ◦ 基本的なログのレベル • DEBUG ◦ デバッグの為に使われるログ 31
32. 構造化されたログで出力する どうやるか • JSONでログを出力しよう なぜ • 次の用途で使いやすい ◦ 分析 ◦ アラート ◦ 検索 32
33. 構造化されたログで出力する • JSONなど解析しやすい形でログを出力しよう • JSONならネイティブにサポートされているサービス・ツールがある ◦ CloudWatch Logsなど • logback（slf4jの実装）でJSON出力するなら ◦ logback-ext-json-classic ◦ logstash/logstash-logback-encoder 33
34. 構造化されたログで出力する • JSONで出力したときの例 ◦ logstash-logback-encoderを使用 34
35. JSONでログ出力すると何が嬉しいのか • JSONのフィールドで検索できる 例: • エラーログを検索 • 特定のAPIのログだけ検索 • 1トランザクションで発生したログを検索 ◦ リクエストIDを使う（後述） • 500エラーのトランザクションだけ検索 35
36. ログでなにを出力するか 36
37. ログを読もう なぜ • 運用していると必ず読む機会が発生する • ログを見直す機会になる ◦ 分かりにくいログを直すチャンス ◦ 足りないログを足すチャンス 37
38. ログを読もう • 障害が起きた時はもちろん • 開発中に問題が起きた時も • テストが落ちた時も ◦ デバッガを出来るだけ使わない • ログから問題の原因の特定が出来ないなら ログを直すことを考えよう 38
39. ログにコンテキストを付与する コンテキストを付与すると • JSONログにその時の状況(コンテキスト)を表すフィールドが追加される なぜ • その時どういう状況であったかを把握しやすくするため ◦ 「Who」や「Why」を追加する 39
40. ログにコンテキストを付与する • どうやってコンテキストを付与するか ◦ MDC（Mapped Diagnostic Context） ▪ 診断コンテキスト from logback ◦ logstash-logback-encoder（今回は話しません） • 付与する内容例 ◦ ユーザID ◦ リクエストされたパス ◦ リクエストID（後述） 40
41. MDCの使い方 • 処理をtry-finallyで囲む形 put/removeする • 必ずfinallyでremove 41
42. ログにコンテキストを付与する • 例: MDCInsertingServletFilter ◦ リクエストされたURL/URIやUserAgentなどが付与される 42
43. ログにコンテキストを付与する • 例: MDCInsertingServletFilter ◦ リクエストされたURL/URIやUserAgentなどが付与される 43 一部省略してます 追加される 追加される
44. トランザクションに紐づくIDをログに付与する どうやるか • 1トランザクションに紐づくID（リクエストID）をログに紐付ける • APIのレスポンスヘッダにも付与すると良い なぜ • 付与したIDを使ってログを検索すれば1トランザクションの処理を追える ※AWS SDKでも使われている 44
45. トランザクションに紐づくIDをログに付与する • 例: ServletFilterでMDCにリクエストIDを付与する ◦ このFilterを最初に適用する 45
46. トランザクションに紐づくIDをログに付与する • 例: ServletFilterでMDCにリクエストIDを付与する ◦ このFilterを最初に適用する 46 追加される
47. リクエストIDをログに付与すると何が嬉しい？ 47 1回のやりとりに リクエストIDを割当 クライアント サーバ
48. リクエストIDをログに付与すると何が嬉しい？ 48 1回のやりとりに リクエストIDを割当 リクエストIDを レスポンスヘッダに クライアント サーバ
49. リクエストIDをログに付与すると何が嬉しい？ 49 ログ
50. リクエストIDをログに付与すると何が嬉しい？ 50
51. リクエストIDをログに付与すると何が嬉しい？ 51
52. リクエストIDをログに付与すると何が嬉しい？ 52 リクエストIDはHoge
53. リクエストIDをログに付与すると何が嬉しい？ 53 リクエストIDはHoge リクエストIDはHoge
54. リクエストIDをログに付与すると何が嬉しい？ 54 大量のログがあっても 特定トランザクションのログだけ調べられる
55. 問題の原因や回復手段を書く • ログ出力の良くない例 ◦ 「予期せぬエラーが発生しました」 ◦ 「エラーが発生しました」 • どうすればよいのか対処しやすい 55
56. 良くないログを直してみる 予期せぬエラーが発生した IOエラーが発生した IOエラーが発生し、決済に失敗した ◦◦に通信を試みましたが接続に失敗したので 決済は行われませんでした ◦◦に通信を試みましたが接続に失敗したので 決済は行われませんでした。◦◦の接続先情報を確認してください 56
57. 良くないログを直してみる 予期せぬエラーが発生した IOエラーが発生した IOエラーが発生し、決済に失敗した ◦◦に通信を試みましたが接続に失敗したので 決済は行われませんでした ◦◦に通信を試みましたが接続に失敗したので 決済は行われませんでした。◦◦の接続先情報を確認してください 57
58. 良くないログを直してみる 予期せぬエラーが発生した IOエラーが発生した IOエラーが発生し、決済に失敗した ◦◦に通信を試みましたが接続に失敗したので 決済は行われませんでした ◦◦に通信を試みましたが接続に失敗したので 決済は行われませんでした。◦◦の接続先情報を確認してください 58
59. 良くないログを直してみる 予期せぬエラーが発生した IOエラーが発生した IOエラーが発生し、決済に失敗した ◦◦に通信を試みましたが接続に失敗したので 決済は行われませんでした ◦◦に通信を試みましたが接続に失敗したので 決済は行われませんでした。◦◦の接続先情報を確認してください 59
60. 良くないログを直してみる 予期せぬエラーが発生した IOエラーが発生した IOエラーが発生し、決済に失敗した ◦◦に通信を試みましたが接続に失敗したので 決済は行われませんでした ◦◦に通信を試みましたが接続に失敗したので 決済は行われませんでした。◦◦の接続先情報を確認してください 60
61. 良くないログを直してみる 予期せぬエラーが発生した IOエラーが発生した IOエラーが発生し、決済に失敗した ◦◦に通信を試みましたが接続に失敗したので 決済は行われませんでした ◦◦に通信を試みましたが接続に失敗したので 決済は行われませんでした。◦◦の接続先情報を確認してください 61
62. 問題の原因や回復手段を書く • Slf4jの引数の一番最後を例外にしておくと スタックトレースが出力される ◦ SLF4JのFAQに書いてある 62
63. 問題の原因や回復手段を書く • Slf4jの引数の一番最後を例外にしておくと スタックトレースが出力される ◦ SLF4JのFAQに書いてある 63
64. 出力するログは自分の言葉で書こう 特にアプリケーションのドメインに関わる部分 64
65. 出力するログは自分の言葉で書こう 特にアプリケーションのドメインに関わる部分 65
66. 出力するログは自分の言葉で書こう • アプリケーションのドメインに関わる単語でログを書こう • 例外からメッセージが帰ってこない可能性がある • スタックトレースが出力されれば十分 ◦ 例外のメッセージも含まれている 66
67. 長い・大きいログは出さない • Ex. ◦ 大きなHTTPリクエスト・レスポンス ◦ ファイルの中身 • 長い・大きいメッセ―ジは読むのが難しい • ログの量やサイズはコストに跳ね返る 67
68. おわりに 68
69. ログ以外の手段 • 運用を支えるための手段はログだけではない ◦ メトリクス・分散トレーシングもある • 耐障害性の高いアプリケーションを作ろう 69
70. まとめ • 障害をゼロにすることは難しい • 運用を支える手段は色々ある • ログは調査時間を減らすためのツール • より有益なログを出して「運用を支えよう」 • もっとログのベストプラクティスが知りたいなら ◦ Optimal Loggingをどうぞ 70