🧙🏼♂️
Python:マルチプロセス動作下における単一ファイルへのログ取得
YAMLで設定しながらログを取る
方々駆けずり回りながらようやっとのことでマルチスレッド処理における
ログ出力を構築できたので、ここに記したい。
ProcessPoolExecutorを使用したマルチプロセスについて書くが、
ThreadPoolExecutorでも同じ。
AIはまだ役に立たない
GPT-4oとかに聞いても、この問題に対してはあまり明確な回答がもらえなかった。
いや、回答は貰えるのだが、クラス分けしたりYAML使ったりすると、
一気に冗長になったりエラー吐いたりして、思うようなログの取得コードにならない。
あと、ネットの海を漂っても、結構mainメソッドの中で全部書かれてたりして、
クラスに分けたり別ファイルに書いたりした時にどうなるのかイマイチ分からなかったりした。
mainメソッドはあまり書きたくない派なのだが、まぁ今回はこれで実現できたしいいかな。
結論 = コード
どんな構成か
- 基本的にログのセッティングはプログラム実行時に1度だけ使うようなものなので、
メインメソッドに出来るだけ設定を書いたりしない - ログのフォーマット等はYAMLファイルに書いておく
- ログの出力ファイル名も自動的に変わったりlogフォルダを作ってそこに保存する
ということで、以下の構成になった - main.py : main()メソッドと自前のクラス内に処理メソッドを書いた
- class_logsetting.py : loggerの設定を行うクラスを作った
- logconf.yaml : loggerの基本設定はYAMLファイルで作った
解説というか、自分へのメモ書き
基本はlogger = logging.getLogger( name = xxxx )でログ取りの為のロガーが生成される。
引数無しで呼び出すとルートロガーになり、基本的に1つしか呼び出せない。
(複数呼び出すとエラーになる)
nameは自由に付けられるのだが、その名前付きロガーに対して設定しなくちゃいけない。
seleniumとかよく使うものはlogger.nameを調べてログの出力レベルを変えておくのが良いです。
ちなみに、ルートロガーから子ロガーが生成されますが、親ロガーの設定を引き継ぎます。
最初p_logger.setLevel(dbg_level)をDEBUGレベルにしたら
seleniumから凄い量のログが出てきて困った。
結局、子ロガーの設定を決めれば親ロガーから引き継がれないので、個別設定すればOK。
今回これでなんとなーくロガーの使い方や挙動が分かるようになってきたけど、
まだまだ使いこなすには至ってないと思う。
なので、多少「こいつホントに分かってるのか？」みたいな部分があっても許してほしい。
参考にさせてもらったWebサイト
これらのページが無ければマルチスレッドでのログ出力は実現できなかったので感謝です。
コード全容
main.pyのコード
main.py
import time
import multiprocessing
from argparse import ArgumentParser
from concurrent.futures import ProcessPoolExecutor
from logging import getLogger, handlers, DEBUG, INFO, ERROR
from class_logsetting import LogSetting
logger = getLogger(__name__) #全体のためのlogger。別ファイルでもこれは必ず書く
class Test():
def __init__(self):
pass
def func1(self, a, b):
logger.info(f"a = {a}, b = {b}")
logger.debug(f"a + b = {a+b}")
time.sleep(3)
a = a + b
logger.info(f"a = {a}, b = {b}")
return a
def func2(self, c, d):
logger.info(f"c = {c}, d = {d}")
logger.debug(f"c + d = {c+d}")
time.sleep(1)
c = c + d
logger.info(f"c = {c}, d = {d}")
return c, d
# ProcessPoolExectorでクラスを跨ぐ時はラッパーが必要
# func1メソッドのラッパー
def run_wrapper_func1(a, b):
obj = Test()
return obj.func1(a, b)
# func2メソッドのラッパー
def run_wrapper_func2(c, d):
obj = Test()
return obj.func2(c, d)
def log_initializer(que, dbg_opt=False):
"""
| ProcessPoolExecutor の initializerオプションで呼ばれる
| 各"子プロセス"で一度だけ実行されるlog設定用メソッド
| loggerとqueueHandlerを子プロセス実行前に作成する事で、
| 各"子プロセス"でのloggerをQueHandlerへと送り込む
"""
dbg_level = INFO
if dbg_opt is True:
dbg_level = DEBUG
p_logger = getLogger() # 子プロセスのルートロガーを生成
p_logger.setLevel(dbg_level) # 子ロガーのログレベルを決めないとNOTSET(0)となり出力されない
# Selenium関係のログ出力をERRORレベルに制限する(YAMLの上書き)
urllib3_logger = getLogger(name = 'urllib3')
urllib3_logger.setLevel(ERROR)
sel_logger = getLogger(name = 'selenium')
sel_logger.setLevel(ERROR)
qh = handlers.QueueHandler(que) # ログレベルのデフォルトはNOTSET(0)
p_logger.addHandler(qh)
# 設定確認用, 通常は必要ない
from logging import getLevelName
p_logger.info(f'root.level: {logger.name} {getLevelName(p_logger.level)} ({p_logger.level})')
p_logger.info(f'logger.level: {logger.name} {getLevelName(logger.level)} ({logger.level})')
p_logger.info(f'qh.level: {logger.name} {getLevelName(qh.level)} ({qh.level})')
return
####### main #######
def main():
# 引数読込パーサーの生成
parser = ArgumentParser(
description="loggerの挙動を見るプログラム",
add_help=True,
)
parser.add_argument('-D', '--DEBUG', action='store_true', help='debug option')
args = parser.parse_args()
# ログ用インスタンス生成
LogSetting.loading_log_setting("logconf.yaml", "log", args.DEBUG)
root_logger = getLogger()
logger.info("最初のログ記録")
with multiprocessing.Manager() as manager:
que = manager.Queue(-1)
listener = handlers.QueueListener(que, *root_logger.handlers, respect_handler_level=True)
listener.start()
with ProcessPoolExecutor(
max_workers = 2,
initializer=log_initializer,
initargs=(que,args.DEBUG,),
) as executor:
proc_func1 = executor.submit(run_wrapper_func1, 1, 2)
proc_func2 = executor.submit(run_wrapper_func2, 3, 4)
proc_func1.result()
proc_func2.result()
listener.stop()
logger.info("並列処理が終わった後でもloggerは使える")
if __name__ == "__main__":
main()
class_logsetting.pyのコード
class_logsetting.py
import os
import datetime
from logging import config, DEBUG, ERROR
import yaml
class LogSetting:
@classmethod # <-- ぶっちゃけstaticmethodで問題ない
def generate_log_filename(cls):
"""
| ログファイルの名前を自動生成
| 書式: log_{YYYYMMDD}_{HHMMSS.log}
| サンプル: log_20250108_150245.log
"""
return f"log_{datetime.datetime.now().strftime('%Y%m%d_%H%M%S')}.log"
@classmethod # <-- ぶっちゃけstaticmethodで問題ない
def loading_log_setting(cls, log_setting_file, log_dir, dbg_opt=False):
"""
| ログの設定をロード
| 同一フォルダに置いたlog_setting_fileを読込
| ログ保存フォルダ log_dir を生成する
| 引数指定された場合は、ログ出力レベルをdebugに変更
Parameters:
---
log_setting_file : str
ログ設定を書いたYAMLファイルのファイル名を指定
log_gir : str
ログ保存フォルダ(指定ディレクトリ下にyyyymm名のディレクトリを作成してlog保存)
dbg_opt : bool, default = False
logging.DEBUGレベルでログを出力させたい時にTrueを与える
"""
# ログ設定ファイルからログ設定を読み込む
try:
# YAML設定ファイルの読み込み
with open(log_setting_file, encoding="utf-8") as file:
config_data = yaml.safe_load( file.read() )
if config_data is None:
raise ValueError("There is no YAML config file. Please check the config data.")
# logフォルダの下に月別のフォルダを作成する
log_dir += '\\' + datetime.datetime.now().strftime('%Y%m') # ←はWindowsのパス区切り文字である事に注意
if not os.path.exists(log_dir): # logフォルダが存在していない場合は新規作成
os.makedirs(log_dir)
# 動的にファイル名を生成し、YAMLのファイル名を更新する
log_filename = LogSetting.generate_log_filename()
config_data['handlers']['file']['filename'] = os.path.join(os.getcwd(), log_dir, log_filename)
if dbg_opt is True:
config_data["root"]["level"] = DEBUG
config_data["handlers"]["file"]["level"] = DEBUG
# ログ設定の初期化
config.dictConfig(config_data)
except Exception as e:
print(f"Error loading YAML configuration: {str(e)}")
logconf.yamlのコード
logconf.yaml
# ログ出力設定ファイル
version: 1
# ロガーの設定をロードしない場合の挙動
disable_existing_loggers: False
# ルートロガーの設定
root:
level: INFO
handlers: [file]
# サブモジュールのロガー設定
loggers:
console:
level: INFO
handlers: [console]
propagate: no
file:
level: INFO
handlers: [file]
propagate: no
urllib3:
level: ERROR
handlers: [file]
propagate: no
selenium:
level: ERROR
handlers: [file]
propagate: no
# 書式
formatters:
multi:
format: '[%(asctime)s] [%(name)-15s] [%(levelname)-8s] [%(processName)-15s] [%(module)-10s] [%(funcName)-18s]: %(message)s'
# ハンドラ
handlers:
console:
class: logging.StreamHandler
level: INFO
formatter: multi
stream: ext://sys.stdout
file:
class: logging.handlers.RotatingFileHandler
level: INFO # 初期値をDEBUGに変えるならココ
filename: log_execute.log
formatter: multi
encoding: utf-8
maxBytes: 10000000
backupCount: 20
queue:
class: logging.handlers.QueueHandler
level: INFO
formatter: multi
実行結果
MainProcessから子プロセスが2つ生成されて、それぞれlog_initializerが動いて
logger.levelを設定している事がわかる。
moduleやfuncnameを設定している事で何のメソッドがlogを出力しているか分かりやすい。
python main.py
[2025-06-24 22:00:21,204] [__main__ ] [INFO ] [MainProcess ] [main ] [main ]: 最初のログ記録
[2025-06-24 22:00:21,300] [root ] [INFO ] [SpawnProcess-3 ] [main ] [log_initializer ]: root.level: __mp_main__ INFO (20)
[2025-06-24 22:00:21,300] [root ] [INFO ] [SpawnProcess-2 ] [main ] [log_initializer ]: root.level: __mp_main__ INFO (20)
[2025-06-24 22:00:21,301] [root ] [INFO ] [SpawnProcess-3 ] [main ] [log_initializer ]: logger.level: __mp_main__ NOTSET (0)
[2025-06-24 22:00:21,301] [root ] [INFO ] [SpawnProcess-2 ] [main ] [log_initializer ]: logger.level: __mp_main__ NOTSET (0)
[2025-06-24 22:00:21,301] [root ] [INFO ] [SpawnProcess-3 ] [main ] [log_initializer ]: qh.level: __mp_main__ NOTSET (0)
[2025-06-24 22:00:21,301] [root ] [INFO ] [SpawnProcess-2 ] [main ] [log_initializer ]: qh.level: __mp_main__ NOTSET (0)
[2025-06-24 22:00:21,301] [__mp_main__ ] [INFO ] [SpawnProcess-3 ] [main ] [func1 ]: a = 1, b = 2
[2025-06-24 22:00:21,301] [__mp_main__ ] [INFO ] [SpawnProcess-2 ] [main ] [func2 ]: c = 3, d = 4
[2025-06-24 22:00:22,306] [__mp_main__ ] [INFO ] [SpawnProcess-2 ] [main ] [func2 ]: c = 7, d = 4
[2025-06-24 22:00:24,306] [__mp_main__ ] [INFO ] [SpawnProcess-3 ] [main ] [func1 ]: a = 3, b = 2
[2025-06-24 22:00:24,348] [__main__ ] [INFO ] [MainProcess ] [main ] [main ]: 並列処理が終わった後でもloggerは使える
--DEBUGオプションつけて実行した場合
ルートロガーの様に見えているものは子プロセスそれぞれのルートロガーである事に注意。
QueHandlerに届いた順に出力されるので、マルチプロセスで処理すると順番が入れ子になる。
例えば何か区切り文字を設定しておいてExcelで開き、processNameでソートすると見やすい。
python main.py -D
[2025-06-24 22:00:26,762] [__main__ ] [INFO ] [MainProcess ] [main ] [main ]: 最初のログ記録
[2025-06-24 22:00:26,843] [root ] [INFO ] [SpawnProcess-3 ] [main ] [log_initializer ]: root.level: __mp_main__ DEBUG (10)
[2025-06-24 22:00:26,843] [root ] [INFO ] [SpawnProcess-2 ] [main ] [log_initializer ]: root.level: __mp_main__ DEBUG (10)
[2025-06-24 22:00:26,844] [root ] [INFO ] [SpawnProcess-3 ] [main ] [log_initializer ]: logger.level: __mp_main__ NOTSET (0)
[2025-06-24 22:00:26,844] [root ] [INFO ] [SpawnProcess-2 ] [main ] [log_initializer ]: logger.level: __mp_main__ NOTSET (0)
[2025-06-24 22:00:26,844] [root ] [INFO ] [SpawnProcess-3 ] [main ] [log_initializer ]: qh.level: __mp_main__ NOTSET (0)
[2025-06-24 22:00:26,844] [root ] [INFO ] [SpawnProcess-2 ] [main ] [log_initializer ]: qh.level: __mp_main__ NOTSET (0)
[2025-06-24 22:00:26,844] [__mp_main__ ] [INFO ] [SpawnProcess-3 ] [main ] [func1 ]: a = 1, b = 2
[2025-06-24 22:00:26,844] [__mp_main__ ] [INFO ] [SpawnProcess-2 ] [main ] [func2 ]: c = 3, d = 4
[2025-06-24 22:00:26,844] [__mp_main__ ] [DEBUG ] [SpawnProcess-3 ] [main ] [func1 ]: a + b = 3
[2025-06-24 22:00:26,844] [__mp_main__ ] [DEBUG ] [SpawnProcess-2 ] [main ] [func2 ]: c + d = 7
[2025-06-24 22:00:27,850] [__mp_main__ ] [INFO ] [SpawnProcess-2 ] [main ] [func2 ]: c = 7, d = 4
[2025-06-24 22:00:29,850] [__mp_main__ ] [INFO ] [SpawnProcess-3 ] [main ] [func1 ]: a = 3, b = 2
[2025-06-24 22:00:29,890] [__main__ ] [INFO ] [MainProcess ] [main ] [main ]: 並列処理が終わった後でもloggerは使える
Discussion