LoginSignup
1
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 1 year has passed since last update.

@JuvenileTalk9

マルチプロセス環境でのファイルへのロギングについて

Last updated at Posted at 2024-01-12

Pythonでファイルへのログ記録を行う場合は、FileHandlerを用いる方法が一般的ですが、マルチプロセス環境では正常に動作しないことがリファレンスに明記されています。

ログ記録はスレッドセーフであり、単一プロセスの複数のスレッドからの単一ファイルへのログ記録はサポートされていますが、複数プロセスからの単一ファイルへのログ記録はサポートされません。なぜなら、複数のプロセスをまたいで単一のファイルへのアクセスを直列化する標準の方法が Python には存在しないからです。

クックブックでは、対策としてSocketHandlerを使う方法と、QueueHandlerを使う方法を紹介されています。

複数のプロセスから単一ファイルへログ記録しなければならないなら、最も良い方法は、すべてのプロセスが SocketHandler に対してログ記録を行い、独立したプロセスとしてソケットサーバを動かすことです。ソケットサーバはソケットから読み取ってファイルにログを書き出します。

別の方法として、 Queue と QueueHandler を使って、マルチプロセスアプリケーションの1つのプロセスに全ての logging イベントを送る事ができます。

この2つのうち、より実装がシンプルなQueueHandlerを使った方法を試してみました。

main.py

main.py
import logging
import logging.config
import logging.handlers
import threading
from multiprocessing import Queue

import sub_process


logger = logging.getLogger("test")


class LoggerThread(threading.Thread):

    def __init__(self, queue: Queue) -> None:
        super().__init__()
        self.queue = queue

    def run(self) -> None:
        while True:
            record = self.queue.get()
            if record is None:
                break
            logger = logging.getLogger(record.name)
            record.msg = "LoggerThreadで記録されたログです: " + record.msg
            logger.handle(record)


def main():
    d = {
        "version": 1,
        "formatters": {
            "full": {
                "format": "{asctime} [{levelname:8}] {module} line:{lineno:d} {message}",
                "style": "{",
            },
            "simple": {
                "format": "{asctime} [{levelname:8}] {message}",
                "style": "{",
            },
        },
        "handlers": {
            "file": {
                "level": "DEBUG",
                "class": "logging.handlers.RotatingFileHandler",
                "filename": "logs/test.log",
                "formatter": "full",
                "maxBytes": 1024 * 1024 * 1,    # 1MB
                "backupCount": 3,
            },
            "console": {
                "level": "DEBUG",
                "class": "logging.StreamHandler",
                "formatter": "simple",
            },
        },
        "loggers": {
            "test": {
                "handlers": ["file", "console"],
                "level": "DEBUG",
            }
        },
    }

    logging.config.dictConfig(d)
    logger.info("これはメインスレッドのmain.pyのログメッセージです ★1")

    q = Queue()
    logger_thread = LoggerThread(q)
    logger_thread.start()

    process = sub_process.SubProcess(5, 1, q)
    process.start()

    logger.info("これはメインスレッドのmain.pyのログメッセージです ★2")

    process.join()
    q.put(None)
    logger_thread.join()


if __name__ == "__main__":
    main()

sub_process.py

sub_process.py
import time
import logging
import logging.handlers
from multiprocessing import Process, Queue


class SubProcess(Process):

    def __init__(self, n_print: int, sleep_time: float, queue: Queue):
        super().__init__()
        logger = logging.getLogger("test")
        self.n_print = n_print
        self.sleep_time = sleep_time
        self.queue = queue
        logger.info("これはメインスレッドのsub_process.pyのログメッセージです")

    def run(self):
        logger = logging.getLogger()
        qh = logging.handlers.QueueHandler(self.queue)
        logger.addHandler(qh)
        logger.setLevel(logging.NOTSET)

        logger = logging.getLogger("test")
        while len(logger.handlers) > 0:
            logger.removeHandler(logger.handlers[0])
        for i in range(self.n_print):
            logger.info(f"これはサブプロセスのsub_process.pyのログメッセージです。count: {i + 1}")
            time.sleep(self.sleep_time)

test.logへの出力結果

2024-01-12 15:45:20,095 [INFO    ] main line:74 これはメインスレッドのmain.pyのログメッセージです ★1
2024-01-12 15:45:20,095 [INFO    ] sub_process line:15 これはメインスレッドのsub_process.pyのログメッセージです
2024-01-12 15:45:20,096 [INFO    ] main line:81 これはメインスレッドのmain.pyのログメッセージです ★2
2024-01-12 15:45:20,098 [INFO    ] sub_process line:27 LoggerThreadで記録されたログです: これはサブプロセスのsub_process.pyのログメッセージです。count: 1
2024-01-12 15:45:21,102 [INFO    ] sub_process line:27 LoggerThreadで記録されたログです: これはサブプロセスのsub_process.pyのログメッセージです。count: 2
2024-01-12 15:45:22,103 [INFO    ] sub_process line:27 LoggerThreadで記録されたログです: これはサブプロセスのsub_process.pyのログメッセージです。count: 3
2024-01-12 15:45:23,104 [INFO    ] sub_process line:27 LoggerThreadで記録されたログです: これはサブプロセスのsub_process.pyのログメッセージです。count: 4
2024-01-12 15:45:24,105 [INFO    ] sub_process line:27 LoggerThreadで記録されたログです: これはサブプロセスのsub_process.pyのログメッセージです。count: 5
2024-01-12 15:45:25,111 [INFO    ] main line:86 これはメインスレッドのmain.pyのログメッセージです ★3

補足

SubProcess.runでtestのハンドラを削除しています。

logger = logging.getLogger("test")
while len(logger.handlers) > 0:
    logger.removeHandler(logger.handlers[0])

この直前では、testにRotatingFileHandlerとStreamHandlerが設定されており、propagateが有効になっています。またrootにQueueHandlerが設定されています。

もしこの状態でtestのハンドラを削除せずにロギングを行おうとすると、testのハンドラが直接呼ばれるのと同時に、rootのQueueHandlerを経由してtestのハンドラが再度呼ばれることになるため、結果として同じ内容が2行ずつログ出力されることになってしまいます。

2024-01-12 17:00:04,652 [INFO    ] main line:67 これはメインスレッドのmain.pyのログメッセージです ★1
2024-01-12 17:00:04,656 [INFO    ] sub_process line:15 これはメインスレッドのsub_process.pyのログメッセージです
2024-01-12 17:00:04,657 [INFO    ] main line:76 これはメインスレッドのmain.pyのログメッセージです ★2
2024-01-12 17:00:04,659 [INFO    ] sub_process line:27 これはサブプロセスのsub_process.pyのログメッセージです。count: 1
2024-01-12 17:00:04,659 [INFO    ] sub_process line:27 LoggerThreadで記録されたログです: これはサブプロセスのsub_process.pyのログメッセージです。count: 1
2024-01-12 17:00:05,660 [INFO    ] sub_process line:27 これはサブプロセスのsub_process.pyのログメッセージです。count: 2
2024-01-12 17:00:05,660 [INFO    ] sub_process line:27 LoggerThreadで記録されたログです: これはサブプロセスのsub_process.pyのログメッセージです。count: 2
2024-01-12 17:00:06,663 [INFO    ] sub_process line:27 これはサブプロセスのsub_process.pyのログメッセージです。count: 3
2024-01-12 17:00:06,663 [INFO    ] sub_process line:27 LoggerThreadで記録されたログです: これはサブプロセスのsub_process.pyのログメッセージです。count: 3
2024-01-12 17:00:07,668 [INFO    ] sub_process line:27 これはサブプロセスのsub_process.pyのログメッセージです。count: 4
2024-01-12 17:00:07,668 [INFO    ] sub_process line:27 LoggerThreadで記録されたログです: これはサブプロセスのsub_process.pyのログメッセージです。count: 4
2024-01-12 17:00:08,670 [INFO    ] sub_process line:27 これはサブプロセスのsub_process.pyのログメッセージです。count: 5
2024-01-12 17:00:08,670 [INFO    ] sub_process line:27 LoggerThreadで記録されたログです: これはサブプロセスのsub_process.pyのログメッセージです。count: 5

もしtestのpropagateを無効にした場合はtestのハンドラが呼ばれた段階でrootへ伝搬されなくなるので、サブプロセス側でのファイル書き込みが発生してしまいます。

2024-01-12 17:02:55,921 [INFO    ] main line:67 これはメインスレッドのmain.pyのログメッセージです ★1
2024-01-12 17:02:55,928 [INFO    ] sub_process line:15 これはメインスレッドのsub_process.pyのログメッセージです
2024-01-12 17:02:55,929 [INFO    ] main line:76 これはメインスレッドのmain.pyのログメッセージです ★2
2024-01-12 17:02:55,930 [INFO    ] sub_process line:27 これはサブプロセスのsub_process.pyのログメッセージです。count: 1
2024-01-12 17:02:56,931 [INFO    ] sub_process line:27 これはサブプロセスのsub_process.pyのログメッセージです。count: 2
2024-01-12 17:02:57,932 [INFO    ] sub_process line:27 これはサブプロセスのsub_process.pyのログメッセージです。count: 3
2024-01-12 17:02:58,934 [INFO    ] sub_process line:27 これはサブプロセスのsub_process.pyのログメッセージです。count: 4
2024-01-12 17:02:59,936 [INFO    ] sub_process line:27 これはサブプロセスのsub_process.pyのログメッセージです。count: 5

サブプロセス内では元あったtestのハンドラを削除することで、QueueHandlerだけを呼び出すようになり、意図した通りの動作にすることができます。このあたりはもう少しうまくやる方法があるかもしれない。。。

1
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
1
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?