構造化ログは運用に優しい

運用においてログを出力しておく事は、障害発生時の調査の手がかりにもなることから非常に重要です。
しかし、だたメッセージを出しておくだけでは調査をスムーズに進める事は難しいでしょう。

例えば、APIでユーザー情報を取得しようとした際にエラーが発生した時のログのパターンとしては以下のようなものが考えられます。

サンプル1

2024/01/01 10:00:00 [INFO] 5237e551-5f01-4154-9664-a73abc600025: 処理開始
2024/01/01 10:00:01 [INFO] 5237e551-5f01-4154-9664-a73abc600025: ユーザー情報取得 https://hoge.com/v1/users/1
2024/01/01 10:00:03 [ERROR] 5237e551-5f01-4154-9664-a73abc600025: ユーザー情報取得の取得に失敗
2024/01/01 10:00:03 [ERROR] 5237e551-5f01-4154-9664-a73abc600025: ユーザーID: 1

これだけであれば、APIでユーザーIDが1のデータを取得しようとしたときにエラーが発生したんだなと言うのがすぐ分かります。

しかし、以下の場合はどうでしょう？

サンプル2

2024/01/01 10:00:00 [INFO] 4e626ed2-7fb4-45d4-bb6c-d3fa3d334be6: 処理開始
2024/01/01 10:00:00 [INFO] 5237e551-5f01-4154-9664-a73abc600025: 処理開始
2024/01/01 10:00:01 [INFO] 4e626ed2-7fb4-45d4-bb6c-d3fa3d334be6: ユーザー一覧取得 https://hoge.com/v1/users
2024/01/01 10:00:01 [INFO] 5237e551-5f01-4154-9664-a73abc600025: ユーザー情報取得 https://hoge.com/v1/users/1
2024/01/01 10:00:01 [INFO] f4518c68-b68d-4c65-98db-e61b1096d36f: 処理開始
2024/01/01 10:00:02 [INFO] 4e626ed2-7fb4-45d4-bb6c-d3fa3d334be6: ユーザー一覧取得に成功 https://hoge.com/v1/users
2024/01/01 10:00:03 [ERROR] 5237e551-5f01-4154-9664-a73abc600025: ユーザー情報取得の取得に失敗
2024/01/01 10:00:03 [INFO] 3eaa36b6-70e8-43b6-adc0-4f8faea55441: 処理開始
2024/01/01 10:00:03 [ERROR] 5237e551-5f01-4154-9664-a73abc600025: ユーザーID: 1

この場合、ぱっと見てどのリクエストがエラーになったのか分かり難いのでは無いでしょうか？

多くのバッチ処理のようにシングルスレッドで動く処理であればサンプル1のように出力されますが、Webサービスのようにマルチスレッドで動く処理はサンプル2のように出力されてしまいます。
サンプルなので出力数は少ないですが、実際の運用環境などではもっと多くのログが出力されるのではないでしょうか？

このようなログ出力では障害発生時の原因特定をスムーズに進める事は出来ません。

そこでオススメしたいのが構造化ログです。

構造化ログはログを構造化することにより分析を行いやすくなります。
そして、人が見ても分かりやすい出力になります。
一言で構造化と言っても色々な形式がありますが、JSON形式にすることが一般的です。

エラー発生時の出力は、以下のようにすることが考えられます。

サンプル3

{
    "date": "2024/01/01",
    "time": "10:00:00",
    "type": "INFO",
    "id": "5237e551-5f01-4154-9664-a73abc600025",
    "message": "ユーザー情報取得の取得に失敗",
    "request': {
        uri": "https://hoge.com/v1/users/1"
    }
}

どうでしょうか？
分かりやすいと思いませんか？

もちろん、サンプル1,2で示したエラーログにもuriを情報として載せることは可能です。

サンプル4

2024/01/01 10:00:03 [ERROR] 5237e551-5f01-4154-9664-a73abc600025: uri: "https://hoge.com/v1/users/1" ユーザーID: 1

しかし、サンプル3に比べて見にくいのではないのでしょうか？
さらに、ヘッダーやボディなどを出力したくなったらどうですか？

例えばヘッダーを出力する場合、構造化ログでは以下のような出力にすることが出来ます。

サンプル5

{
    "date": "2024/01/01",
    "time": "10:00:03",
    "type": "INFO",
    "id": "5237e551-5f01-4154-9664-a73abc600025",
    "message": "ユーザー情報取得の取得に失敗",
    "request": {
        "method": "GET",
        "uri": "https://hoge.com/v1/users/1",
        "header": {
            "Content-Type": [
                "application/json"
            ]
        }
    }
}

このように構造化ログにすることで多くの情報を分かりやすく出力することが可能となります。

構造化ログを行うことでデータ量が増え、クラウドサービスを利用しているとコストが増えるなどのデメリットも存在します。
しかし、エラー発生時にエラー原因となっている情報を効果的に出力することが可能になるなどデメリットを補って余りあるメリットも存在するので、是非構造化ログにチャレンジしてみて下さい。