LoginSignup
2
4

More than 3 years have passed since last update.

@sa_hm490(さ＊)

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

Last updated at Posted at 2020-05-12

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

環境

  • CentOS 7
  • Python 3.6

登場人物（？）

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

発端

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

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()
実行結果
$ 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を導入しました。

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()
実行結果
$ 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で使っているディスクリプタを設定すればいいということみたいです。

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")
    )
実行結果
$ 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
python-daemon日志记录的一个小问题_python_liuxingen的专栏-CSDN博客

2
4
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
2
4