AWS LambdaでPythonのログ出力をカスタマイズする方法

2022.04.28

本記事のポイント

Pythonの開発をしていると、ログ出力の設定をカスタマイズしたい場面が出てきます。

ローカル環境では期待通りに動いたログの設定が、AWS Lambdaでは期待通りに動作しないことがあります。

そこで今回は、AWS LambdaでPythonのログ出力をカスタマイズする方法について、私が良いと思った設定方法を2つご紹介します。

はじめに

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でも、ローカル環境でも同じコードで動作するものとする

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 addition

settings.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ロガーの設定はルートロガーには伝播しません。伝播してしまうと、ルートロガーの設定で同じ内容のログが出力されてしまいます。