apache配置完django后启动失败_【django深坑】一案例探究django项目日志配置加载&修改过程...
背景这段时间在使用django框架过程中碰到一个奇怪的问题，明明在代码中对日志级别进行了设置，但是本地环境调试时候一直没有生效，用的还是一开始设置的默认级别。百思不得其解，所以从源码的角度尝试去分析这个问题，发现原来这是django的一个深坑。这篇文章记录下来，免得更多人踩坑。问题代码修改日志级别相关的代码如下，相信也算是常见的用法:# settings.pyLOGGING = {'v...
背景
这段时间在使用django框架过程中碰到一个奇怪的问题，明明在代码中对日志级别进行了设置，但是本地环境调试时候一直没有生效，用的还是一开始设置的默认级别。百思不得其解，所以从源码的角度尝试去分析这个问题，发现原来这是django的一个深坑。这篇文章记录下来，免得更多人踩坑。
问题代码
修改日志级别相关的代码如下，相信也算是常见的用法:
# settings.py
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'handlers': {
'file': {
'level': 'DEBUG',
'class': 'logging.FileHandler',
'filename': './debug.log',
},
},
'loggers': {
'test_logger': {
'handlers': ['file'],
'level': 'INFO',
'propagate': True,
},
},
}
# views.py
import logging
from django.http import HttpResponse
logger = logging.getLogger("test_logger")
logger.setLevel("DEBUG")
def hello(request):
logger.debug("debug test...")
logger.info("info test...")
return HttpResponse("hello world")使用上面代码，在本地环境启动工程之后访问hello视图对应的页面，我们的预期是能同时打debug和info级别的日志，但是实际上只打出了info级别的日志：
这就说明我们对logger日志级别的修改是没有生效的。
接下来我又尝试了将logger.setLevel("DEBUG")语句放到hello函数中重新启动访问页面，打出来的日志就符合预期了：
看到这里，一句”卧槽“涌上心头，实在觉得这个现象太过玄学，决定看看源码一探究竟。
问题探究
setLevel语句是一样的，放的地方不同导致了不同的效果，两个地方的区别在于一个是启动时执行(views文件最外层)，一个是运行时执行(实际访问页面)。所以，要想探究不生效的原因，还得先从python manage.py runserver这个语句入手，对整个启动过程进行排查。
对于django启动过程的源码，我之前写过几篇阅读笔记可以先大概了解一下：
https://zhuanlan.zhihu.com/p/93578120zhuanlan.zhihu.com因为篇幅关系，这里就不再将django的启动过程重新讲一遍，只对我认为与这个问题有关的相关代码重点列出来。
- 首先，启动之后，执行顺序为manage.py->django.core.management.ManagementUtility.execute()。在该函数中，有这么一段代码：
# django.core.management.__init__.py
...
if subcommand == 'runserver' and '--noreload' not in self.argv:
try:
autoreload.check_errors(django.setup)()
except Exception:
...
# In all other cases, django.setup() is required to succeed.
else:
django.setup()
...可以看到，不论是什么命令，到了这里都会去执行一下django.setup函数。
2. django.setup()：从代码可知，在setup函数中，django会将LOGGING_CONFIG给加载一遍，这里加载进来的就是我们项目默认的日志配置（如日志级别为INFO等）。加载完日志配置之后，就会去加载各个app下面的配置。
# django.__init__.py
def setup(set_prefix=True):
"""
Configure the settings (this happens as a side effect of accessing the
first setting), configure logging and populate the app registry.
Set the thread-local urlresolvers script prefix if `set_prefix` is True.
"""
from django.apps import apps
from django.conf import settings
from django.urls import set_script_prefix
from django.utils.log import configure_logging
configure_logging(settings.LOGGING_CONFIG, settings.LOGGING)
if set_prefix:
set_script_prefix(
'/' if settings.FORCE_SCRIPT_NAME is None else settings.FORCE_SCRIPT_NAME
)
apps.populate(settings.INSTALLED_APPS)3. 运行完django.setup()之后，回到django.core.management.ManagementUtility.execute()，下面有这么一段代码，其实也就是根据我们执行的命令，找到对应的命令代码去执行，启动项目时候执行的是runserver命令。
# django.core.management.__init__.py
...
self.fetch_command(subcommand).run_from_argv(self.argv)
...4. 找到runserver对应的命令文件django.core.management.commands.runserver.py，看看都干了些什么：
# django.core.management.commands.runserver.py
class Command(BaseCommand):
def get_handler(self, *args, **options):
"""Return the default WSGI handler for the runner."""
return get_internal_wsgi_application()
def handle(self, *args, **options):
...
self.run(**options)
def run(self, **options):
"""Run the server, using the autoreloader if needed."""
use_reloader = options['use_reloader']
if use_reloader:
autoreload.run_with_reloader(self.inner_run, **options)
else:
self.inner_run(None, **options)
def inner_run(self, *args, **options):
...
## 重点
self.check(display_num_errors=True)
# Need to check migrations here, so can't use the
# requires_migrations_check attribute.
self.check_migrations()
...
try:
## 重点
handler = self.get_handler(*args, **options)
run(self.addr, int(self.port), handler,
ipv6=self.use_ipv6, threading=threading, server_cls=self.server_cls)
except socket.error as e:
...这个文件可以说是runserver最核心的逻辑了（这里省略了与本文关系不大的部分），对于Command命令，我们需要先看handler函数，在最后它执行了self.run()函数，在这个函数中又调用了self.inner_run()函数。
在self.inner_run()函数中，首先调用了self.check()函数，这个check()函数其实很好理解，我们知道，当我们在代码中把一些项目的配置项写错的时候，django项目是无法正常启动的，会报错，这就是得益于这个check函数。篇幅关系，check()函数这里就不展开了，感兴趣的同学可以自己看看其实现。在check()函数中，django会帮我们检查路由配置是否正确，所以会import到对应app下面的urls.py文件，而urls.py中又会用到视图函数，所以会import到对应的views.py。当第一次import views.py文件的时候，最外层的这些语句都会被执行，所以，我们写在最外层的logger.setLevel("DEBUG")其实是生效过的，在这个时间点，日志的级别是会被修改为DEBUG级别的。
但是好景不长，在check完之后，在正式拉起服务之前，self.inner_run()函数执行了self.get_handler()函数，我们知道django是通过wsgi协议来处理请求的，所以这里需要获取到对应的handler，调用get_internal_wsgi_application()函数。
5. 在django.core.servers.basehttp.py文件中可以找到该函数。对于django自动生成的项目中，其实settings都会配置WSGI_APPLICATION这一项，值为WSGI_APPLICATION = '项目名.wsgi.application'，而且在项目目录下会有一个wsgi.py文件。
# django.core.servers.basehttp.py
def get_internal_wsgi_application():
from django.conf import settings
app_path = getattr(settings, 'WSGI_APPLICATION')
if app_path is None:
return get_wsgi_application()
try:
return import_string(app_path)
except ImportError as err:
...6. 项目下的wsgi.py内容如下，可以看到，它也是去执行了get_wsgi_application()这个函数。
import os
from django.core.wsgi import get_wsgi_application
os.environ.setdefault("DJANGO_SETTINGS_MODULE", "setup_log_test.settings")
application = get_wsgi_application()7. 最后一步，看一下get_wsgi_application()函数都干了什么：
# django.core.wsgi.py
def get_wsgi_application():
...
django.setup(set_prefix=False)
return WSGIHandler()看到这里就可以破案了。
在get_wsgi_application()函数里面又执行了一次django.setup()，从上面的分析我们可以知道setup()函数会加载一次项目日志的默认配置，而第二次加载是发生在日志级别修改setLevel之后的，所以这个时候日志级别又变成了INFO级别，看上去就是setLevel写了没用。这也就是为什么写在views.py文件的最外层会失效，写在视图函数里面就能正常修改日志级别的原因（写在视图函数里的话是真正处理请求的时候才会执行而非启动时）。
总结
这篇文章通过一个案例，介绍了django项目在启动过程日志加载的过程，同时排了一个埋得比较深的坑，即如果将日志配置修改放在views.py文件的最外层，会因为dango.setup()->check()->django.setup()的这一过程不断地加载日志默认配置->修改日志配置->加载日志默认配置而覆盖掉修改，从而导致日志修改失效。以后在运行代码中修改日志相关配置时候需要特别注意。
码字不易，如果觉得本文还有点帮助，一键三连点波关注哈~
希望大家也多多关注公众号“进击的程序人”，以后的分享文章&代码会优先发在公众号哈~
腾讯云面向开发者汇聚海量精品云计算使用和开发经验，营造开放的云计算技术生态圈。
更多推荐
0
0- 0
已为社区贡献4条内容
所有评论(0)