ログ収集癖

ログ収集癖   2023/10/27   レバテック開発部  瀬尾光希 

|　© Leverages inc. 2 • 所属 ◦ レバテック開発部／基盤システムグループ  • 経歴
◦ 2021年04月 - 通信事業社に新卒入社  ◦ 2022年07月 - レバレジーズ株式会社に中途入社  • 出身 ◦ 宮崎県宮崎市（陸の孤島育ち）  • 趣味 ◦ ピアノ（演奏／編曲）  ◦ ゲーム、アニメ、漫画  • 最近のトピック ◦ 広島県福山市のふるさと納税でカクレクマノミを買いました  ◦ こいつと一生を過ごす  瀬尾光希（せおこうき）自己紹介自分で描いた卵かけご飯まあまあ美味そう

|　© Leverages inc. 3 今日は何の話？ Node.jsのマイクロサービスを運用していて   • どうロギングすれば運用しやすくなるか  
• そしてどうすればそれを実現できるか   を考えて改善に取り組んだことについての経験談。   なんやそのタイトルは

|　© Leverages inc. 4 目次 • はじめてのDevOpsで得たロギングの勘所   • ロギングのベストプラクティス
  • Node.jsでの実現  • 実現後の世界  • まとめ 

|　© Leverages inc. 5 目次 • はじめてのDevOpsで得たロギングの勘所 • ロギングのベストプラクティス  
• Node.jsでの実現  • 実現後の世界  • まとめ 

|　© Leverages inc. 6 Datadog との出会い（1/2）はじめてのDevOpsで得たロギングの勘所

|　© Leverages inc. 7 • ただログを集めて確認できるサイトだと思ってた ◦ 見づらいなとは思っていたけどこんなもんなんやろな〜と思ってた • ログがアプリのどこで発生していて、どう処理されて表示されているのか知らなかった
◦ ログの表示形式は仕様上決まっていて変更できないものだと思ってた Datadog との出会い（2/2）はじめてのDevOpsで得たロギングの勘所知り合って間もない頃の Datadogちゃんが見せてくれたログ一覧

|　© Leverages inc. 8 ログをよくみる羽目になるはじめてのDevOpsで得たロギングの勘所さまざまな障害対応を通して Datadogで何度もログを確認する日々 …

|　© Leverages inc. 9 • 日々の障害対応が簡単になるような情報を   ロギングしたくなる  → ログは自分を楽にするためのものと気づく
  • ある日Datadog にログメッセージの情報を   認識させる作業を行った  → Datadogでログを分析できることを知る Datadogとロギングのことを知り始めるはじめてのDevOpsで得たロギングの勘所 Datadogが取得したログをパースする処理の一部 Filterでサービス毎に限定しそれぞれ処理しているログの入口ログの流れ

ログ周りがベストな状態になれば障害対応でもっと楽できるんでは …？ログってもっと分析できるんでは …？

|　© Leverages inc. 11 ログのことが気になって仕方なくなったはじめてのDevOpsで得たロギングの勘所 Datadogのログ分析をちゃんと活かしたい… ログが気になって仕事に手がつかなくなる瀬尾ログをいい感じにしたい… そして…

|　© Leverages inc. 12 ※実話です

• Node.jsでの実現  • 実現後の世界  • まとめ 

|　© Leverages inc. 14 • アプリの動作を記録する   • 問題の発生時にトラブルシューティングをする  
• アプリの問題を発生前に見つけて改善する   • システムの利用状況を統計する   • 監査  • プロファイル  • …  ロギングの目的ロギングのベストプラクティス目的が明確にあるなら、それ相応の手段を考えられるじゃない！

|　© Leverages inc. 15 1. ライブラリを使おう！ ◦ ログに出すべき情報を自動で出してくれるようなものがあります 2. 正しいログレベルをつけよう！
◦ 用途ごとに適切な設定をすべし（ INFO, WARN, ERROR, …次ページでちょっと説明） 3. 集中管理できる場所に集めよう！ ◦ うちにはもうDatadogがあるね 4. 構造化されたフォーマットでロギングしよう！ ◦ ログは膨大な量になるので、人間より機械が読みやすいことの方が優先 ◦ Datadogだと、JSON形式のログは自動でパースされる 5. ログメッセージと共に Context を記録しよう！ ◦ ログを読むときの目的を考えて、それ応じた関連情報を含めておきたい 6. 実行ごとに一意な識別子（ Request ID）を含めよう！ ◦ リクエストを同時に処理するとログが混在してどれがどれだかわからんなる … ロギングのベストプラクティス（受け売り ∧ 抜粋）ロギングのベストプラクティス

|　© Leverages inc. 16 ログレベルの目安（諸説あり？）ロギングのベストプラクティスログレベル説明備考 FATAL
システムの終了を伴う致命的なエラーを記録   Goで出すとログ出力後   os.Exit(1) するらしい   ERROR 回復可能なプログラム実行中のエラーを記録   対応が必要なもの   WARN エラーになる可能性のあるイベントを記録   対応不必要だが   キャッチしときたいもの   INFO 期待されるイベントを記録（開始/終了やビジネスロジック）   基本はこのレベル   DEBUG なんでも記録  障害対応とかで確認したい細々としたもの   強 💥

|　© Leverages inc. 17 で、うちのシステムは… ロギングのベストプラクティス 1. ライブラリを使おう！ ◦ 2.
正しいログレベルをつけよう！ ◦ 3. 集中管理できる場所に集めよう！ ◦ 4. 構造化されたフォーマットでロギングしよう！ ◦ 5. ログメッセージと共に Context を記録しよう！ ◦ 6. 実行ごとに一意な識別子（ Request ID）を含めよう！ ◦ 微妙… そらこんな顔なるわ

|　© Leverages inc. 18 決意ロギングのベストプラクティス俺がやるしか……

|　© Leverages inc. 19 アツい修行の日々… ロギングのベストプラクティス ♪ ロッキーのテーマもうこれで終わってもいい ───

  • Node.jsでの実現 • 実現後の世界  • まとめ 

|　© Leverages inc. 21 もともと抱えていた課題   • 別々のリクエストに紐づくログが混在してしまう   •
安直に ID をバケツリレーするにも Clean Architecture が邪魔をして大変   どこからでも簡単に取得できるような Request ID を作れないものか…       　　　　　　　　　　　　─── そして２人は出会うマジで早く実現したかった Request ID Node.jsでの実現 Controller Usecase Adapter logger.info(requestId) Request ID Request ID Request ID 遠いわ！！

|　© Leverages inc. 22 • Node.js が提供する API（Stable）   •
非同期処理においてスレッドローカル変数   のようなものを実現　  AsyncLocalStorage との邂逅 Node.jsでの実現公式ドキュメントより引用実行ごとにストレージを作り、使いまわしたい情報を格納しておける！

|　© Leverages inc. 23 AsyncLocalStorage の簡単な使い方 Node.jsでの実現 run() 中で実行される非同期関数内では、 getStore()
によっていつでも “hoge” を取得できる便利〜!!  君の好きなオブジェクトも入るよ！

|　© Leverages inc. 24 AsyncLocalStorage の仕組みを簡単に解説（1/2） Node.jsでの実現 Node.jsで非同期処理を実行するとき "非同期リソース" が生成され、実行はそれに紐付けられる。
  非同期リソースは、自分の実行IDと呼び出し元の非同期リソースIDを持つ。   非同期処理A  非同期リソースA ポチッ  • Trigger ID: X • Execution ID: A • Trigger ID: 0 (Nodejs) • Execution ID: X 非同期処理A実行！そして非同期処理B呼び出し… 非同期リソースB • Trigger ID: A • Execution ID: B 非同期処理B実行！非同期リソースはクラスのインスタンスのようなものかも 

|　© Leverages inc. 25 AsyncLocalStorage の仕組みを簡単に解説（2/2） Node.jsでの実現 AsyncLocalStorage はカスタム非同期リソースを生成して、指定した値をバケツリレーしてくれる。  
非同期処理A  カスタムリソースA ポチッ  • Trigger ID: X • Execution ID: A • Store: “hoge”   • Trigger ID: A • Execution ID: B • Store: “hoge” 非同期処理B実行！ありがとねぇ  AsyncLocalStorageで実行 • Trigger ID: 0 (Nodejs) • Execution ID: X • Store: “hoge”  非同期処理A実行！そして非同期処理B呼び出し… 裏でバケツリレーをやってくれるカスタムリソースB

|　© Leverages inc. 26 ロギングのライブラリ Node.jsでの実現がおすすめ  • JSON形式のログ出力 •
hostname, pid, UTC を自動出力 • ロギング時にトリガーする関数を設定できる • オブジェクトの自動プロパティ化   • 軽いらしい  • プロパティを指定して個人情報などを   伏せ字にすることも可能 

|　© Leverages inc. 27 つまり… Node.jsでの実現 1. Controller で Request
ID を生成  2. Controller から AsyncLocalStorage 内で Usecase を呼び出す  3. Usecase 内の Pino によるロギングはその度に AsyncLocalStorage から Request ID を取得する  4. Pino にはロギング直前の Object を（適当に）渡しておく   • ログの構造化  • Request ID の付与   • Context の付与   が一気に実現 

|　© Leverages inc. 28 俺自身が best practice… になることだ Node.jsでの実現 1.
ライブラリを使おう！ ◦ 2. 正しいログレベルをつけよう！ ◦ 3. 集中管理できる場所に集めよう！ ◦ 4. 構造化されたフォーマットでロギングしよう！ ◦ 5. ログメッセージと共に Context を記録しよう！ ◦ 6. 実行ごとに一意な識別子（ Request ID）を含めよう！ ◦ ログおじいさんとログおばあさん

AsyncLocalStorage + Pino 銀の弾丸はここにあったんやぁ…

|　© Leverages inc. 31 構造化ロギングによる変化｜Before 実現後の世界 • ログのすべてがメッセージフィールドに存在   •
ログメッセージを頑張ってパースしてhostname などの情報を得ていた   • Datadog が発報するアラートに付加情報が少なかった  • トラブルシューティングの際は、ログの取捨選択を職人技で行っていた   • ログ分析によるメトリクスの作成が難しかった   • 見づらい  ログには Msg のみこの Grok で頑張ってパースする   （しかもこれでは全ての要素はパースできてない）   パース結果  

|　© Leverages inc. 32 構造化ロギングによる変化｜After✌ 実現後の世界 Request ID Msg Name
パースを頑張らなくても（重要）   ログの要素がDatadog側で全てパースされている状態全てのログにRequest IDが含まれていてめっちゃ検索しやすい

|　© Leverages inc. 34 • ログにも目的があって、そのための設計が大事だよ！   • ログにもベストプラクティスがあるよ！  
• Node.js の AsyncLocalStorage は便利だよ！   • ロギングライブラリの Pino おすすめだよ！   • Datadog のダッシュボードいじり楽しいよ！   まとめ

ログ収集癖おしまい 

|　© Leverages inc. 36 参考資料 • Logging Best Practices: The
13 You Should Know • ロギングベストプラクティス • ロギングベストプラクティスの個人的所感 • マイクロサービスのロギングベストプラクティス • 今さら聞けないログの基本と設計指針 • 11 Best Practices for Logging in Node.js • Asynchronous context tracking｜Node.js v21.1.0 documentation • JavaScriptの非同期処理をじっくり理解する (4) AbortSignal, Event, Async Context • Async Hooksを使ってリクエストごとに一意な IDをログに出力する

ログ収集癖

ログ収集癖

More Decks by Tech Leverages

Other Decks in Technology

Featured

Transcript