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

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

https://docs.python.org/ja/3/howto/logging-cookbook.html#multiple-processes

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

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

https://docs.python.org/ja/3/howto/logging-cookbook.html#network-logging

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

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

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

### main.py
```python: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

```python: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`のハンドラを削除しています。

```python
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`だけを呼び出すようになり、意図した通りの動作にすることができます。このあたりはもう少しうまくやる方法があるかもしれない。。。