pythonのlogging設定をモジュール間で共有する方法

Question

前提・実現したいこと

python3.7にて、CICDツールを作成しており、logging機能を実装しております。
loggingの設定をファイルに定義し、dictconfigにて設定を読み込ませlog出力しようとしております。
モジュール間でのlogging設定を共有する方法がわからず悩んでおります。
main.pyでloggerの設定をし、sub.pyでloggerを取得し、ログ出力しております。
sub.pyおいて、関数の外側でloggerを取得できるのが理想です。(モジュール内で1回のloggerの取得で済むため)

発生している問題・エラーメッセージ

sub.pyおいて、関数の外側でloggerを取得するとログ出力されず、関数内でloggerを取得するとログ出力されます。

• main.py

logging.config.dictConfig('path to setting file')
logger = logging.getLogger(__name__)

• sub.py

下記はうまくいかないパターン

logger = logging.getLogger(__name__)
def funcA():
  logger.debug('hoge')

下記はうまくいくパターン

def funcA():
　logger = logging.getLogger(__name__)
  logger.debug('hoge')

補足情報（FW/ツールのバージョンなど）

python3.7、フレームワークは使用しておりません。

Answer 1

2番目の例でも期待通りに動作しますが、
main側でのsubの扱いはどのようにされてますか。

getLogger が dictConfig の前か後か、この場合
sub を import する位置によって動作が変わってくるはずです。

---

ロギングの環境設定より disable_existing_loggers

警告 fileConfig() 関数はデフォルト引数 disable_existing_loggers を取り、後方互換性のためにデフォルト値は True になっています。 これはあなたの望むものかもしれませんし、そうでないかもしれません。というのは、設定で明示的に指定したクラス (もしくはその親クラス) を除いて、 fileConfig() が呼び出される前に存在した非ルートロガーを無効化してしまうからです。 より詳細なことはリファレンスを参照し、望むならこの引数に False を指定してください。

dictConfig() に渡した辞書で、キー disable_existing_loggers にブール値を指定することができ、辞書で指定しなかった場合はデフォルトで True と解釈されます。こうすると上で説明したロガー無効化が動作しますが、これはあなたが望んだものでないかもしれません - その場合は、明示的にキーに False を指定してください。

解決策:

'disable_existing_loggers': False を設定する

---

disable_existing_loggers の挙動について、動作確認用のサンプルコードを追記します。
コメントアウト部分を編集して試してみてください。
(※ モジュールキャッシュの影響がないことを明示する為、
import sub が dictConfig 後の時は、ファイル先頭のimportはコメントアウトで)

	(1) disable_existing_loggers	(2) import sub の位置
case 1	True(省略時)	ファイル先頭
case 2	True(省略時)	dictConfig 後
case 3	False	ファイル先頭
case 4	False	dictConfig 後

# main.py

import logging.config
import sub

if __name__ == "__main__":
    logging.config.dictConfig({
        'version': 1,
        'formatters': {
            'brief': {
                'format': '[%(asctime)s] %(levelname)s in %(module)s %(funcName)s: %(message)s',
            }
        },
        'handlers': {
            'console': {
                'class': 'logging.StreamHandler',
                'formatter': 'brief',
                'stream': 'ext://sys.stdout',
            }
        },
        'root': {
            'level': 'DEBUG',
            'handlers': ['console']
        },
        # (1)
        # 'disable_existing_loggers': False,
    })
    # (2)
    # import sub

    logger = logging.getLogger(__name__)
    logger.debug("TEST")

    sub.funcA()
    sub.funcB()

# sub.py

import logging

logger = logging.getLogger(__name__)

def funcA():
    logger.debug("TEST")

def funcB():
    logger = logging.getLogger(__name__)
    logger.debug("TEST")

Comments

[chomechome]

ご回答ありがとうございます。
subをimportした後にdictconfigを呼んでおります。
disable_existing_loggersはFalseにしています。

今、dictconfigを読んでからsubをimportするようにしたら関数外でloggerを取得してもログ出力されるようになりました。

[chomechome]

dictconfigを呼んでから、subをimportするようにしたらログ出力されるようになった理由がわかりました。
dictconfigでは`rootロガー`に対して設定を定義しており、rootロガーに設定が反映される前に他ファイルでロガーを取得しても意図した設定が反映されないからです。

1. dictconfigでrootロガーに設定する。
2. subをimport
3. subでlogger取得(rootロガーの設定を引き継ぐ)
4. ログ出力
となるようです。

subをimport後に、dictconfigした際に、subの関数内でloggerを取得したらログ出力された理由。
1. subをimport
2.dictconfig
3. subの関数内でloggerを取得
→関数が呼ばれた時点のrootロガーに設定された後のloggerを取得
4.subでログ出力
ということが考察できました。

[teamikl]

解決されたみたいですが、
若干、原因に対しての認識が異なります。

>dictconfigでは`rootロガー`に対して設定を定義しており、rootロガーに設定が反映される前に他ファイルでロガーを取得しても意図した設定が反映されないからです。

ここの原因は、ドキュメントの引用箇所より

> fileConfig() が呼び出される前に存在した非ルートロガーを無効化してしまうからです。

disable_existing_loggers=True の場合は、
上記に示された通りの挙動になります。

disable_existing_loggers が False の場合は、ここの挙動を変更でき
回答の２番目のコードも、getLoggerや import sub の位置に関わらず、
(dictConfig後であれば) 期待通りの挙動になるはずです。

なので、根本的な解決策は
import sub を dictConfig の後にする、ではなく
'disable_existing_loggers': False の設定だと思います。

一応、import sub を後に遅らせるでも意図通りの挙動になるので
充分かもしれませんが、ファイル先頭でimport出来ない等の
制限に成ります。

> subをimportした後にdictconfigを呼んでおります。
> disable_existing_loggersはFalseにしています。

もし、この条件で質問文に記載されたような挙動になっていた場合は、
dictConfigの設定方法に齟齬があるのかもしれません。

disable_existing_loggersが正しく False に設定されているか、
TrueとFalseで挙動の違いを確認できるか等を再確認してみてください。

[chomechome]

ご回答ありがとうございます。
disable_existing_loggersのTrue、Falseの挙動について、これから確認いたします。
昨日、実験して確認した内容は下記になります。

sub.pyについて下記のように関数外でloggerを取得する。
```python
logger = logging.getLogger(__name__)
def funcA():
logger.debug('hoge')
```

main.pyについて下記のように、sub.pyをimport後にdictconfigにて設定する。
sub.pyでは関数外でloggerを取得しているので、sumをimportした際にloggerの取得が行われ、そのloggerはmain.pyでのloggerの設定が効いていない。
```python
import sub

logging.config.dictConfig('path to setting file')

sub.funcA()
```

dictconfigした後にsubをimportするようにしたら、dictconfigにてロガーへの設定が行われ、subをimportした際に設定完了したロガーが読み込まれる。

```python
logging.config.dictConfig('path to setting file')

import sub

sub.funcA()
```

[teamikl]

「disable_existing_loggersがTrue の時」の挙動は、説明された通りで合ってます。
それ自体は間違いではないのですが、認識が異なると思った点は

＞disable_existing_loggersはFalseにしています。

とのことなので、懸念があるのは、
disable_existing_loggers を False にしたつもりが設定が効いてないケース。
この設定は、デフォルト(何も指定しない場合) で True です。

logging.config.dictConfig('path to setting file')
の'path to setting file' で省略された箇所が重要で、
特に disable_existing_loggers を設定した箇所辺りを要確認。