AWS LambdaでPythonのログ出力をカスタマイズする方法
はじめに
pythonで開発していると、ログ出力の設定をカスタマイズしたい場面が出てきます。
ローカル環境では思い通りにカスタマイズできたログ出力が、AWS Lambdaで同じように実行してみるとなぜか同じログが2つ出てくるなど、思い通りにログが出ないといった経験はないでしょうか。
実は、AWS Lambdaではデフォルトでログのハンドラが設定されています。独自にログの設定をカスタマイズしたい場合は、Lambdaのデフォルトの設定と衝突しないようにすることが必要です。
そこで今回は、AWS LambdaでPythonのログ出力をカスタマイズする方法についてお伝えしたいと思います。方法はいくつか存在するのですが、私が良いと思った設定方法を2つ紹介します。
また、AWSを使ったログ出力を見直す上で、確認しておきたい基本事項についても解説します。ログ出力に活躍するサービスも踏まえ、自社の取得環境を見直してみてください。
そもそもなぜログを出力するのか
ログの取得は、業務を遂行する上では直接関係のない作業のようにも思えます。それでもログ出力を怠るべきではない理由は、エラー対応を効率化するためです。
ログの出力設定が正しく行われていることで、ログを確認するだけでエラーの原因を特定したり、何をどのように改善すれば良いかを素早く把握したりが実現します。また、このログ出力はカスタマイズによって、さらに質の高いものへ引き上げることも可能です。有意義なカスタマイズを実現するためにも、ログ出力の意味を正しく理解しておきましょう。
今回の要件
今回の設定の要件をまとめます。
Python 3.9
ログの出力はpythonの標準ライブラリのloggingを使用
AWS Lambdaの関数ログはCloudWatch Logsで表示ログの収集や分析はCloudWatch Logs Insightsの使用を想定し、ログはjsonフォーマットで出力Lambdaでも、ローカル環境でも同じコードで動作するものとする
取得できるログの種類
ログとは一言で言っても、実際には様々なレベルでログの取得が行われます。代表的な種類としては、以下のようなものです。
- INFO:一般的な情報の伝達
- NOTICE:重要情報の確認
- WARN:警告
- ERROR:エラー発生の警告
- CRIT:致命的なエラーの警告
- ALERT:早急な対応が必要なエラーの発生
- EMERG:システム利用不能
それぞれのメッセージがどのような意味を持っているかはもちろん、その緊急性もログによって大きく異なります。
対応の優先順位を即座に把握するためにも、それぞれのログのレベルを正確に把握しておくことが、システムの安定稼働においては重要です。
loggingとprint()の違い
ログを取得する方法には、大きく分けてloggingとprint()の2種類があります。特に後者については比較的手軽に取り組みやすいため、好んで使用している人も多いかもしれません。
ただ、将来性を踏まえると早期からloggingによるログの取得を定着させておく方がおすすめできます。というのも、loggingの場合はプログラムのエラーをログとして正規に記録し、原因の特定や発生場所を把握する上で役に立つからです。
また、上で紹介したようなログのレベルを正しく仕分けた上で表示することができ、やはりログ出力の業務においては欠かせません。
プロトタイプ運用であればprint()でも構いませんが、本番環境ではloggingで取得することを前提とすべきでしょう。
CloudWatch Logsの強み
そんなログ取得において、AWSの便利なサービスとして活用したいのがCloudWatch Logsです。CloudWatch Logsは、AWSの各種サービスからログをまとめて取得することができます。
EC2 インスタンスやAWS CloudTrailなど、様々なサービスをソースにログファイルを確認したり、保存したりといった手続きが可能です。
同サービスを使って、ログの管理を一元化することができます。別個にログの出力や確認を行うのは面倒が大きいものですが、CloudWatch Logsがあれば、そのような面倒に振り回されることはありません。
Pythonでログ出力をカスタマイズする方法
まずローカル環境で動く、ログのカスタマイズ方法について説明します。
例えばですが、ディレクトリ構造は以下のようになっているとします。
src/
|--main.py
|--app.py
|--settings.py
|--utils/
| |--calculate.pyそれぞれのファイルの中身は以下のようになっています。
main.py
import json
import sys
from logging import getLogger, Formatter, basicConfig, StreamHandler
import traceback
from app import app
import settings
logger = getLogger(__name__)
def init_logging():
class JsonFormatter(Formatter):
def format(self, record):
d_record = vars(record)
if d_record.get("exc_info"):
d_record["exc_text"]= traceback.format_exc()
def class2str(value):
if not isinstance(value, (bool, str, int, float, type(None))):
return str(value)
return json.dumps(d_record, default=class2str)
logger = getLogger()
handler = StreamHandler(sys.stdout)
handler.setFormatter(JsonFormatter())
handler.setLevel(settings.HANDLER_LOG_LEVEL)
logger.setLevel(settings.LOGGER_LOG_LEVEL)
logger.addHandler(handler)
if __name__ == '__main__':
init_logging()
app()ログの設定はmain.pyの関数init_loggingで行なっています。今回は全て同じ設定としたかったため、ルートロガーの設定を変更しています。以下のようにすることでルートロガーの設定が変更できます。
logger = getLogger()このloggerに出力レベルやフォーマットをカスタマイズしたものを設定します。フォーマットは独自のJsonFormatterを用意しています。
続いて、mainで呼び出す関数を作成します。
app.py
from utils.calculate import calculate
from logging import getLogger
logger = getLogger(__name__)
def app():
try:
calculate(1,4)
except Exception as e:
logger.error(e) calculate.py
from logging import getLogger
logger = getLogger(__name__)
def calculate(x, y):
addition = x + y
logger.warning(f"{x} + {y} = {addition}")
return additionsettings.py
# デフォルトはWARNING
HANDLER_LOG_LEVEL = "WARNING"
LOGGER_LOG_LEVEL = "WARNING"各ファイルのロガーは以下のように設定します。
logger = getLogger(__name__)ロガーは階層構造となっています。ロガーをモジュール単位で構成すれば、Pythonパッケージ階層と同一になります。今回の場合、utils/calculate.pyのロガーはutils.calculateという名前となります。下位層のロガーは上位層のロガーに伝播します。今回はそれぞれのロガーで設定を追加していないので、ルートロガーの設定が反映されます。
さて、適切にロガーが設定されたか確認してみます。main.pyを実行すると、以下のようなログが出力されます。設定したJsonフォーマットとなっており、うまくいっているようです。
{"name": "utils.calculate", "msg": "1 + 3 = 4", "args": [], "levelname": "WARNING", "levelno": 30, "pathname": "/home/ops_blog/src/utils/calculate.py", "filename": "calculate.py", "module": "calculate", "exc_info": null, "exc_text": null, "stack_info": null, "lineno": 7, "funcName": "calculate", "created": 1650613366.9145358, "msecs": 914.5357608795166, "relativeCreated": 6.109952926635742, "thread": 139869548664640, "threadName": "MainThread", "processName": "MainProcess", "process": 22332}
{"name": "app", "msg": 4, "args": [], "levelname": "WARNING", "levelno": 30, "pathname": "/home/ops_blog/src/app.py", "filename": "app.py", "module": "app", "exc_info": null, "exc_text": null, "stack_info": null, "lineno": 9, "funcName": "app", "created": 1650613366.9152038, "msecs": 915.2038097381592, "relativeCreated": 6.77800178527832, "thread": 139869548664640, "threadName": "MainThread", "processName": "MainProcess", "process": 22332}AWS Lambdaでうまくいかない理由
上記をAWS Lambdaで同じように実行してみます。ただ、main.pyの以下の部分は、lambda_function.pyの該当部分に変更しましょう。
main.py
if __name__ == '__main__':
init_logging()
app()
lambda_function.py
def lambda_handler(event, context):
try:
init_logging()
app()
except Exception as e:
logger.error("error")
return {
'statusCode': 200,
'body': json.dumps('Hello from Lambda!')
}テストを実行してみます。
[WARNING] 2022-04-22T08:10:11.747Z 3b79c35f-5891-4e02-ab36-2bf28f9a8fd6 1 + 3 = 4
{"name": "utils.calculate", "msg": "1 + 3 = 4", "args": [], "levelname": "WARNING", "levelno": 30, "pathname": "/var/task/utils/calculate.py", "filename": "calculate.py", "module": "calculate", "exc_info": null, "exc_text": null, "stack_info": null, "lineno": 7, "funcName": "calculate", "created": 1650615011.7477973, "msecs": 747.7972507476807, "relativeCreated": 83.09292793273926, "thread": 140597445646144, "threadName": "MainThread", "processName": "MainProcess", "process": 9, "aws_request_id": "3b79c35f-5891-4e02-ab36-2bf28f9a8fd6", "message": "1 + 3 = 4", "asctime": "2022-04-22T08:10:11"}
[WARNING] 2022-04-22T08:10:11.748Z 3b79c35f-5891-4e02-ab36-2bf28f9a8fd6 4
{"name": "app", "msg": 4, "args": [], "levelname": "WARNING", "levelno": 30, "pathname": "/var/task/app.py", "filename": "app.py", "module": "app", "exc_info": null, "exc_text": null, "stack_info": null, "lineno": 10, "funcName": "app", "created": 1650615011.7481797, "msecs": 748.1796741485596, "relativeCreated": 83.47535133361816, "thread": 140597445646144, "threadName": "MainThread", "processName": "MainProcess", "process": 9, "aws_request_id": "3b79c35f-5891-4e02-ab36-2bf28f9a8fd6", "message": "4", "asctime": "2022-04-22T08:10:11"}
END RequestId: 3b79c35f-5891-4e02-ab36-2bf28f9a8fd6同じ内容のログに対して、json形式と別の形式のログの2つが出てきてしまいました。 ローカルでは存在しなかったログが出てきてしまう原因は、AWS Lambdaに元から設定されているロガーハンドラにあります。試しにmain.pyに以下のコードを追加し、ロガーに設定されたハンドラを見てみます。
print("handler", logger.handler)handler [<LambdaLoggerHandler (NOTSET)>, <StreamHandler <stdout> (WARNING)>]init_loggingで設定したStreamHandlerに加えて、LambdaLoggerHandlerがあることがわかりました。問題は、どうやって1つのロガーに集約するかです。前置きが長くなってしまいましたが、次の章で解決方法を2つ紹介します。
AWS LambdaにおけるPythonでログ出力をカスタマイズする方法
AWS Lambdaでpythonのログをカスタマイズする方法ですが、私が多数のブログやGitHub, Stack Overflowなどを検索して調べた限りだと様々な意見があり、現時点でこれがベストだというものは探しきれませんでした。そのため、どれを採用するかは悩みました。
また条件として、ローカルとlambdaでコードは同じ実装をしたいという思いがありました。コード中でLambdaLoggerHandlerのような記述はしたくありません。その中で、私が採用した実装方法は2つあります。
1つ目は、ルートロガーは1つにして、その設定をカスタマイズする方法です。2つ目は、ルートより下位のロガーで設定をカスタマイズし、ルートには設定を伝播させない方法です。
できれば2つ目の方法をおすすめしたいです。
方法1. ルートロガーの設定をカスタマイズする方法
ルートロガーの設定をカスタマイズする方法を紹介します。まず実装したコードを対象部分のみ抜粋して載せます。
init_logging
from logging import basicConfig
# If the handler already exists, it is ignored.
basicConfig()
logger = getLogger()
for handler in logger.handlers:
handler.setFormatter(JsonFormatter())
handler.setLevel(settings.HANDLER_LOG_LEVEL)
logger.setLevel(settings.LOGGER_LOG_LEVEL)
logger.addHandler(handler)basicConfigはルートハンドラが存在していない場合、StreamHandlerがセットされます。すでにハンドラが存在している場合は無視されますので、ローカル環境ではStreamHandlerが、AWS Lambdaでは元々存在しているLambdaHandlerがハンドラとしてセットされるようにしています。
それぞれの環境で1つしかハンドラが設定されておりませんが、書き方を統一するためfor文で記述しています。
ハンドラにjsonフォーマットや、出力ログレベルを設定し、ロガーのハンドラにセットします。
# lambda
handler [<LambdaLoggerHandler (WARNING)>]
# local
handler [<StreamHandler <stdout> (WARNING)>]実行してみると、以下のように1つずつしかログが出なくなりました。期待通りの設定となっているようです。
{ "name": "utils.calculate", "msg": "1 + 3 = 4", "args": [], "levelname": "WARNING", "levelno": 30, "pathname": "/var/task/utils/calculate.py", "filename": "calculate.py", "module": "calculate", "exc_info": null, "exc_text": null, "stack_info": null, "lineno": 7, "funcName": "calculate", "created": 1650851330.6537538, "msecs": 653.7537574768066, "relativeCreated": 60.68134307861328, "thread": 140204420212544, "threadName": "MainThread", "processName": "MainProcess", "process": 9, "aws_request_id": "17029fd9-3827-4b84-97ab-83d8afb1c1be" }
{ "name": "app", "msg": 4, "args": [], "levelname": "WARNING", "levelno": 30, "pathname": "/var/task/app.py", "filename": "app.py", "module": "app", "exc_info": null, "exc_text": null, "stack_info": null, "lineno": 10, "funcName": "app", "created": 1650851330.653928, "msecs": 653.9280414581299, "relativeCreated": 60.85562705993652, "thread": 140204420212544, "threadName": "MainThread", "processName": "MainProcess", "process": 9, "aws_request_id": "17029fd9-3827-4b84-97ab-83d8afb1c1be" }この方法を利用するメリット
この方法の良いところは、ルートロガーの設定をカスタマイズしているので、細かく下位のロガーについて案じる必要がないことです。また、LambdaLoggetHanderの場合、 Lambda固有のパラメータ (aws_request_idなど)も出力されます。
この方法の懸念事項
不安点としては、Lambdaの場合、Lambda Logger Handlerを直接触っているので、何かカスタマイズした影響があるかもしれないことです。ただ私は現時点で特に困っておりません。
また、LambdaLoggerHandlerを削除してStreamHandlerをセットする方法もあります。ただ、ログの二重化は防げますが、セットされているルートロガーを削除するのは危険ではないかとの見方もあり、今回は採用を見送りました。
方法2. ルートより下のロガーをカスタマイズする
次に、ルートロガーの設定はいじらず、ルートより下位のロガーをカスタマイズする方法を紹介します。方法1のような、既にあるLambdaLoggerHandlerをいじることに少し抵抗がある場合はこちらの設定が良いでしょう。
この設定をうまくやるためには、ディレクトリ構造を変更する必要があります。トップディレクトリから1つ新たにディレクトリを作成し、メイン以外のファイルを移動させます。
ここが重要ポイントです。理由は後で説明します。ディレクトリ名は今回のプロジェクト名の”ops”としています。
src/
|--main.py(lambda_function.py)
|--settings.py
|--ops/
| |--app.py
| |--utils/
| |--calculate.pyそして、ロガー名:opsをカスタマイズします。ロガー名はディレクトリの名前と一致させます。
init_logging
logger = getLogger("ops")
logger.propagate = False
handler = StreamHandler(sys.stdout)
handler.setFormatter(JsonFormatter())
handler.setLevel(settings.HANDLER_LOG_LEVEL)
logger.setLevel(settings.LOGGER_LOG_LEVEL)
logger.addHandler(handler)ops/以下の各ファイルでloggerの設定は以下のようにします。
ops以下のファイル
from logging import getLogger
logger = getLogger(__name__)
# 使用時
logger.error("error")ops/以下の各ファイルのロガー名は”__name__”を指定することでモジュールの階層をなぞることができます。ops/utils/calculate.pyの場合、ロガー名はops.utils.calculateとなります。ロガーは階層構造を持っており、ドットをセパレータとして概念的に並べられます。
ops.utils.calculateの上位のロガーはops.utilsであり、そのさらに上はopsです。つまり、init_loggingでopsのロガーの設定を行うだけで下位ロガーの設定は必要なくなります。opsディレクトリを作らないと、綺麗な階層構造とならないため、各ディレクトリ(ex: utils, foo, …)で設定しなければなりません。
また、init_logging内のlogger.propagete = Falseについてですが、これより上位のロガーには伝播させないことを意味します。つまり、opsロガーの設定はルートロガーには伝播しません。伝播してしまうと、ルートロガーの設定で同じ内容のログが出力されてしまいます。
この方法を利用するメリット
方法2の良いところは、ルートロガーがなんであろうと関係がないので環境に左右されません。また、認識していないルートロガーの設定を変更するといった事態が発生しません。pythonのロガーの考え方としても、この方法が望ましいでしょう。これが方法1より方法2をおすすめした理由です。
この方法を利用するデメリット
デメリットとしては、Lambda固有のパラメータ(aws_request_idなど)はログとして出力できません。また、ディレクトリ構造を整える必要があり、構成が異なる場合に作業が大変になる時は方法1が良いと思います。
参考文献
Python Logging HOWTO
https://docs.python.org/ja/3/howto/logging.html#logging-advanced-tutorial
Python の AWS Lambda 関数ログ作成
https://docs.aws.amazon.com/ja_jp/lambda/latest/dg/python-logging.html
まとめ
いかがでしたでしょうか。今回はAWS LambdaでPythonのログ出力をカスタマイズする方法について2つの方法を紹介しました。プロジェクトや、考え方によって2つの方法を使い分けることができると思います。
また、AWS Lambdaで出力したログはCloudWatch Logsで確認できます。ログの取得を一元化できるこのサービスを使うことで、ログ出力の業務全般を効率化することができます。また、Json形式にすることでLogs Insightsで検索する場合にフィルタリングがしやすくなり、エラー発生時の運用が楽になるかと思います。
AWS Lambdaを使用する場合は参考にしてみてください。
ご覧いただきありがとうございました。
この記事をシェア
