Overview
業務で AWS Lambda を使用してとある実装をしたのでその紹介です。
久しぶりに業務でOSS作りました。https://t.co/5fNBhiRsle
— ema (@ema_hiro) 2020年11月19日
なぜ作ったのか？
Lambda 上でログを吐くとデフォルトで Cloud Watch Logs(以下 CW Logs) にログが飛ぶのですがこの CW Logs の生ログ検索が非常に使いづらく、また Lambda は非同期でバンバン実行されるので、どのログがいつ実行されたLambdaに紐づいているのかわからず、ログは追えるけどどういう流れでそのログが出力されたのがわからない、という問題を抱えてました。 そこで Stackdriver logging でやっていたようなログの構造化ができないのか調査したところ 公式ドキュメントにある https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/logs/CWL_AnalyzeLogData-discoverable-fields.html によると、デフォルトのCW Logs のフィールドに加えて、JSON文字列を出力した場合にその key がそのままCW Logs のフィールドとして使えることがわかったので trace をつけた json 文字列をログとして出力して、CW Logs Insight で trace でフィルタして引っ掛けると実行ごとのログの一覧できる Logger を作りました。
どう作ったか？
以前似たような Loggerを作ったことがあったので、それと同じようなロガーを実装しました。
具体的には Opencensus の分散トレーシングのライブラリ（https://pkg.go.dev/go.opencensus.io/trace） を使用して Lambda が起動するごとに一意な traceID と spanID を発行し、それを一連の処理の context として引き継いでいくことで Lambda の起動ごとにログをまとめられるようにしています。
How to Use
Lambda のエントリーポイント（ Go の場合は main.go) で lambda.Start を Call する前に SpanContext をセットし、その Context を log の出力の時に使用します。
詳細は Readme を参照してください。
結果
このロガーを使用するようになったことにより、CW Logs Insight で以下のようなクエリを叩くと、特定の trace に紐づく一連のログを全て出力できようになりました。
fields @timestamp, @message | filter trace="service/$ServiceName/trace/xxxxxxxxxxxxxxx..." | sort @timestamp desc
Lambda の起動ごとの一連の流れをログで確認することができるようになったことに加えて CWLogs Insight は非常に高速にフィルタした結果を取り出してくれるので、サービスの中で何が起きているのかをすぐにわかるようになりました。
その他
実はこのロガーは Lambda の起動ごとに一つの処理しか行わない想定で、起動につき一つのライフサイクルのログのしか表示されないものかと思っていましたが、どうやら実際のログを追ってみると別のライフサイクルの Lambda のログも表示されることがわかりました。
Lambda の一度の起動につき、１つの処理しか行われない（Lambda が立ち上がっているインスタンスの使い回しは発生しない）と思っていました、実際にはインスタンスを使いまわしてるケースが存在することがわかりました。
ログはグルーピングされているので運用上特に困ることはないんですが、Lambda の振る舞いを知る機会にもなりました。
