logging+python-daemon でログがうまく出力されない

タイトルの状況で数時間悩んだのと、そのものずばりな日本語記事がなかった？のでメモしておきます。
※プログラム内で`logging`を設定していますが、この辺の使い方もいまいち理解しきれてないのでスタンダードな設定ではないかもしれません……。

# 環境

- CentOS 7
- Python 3.6

# 登場人物（？）

- logging：ログをいい感じに取れるやつ。標準モジュール
- daemon：プログラムをデーモン化（バックグラウンドでプロセスを動かす）してくれるやつ。使いたいときは`pip install python-daemon`する

# 発端
`logging`を設定したプログラムを書いていたところ、

``` python:main.py
import logging
import logging.config
import time
from datetime import datetime

logging.config.dictConfig({
    "version": 1,
    "formatters": {
        "customFormat": {
            "format": "%(asctime)s %(filename)-10s %(funcName)-12s:%(lineno)3d %(levelname)-8s %(message)s"
        },
    },
    "handlers": {
        "fileHandler": {
            "class": "logging.FileHandler",
            "formatter": "customFormat",
            "filename": "./logger.log",
        },
    },
    "root": {
        "handlers": ["fileHandler"],
        "level": logging.INFO
    }
})

logger = logging.getLogger("__name__")


def jobs():
    print(datetime.now())
    time.sleep(5)


def main():
    logger.info("プログラムを開始します")

    try:
        for i in range(5):
            jobs()
    except KeyboardInterrupt:
        logger.info("プログラムを終了します")
    except Exception:
        logger.exception("エラーが発生しました")


if __name__ == '__main__':
    main()
```

``` bash:実行結果
$ python main.py
2020-05-12 20:07:10.292458
2020-05-12 20:07:15.296090
2020-05-12 20:07:20.301494
2020-05-12 20:07:25.306906
2020-05-12 20:07:30.312486

$ cat logger.log
2020-05-12 20:07:10,292 main.py    main        : 45 INFO     プログラムを開始します
2020-05-12 20:07:10,292 main.py    jobs        : 40 INFO     時間を出力しました
2020-05-12 20:07:15,296 main.py    jobs        : 40 INFO     時間を出力しました
2020-05-12 20:07:20,301 main.py    jobs        : 40 INFO     時間を出力しました
2020-05-12 20:07:25,307 main.py    jobs        : 40 INFO     時間を出力しました
2020-05-12 20:07:30,312 main.py    jobs        : 40 INFO     時間を出力しました
```

`jobs()`をデーモン化したくなったので`daemon`を導入しました。

``` python:main.py
import os
import logging
import logging.config
import time
from datetime import datetime

import daemon
import daemon.pidfile

logging.config.dictConfig({
    "version": 1,
    "formatters": {
        "customFormat": {
            "format": "%(asctime)s %(filename)-10s %(funcName)-12s:%(lineno)3d %(levelname)-8s %(message)s"
        },
    },
    "handlers": {
        "fileHandler": {
            "class": "logging.FileHandler",
            "formatter": "customFormat",
            "filename": "./logger.log",
        },
    },
    "root": {
        "handlers": ["fileHandler"],
        "level": logging.INFO
    }
})

logger = logging.getLogger("__name__")

def start():
    """
    デーモン化する
    """
    # 多重起動防止
    pid = daemon.pidfile.PIDLockFile("/tmp/testdaemon.pid")
    if pid.is_locked():
        raise Exception("Process is already started.")

    # デーモン化関連の設定
    dc = daemon.DaemonContext(
        working_directory = os.getcwd(),       # デーモン化した際のカレントディレクトリ。設定しない場合は"/"になる
        umask = 0o002,
        pidfile = pid,                         # バックグラウンドで動かす場合はpidファイルが必要らしい
        stdout = open("./daemonout.log", "a"), # 標準出力がファイル出力になるはず
        stderr = open("./daemonerr.log", "a")  # 標準エラー出力もファイル出力になるはず
        )

    def forever():
        for i in range(5):
            jobs()

    with dc:
        forever()


def jobs():
    print(datetime.now())
    logger.info("時間を出力しました")
    time.sleep(5)


def main():
    logger.info("プログラムを開始します")

    try:
        start()
    except KeyboardInterrupt:
        logger.info("プログラムを終了します")
    except Exception:
        logger.exception("エラーが発生しました")


if __name__ == '__main__':
    main()
```

``` bash:実行結果
$ python main.py

$ ps aux | grep main.py
sss     14470 38.2  1.3  68332 27028 ?        S    20:26   0:01 python main.py
sss     14482  0.0  0.0  22556  1012 pts/1    S+   20:26   0:00 grep --color=auto main.py

$ cat logger.log
2020-05-12 20:26:20,621 main.py    main        : 74 INFO     プログラムを開始します

$ cat daemonout.log
2020-05-12 20:26:22.204808
2020-05-12 20:26:27.208074
2020-05-12 20:26:32.214878
2020-05-12 20:26:37.221952
2020-05-12 20:26:42.228493

$ cat daemonerr.log
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.6/logging/__init__.py", line 998, in emit
    self.flush()
  File "/usr/lib/python3.6/logging/__init__.py", line 978, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "main.py", line 85, in <module>
    main()
  File "main.py", line 77, in main
    start()
  File "main.py", line 64, in start
    forever()
  File "main.py", line 61, in forever
    jobs()
  File "main.py", line 69, in jobs
    logger.info("時間を出力しました")
Message: '時間を出力しました'
Arguments: ()
~~~以下Logging errorが続く~~~

```

- `ps`と`daemonout.log`の結果を見るに`jobs()`はちゃんとバックグラウンドで動いているっぽい
- でも`logging`でとっているはずのログが取れていない🤔
- `daemonerr.log`に出力されたエラーが`Bad file descriptor`……？？

# 原因
`daemon.DaemonContext()` を`with`で開くことで`with`ブロック内のプログラムをデーモン化してくれるようなのですが、その際に今まで作成したファイルディスクリプタ(`open()`とかで作成されるやつ……のはず)を全て閉じてしまうようです。
つまり、`logging`の開始時点で作成した`logger.log`に書き込むためのファイルディスクリプタも`with`ブロックに入った時点で閉じられてしまい、ファイルにアクセスできずに`Bad file descriptor`のエラーを吐いていたらしい。

# 対策
`daemon.DaemonContext()`には、ディスクリプタを閉じないようにするための`files_preserve`という引数が存在します。
この引数に`logging`で使っているディスクリプタを設定すればいいということみたいです。

``` python:main.py
# daemon.DaemonContext()の部分のみ抜粋
dc = daemon.DaemonContext(
    working_directory = os.getcwd(),
    umask = 0o002,
    pidfile = pid,
    files_preserve = [logging.root.handlers[0].stream],  # add
    stdout = open("./daemonout.log", "a"),
    stderr = open("./daemonerr.log", "a")
    )
```

``` bash:実行結果
$ cat logger.log
2020-05-12 20:51:46,897 main.py    main        : 75 INFO     プログラムを開始します
2020-05-12 20:51:48,292 main.py    jobs        : 70 INFO     時間を出力しました
2020-05-12 20:51:48,292 main.py    jobs        : 70 INFO     時間を出力しました
2020-05-12 20:51:53,297 main.py    jobs        : 70 INFO     時間を出力しました
2020-05-12 20:51:53,297 main.py    jobs        : 70 INFO     時間を出力しました
2020-05-12 20:51:58,303 main.py    jobs        : 70 INFO     時間を出力しました

$ cat daemonout.log
2020-05-12 20:51:48.292055
2020-05-12 20:51:53.297714
2020-05-12 20:51:58.303235
2020-05-12 20:52:03.309244
2020-05-12 20:52:08.312017

$ cat daemonerr.log

```
これで`logging`のログは`logger.log`に、標準出力と標準エラー出力はそれぞれ引数で指定したファイルに吐き出すことができました。

# `files_preserve`の設定値について
リストになっていることからもわかるように、複数指定することができます。
また、ディスクリプタの種類や使用しているロガーの階層などによって設定すべき値が少し変わるようです。
今回の`logging.root.handlers[0].stream`は、root loggerかつfile handlerを使っているときのもの……という認識です。
試してないのですが、rootじゃなくて1階層下のロガー（例えば`mylogger`）を設定したいときは`logging.root.mylogger.handlers[0].stream`とかでいけそうですかね。
あとはfile handlerではなくてsyslog handlerなんかを使おうとしたりすると末尾が違うみたいです。（この辺りは参考文献を見てみてください）


# 参考文献

[Maintaining Logging and/or stdout/stderr in Python Daemon - Stack Overflow](https://stackoverflow.com/questions/13180720/maintaining-logging-and-or-stdout-stderr-in-python-daemon)
[python-daemon日志记录的一个小问题_python_liuxingen的专栏-CSDN博客](https://blog.csdn.net/liuxingen/article/details/71169502)