技術戦略部 SREグループのカンタンです。
弊社が提供しているタクシーアプリ「GO」、タクシーデリバリーアプリ「GO Dine」、法人向けサービス「GO BUSINESS」の実現に当たって多数のマイクロサービスを構築することになりました。
マイクロサービスの増加に伴って、ログの出力フォーマット、収集方法、閲覧方法の共通化がより大事になってきました。本記事では弊社で考えたログフォーマットを紹介させていただきます。
課題
お客様からのお問い合わせ対応、障害の原因調査、パフォーマンス管理、サーバ処理の記録としてなど、ログは様々な用途で利用されていてシステム開発にあたりとても大事なデータです。マイクロサービス化に伴って全体のシステムが複雑になるため、ログ出力の際に様々なシステム特性を考慮する必要があります:
弊社ではこういった複雑なシステム構成を考慮した共通ログフォーマットを定義して、一部のサービスに導入しています。以下のポイントに特に注目しています:
- APIサーバはREST、gRPC、GraphQLなど利用されているプロトコルと関係なく同様に扱ってログ出力すること
- サーバ処理の中のDBへのクエリーと他のサービスへのHTTPリクエストはアウトバウンドリクエストとして同様に扱ってログ出力すること
- API処理も非同期処理もバッチ処理も、処理の種類と関係なく同様に扱ってログ出力できること
- エラーが発生した際のエラーフォーマットも定義すること
- 複数のサービスを跨いだ処理のログを追えるように、分散トレーシング情報をログに残すこと
- サービス固有情報をログに残せること
ログフォーマット
定義したフォーマットは以下の通りになります。MoT TechTalk #6 タクシーデリバリーアプリ「GO Dine」を支えるバックエンドで口頭で軽く説明させていただきましたので興味のある方は是非ご覧ください。
項目を一つずつ解説していきます！
{ // 基本情報 "type": "log", "level": "info", "time": "2021-10-20T01:10:34.496135682Z", "msg": "sample message", "request_id": "7afc560a76a6ebc3f36ff92d06890bdf", // フィンガープリント "fp": { ... }, // インバウンドリクエスト "in_request": { ... }, // サービス固有情報 "local_ctx": { ... }, // アウトバウンドリクエスト "out_request": { ... }, // エラー情報 "error": { ... }, }
基本情報
// 基本情報 "type": "log", "level": "info", "time": "2021-10-20T01:10:34.496135682Z", "msg": "sample message", "request_id": "7afc560a76a6ebc3f36ff92d06890bdf",
全てのログに必ず残している基本情報になります。
フィンガープリント
"fp": { "id": "9caec624-23ab-4141-b725-cb08da489d5d", "ct": "2021-10-20T01:10:34.42307788Z" },
フィンガープリント fp は処理を開始した時に生成されるユニークID idと処理開始日時 ct を持っています（APIリクエストを受けた直後、またはバッチ処理を始めた直後生成されます)。その処理と関連する全てのログが同じフィンガープリントを持つことで、あるリクエストと関連する全てのログを簡単に抽出できます。
分散トレーシングのために、エンドクライアントから発生したリクエストと関連する全ての処理に同じリクエストID request_id を渡すことが一般的だと思いますが、同じリクエストID処理の中で複数APIサブリクエストがあった場合、一つ一つのサブリクエストログを区別できるように定義しています。
また、特定なログをピンポイントで削除する必要があった場合、フィンガープリントidと基本情報に入っている time フィールドの組み合わせで削除対象のログに簡単に絞れます。
インバウンドリクエスト
"in_request": { "type": "sample type", "service": "sample service", "method": "sample method", "start_time": "2021-10-20T01:10:34.469335554Z", "duration_ms": 40.309, "status_code": "OK", "body": { ... } "ctx": { "ua": "sample ua", "values": { ... } }, },
サーバで処理中のAPIリクエスト情報をin_requestフィールドに入れています。
ログ閲覧する時にAPIリクエストと同様に扱えるように、バッチ処理の場合もこの情報を残しています（ body , ctx など一部情報が存在しない場合もあります）
サービス固有情報
"local_ctx": { ... },
local_ctx は情報を自由に残してもいいフィールドになります。個人情報を残さないように注意する必要があります。処理中のリソースID、エンドユーザのIDなど、ログ検索する時に役に立つ情報を残すイメージです。
アウトバウンドリクエスト
"out_request": { "type": "sample type", "service": "sample service", "method": "sample method", "start_time": "2021-10-20T01:10:34.469352098Z", "duration_ms": 26.775, "status_code": "OK", "body": { ... }, "ctx": { "ua": "sample server A/1.0.0", "values": { ... } }, "details": { "deadline": "2021-10-20T01:10:49.469341116Z" } },
他のサービスにAPIリクエストを投げたりDBにクエリーを実行したりする時のログをout_requestフィールドに残します。DBとAPIリクエストを同様に扱うことで、ログ閲覧する時に例えばDBのクエリー実行時間とAPIサービスへのリクエスト時間を並べて比較できたりして見やすいです。
エラー情報
"error": { "type": "INVALID_ARGUMENT", "domain": "SAMPLE_DOMAIN", "code": "SampleErrorCode", "message": "sample error message", "details": { ... }, "wrapped_error": { ... } },
エラーが発生した時にエラー情報を error フィールドに決まったフォーマットで残すようにしています。gRPCの詳細エラーモデルをベースにフォーマットを決めています。
参考:
- https://github.com/googleapis/googleapis/blob/master/google/rpc/status.proto
- https://github.com/googleapis/googleapis/blob/master/google/rpc/error_details.proto
サンプルとユースケース
これからはgRPC、REST、GraphQL APIリクエスト、DBクエリー、非同期処理などのサンプルログとユースケースを一部紹介したいと思います！実データではないため、あらかじめご了承ください。
サンプル
APIリクエスト
このサンプルでは、gRPCサーバがリクエストを受けて、RDBからデータを取得して、他のAPIサービスにHTTPリクエストを投げて結果を返しています。JSONの中に解説コメントを残しています。
// -------------------- // 全体の流れ： // - gPRCリクエストを受けて、リクエスト情報を抽出する // - RDBから情報を2回取得してログを残す // - 他のAPIサービスにリクエストを投げてログを残す // - レスポンスを返す前にリクエストログを残す // -------------------- // 一つ目のRDBリクエスト { "type": "log", "level": "info", "time": "2021-10-20T04:38:57.463749695Z", "msg": "sql query", // リクエストIDとフィンガープリントは変化しない "request_id": "4ea4ba99-b89a-9669-b031-430790670b70", "fp": { "id": "b4ed2c40-cc9d-4d79-858c-2510beb7afbf", "ct": "2021-10-20T04:38:57.462385582Z" }, "in_request": { // gRPCリクエスト情報 "type": "grpc", "service": "UserService", "method": "GetUser", "start_time": "2021-10-20T04:38:57.462391602Z", "ctx": { "ua": "grpc-node/1.24.7 grpc-c/8.0.0 (osx; chttp2; ganges)" } }, "local_ctx": { // サービス固有情報 "user_id": "4661c5c5-7b6e-4741-905a-8afec78f2d07" }, "out_request": { // SQL文、実行時間などが残っています "type": "sql", "start_time": "2021-10-20T04:38:57.462476337Z", "duration_ms": 1.252, "body": "SELECT id, name FROM users WHERE id = $1" } } // 2つ目のRDBリクエスト { "type": "log", "level": "info", "time": "2021-10-20T04:38:57.464545105Z", "msg": "sql query", // リクエストIDとフィンガープリントは変化しない "request_id": "4ea4ba99-b89a-9669-b031-430790670b70", "fp": { "id": "b4ed2c40-cc9d-4d79-858c-2510beb7afbf", "ct": "2021-10-20T04:38:57.462385582Z" }, "in_request": { // gRPCリクエスト情報 "type": "grpc", "service": "UserService", "method": "GetUser", "start_time": "2021-10-20T04:38:57.462391602Z", "ctx": { "ua": "grpc-node/1.24.7 grpc-c/8.0.0 (osx; chttp2; ganges)" } }, "local_ctx": { // サービス固有情報 "user_id": "4661c5c5-7b6e-4741-905a-8afec78f2d07" }, "out_request": { // SQL文、実行時間などが残っています "type": "sql", "start_time": "2021-10-20T04:38:57.463885656Z", "duration_ms": 0.647, "body": "SELECT * FROM user_settings WHERE user_id = $1" } } // 他のサービスへのHTTPリクエスト { "type": "log", "level": "info", "time": "2021-10-20T04:38:57.488579457Z", "msg": "http client request", // リクエストIDとフィンガープリントは変化しない "request_id": "4ea4ba99-b89a-9669-b031-430790670b70", "fp": { "id": "b4ed2c40-cc9d-4d79-858c-2510beb7afbf", "ct": "2021-10-20T04:38:57.462385582Z" }, "in_request": { // gRPCリクエスト情報 "type": "grpc", "service": "UserService", "method": "GetUser", "start_time": "2021-10-20T04:38:57.462391602Z", "ctx": { "ua": "grpc-node/1.24.7 grpc-c/8.0.0 (osx; chttp2; ganges)" } }, "local_ctx": { // サービス固有情報 "user_id": "4661c5c5-7b6e-4741-905a-8afec78f2d07" }, "out_request": { // 叩いたAPI情報、リクエスト時間が残っています "type": "http", "service": "OrderService", "method": "GET /v1/users/4661c5c5-7b6e-4741-905a-8afec78f2d07/orders", "start_time": "2021-10-20T04:38:57.464601612Z", "duration_ms": 23.971 } } // 最後に、リクエストログ { "type": "log", "level": "info", "time": "2021-10-20T04:38:57.488636837Z", "msg": "unary call ended with code OK", // リクエストIDとフィンガープリントは変化しない "request_id": "4ea4ba99-b89a-9669-b031-430790670b70", "fp": { "id": "b4ed2c40-cc9d-4d79-858c-2510beb7afbf", "ct": "2021-10-20T04:38:57.462385582Z" }, "in_request": { // gRPCリクエスト情報 "type": "grpc", "service": "UserService", "method": "GetUser", "start_time": "2021-10-20T04:38:57.462391602Z", "duration_ms": 26.236, // 全体のリクエスト時間 "status_code": "OK", "body": { "id": "4661c5c5-7b6e-4741-905a-8afec78f2d07", }, "ctx": { "ua": "grpc-node/1.24.7 grpc-c/8.0.0 (osx; chttp2; ganges)" } }, "local_ctx": { // サービス固有情報 "user_id": "4661c5c5-7b6e-4741-905a-8afec78f2d07" } }
処理の流れが見やすく、RDBからのデータ取得に1.252msと0.647ms、APIリクエストに23.971ms、全体のリクエスト処理に26.236msかかったこともわかりやすくなっています。
非同期処理
このサンプルでは、GraphQLサーバがリクエストを受けて、RDBにデータをインサートして、非同期処理をトリガーさせて、リクエスト処理を終了する。非同期処理が起動して、他のAPIサービスにgRPCリクエストを投げてエラーで終わる。JSONの中に解説コメントを残しています。
// -------------------- // 全体の流れ: // - GraphQLリクエストを受けて、リクエスト情報を抽出する // - RDBに情報をインサートしてログを残す // - 非同期処理をトリガーさせる // - レスポンスを返す前にリクエストログを残す // - 非同期処理が起動する // - 非同期処理の中で他のAPIサービスにリクエストを投げてエラーログを残す // - 非同期処理が終了する // -------------------- // DBにデータをインサートする { "type": "log", "level": "info", "time": "2021-10-20T05:05:19.356962727Z", "msg": "sql query", "request_id": "35678205f328c61902b4c3d9b8e6c38c", "fp": { "id": "ecfa6cd4-fc29-4978-aec9-ed487dccad7a", "ct": "2021-10-20T05:05:18.417785119Z" }, "in_request": { // GraphQLリクエスト情報 "type": "graphql", "service": "OrderService", "method": "createOrder", "start_time": "2021-10-20T05:05:18.417787902Z", "ctx": { "ua": "Dart/2.12 (dart:io)", "values": { "user_id": "4661c5c5-7b6e-4741-905a-8afec78f2d07" } } }, "local_ctx": { // サービス固有情報 "order_id": "c3a16de9-4ea1-4335-a3c4-62286bc24da2", "user_id": "4661c5c5-7b6e-4741-905a-8afec78f2d07" }, "out_request": { "type": "sql", "start_time": "2021-10-20T05:05:19.352202876Z", "duration_ms": 4.743, "body": "INSERT INTO orders (order_code) VALUES ($1) RETURNING id" } } // リクエストログ { "type": "log", "level": "info", "time": "2021-10-20T05:05:22.459575893Z", "msg": "unary call ended with code OK", "request_id": "35678205f328c61902b4c3d9b8e6c38c", "fp": { "id": "ecfa6cd4-fc29-4978-aec9-ed487dccad7a", "ct": "2021-10-20T05:05:18.417785119Z" }, "in_request": { // GraphQLリクエスト情報 "type": "graphql", "service": "OrderService", "method": "createOrder", "start_time": "2021-10-20T05:05:18.417787902Z", "duration_ms": 4041.781, "status_code": "OK", "ctx": { "ua": "Dart/2.12 (dart:io)", "values": { "user_id": "4661c5c5-7b6e-4741-905a-8afec78f2d07" } }, "details": { "deadline": "2021-10-20T05:05:33.417600265Z" } }, "local_ctx": { // サービス固有情報 "order_id": "c3a16de9-4ea1-4335-a3c4-62286bc24da2", "user_id": "4661c5c5-7b6e-4741-905a-8afec78f2d07" } } // 非同期処理の中で他のAPIサービスにリクエストを投げて { "type": "log", "level": "error", "time": "2021-10-20T05:05:25.069072811Z", "msg": "unary client call ended with code Internal", "request_id": "35678205f328c61902b4c3d9b8e6c38c", "fp": { "id": "ecfa6cd4-fc29-4978-aec9-ed487dccad7a", "ct": "2021-10-20T05:05:18.417785119Z" }, "in_request": { // 非同期処理情報 "type": "background", "service": "Async", "method": "NotifyNewOrder", "start_time": "2021-10-20T05:05:22.460569663Z", "details": { "deadline": "2021-10-20T05:05:33.417600265Z" } }, "local_ctx": { // サービス固有情報 "order_id": "c3a16de9-4ea1-4335-a3c4-62286bc24da2", "user_id": "4661c5c5-7b6e-4741-905a-8afec78f2d07" }, "out_request": { // 叩いたgRPC API情報、リクエスト時間が残っています "type": "grpc", "service": "NotificationService", "method": "NotifyNewOrder", "start_time": "2021-10-20T05:05:22.462733721Z", "duration_ms": 2605.778, "status_code": "Internal", "ctx": { "ua": "graphql server/1.0.0" }, "details": { "deadline": "2021-10-20T05:05:37.462720694Z" } }, "error": { // エラー情報 "type": "INTERNAL", "domain": "SAMPLE_DOMAIN", "code": "DESTINATION_UNREACHABLE", "message": "couldn't reach notification destination" }, } // 非同期処理終了ログ { "type": "log", "level": "info", "time": "2021-10-20T05:05:25.079072811Z", "msg": "NotifyNewOrder: error", "request_id": "35678205f328c61902b4c3d9b8e6c38c", "fp": { "id": "ecfa6cd4-fc29-4978-aec9-ed487dccad7a", "ct": "2021-10-20T05:05:18.417785119Z" }, "in_request": { // 非同期処理情報 "type": "background", "service": "Async", "method": "NotifyNewOrder", "start_time": "2021-10-20T05:05:22.460569663Z", "duration_ms": 2606, "status_code": "Internal", "details": { "deadline": "2021-10-20T05:05:33.417600265Z" } }, "local_ctx": { // サービス固有情報 "order_id": "c3a16de9-4ea1-4335-a3c4-62286bc24da2", "user_id": "4661c5c5-7b6e-4741-905a-8afec78f2d07" }, "error": { // エラー情報 "type": "INTERNAL", "domain": "SAMPLE_DOMAIN", "code": "NOTIFICATION_FAILED", "message": "couldn't send new order notification" }, }
ユースケース
分散トレーシング
このユースケースでは以下のシークエンス図のように複数サービスを跨いでリクエストを処理することをイメージしています。
共通ログフォーマットを使うことで、例えばBigQueryで以下のようなログ一覧を出すことができます。 全てのリクエストがクライアントから発生した元々のリクエストと紐づいているため、同一のリクエストIDを持っています。各サービスごとにリクエストを受けた時にフィンガープリントが発行されます(フィンガープリントごとに色を分けています)。分散トレーシングツールを導入しなくても、ある程度の分散トレーシングをローコストで行えます。
パフォーマンス管理
このユースケースでは一つのAPIリクエスト処理だけのログをBigQueryなどで一覧で出すことで、時間がかかっている処理を特定できるようになります。今回は PaymentService 、EstimationService とUserService へのリクエスト処理が遅いことがわかります。また、SQLクエリー数が多いこともわかります。Application Performance Monitoring (APM)ツールを導入しなくても、ある程度のパフォーマンス管理をローコストで行えます。
エラー集計
このユースケースではAPIごとに起きているエラー数を集計しています。ログフォーマットが決まっているおかげで、集計を行う軸を自由に変えられます: サービス別のエラー数、ユーザエージェント別のエラー数、サービス固有情報local_context に入っているユーザIDまたは注文IDごとのエラー数など...
まとめと今後の課題
紹介させていただいた共通フォーマットでログを簡単に出力するためのGolangロガーを開発して、弊社の一部のサービスに導入してみました。多数のマイクロサービスを利用するプロダクトでも、共通ログフォーマットを持つことでログの閲覧方法が統一されたり、システム全体の見える化が進んだように感じました。複数サービスを跨ぐリクエストのお問い合わせ対応が楽になり、分散トレーシングとパフォーマンス管理をローコストでできたりして、できることが増えて結果として良かったと思いました。
一方、新しい課題も見えてきました:
- 全てのSQLクエリーやアウトバウンドHTTPリクエストをログに残しているため、ログの量が多い
- 一つ一つのログにトレーシング情報、インバウンドリクエスト情報、サービス固有情報が含まれているためオーバーヘッドが大きい
- Golangのロガーを作って様々なサービスに導入したが、Pythonなど他の言語はサポートできていない
ログをリクエスト処理の中で貯めておいて、リクエスト終了時に一つのログとして出力したり、トレーシング情報を別のログレベルで出力したり、ログサンプリングを導入したりすることなど改善案がいくつかありますので今後も検討していきたいと思います！
マイクロサービス化が進んでいるまたは検討されている方へ、ご自身の組織と合う共通なログフォーマットを導入することをおすすめしますのでこの記事がご参考になれば幸いです！
