はじめに

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つ目の対処法は、デフォルトのハンドラをそのまま使用すること。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名をモジュール名などにしたいときに不便）。

その２：logger.propagateをFalseにする

2つ目の対処法は、logger.propagateをFalseにすること（参照）。これを設定することで、ルートロガーなどの親ロガーへのログ伝搬を制御することができる。つまり、名前付きハンドラを作成し、ログを出力しても、lambdaのデフォルトのハンドラではログが出力されなくなる。

コード

propagateをコメントアウトした場合


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のデフォルトのハンドラにまで伝搬するので、ログ出力の際にログが重複してしまっている。

コード

propagateを設定した場合


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にする

AWS lambdaでログが重複して出力される理由と対処法（Python）