2つのpythonファイルでloggingの挙動が異なる

前提・実現したいこと

pythonのloggingで，jsonファイルに記述した設定ファイルからloggerを定義し，ログの記録を行いたい．

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

arduino.pyでは期待通り標準出力およびファイルにログの出力がされるが，baseapp.pyではどちらの出力もされません．
baseapp.pyのほうで，どこかでログレベルがWARNINGに設定されている可能性があるが，原因がわかりません．

該当のソースコード

json
1{
2    "version": 1,
3    "disable_existing_loggers": false,
4    "filters": {},
5
6    "formatters": {
7        "mainFormatter": {
8            "format": "%(asctime)s %(filename)s:%(lineno)s %(funcName)s %(module)s [%(levelname)s]: %(message)s"
9        },
10        "print": {
11            "format": "[%(levelname)s]\t%(message)s",
12            "level": "INFO"
13        }
14    },
15
16    "handlers": {
17        "logFileHandler": {
18            "class": "logging.FileHandler",
19            "level": "DEBUG",
20            "formatter": "mainFormatter",
21            "filename": "./logs/__main__.log",
22            "mode": "a",
23            "encoding": "utf-8"
24        },
25        "printHandler": {
26            "class": "logging.StreamHandler",
27            "level": "DEBUG",
28            "formatter": "print",
29            "stream": "ext://sys.stdout"
30        },
31        "arduinoHandler": {
32            "class": "logging.FileHandler",
33            "level": "DEBUG",
34            "formatter": "mainFormatter",
35            "filename": "./logs/arduino.log",
36            "mode": "a",
37            "encoding": "utf-8"
38        },
39        "guiHandler": {
40            "class": "logging.FileHandler",
41            "level": "DEBUG",
42            "formatter": "mainFormatter",
43            "filename": "./logs/gui.log",
44            "mode": "a",
45            "encoding": "utf-8"
46        }
47    },
48
49    "loggers": {
50        "__main__": {
51            "level": "DEBUG",
52            "handlers": ["logFileHandler", "printHandler"],
53            "propagate": false
54        },
55        "arduino": {
56            "level": "DEBUG",
57            "handlers": ["arduinoHandler", "printHandler"],
58            "propagate": false
59        },
60        "gui": {
61            "level": "DEBUG",
62            "handler": ["guiHandler"],
63            "propagate": false
64        },
65        "gui.app": {
66            "level": "DEBUG",
67            "handler": ["guiHandler", "printHandler"],
68            "propagate": false
69        },
70        "gui.frame": {
71            "level": "DEBUG",
72            "handler": ["guiHandler", "printHandler"],
73            "propagate": false
74        }
75    },
76
77    "root": {
78        "level": "DEBUG"
79    }
80}

python
1# coding: utf-8
2# arduino.py
3import os
4import csv
5import time
6import serial
7import threading
8from json import load
9from logging import config, getLogger
10with open('./config/log_conf.json', 'r') as f:
11    config.dictConfig(load(f))
12
13
14class Arduino:
15    def __init__(self) -> None:
16        self.logger = getLogger('arduino')
17        self.logger.debug('init arduino')
18        
19
20def main():
21    ard = Arduino()
22    try:
23        i = 0
24        while True:
25            i += 1
26            ard.logger.info(i)
27            time.sleep(0.02)
28    except KeyboardInterrupt as e:
29        ard.logger.info('finish with Cntl-C')
30
31
32if __name__ == '__main__':
33    main()

python
1# coding: utf-8
2# baseapp.py
3import os
4import time
5import tkinter as tk
6from json import load
7from logging import config, getLogger
8with open('./config/log_conf.json', 'r') as f:
9    config.dictConfig(load(f))
10
11
12class BaseApp(tk.Tk):
13    def __init__(self):
14        super().__init__()
15        self.logger = getLogger('gui.app')
16        self.title('BaseApp')
17        self.logger.debug("BaseApp is initialized.")
18
19class BaseFrame(tk.Frame):
20    def __init__(self, master=None):
21        self.logger = getLogger("gui.frame")
22        self.master = BaseApp() if master == None else master
23        super().__init__(master=self.master)
24        self.logger.debug("%sFrame is initialized.", self.__class__)
25
26if __name__ == '__main__':
27    app = BaseFrame()
28    app.logger.info("app is running")
29    app.mainloop()

試したこと

rootの設定

ルートロガーにハンドラーが定義されておらず，basicConfig()が自動で呼び出されている可能性の検証のため，rootに対してハンドラーの設定を行った．loggingドキュメント

json
1"root": {
2        "level": "DEBUG"
3        "handler": ["logFileHandler"]
4    }

しかし，これが原因であればarduino.pyでも同様に動作しないはず．

ログレベルの変更

baseapp.pyのclass.__init__内のself.logger.debug(''')をself.logger.warning(''')とするとログが標準出力に表示されました．ファイルへの出力は相変わらずされないです．どこかで，ログのレベルがWARNINGに設定されている可能性があるのかと思いましたが，loggingに関する記述はarduino.pyとbaseapp.pyで同じなのでなぜこのようになるのかわかりません．

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

Python 3.9.1
tkinter 8.6.9
logging 0.5.1.2

ここにより詳細な情報を記載してください。

行動規範の内容に同意します

回答2件

ベストアンサー

おはようございます。

問題文読ませていただきました。

python
1"gui": {
2    "level": "DEBUG",
3    "handler": ["guiHandler"],
4    "propagate": false
5},
6"gui.app": {
7    "level": "DEBUG",
8    "handler": ["guiHandler", "printHandler"],
9    "propagate": false
10},
11"gui.frame": {
12    "level": "DEBUG",
13    "handler": ["guiHandler", "printHandler"],
14    "propagate": false
15}