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

# はじめに
AWS lambda上で、Pythonのloggingモジュールを使い、ログを表示させていたところ、重複してログが表示されていることに気づいたので、重複してログが出力される理由とその対処法を調査した。

# ログが重複する理由

### lambdaのlogging仕様
lambda上では、デフォルトで、ルートロガーにLambdaLoggerHandlerというハンドラが登録されている。([参照記事](https://qiita.com/k_hoso/items/ba7614775dbec089d18d))
つまり、自分で新たなハンドラを登録すると、ハンドラが複数存在することになり、ログが重複して出力されてしまう。

#### コード

```python: デフォルトで存在するハンドラの確認

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	ログだよ

```

#### コード

```python: ハンドラが重複したとき

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内で複数のハンドラを使う必要がないときは、この方法で十分かも。

#### コード

```python:

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にすること（[参照](https://docs.python.org/ja/3/howto/logging.html#next-steps)）。これを設定することで、ルートロガーなどの親ロガーへのログ伝搬を制御することができる。つまり、名前付きハンドラを作成し、ログを出力しても、lambdaのデフォルトのハンドラではログが出力されなくなる。

#### コード

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

#### コード

```python: 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にする