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

by Masaya Saito

Slide 1

Slide 1 text

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

Slide 2

Slide 2 text

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

Slide 3

Slide 3 text

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

Slide 4

Slide 4 text

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

Slide 5

Slide 5 text

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

Slide 6

Slide 6 text

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

Slide 7

Slide 7 text

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

Slide 8

Slide 8 text

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

Slide 9

Slide 9 text

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

Slide 10

Slide 10 text

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

Slide 11

Slide 11 text

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

Slide 12

Slide 12 text

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

Slide 13

Slide 13 text

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

Slide 14

Slide 14 text

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

Slide 15

Slide 15 text

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

Slide 16

Slide 16 text

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

Slide 17

Slide 17 text

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

Slide 18

Slide 18 text

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

Slide 19

Slide 19 text

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

Slide 20

Slide 20 text

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

Slide 21

Slide 21 text

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

Slide 22

Slide 22 text

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

Slide 23

Slide 23 text

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

Slide 24

Slide 24 text

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

Slide 25

Slide 25 text

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

Slide 26

Slide 26 text

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

Slide 27

Slide 27 text

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

Slide 28

Slide 28 text

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

Slide 29

Slide 29 text

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

Slide 30

Slide 30 text

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

Slide 31

Slide 31 text

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

Slide 32

Slide 32 text

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

Slide 33

Slide 33 text

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

Slide 34

Slide 34 text

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

Slide 35

Slide 35 text

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

Slide 36

Slide 36 text

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

Slide 37

Slide 37 text

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

Slide 38

Slide 38 text

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

Slide 39

Slide 39 text

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

Slide 40

Slide 40 text

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

Slide 41

Slide 41 text

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

Slide 42

Slide 42 text

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

Slide 43

Slide 43 text

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

Slide 44

Slide 44 text

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

Slide 45

Slide 45 text

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

Slide 46

Slide 46 text

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

Slide 47

Slide 47 text

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

Slide 48

Slide 48 text

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

Slide 49

Slide 49 text

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

Slide 50

Slide 50 text

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

Slide 51

Slide 51 text

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

Slide 52

Slide 52 text

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

Slide 53

Slide 53 text

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

Slide 54

Slide 54 text

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

Slide 55

Slide 55 text

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

Slide 56

Slide 56 text

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

Slide 57

Slide 57 text

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

Slide 58

Slide 58 text

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

Slide 59

Slide 59 text

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

Slide 60

Slide 60 text

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

Slide 61

Slide 61 text

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

Slide 62

Slide 62 text

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

Slide 63

Slide 63 text

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

Slide 64

Slide 64 text

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

Slide 65

Slide 65 text

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

Slide 66

Slide 66 text

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

Slide 67

Slide 67 text

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

Slide 68

Slide 68 text

おわりに 68

Slide 69

Slide 69 text

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

Slide 70

Slide 70 text

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