はじめに
AWS lambda上で、Pythonのloggingモジュールを使い、ログを表示させていたところ、重複してログが表示されていることに気づいたので、重複してログが出力される理由とその対処法を調査した。
ログが重複する理由
lambdaのlogging仕様
lambda上では、デフォルトで、ルートロガーにLambdaLoggerHandlerというハンドラが登録されている。(参照記事)
つまり、自分で新たなハンドラを登録すると、ハンドラが複数存在することになり、ログが重複して出力されてしまう。
コード
from logging import getLogger, StreamHandler, DEBUG, Formatter
def lambda_handler(event, context):
logger = getLogger()
logger.setLevel(DEBUG)
print(logger.handlers)
logger.info("ログだよ")
return "success"
結果
[<LambdaLoggerHandler (NOTSET)>] #デフォルトでこのハンドラが存在している
[INFO] 2022-03-16T04:34:03.082Z ce98337d-0404-4562-be66-3d6292ea20f6 ログだよ
コード
from logging import getLogger, StreamHandler, DEBUG, Formatter
def lambda_handler(event, context):
logger = getLogger()
logger.setLevel(DEBUG)
handler = StreamHandler()
handler.setFormatter(Formatter('%(asctime)s - %(levelname)s - %(name)s: %(message)s', datefmt='%Y-%m-%d %H:%M:%S'))
logger.addHandler(handler) #ハンドラの追加
print(logger.handlers)
logger.info("ログだよ")
return "success"
結果
[<LambdaLoggerHandler (NOTSET)>, <StreamHandler <stderr> (NOTSET)>]
[INFO] 2022-03-16T04:42:32.347Z bf22b961-fada-447d-a0cb-74e501e1621e ログだよ # LambdaLoggerHandlerによる出力
2022-03-16 04:42:32 - INFO - root: ログだよ # StreamHandlerによる出力
対処法
その1:デフォルトのハンドラをそのまま使用する
1つ目の対処法は、デフォルトのハンドラをそのまま使用すること。lambda内で複数のハンドラを使う必要がないときは、この方法で十分かも。
コード
from logging import getLogger, StreamHandler, DEBUG, Formatter
def lambda_handler(event, context):
logger = getLogger()
logger.setLevel(DEBUG)
for handler in logger.handlers: # ここでフォーマッターの変更も可能
handler.setFormatter(Formatter('%(asctime)s - %(levelname)s - %(name)s: %(message)s', datefmt='%Y-%m-%d %H:%M:%S'))
print(logger.handlers)
logger.info("ログだよ")
return "success"
結果
[<LambdaLoggerHandler (NOTSET)>]
2022-03-16 04:51:51 - INFO - root: ログだよ
デメリット
loggerに名前を付けることができず、%(name)sのところにrootと出てきてしまう(logger名をモジュール名などにしたいときに不便)。
その2:logger.propagateをFalseにする
2つ目の対処法は、logger.propagateをFalseにすること(参照)。これを設定することで、ルートロガーなどの親ロガーへのログ伝搬を制御することができる。つまり、名前付きハンドラを作成し、ログを出力しても、lambdaのデフォルトのハンドラではログが出力されなくなる。
コード
from logging import getLogger, StreamHandler, DEBUG, Formatter
def lambda_handler(event, context):
logger = getLogger('example') # 'example'という名前のロガーを作成
logger.setLevel(DEBUG)
# logger.propagate = False
handler = StreamHandler()
logger.addHandler(handler)
for handler in logger.handlers:
handler.setFormatter(Formatter('%(asctime)s - %(levelname)s - %(name)s: %(message)s', datefmt='%Y-%m-%d %H:%M:%S'))
print(logger.handlers)
logger.info("ログだよ")
return "success"
結果
[<StreamHandler <stderr> (NOTSET)>]
2022-03-16 05:02:19 - INFO - example: ログだよ # 'example'ロガーのログ
[INFO] 2022-03-16T05:02:19.960Z d10cb690-47f6-45d9-90d6-716329e02889 ログだよ # ルートロガーのログ
この場合、'example'というロガーを作成(ルートロガーとは異なる)したので、このロガーのハンドラにはlambdaのデフォルトのハンドラは存在しないが、ログ情報はルートロガーに存在するlambdaのデフォルトのハンドラにまで伝搬するので、ログ出力の際にログが重複してしまっている。
コード
from logging import getLogger, StreamHandler, DEBUG, Formatter
def lambda_handler(event, context):
logger = getLogger('example')
logger.setLevel(DEBUG)
logger.propagate = False # propagateを設定
handler = StreamHandler()
logger.addHandler(handler)
for handler in logger.handlers:
handler.setFormatter(Formatter('%(asctime)s - %(levelname)s - %(name)s: %(message)s', datefmt='%Y-%m-%d %H:%M:%S'))
print(logger.handlers)
logger.info("ログだよ")
return "success"
結果
[<StreamHandler <stderr> (NOTSET)>]
2022-03-16 05:07:52 - INFO - example: ログだよ # 'example'ロガーのみが出力
このように、propagateをFalseに設定すると、'example'ロガーからのログのみが出力され、ログの重複もなくなる。
結論
- lambda上では、デフォルトのハンドラがルートロガーに存在する
- ログの重複を避けるには
- デフォルトのハンドラを使用する
- propagateをFalseにする