Upgrade to Pro — share decks privately, control downloads, hide ads and more …

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

Masaya Saito
November 23, 2019

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

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

Masaya Saito

November 23, 2019
Tweet

Other Decks in Programming

Transcript

  1. 運用を支えるための
    ログを出すには
    どうするか?
    斎藤将也

    View Slide

  2. 自己紹介
    ● 無職
    ● 前職ではアプリケーションエンジニア
    ○ SaaSとして動くSpring Bootで書かれたサーバーサイドの開発と運用
    ● 仕事で使ってたツール
    ○ Spring Boot/Spring MVC
    ○ Slf4j + Logback
    ○ AWS, CloudWatch Logs
    ○ Docker, AWS ECS
    2

    View Slide

  3. アジェンダ
    ● なぜログを出力するか
    ● どこでログを出力するか
    ● どのようなログを出力するか
    ● ログでなにを出力するか
    ● ログ以外の手段
    ● まとめ
    3

    View Slide

  4. なぜログを出力するのか
    4

    View Slide

  5. 運用では色々なことが起きる
    5

    View Slide

  6. 運用では色々なことが起きる
    6
    ユーザからの問い合わせ
    エラー/バグ
    パフォーマンスダウン

    View Slide

  7. 運用では色々なことが起きる
    ● 色々なことが起きる
    ○ バグ
    ○ 問い合わせ
    ○ パフォーマンス劣化
    ● 障害は必ず起きる
    ○ 100%の可用性はありえない
    ● でも出来る限りサービスを提供したい
    ○ 障害の調査時間・復旧時間を短くして機会損失を減らす
    7

    View Slide

  8. じゃあどうするか
    ● 高い信頼性を持つアプリケーションを作る
    ● モニタリングで調査・復旧時間を短くする
    8

    View Slide

  9. じゃあどうするか
    ● 高い信頼性を持つアプリケーションを作る
    ● モニタリングで調査・復旧時間を短くする
    今日の話
    ● 調査・復旧時間を減らすためにログにどんな工夫をするべきか
    9

    View Slide

  10. そもそもログってなんだっけ
    ● 「いつ」を示すタイムスタンプを持つ
    ● 「その時どういう動作を行ったか」を示す
    ○ 「17時、決済サービスとの通信は正常に終了した」
    ○ 「18時、決済サービスがダウンしている」
    ● 当時の動作からシステムがどういう状態だったかが分かる
    10

    View Slide

  11. どんな場面でログを読むのか
    ● 障害発生時
    ● ユーザサポート
    ● 開発・テスト
    などなど
    11

    View Slide

  12. ログを出力するのは誰かに読んでもらうため
    ● ログを読む人はシステムによって様々
    ○ 自分以外の開発者
    ○ 運用してる人
    ○ ユーザサポート
    ○ 半年後の自分
    ● 意図の伝わるログを出力しよう
    12

    View Slide

  13. どんなログがいいか?
    ● 5W1Hがわかるログが良い
    ○ 「いつ」「だれが」「なぜ」「何が起きて」「何をすれば良いのか」
    ○ 特にエラーログ
    ● アプリケーションの特性・要件・コンテキストに合わせて
    トラブルシューティングなどで必要なログを書こう
    ○ 「ユーザID 〇〇のユーザの注文を〇〇 Payで決済した」
    ○ 「ユーザがログインに失敗した」
    13

    View Slide

  14. 運用を支えるログとは
    ● 「運用を支える」
    ○ 復旧時間や調査時間を出来るだけ短くする
    ● ログ
    ○ ある時点でのシステムの状態
    運用を支えるログとは
    ➔ システムで起きた問題や状況を
    運用している人間が
    調査に掛かる時間を短くするログ
    14

    View Slide

  15. どこでログを出力するか
    15

    View Slide

  16. 関数の最初でログを出力しない
    ● やりがち
    ● どうしてもほしいならDEBUGレベルで
    ● 関数の最後に、どういう結果になったかをログに吐く方がいい
    ○ 最初に吐くより情報量が多い
    ○ 関数の最初: 「ユーザを作成しようとしています。」
    ○ 関数の最後:「○○というユーザIDのユーザを作成しました」
    ● AOPで出力するログはオススメしない
    ○ ログ量が多くなってノイズになりがち
    ○ 業務的な情報がないログが出がち
    ○ 個人情報がログに出てしまったりも・・・
    16

    View Slide

  17. 関数の最初でログを出力しない
    おすすめしない例
    17

    View Slide

  18. 関数の最初でログを出力しない
    おすすめしない例
    18

    View Slide

  19. 関数の最初でログを出力しない
    まだマシ例
    19

    View Slide

  20. 関数の最初でログを出力しない
    良い例
    20

    View Slide

  21. AOPで出力するログって?
    ● Aspect指向プログラミング(AOP)で出力するログ
    ○ サンプルでよく見るやつ
    ● 出すなら何か見たいものだけに絞る必要がある
    21

    View Slide

  22. ログは多すぎてはいけない
    ● Ex.
    ○ 繰り返し回数の多いループ内でのログ
    ○ そもそも単純に吐いてるログが多い
    ● ログが多いと読むのに時間がかかる
    ● ディスクを食いつぶしたり・・・
    ○ 別の障害に繋がる可能性も・・・?
    ● ログを保持するコストに跳ね返る
    22

    View Slide

  23. システム間通信の結果はログに
    なぜ
    ● システム間通信をする部分には障害が起きやすい
    ● どういう依存があるかもログから分かる
    ● 外部システム起因の障害の切り分けに使える
    23

    View Slide

  24. システム間通信の結果はログに
    ● INFOレベルで出力する
    ● 次のような内容が書かれていると良い
    ○ どういうAPIを呼び出したか?
    ○ どういうステータスコードが帰ってきたか?
    ○ どの程度処理時間がかかったか?
    24

    View Slide

  25. システム間通信の結果はログに
    ● 通信ライブラリのインターセプタなどで書く
    ○ Ex. okhttp-logging-interceptor
    25

    View Slide

  26. システム間通信の結果はログに
    ● 通信ライブラリのインターセプタなどで書く
    ○ Ex. okhttp-logging-interceptor
    ● 通信結果の記録にリクエストIDを出力しておくと便利
    ○ リクエストIDについては後述
    ○ どう便利なのかについても後述
    26

    View Slide

  27. 通信の結果をログに吐くだけでいい?
    通信を行ったビジネスロジック側にもログは必要
    なぜ
    ● 通信ライブラリのログ出力部分では
    ERRORなのかINFOなのか判断できない
    ● ビジネスロジック側ならもっと情報が出力できる
    ○ 「○○というユーザのポイントの発行に失敗しました」
    27

    View Slide

  28. どのようなログを出力するか
    28

    View Slide

  29. ログレベルを使い分ける
    ログレベル周りでありがちなこと
    ● ログレベルと出力している内容が合ってない
    ○ すぐに対応が必要なログも見逃してしまう
    ○ 障害時の初期対応はエラーログだけ見たいのに・・・
    ● フレームワークのDEBUGログが出ている
    本当は状況に合わせて必要なログを読みたい
    29

    View Slide

  30. ログレベルを使い分ける
    ● 適切にログレベルを選ぶ
    ● 基本出力するログレベルはINFOレベル以上にする
    ○ DEBUG以下はフレームワークのログとかも出てしまう
    ● INFOで出力する例
    ○ ビジネスロジックで発生したイベントの結果
    ○ 外部通信の結果
    ○ バッチ処理の周期的なサマリ
    ■ 「何件処理しました。そのうち何件は失敗しました」
    ○ など
    30

    View Slide

  31. ログレベルを使い分ける
    ● ERROR
    ○ 運用の継続が困難な問題が発生した時
    ○ 人の介入が必要な場合は出力する
    ■ Ex. データベースの名前解決に失敗
    ● WARN
    ○ 一時的な問題が発生した時や予期せぬ状態
    ■ Ex. リトライ可能な問題, 一時的なキャパシティ不足
    ● INFO
    ○ 基本的なログのレベル
    ● DEBUG
    ○ デバッグの為に使われるログ
    31

    View Slide

  32. 構造化されたログで出力する
    どうやるか
    ● JSONでログを出力しよう
    なぜ
    ● 次の用途で使いやすい
    ○ 分析
    ○ アラート
    ○ 検索
    32

    View Slide

  33. 構造化されたログで出力する
    ● JSONなど解析しやすい形でログを出力しよう
    ● JSONならネイティブにサポートされているサービス・ツールがある
    ○ CloudWatch Logsなど
    ● logback(slf4jの実装)でJSON出力するなら
    ○ logback-ext-json-classic
    ○ logstash/logstash-logback-encoder
    33

    View Slide

  34. 構造化されたログで出力する
    ● JSONで出力したときの例
    ○ logstash-logback-encoderを使用
    34

    View Slide

  35. JSONでログ出力すると何が嬉しいのか
    ● JSONのフィールドで検索できる
    例:
    ● エラーログを検索
    ● 特定のAPIのログだけ検索
    ● 1トランザクションで発生したログを検索
    ○ リクエストIDを使う(後述)
    ● 500エラーのトランザクションだけ検索
    35

    View Slide

  36. ログでなにを出力するか
    36

    View Slide

  37. ログを読もう
    なぜ
    ● 運用していると必ず読む機会が発生する
    ● ログを見直す機会になる
    ○ 分かりにくいログを直すチャンス
    ○ 足りないログを足すチャンス
    37

    View Slide

  38. ログを読もう
    ● 障害が起きた時はもちろん
    ● 開発中に問題が起きた時も
    ● テストが落ちた時も
    ○ デバッガを出来るだけ使わない
    ● ログから問題の原因の特定が出来ないなら
    ログを直すことを考えよう
    38

    View Slide

  39. ログにコンテキストを付与する
    コンテキストを付与すると
    ● JSONログにその時の状況(コンテキスト)を表すフィールドが追加される
    なぜ
    ● その時どういう状況であったかを把握しやすくするため
    ○ 「Who」や「Why」を追加する
    39

    View Slide

  40. ログにコンテキストを付与する
    ● どうやってコンテキストを付与するか
    ○ MDC(Mapped Diagnostic Context)
    ■ 診断コンテキスト from logback
    ○ logstash-logback-encoder(今回は話しません)
    ● 付与する内容例
    ○ ユーザID
    ○ リクエストされたパス
    ○ リクエストID(後述)
    40

    View Slide

  41. MDCの使い方
    ● 処理をtry-finallyで囲む形 put/removeする
    ● 必ずfinallyでremove
    41

    View Slide

  42. ログにコンテキストを付与する
    ● 例: MDCInsertingServletFilter
    ○ リクエストされたURL/URIやUserAgentなどが付与される
    42

    View Slide

  43. ログにコンテキストを付与する
    ● 例: MDCInsertingServletFilter
    ○ リクエストされたURL/URIやUserAgentなどが付与される
    43
    一部省略してます
    追加される
    追加される

    View Slide

  44. トランザクションに紐づくIDをログに付与する
    どうやるか
    ● 1トランザクションに紐づくID(リクエストID)をログに紐付ける
    ● APIのレスポンスヘッダにも付与すると良い
    なぜ
    ● 付与したIDを使ってログを検索すれば1トランザクションの処理を追える
    ※AWS SDKでも使われている
    44

    View Slide

  45. トランザクションに紐づくIDをログに付与する
    ● 例: ServletFilterでMDCにリクエストIDを付与する
    ○ このFilterを最初に適用する
    45

    View Slide

  46. トランザクションに紐づくIDをログに付与する
    ● 例: ServletFilterでMDCにリクエストIDを付与する
    ○ このFilterを最初に適用する
    46
    追加される

    View Slide

  47. リクエストIDをログに付与すると何が嬉しい?
    47
    1回のやりとりに
    リクエストIDを割当
    クライアント サーバ

    View Slide

  48. リクエストIDをログに付与すると何が嬉しい?
    48
    1回のやりとりに
    リクエストIDを割当
    リクエストIDを
    レスポンスヘッダに
    クライアント サーバ

    View Slide

  49. リクエストIDをログに付与すると何が嬉しい?
    49
    ログ

    View Slide

  50. リクエストIDをログに付与すると何が嬉しい?
    50

    View Slide

  51. リクエストIDをログに付与すると何が嬉しい?
    51

    View Slide

  52. リクエストIDをログに付与すると何が嬉しい?
    52
    リクエストIDはHoge

    View Slide

  53. リクエストIDをログに付与すると何が嬉しい?
    53
    リクエストIDはHoge
    リクエストIDはHoge

    View Slide

  54. リクエストIDをログに付与すると何が嬉しい?
    54
    大量のログがあっても
    特定トランザクションのログだけ調べられる

    View Slide

  55. 問題の原因や回復手段を書く
    ● ログ出力の良くない例
    ○ 「予期せぬエラーが発生しました」
    ○ 「エラーが発生しました」
    ● どうすればよいのか対処しやすい
    55

    View Slide

  56. 良くないログを直してみる
    予期せぬエラーが発生した
    IOエラーが発生した
    IOエラーが発生し、決済に失敗した
    ○○に通信を試みましたが接続に失敗したので
    決済は行われませんでした
    ○○に通信を試みましたが接続に失敗したので
    決済は行われませんでした。○○の接続先情報を確認してください
    56

    View Slide

  57. 良くないログを直してみる
    予期せぬエラーが発生した
    IOエラーが発生した
    IOエラーが発生し、決済に失敗した
    ○○に通信を試みましたが接続に失敗したので
    決済は行われませんでした
    ○○に通信を試みましたが接続に失敗したので
    決済は行われませんでした。○○の接続先情報を確認してください
    57

    View Slide

  58. 良くないログを直してみる
    予期せぬエラーが発生した
    IOエラーが発生した
    IOエラーが発生し、決済に失敗した
    ○○に通信を試みましたが接続に失敗したので
    決済は行われませんでした
    ○○に通信を試みましたが接続に失敗したので
    決済は行われませんでした。○○の接続先情報を確認してください
    58

    View Slide

  59. 良くないログを直してみる
    予期せぬエラーが発生した
    IOエラーが発生した
    IOエラーが発生し、決済に失敗した
    ○○に通信を試みましたが接続に失敗したので
    決済は行われませんでした
    ○○に通信を試みましたが接続に失敗したので
    決済は行われませんでした。○○の接続先情報を確認してください
    59

    View Slide

  60. 良くないログを直してみる
    予期せぬエラーが発生した
    IOエラーが発生した
    IOエラーが発生し、決済に失敗した
    ○○に通信を試みましたが接続に失敗したので
    決済は行われませんでした
    ○○に通信を試みましたが接続に失敗したので
    決済は行われませんでした。○○の接続先情報を確認してください
    60

    View Slide

  61. 良くないログを直してみる
    予期せぬエラーが発生した
    IOエラーが発生した
    IOエラーが発生し、決済に失敗した
    ○○に通信を試みましたが接続に失敗したので
    決済は行われませんでした
    ○○に通信を試みましたが接続に失敗したので
    決済は行われませんでした。○○の接続先情報を確認してください
    61

    View Slide

  62. 問題の原因や回復手段を書く
    ● Slf4jの引数の一番最後を例外にしておくと
    スタックトレースが出力される
    ○ SLF4JのFAQに書いてある
    62

    View Slide

  63. 問題の原因や回復手段を書く
    ● Slf4jの引数の一番最後を例外にしておくと
    スタックトレースが出力される
    ○ SLF4JのFAQに書いてある
    63

    View Slide

  64. 出力するログは自分の言葉で書こう
    特にアプリケーションのドメインに関わる部分
    64

    View Slide

  65. 出力するログは自分の言葉で書こう
    特にアプリケーションのドメインに関わる部分
    65

    View Slide

  66. 出力するログは自分の言葉で書こう
    ● アプリケーションのドメインに関わる単語でログを書こう
    ● 例外からメッセージが帰ってこない可能性がある
    ● スタックトレースが出力されれば十分
    ○ 例外のメッセージも含まれている
    66

    View Slide

  67. 長い・大きいログは出さない
    ● Ex.
    ○ 大きなHTTPリクエスト・レスポンス
    ○ ファイルの中身
    ● 長い・大きいメッセ―ジは読むのが難しい
    ● ログの量やサイズはコストに跳ね返る
    67

    View Slide

  68. おわりに
    68

    View Slide

  69. ログ以外の手段
    ● 運用を支えるための手段はログだけではない
    ○ メトリクス・分散トレーシングもある
    ● 耐障害性の高いアプリケーションを作ろう
    69

    View Slide

  70. まとめ
    ● 障害をゼロにすることは難しい
    ● 運用を支える手段は色々ある
    ● ログは調査時間を減らすためのツール
    ● より有益なログを出して「運用を支えよう」
    ● もっとログのベストプラクティスが知りたいなら
    ○ Optimal Loggingをどうぞ
    70

    View Slide