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