django 中如何优雅的记录日志
logging 结构
在
Django中使用 Python 的标准库 logging 模块来记录日志，关于 logging 的配置，不做过多介绍，只写其中最重要的四个部分：Loggers、Handlers、Filters和Formatters。
Loggers
Logger 即记录器，是日志系统的入口。它有三个重要的工作：
- 向应用程序（也就是你的项目）公开几种方法，以便运行时记录消息
- 根据传递给
Logger的消息的严重性，确定消息是否需要处理 - 将需要处理的消息传递给所有感兴趣的处理器
Handler
每一条写入 Logger 的消息都是一条日志记录，每一条日志记录都包含级别，代表对应消息的严重程度。常用的级别如下：
DEBUG：排查故障时使用的低级别系统信息，通常开发时使用INFO：一般的系统信息，并不算问题WARNING：描述系统发生小问题的信息，但通常不影响功能ERROR：描述系统发生大问题的信息，可能会导致功能不正常CRITICAL：描述系统发生严重问题的信息，应用程序有崩溃的风险
当 Logger 处理一条 消息时，会将自己的日志级别和这条消息配置的级别做对比。如果消息的级别匹配或者高于 Logger 的日志级别，它就会被进一步处理，否则这条消息就会被忽略掉。
当 Logger 确定了一条消息需要处理之后，会把它传给 Handler。
Handlers
Handler 即处理器，它的主要功能是决定如何处理 Logger 中的每一条消息，比如把消息输出到屏幕、文件或者 Email 中。
和 Logger 一样，Handler 也有级别的概念。如果一条日志记录的级别不匹配或者低于 Handler 的日志级别，则会被 Handler 忽略。
一个 Logger 可以有多个 Handler，每一个 Handler 可以有不同的日志级别。这样就可以根据消息的重要性不同，来提供不同类型的输出。例如，你可以添加一个 Handler 把 ERROR 和 CRITICAL 消息发到你的 Email，再添加另一个 Handler 把所有的消息（包括 ERROR 和 CRITICAL 消息）保存到文件里。
Filters
Filter 即过滤器。在日志记录从 Logger 传到 Handler 的过程中，使用 Filter 来做额外的控制。例如，只允许某个特定来源的 ERROR 消息输出。
Filter 还被用来在日志输出之前对日志记录做修改。例如，当满足一定条件时，把日志级别从 ERROR 降到 WARNING 。
Filter 在 Logger 和 Handler 中都可以添加，多个 Filter 可以链接起来使用，来做多重过滤操作。
Formaters
Formatter 即格式化器，主要功能是确定最终输出的形式和内容。
实现方式
说了这么多理论，是时候来看看具体怎么实现了。
其实最简单的方式就是直接在文件开头 import，然后程序中调用，像下面这样：
# import the logging library
import logging
# Get an instance of a logger
logging.basicConfig(
format='%(asctime)s - %(pathname)s[%(lineno)d] - %(levelname)s: %(message)s',
level=logging.INFO)
logger = logging.getLogger(__name__)
def my_view(request, arg1, arg):
...
if bad_mojo:
# Log an error message
logger.error('Something went wrong!')
但这种方式并不好，如果在每个文件开头都这样写一遍，第一是麻烦，第二是如果哪天要改变输出日志格式，那每个文件都要改一遍，还不累死。
很显然，如果能封装成一个类，用的时候调用这个类，修改的时候也只需要修改这一个地方，是不是就解决这个问题了呢？
自定义类
下面来看看具体这个类怎么封装：
class CommonLog(object):
"""
日志记录
"""
def __init__(self, logger, logname='web-log'):
self.logname = os.path.join(settings.LOGS_DIR, '%s' % logname)
self.logger = logger
self.logger.setLevel(logging.DEBUG)
self.logger.propagate = False
self.formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s: %(message)s', '%Y-%m-%d %H:%M:%S')
def __console(self, level, message):
# 创建一个FileHandler，用于写到本地
fh = logging.handlers.TimedRotatingFileHandler(self.logname, when='MIDNIGHT', interval=1, encoding='utf-8')
# fh = logging.FileHandler(self.logname, 'a', encoding='utf-8')
fh.suffix = '%Y-%m-%d.log'
fh.setLevel(logging.DEBUG)
fh.setFormatter(self.formatter)
self.logger.addHandler(fh)
# 创建一个StreamHandler,用于输出到控制台
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
ch.setFormatter(self.formatter)
self.logger.addHandler(ch)
if level == 'info':
self.logger.info(message)
elif level == 'debug':
self.logger.debug(message)
elif level == 'warning':
self.logger.warning(message)
elif level == 'error':
self.logger.error(message)
# 这两行代码是为了避免日志输出重复问题
self.logger.removeHandler(ch)
self.logger.removeHandler(fh)
# 关闭打开的文件
fh.close()
def debug(self, message):
self.__console('debug', message)
def info(self, message):
self.__console('info', message)
def warning(self, message):
self.__console('warning', message)
def error(self, message):
self.__console('error', message)
这是我在项目中还在用的一段代码，生成的文件按天进行切分。
当时写这段代码，有个问题折腾了我很久，就是显示代码报错行数的问题。当 formatter 配置 %(lineno)d 时，每次并不是显示实际的报错行，而是显示日志类中的代码行，但这样显示就失去意义了，所以也就没有配置，用了 %(name)s 来展示实际的调用文件。
其实，如果只是为了排错方便，记录一些日志，这个类基本可以满足要求。但如果要记录访问系统的所有请求日志，那就无能为力了，因为不可能手动在每个接口代码加日志，也没必要。
这个时候，很自然就能想到 Django 中间件了。
Django 中间件
中间件日志代码一共分三个部分，分别是：Filters 代码，middleware 代码，settings 配置，如下：
local = threading.local()
class RequestLogFilter(logging.Filter):
"""
日志过滤器
"""
def filter(self, record):
record.sip = getattr(local, 'sip', 'none')
record.dip = getattr(local, 'dip', 'none')
record.body = getattr(local, 'body', 'none')
record.path = getattr(local, 'path', 'none')
record.method = getattr(local, 'method', 'none')
record.username = getattr(local, 'username', 'none')
record.status_code = getattr(local, 'status_code', 'none')
record.reason_phrase = getattr(local, 'reason_phrase', 'none')
return True
class RequestLogMiddleware(MiddlewareMixin):
"""
将request的信息记录在当前的请求线程上。
"""
def __init__(self, get_response=None):
self.get_response = get_response
self.apiLogger = logging.getLogger('web.log')
def __call__(self, request):
try:
body = json.loads(request.body)
except Exception:
body = dict()
if request.method == 'GET':
body.update(dict(request.GET))
else:
body.update(dict(request.POST))
local.body = body
local.path = request.path
local.method = request.method
local.username = request.user
local.sip = request.META.get('REMOTE_ADDR', '')
local.dip = socket.gethostbyname(socket.gethostname())
response = self.get_response(request)
local.status_code = response.status_code
local.reason_phrase = response.reason_phrase
self.apiLogger.info('system-auto')
return response
settings.py 文件配置：
MIDDLEWARE = [
'django.middleware.security.SecurityMiddleware',
'django.contrib.sessions.middleware.SessionMiddleware',
'django.middleware.common.CommonMiddleware',
'django.middleware.csrf.CsrfViewMiddleware',
'django.contrib.auth.middleware.AuthenticationMiddleware',
'django.contrib.messages.middleware.MessageMiddleware',
'django.middleware.clickjacking.XFrameOptionsMiddleware',
# 自定义中间件添加在最后
'lib.log_middleware.RequestLogMiddleware'
]
LOGGING = {
# 版本
'version': 1,
# 是否禁止默认配置的记录器
'disable_existing_loggers': False,
'formatters': {
'standard': {
'format': '{"time": "%(asctime)s", "level": "%(levelname)s", "method": "%(method)s", "username": "%(username)s", "sip": "%(sip)s", "dip": "%(dip)s", "path": "%(path)s", "status_code": "%(status_code)s", "reason_phrase": "%(reason_phrase)s", "func": "%(module)s.%(funcName)s:%(lineno)d", "message": "%(message)s"}',
'datefmt': '%Y-%m-%d %H:%M:%S'
}
},
# 过滤器
'filters': {
'request_info': {'()': 'lib.log_middleware.RequestLogFilter'},
},
'handlers': {
# 标准输出
'console': {
'level': 'ERROR',
'class': 'logging.StreamHandler',
'formatter': 'standard'
},
# 自定义 handlers，输出到文件
'restful_api': {
'level': 'DEBUG',
# 时间滚动切分
'class': 'logging.handlers.TimedRotatingFileHandler',
'filename': os.path.join(LOGS_DIR, 'web-log.log'),
'formatter': 'standard',
# 调用过滤器
'filters': ['request_info'],
# 每天凌晨切分
'when': 'MIDNIGHT',
# 保存 30 天
'backupCount': 30,
},
},
'loggers': {
'django': {
'handlers': ['console'],
'level': 'ERROR',
'propagate': False
},
'web.log': {
'handlers': ['restful_api'],
'level': 'INFO',
# 此记录器处理过的消息就不再让 django 记录器再次处理了
'propagate': False
},
}
}
通过这种方式，只要过 Django 的请求就都会有日志，不管是 web 还是 Django admin。具体记录哪些字段可以根据项目需要进行获取和配置。
有一点需要注意的是，通过 request.user 来获取用户名只适用于 session 的认证方式，因为 session 认证之后会将用户名赋值给 request.user，所以才能取得到。
假设用 jwt 方式认证，request.user 是没有值的。想要获取用户名可以有两种方式：一是在日志中间件中解析 jwt cookie 获取用户名，但这种方式并不好，更好的方法是重写 jwt 认证，将用户名赋值给 request.user，这样就可以在其他任何地方调用 request.user 来取值了。
本以为代码上线之后，就可以愉快的看日志，通过日志来分析问题了，但现实总是跟想象不同，两个异常现象纷纷挥起大手，啪啪地打在我的脸上。
两个异常如下：
- 日志写入错乱；
- 日志并没有按天分割，而且还会丢失。
在网上查找一些资料，发现了原因所在：
Django logging 是基于 Python logging 模块实现的，logging 模块是线程安全的，但不能保证多进程安全。我的 Django 项目是通过 uwsgi 启的多进程，所以就发生了上述两个问题。
下面来详细描述一下这个异常过程，假设我们每天生成一个日志文件 error.log，每天凌晨进行日志分割。那么，在单进程环境下是这样的：
- 生成 error.log 文件；
- 写入一天的日志；
- 零点时，判断 error.log-2020-05-15 是否存在，如果存在则删除；如果不存在，将 error.log 文件重命名为 error.log-2020-05-15；
- 重新生成 error.log 文件，并将 logger 句柄指向新的 error.log。
再来看看多进程的情况：
- 生成 error.log 文件；
- 写入一天的日志；
- 零点时，1 号进程判断 error.log-2020-05-15 是否存在，如果存在则删除；如果不存在，将 error.log 文件重命名为 error.log-2020-05-15；
- 此时，2 号进程可能还在向 error.log 文件进行写入，由于写入文件句柄已经打开，所以会向 error.log-2020-05-15 进行写入；
- 2 号进程进行文件分割操作，由于 error.log-2020-05-15 已经存在，所以 2 号进程会将它删除，然后再重命名 error.log，这样就导致了日志丢失；
- 由于 2 号进程将 error.log 重命名为 error.log-2020-05-15，也会导致 1 号进程继续向 error.log-2020-05-15 写入，这样就造成了写入错乱。
原因清楚了，那么，有什么解决办法呢？两个方案：
使用 concurrent-log-handler 包
这个包通过加锁的方式实现了多进程安全，并且可以在日志文件达到特定大小时，分割文件，但是不支持按时间分割。
包的源码我并没有仔细研究，也就没办法再细说了，大家如果感兴趣的话可以自己找来看。
由于我的需求是按时间进行分割，显然就不能用了，自己写吧。
重写 TimedRotatingFileHandler
通过上面的分析可以知道，出问题的点就是发生在日志分割时，一是删文件，二是没有及时更新写入句柄。
所以针对这两点，我的对策就是：一是去掉删文件的逻辑，二是在切割文件时，及时将写入句柄更新到最新。
代码如下：
# 解决多进程日志写入混乱问题
import os
import time
from logging.handlers import TimedRotatingFileHandler
class CommonTimedRotatingFileHandler(TimedRotatingFileHandler):
@property
def dfn(self):
currentTime = int(time.time())
# get the time that this sequence started at and make it a TimeTuple
dstNow = time.localtime(currentTime)[-1]
t = self.rolloverAt - self.interval
if self.utc:
timeTuple = time.gmtime(t)
else:
timeTuple = time.localtime(t)
dstThen = timeTuple[-1]
if dstNow != dstThen:
if dstNow:
addend = 3600
else:
addend = -3600
timeTuple = time.localtime(t + addend)
dfn = self.rotation_filename(self.baseFilename + "." + time.strftime(self.suffix, timeTuple))
return dfn
def shouldRollover(self, record):
"""
是否应该执行日志滚动操作：
1、存档文件已存在时，执行滚动操作
2、当前时间 >= 滚动时间点时，执行滚动操作
"""
dfn = self.dfn
t = int(time.time())
if t >= self.rolloverAt or os.path.exists(dfn):
return 1
return 0
def doRollover(self):
"""
执行滚动操作
1、文件句柄更新
2、存在文件处理
3、备份数处理
4、下次滚动时间点更新
"""
if self.stream:
self.stream.close()
self.stream = None
# get the time that this sequence started at and make it a TimeTuple
dfn = self.dfn
# 存档log 已存在处理
if not os.path.exists(dfn):
self.rotate(self.baseFilename, dfn)
# 备份数控制
if self.backupCount > 0:
for s in self.getFilesToDelete():
os.remove(s)
# 延迟处理
if not self.delay:
self.stream = self._open()
# 更新滚动时间点
currentTime = int(time.time())
newRolloverAt = self.computeRollover(currentTime)
while newRolloverAt <= currentTime:
newRolloverAt = newRolloverAt + self.interval
# If DST changes and midnight or weekly rollover, adjust for this.
if (self.when == 'MIDNIGHT' or self.when.startswith('W')) and not self.utc:
dstAtRollover = time.localtime(newRolloverAt)[-1]
dstNow = time.localtime(currentTime)[-1]
if dstNow != dstAtRollover:
if not dstNow: # DST kicks in before next rollover, so we need to deduct an hour
addend = -3600
else: # DST bows out before next rollover, so we need to add an hour
addend = 3600
newRolloverAt += addend
self.rolloverAt = newRolloverAt
在 settings handles 中引入上面 class 即可。
视图函数中使用log
import logging
log = logging.getLogger('middleware')
log.debug("......")
生产环境已经上线后，运行稳定，没有再发生异常。
以上。
