Flask - app.loggerが2重に出力される問題の解消

内容

AWS ECS上で実行しているFlaskアプリでログ出力（app.logger.info()）した際、
CloudWatch logsに2重にログが出力される現象が発生したため、原因の調査、解消を行った

結論

以下の変更を行うことで解消

問題発生時のコード

import logging
from flask import Flask

app = Flask(__name__)
logging.basicConfig(level=logging.INFO)  # ログレベル設定

app.logger.info('INFO')

問題解消後のコード

import logging
from flask import Flask

app = Flask(__name__)
logging.getLogger().setLevel(logging.INFO)  # logging.basicConfig から logging.getLogger().setLevel に変更

app.logger.info('INFO')

原因

https://stackoverflow.com/questions/69044301/duplicate-logs-when-calling-logging-basicconfig
によると、Pythonのloggingは階層構造をしており、下位から上位の階層にログが伝播する、
logging.basicConfigを実行するとルートにロガーを設定しているとある
また、この伝播を停止することで2重ログが解消できそう

Flask、logging.basicConfig の挙動

Flask、logging.basicConfigによってloggingに設定されるconfig内容を確認

Flask

Flask Default Configurationによると、
「もし自分でログ処理設定をしない場合、Flaskはapp.loggerへStreamHandlerを自動的に追加する」とある

logging.basicConfig

logging.basicConfigによると、
「デフォルトの Formatter を持つ StreamHandler を生成してルートロガーに追加し」とある

logging-tree で logging の階層構造を確認

logging-treeを使用して logging の階層構造を確認

logging.basicConfig を実行しなかった場合の logging 階層構造

<--""
   Level WARNING
   |
   o<--"app"
   |   Level NOTSET so inherits level WARNING
   |   Handler Stream <_io.TextIOWrapper name='<stderr>' mode='w' encoding='utf-8'>
   |     Formatter fmt='[%(asctime)s] %(levelname)s in %(module)s: %(message)s' datefmt=None
   |
   o<--"asyncio"
   |   Level NOTSET so inherits level WARNING
   |
   o<--[aws_xray_sdk]
   |
   ...

treeの"app" にのみ Handler Stream が設定されていることがわかる

logging.basicConfig を実行した場合の logging 階層構造

<--""
   Level INFO
   Handler Stream <_io.TextIOWrapper name='<stderr>' mode='w' encoding='utf-8'>
     Formatter fmt='%(levelname)s:%(name)s:%(message)s' datefmt=None
   |
   o<--"app"
   |   Level NOTSET so inherits level INFO
   |   Handler Stream <_io.TextIOWrapper name='<stderr>' mode='w' encoding='utf-8'>
   |     Formatter fmt='[%(asctime)s] %(levelname)s in %(module)s: %(message)s' datefmt=None
   |
   o<--"asyncio"
   |   Level NOTSET so inherits level INFO
   |
   o<--[aws_xray_sdk]
   |
   ...

treeのルート（""）と、"app" に Handler Stream が設定されていることがわかる
また、ルートのログレベルにINFOが設定され、下位のログレベルにも継承されていることがわかる
やはり"app"からルートにログが伝播することで2重ログが発生していると思われる

解決方法

上記原因より、"app"のログをルートに伝播しない、もしくはルートに Handler Stream を設定しなければ良い
logging.basicConfigの代わりにlogging.getLogger().setLevelでルートのログレベルを設定するように変更することで解消した