之前写过一篇文章 Django 中如何优雅的记录日志&＃xff0c;本以为代码上线之后&＃xff0c;就可以愉快的看日志&＃xff0c;通过日志来分析问题了&＃xff0c;但现实总是跟想象不同&＃xff0c;两个异常现象纷纷挥起大手&＃xff0c;啪啪地打在我的脸上。
两个异常如下&＃xff1a;日志写入错乱&＃xff1b;
日志并没有按天分割&＃xff0c;而且还会丢失。
在网上查找一些资料&＃xff0c;发现了原因所在&＃xff1a;Django logging 是基于 Python logging 模块实现的&＃xff0c;logging 模块是线程安全的&＃xff0c;但不能保证多进程安全。我的 Django 项目是通过 uwsgi 启的多进程&＃xff0c;所以就发生了上述两个问题。
下面来详细描述一下这个异常过程&＃xff0c;假设我们每天生成一个日志文件 error.log&＃xff0c;每天凌晨进行日志分割。那么&＃xff0c;在单进程环境下是这样的&＃xff1a;生成 error.log 文件&＃xff1b;
写入一天的日志&＃xff1b;
零点时&＃xff0c;判断 error.log-2020-05-15 是否存在&＃xff0c;如果存在则删除&＃xff1b;如果不存在&＃xff0c;将 error.log 文件重命名为 error.log-2020-05-15&＃xff1b;
重新生成 error.log 文件&＃xff0c;并将 logger 句柄指向新的 error.log。
再来看看多进程的情况&＃xff1a;生成 error.log 文件&＃xff1b;
写入一天的日志&＃xff1b;
零点时&＃xff0c;1 号进程判断 error.log-2020-05-15 是否存在&＃xff0c;如果存在则删除&＃xff1b;如果不存在&＃xff0c;将 error.log 文件重命名为 error.log-2020-05-15&＃xff1b;
此时&＃xff0c;2 号进程可能还在向 error.log 文件进行写入&＃xff0c;由于写入文件句柄已经打开&＃xff0c;所以会向 error.log-2020-05-15 进行写入&＃xff1b;
2 号进程进行文件分割操作&＃xff0c;由于 error.log-2020-05-15 已经存在&＃xff0c;所以 2 号进程会将它删除&＃xff0c;然后再重命名 error.log&＃xff0c;这样就导致了日志丢失&＃xff1b;
由于 2 号进程将 error.log 重命名为 error.log-2020-05-15&＃xff0c;也会导致 1 号进程继续向 error.log-2020-05-15 写入&＃xff0c;这样就造成了写入错乱。
原因清楚了&＃xff0c;那么&＃xff0c;有什么解决办法呢&＃xff1f;两个方案&＃xff1a;
使用 concurrent-log-handler 包
这个包通过加锁的方式实现了多进程安全&＃xff0c;并且可以在日志文件达到特定大小时&＃xff0c;分割文件&＃xff0c;但是不支持按时间分割。
包的源码我并没有仔细研究&＃xff0c;也就没办法再细说了&＃xff0c;大家如果感兴趣的话可以自己找来看。
由于我的需求是按时间进行分割&＃xff0c;显然就不能用了&＃xff0c;自己写吧。
重写 TimedRotatingFileHandler
通过上面的分析可以知道&＃xff0c;出问题的点就是发生在日志分割时&＃xff0c;一是删文件&＃xff0c;二是没有及时更新写入句柄。
所以针对这两点&＃xff0c;我的对策就是&＃xff1a;一是去掉删文件的逻辑&＃xff0c;二是在切割文件时&＃xff0c;及时将写入句柄更新到最新。
代码如下&＃xff1a;
# 解决多进程日志写入混乱问题
import os
import time
from logging.handlers import TimedRotatingFileHandler
class CommonTimedRotatingFileHandler(TimedRotatingFileHandler):
&＃64;property
def dfn(self):
currentTime &＃61; int(time.time())
# get the time that this sequence started at and make it a TimeTuple
dstNow &＃61; time.localtime(currentTime)[-1]
t &＃61; self.rolloverAt - self.interval
if self.utc:
timeTuple &＃61; time.gmtime(t)
else:
timeTuple &＃61; time.localtime(t)
dstThen &＃61; timeTuple[-1]
if dstNow !&＃61; dstThen:
if dstNow:
addend &＃61; 3600
else:
addend &＃61; -3600
timeTuple &＃61; time.localtime(t &＃43; addend)
dfn &＃61; self.rotation_filename(self.baseFilename &＃43; "." &＃43; time.strftime(self.suffix, timeTuple))
return dfn
def shouldRollover(self, record):
"""是否应该执行日志滚动操作&＃xff1a;1、存档文件已存在时&＃xff0c;执行滚动操作2、当前时间 >&＃61; 滚动时间点时&＃xff0c;执行滚动操作"""
dfn &＃61; self.dfn
t &＃61; int(time.time())
if t >&＃61; 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 &＃61; None
# get the time that this sequence started at and make it a TimeTuple
dfn &＃61; 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 &＃61; self._open()
# 更新滚动时间点
currentTime &＃61; int(time.time())
newRolloverAt &＃61; self.computeRollover(currentTime)
while newRolloverAt <&＃61; currentTime:
newRolloverAt &＃61; newRolloverAt &＃43; self.interval
# If DST changes and midnight or weekly rollover, adjust for this.
if (self.when &＃61;&＃61; &＃39;MIDNIGHT&＃39; or self.when.startswith(&＃39;W&＃39;)) and not self.utc:
dstAtRollover &＃61; time.localtime(newRolloverAt)[-1]
dstNow &＃61; time.localtime(currentTime)[-1]
if dstNow !&＃61; dstAtRollover:
if not dstNow: # DST kicks in before next rollover, so we need to deduct an hour
addend &＃61; -3600
else: # DST bows out before next rollover, so we need to add an hour
addend &＃61; 3600
newRolloverAt &＃43;&＃61; addend
self.rolloverAt &＃61; newRolloverAt
在 settings handles 中引入上面 class 即可。
生产环境已经上线了两周&＃xff0c;运行稳定&＃xff0c;没有再发生异常。
以上。
参考文档&＃xff1a;
技术博客&＃xff1a;
同时&＃xff0c;也欢迎关注我的微信公众号 AlwaysBeta&＃xff0c;更多精彩内容等你来。![]()
京公网安备 11010802041100号