Lambdaのログをrequest IDで追えるようにする小さなライブラリ
lambda_json_loggerを作りました。AWS Lambdaのログを1行1 JSONで出すためのライブラリで、依存はありません。
Lambdaのデフォルトのログはテキスト形式で、リクエストIDが行頭のプレフィックスに埋め込まれています。CloudWatch Logs Insightsから見ると単なる文字列の一部なので、parseを書かないと絞り込めません。リクエストの内容（event）もデフォルトでは出てこないため、「このエラーはどんなリクエストで起きたのか」を後から追えません。
調査のたびにparseを書くのは地味に効いてきます。障害対応の最中に正規表現を組み立てているのは、本来やりたいことではありません。
loggingのFormatterを差し替えて、リクエストID・環境名・eventをJSONのトップレベルフィールドとして出すようにしました。InsightsはJSONログを自動でパースするので、そのままクエリできます。
この記事の内容は次のとおりです。
使う
GitHubから直接インストールできます。
pip install "lambda_json_logger @ git+https://github.com/yosuke318/lambda_json_logger.git"ハンドラの先頭でロガーを取るだけです。
from lambda_json_logger import getLambdaJsonLoggerInstance
def lambda_handler(event, context):
logger = getLambdaJsonLoggerInstance(context=context, stage="dev", event=event)
logger.info("processing started")
return {"statusCode": 200}出力されるJSONは次のようになります。
| フィールド | 中身 |
|---|---|
time | 出力時刻 |
level | INFO / ERRORなど |
message | ログメッセージ |
function_name | 出力元の関数名 |
module | 出力元のモジュール名 |
aws_request_id | contextから取得したリクエストID |
stage | 任意で渡す環境名 |
event | 渡した場合のみ出力される |
exception | logger.exception()やexc_info=Trueのときのみ |
これでInsights側はこう書けます。
fields @timestamp, message, event.httpMethod, event.path
| filter aws_request_id = "8f7e6d5c-..."
| filter level = "ERROR"
| sort @timestamp descネストしたキーもドット記法で辿れるので、event.path like /^\/orders/のような絞り込みができます。
ウォームスタートでリクエストIDがずれる
ここが実装で一番気を使った箇所になりました。
Lambdaは実行環境を使い回すので、ロガーはプロセス内で共有されます。最初に作ったときのcontextをFormatterが持ったままだと、2回目以降の呼び出しで前のリクエストのIDが出続けます。
厄介なのは、この状態でもログ自体は正常に出ることです。JSONの形も崩れず、フィールドも揃っています。間違っているのは中身だけで、しかもそのログを頼りに調査するので、誤った結論に誘導されてしまいます。
ハンドラは1つだけ作り、Formatterは毎回作り直して差し替える形にしました。
if not logger.handlers:
logger.addHandler(StreamHandler())
formatter = LambdaJsonFormatter(context=context, stage=stage, event=event)
for handler in logger.handlers:
handler.setFormatter(formatter)呼び出しごとの値をclosureではなくFormatterのインスタンスに持たせているのは、このためです。裏返すと、ハンドラ関数の先頭で毎回呼び直す必要があります。呼ばないと前のリクエストのIDのまま出てしまいます。
もう1つ、logger.propagate = Falseを入れています。Lambdaランタイムはルートロガーに届いたものを自前で出力するので、伝播させると同じ行が2回出てしまうためです。
載せすぎない
eventを渡すと全ログ行に載ります。CloudWatchの課金は取り込みバイト数にかかるので、大きなeventを渡したまま1リクエストで何十行も出すとログ量が膨らみます。気になる場合はeventを渡さず、開始時に1行だけ出して、あとはaws_request_idで突き合わせれば十分です。eventを省略すればキー自体が出力されません。
logger.exception()のトレースバックはexceptionフィールドに入ります。改行が\nにエスケープされるので、CloudWatch上で複数イベントに分割されません。JSON化できない値が混ざってもdefault=strで文字列化されるため、ログ呼び出しが例外で落ちることもありません。
ログを出す処理がログを出せずに落ちるのは避けたいので、ここは握りつぶす側に倒しています。
テスト
contextはLambdaランタイムが渡してくるオブジェクトなので、テストではDummyContextを用意してaws_request_idだけ持たせています。ハンドラの標準出力をバッファに差し替え、出てきた行をjson.loadsして構造を検証する方式にしました。
出力が1行1 JSONであることが仕様なので、テストも「パースできること」から確認するのが素直でした。
標準機能との住み分け
AWSは2023年11月16日にLambdaのAdvanced Logging Controlsを追加していて、関数設定でログ形式をJSONにするとrequestIdやlevelを含む構造化ログがランタイム側で出ます。コード変更なしでログレベルを変えられ、出力先のロググループも選べます。
新規に組むなら、まずそちらで足りるか確認したほうがいいと思います。 ライブラリを1つ足すより、設定を1つ変えるほうが常に安く済みます。
このライブラリが要るのは、stageのような任意のフィールドを足したい場合と、その機能を使わない構成のときです。ランタイム側のJSON出力は項目が決まっているので、独自のフィールドを載せたいならFormatterを持つことになります。