虚無ありき

うるせーーーしらねーーー

Django の logging 設定

Django Python Logging

tl;dr

  • Django の logging の設定についてのメモ
  • Django の Default の設定 logging の設定は Admin に Email を送ったりしていたため、設定を弄った

何がしたいか

  • Application Server を WSGI にする場合と Local Server にする場合
  • LOG_LEVEL を development と production にする場合
  • 上のそれぞれ 2 パターン * 2 パターンを環境変数で切り替えられるようにしたかった
    • WSGI の場合は File のみに吐く
    • Local Server の場合は File と Console に吐く
    • development の場合は DEBUG レベルの Log と traceback を表示する
    • production の場合は INFO レベルの Log のみを表示する

環境

$ cat /etc/os-release
NAME="Alpine Linux"
ID=alpine
VERSION_ID=3.8.2
PRETTY_NAME="Alpine Linux v3.8"
HOME_URL="http://alpinelinux.org"
BUG_REPORT_URL="http://bugs.alpinelinux.org"
$ python -V
Python 3.7.2
$ django-admin version
2.1.5

Django の Logging の初期設定

初期設定は、Python の dictConfig 形式で表すと、

DEFAULT_LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse',
        },
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    'formatters': {
        'django.server': {
            '()': 'django.utils.log.ServerFormatter',
            'format': '[{server_time}] {message}',
            'style': '{',
        }
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'filters': ['require_debug_true'],
            'class': 'logging.StreamHandler',
        },
        'django.server': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'formatter': 'django.server',
        },
        'mail_admins': {
            'level': 'ERROR',
            'filters': ['require_debug_false'],
            'class': 'django.utils.log.AdminEmailHandler'
        }
    },
    'loggers': {
        'django': {
            'handlers': ['console', 'mail_admins'],
            'level': 'INFO',
        },
        'django.server': {
            'handlers': ['django.server'],
            'level': 'INFO',
            'propagate': False,
        },
    }
}

この設定は、Django - Docs - logging から引用すると、

  • DEBUG が True のとき:
  • DEBUG が False のとき:
  • DEBUG の値にかかわらず:
    • django.server ロガーは INFO レベル以上のメッセージをコンソールに送信します。
  • All loggers except django.server propagate logging to their parents, up to the root django logger. The console and mail_admins handlers are attached to the root logger to provide the behavior described above.

だそうだ。

もう少しちゃんと調べる。 まず、django.setup() した後に設定されている logger の list は、

# coding: utf-8
import logging
import os
from pprint import pprint

import django

if __name__ == "__main__":
    os.environ.setdefault("DJANGO_SETTINGS_MODULE", "config.settings")
    django.setup()
    pprint(logging.root.manager.loggerDict)

を使って、結果は、

$ python3 logging_test.py
{'django': <Logger django (INFO)>,
 'django.db': <logging.PlaceHolder object at 0x7f70c014deb8>,
 'django.db.backends': <Logger django.db.backends (INFO)>,
 'django.db.backends.schema': <Logger django.db.backends.schema (INFO)>,
 'django.request': <Logger django.request (INFO)>,
 'django.security': <logging.PlaceHolder object at 0x7f70bf5a46d8>,
 'django.security.csrf': <Logger django.security.csrf (INFO)>,
 'django.server': <Logger django.server (INFO)>,
 'django.template': <Logger django.template (INFO)>,
 'factory': <logging.PlaceHolder object at 0x7f70be564400>,
 'factory.generate': <Logger factory.generate (WARNING)>,
 'faker': <logging.PlaceHolder object at 0x7f70be508828>,
 'faker.factory': <Logger faker.factory (WARNING)>,
 'requests': <Logger requests (WARNING)>,
 'urllib3': <Logger urllib3 (WARNING)>,
 'urllib3.connection': <Logger urllib3.connection (WARNING)>,
 'urllib3.connectionpool': <Logger urllib3.connectionpool (WARNING)>,
 'urllib3.poolmanager': <Logger urllib3.poolmanager (WARNING)>,
 'urllib3.response': <Logger urllib3.response (WARNING)>,
 'urllib3.util': <logging.PlaceHolder object at 0x7f70be826e80>,
 'urllib3.util.retry': <Logger urllib3.util.retry (WARNING)>}

つまり、django 以外の library が logger を設定していたり、django.server 以外の logger が使われている。

Django で使われている Logger

Django - Docs - logging より、

  • django
    • django の Logger をまとめるための logger, logging 自体は行わない
  • django.request
    • request に関する logger。5xx 系は error, 4xx 系は warning として処理をする
    • [26/Feb/2019 08:48:34] "GET / HTTP/1.1" 200 4051 みたいな log を吐いている
  • django.server
    • runserver コマンドによって呼び出されたサーバーによって受信された request の処理に関する logger
    • 基本的には django.request と同じ
  • django.template
    • Template のレンダリングに関する logger
    • context 変数などが足りない場合 debug レベルの log を吐く
  • django.db.backends
    • データベースに関する logger
    • SQL 文などを debug で log している
  • django.security
    • セキュリティ関連に関する logger

とのことで、それぞれの logger の中身を調べると、

# coding: utf-8
import logging
import os

import django

if __name__ == "__main__":
    os.environ.setdefault("DJANGO_SETTINGS_MODULE", "config.settings")
    django.setup()
    print(vars(logging.getLogger("root")))
    for logger_name in logging.root.manager.loggerDict.keys():
        if "django" not in logger_name:
            continue
        print(vars(logging.getLogger(logger_name)))

$ python3 logging_test.py
{'filters': [], 'name': 'root', 'level': 0, 'parent': <RootLogger root (WARNING)>, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f5c77908cf8>}
{'filters': [], 'name': 'django.template', 'level': 0, 'parent': <Logger django (INFO)>, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f5c77908cf8>}
{'filters': [], 'name': 'django', 'level': 20, 'parent': <RootLogger root (WARNING)>, 'propagate': True, 'handlers': [<StreamHandler <stderr> (INFO)>, <AdminEmailHandler (ERROR)>], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f5c77908cf8>}
{'filters': [], 'name': 'django.db.backends', 'level': 0, 'parent': <Logger django (INFO)>, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f5c77908cf8>}
{'filters': [], 'name': 'django.db', 'level': 0, 'parent': <Logger django (INFO)>, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f5c77908cf8>}
{'filters': [], 'name': 'django.request', 'level': 0, 'parent': <Logger django (INFO)>, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f5c77908cf8>}
{'filters': [], 'name': 'django.server', 'level': 20, 'parent': <Logger django (INFO)>, 'propagate': False, 'handlers': [<StreamHandler <stderr> (INFO)>], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f5c77908cf8>}
{'filters': [], 'name': 'django.security.csrf', 'level': 0, 'parent': <Logger django (INFO)>, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f5c77908cf8>}
{'filters': [], 'name': 'django.security', 'level': 0, 'parent': <Logger django (INFO)>, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f5c77908cf8>}
{'filters': [], 'name': 'django.db.backends.schema', 'level': 0, 'parent': <Logger django.db.backends (INFO)>, 'propagate': True, 'handlers': [], 'disabled': False, '_cache': {}, 'manager': <logging.Manager object at 0x7f5c77908cf8>}

見辛いので、いらない項目を消して、整形すると、

{'handlers': [],
 'level': 0,
 'name': 'root',
 'parent': <RootLogger root (WARNING)>,
 'propagate': True}
{'handlers': [<StreamHandler <stderr> (INFO)>, <AdminEmailHandler (ERROR)>],
 'level': 20,
 'name': 'django',
 'parent': <RootLogger root (WARNING)>,
 'propagate': True}
{'handlers': [],
 'level': 0,
 'name': 'django.template',
 'parent': <Logger django (INFO)>,
 'propagate': True}
{'handlers': [],
 'level': 0,
 'name': 'django.db.backends',
 'parent': <Logger django.db (INFO)>,
 'propagate': True}
{'handlers': [],
 'level': 0,
 'name': 'django.db',
 'parent': <Logger django (INFO)>,
 'propagate': True}
{'handlers': [],
 'level': 0,
 'name': 'django.request',
 'parent': <Logger django (INFO)>,
 'propagate': True}
 {'handlers': [<StreamHandler <stderr> (INFO)>],
 'level': 20,
 'name': 'django.server',
 'parent': <Logger django (INFO)>,
 'propagate': False}
{'handlers': [],
 'level': 0,
 'name': 'django.security.csrf',
 'parent': <Logger django.security (INFO)>,
 'propagate': True}
{'handlers': [],
 'level': 0,
 'name': 'django.security',
 'parent': <Logger django (INFO)>,
 'propagate': True}
{'handlers': [],
 'level': 0,
 'name': 'django.db.backends.schema',
 'parent': <Logger django.db.backends (INFO)>,
 'propagate': True}

上の出力を整理すると、

{'handlers': [<StreamHandler <stderr> (INFO)>, <AdminEmailHandler (ERROR)>],
 'level': 20,
 'name': 'django',
 'parent': <RootLogger root (WARNING)>,
 'propagate': True}

に対して、その他大勢の logger が、

{'handlers': [],
 'level': 0,
 'name': 'django.template',
 'parent': <Logger django (INFO)>,
 'propagate': True}

のようにして、propagate している。そのため、DEBUG メッセージも含めて django logger に propagate しているけど django logger が INFO 未満を切り捨てている事になっている。

ちなみに、python の logging の level と数値の対応は下記の通りである。

Level Num
CRITICAL 50
ERROR 40
WARNING 30
INFO 20
DEBUG 10
NOTSET 0

また、

 {'handlers': [<StreamHandler <stderr> (INFO)>],
 'level': 20,
 'name': 'django.server',
 'parent': <Logger django (INFO)>,
 'propagate': False}

だけ、propagate せずに、そのまま stderr に吐いている。

ここで、django.request と django.server が同じログを吐く場合、./manage.py runserver をした場合、ログが重複するのではないかと考えたが、重複していない。これは、./manage.py runserver の場合は django.server にのみ、WSGI などを使った場合は django.request のみに行っているようだ。

どうしたか

とりあえず、setting.py で DEBUG = True にしても実際には INFO レベルの Log しか吐かれていないようだった。そのため、環境変数で LOG_LEVEL = DEBUG にした場合、DEBUG レベルの Log を吐いてほしい。また、DUBUG=True の場合は、Local Server を使っているとして、console と file の両方に、DEBUG=False の場合は、WSGI を使っているとして file のみに Log を吐いてほしい。

# coding: utf-8
from .settings import LOG_FILE_PATH
from copy import deepcopy

TEMPLATE = {
    "version": 1,
    "disable_existing_loggers": False,
    "filters": {
        "require_debug_true": {
            "()": "django.utils.log.RequireDebugTrue",
        },
    },
    "formatters": {
        "default": {
            "format": "[%(asctime)s] %(levelname)s %(message)s",
            "datefmt": "%Y-%m-%d %H:%M:%S",
        },
        "long": {
            "format": "[%(asctime)s] %(levelname)s - %(filename)s#%(funcName)s:%(lineno)d: %(message)s",
            "datefmt": "%Y-%m-%d %H:%M:%S",
        },
    },
    "handlers": {
        "console": {
            "level": "INFO",
            "filters": ["require_debug_true"],
            "class": "logging.StreamHandler",
            "formatter": "default",
            "stream": "ext://sys.stderr",
        },
        "file": {
            "level": "INFO",
            "class": "logging.FileHandler",
            "formatter": "default",
            "filename": LOG_FILE_PATH,
        },
    },
    "loggers": {
        "django": {
            "handlers": ["console", "file"],
            "level": "INFO",
        },
        "django.server": {
            "handlers": ["console", "file"],
            "level": "INFO",
            "propagate": False,
        },
    },
}

# DUBUG is False --- console is filtered and django.server not work
wsgi_info = deepcopy(TEMPLATE)

wsgi_debug = deepcopy(TEMPLATE)
wsgi_debug["handlers"]["file"]["level"] = "DEBUG"
wsgi_debug["handlers"]["file"]["formatter"] = "long"
wsgi_debug["loggers"]["django"]["level"] = "DEBUG"

# DUBUG is True --- console is not filtered and django.server works
local_info = deepcopy(TEMPLATE)

local_debug = deepcopy(TEMPLATE)
local_debug["handlers"]["file"]["level"] = "DEBUG"
local_debug["handlers"]["file"]["formatter"] = "long"
local_debug["handlers"]["console"]["level"] = "DEBUG"
local_debug["handlers"]["console"]["formatter"] = "long"
local_debug["loggers"]["django"]["level"] = "DEBUG"
local_debug["loggers"]["django.server"]["level"] = "DEBUG"

上のような file を作成し、setting.py にて

from .logging_conf import wsgi_info, wsgi_debug, local_info, local_debug

if DEBUG:
    if os.environ.get("LOG_LEVEL") == "DEBUG":
        LOGGING = local_debug
    else:
        LOGGING = local_info
else:
    if os.environ.get("LOG_LEVEL") == "DEBUG":
        LOGGING = wsgi_debug
    else:
        LOGGING = wsgi_info

とした。

注意点

from logging.config import dictConfig
dictConfig(wsgi_info)

のように setting.py の中で設定した場合、きちんと反映されないため LOGGING 変数を使う必要がある。

disable_existing_loggers キーが True もしくは何もセットしない場合 (default は True) 、下記の Logger も削除されてしまうため、注意が必要である。

'factory': <logging.PlaceHolder object at 0x7f70be564400>,
'factory.generate': <Logger factory.generate (WARNING)>,
'faker': <logging.PlaceHolder object at 0x7f70be508828>,
'faker.factory': <Logger faker.factory (WARNING)>,
'requests': <Logger requests (WARNING)>,
'urllib3': <Logger urllib3 (WARNING)>,
'urllib3.connection': <Logger urllib3.connection (WARNING)>,
'urllib3.connectionpool': <Logger urllib3.connectionpool (WARNING)>,
'urllib3.poolmanager': <Logger urllib3.poolmanager (WARNING)>,
'urllib3.response': <Logger urllib3.response (WARNING)>,
'urllib3.util': <logging.PlaceHolder object at 0x7f70be826e80>,
'urllib3.util.retry': <Logger urllib3.util.retry (WARNING)>}

setting.py の LOGGING_CONFIG = None にした場合、django.template などの設定も削除される。そのため、注意が必要である。