1、 问题描述
项目中,使用RotatingFileHandler根据日志文件大小来切分日志。设置文件的MaxBytes为1GB, backupCount大小为5。
经查看,发现日志文件的大小均小于10MB,且每个回滚日志文件的写入时间也都比较接近。
2、 分析
日志文件过小,猜测是代码有问题,或者是文件内容有丢失;日志写入时间接近猜测是同时写入的问题。
经检查,代码没有问题,排除此原因。考虑当前使用gunicorn的多进程启动程序,多半是多个进程同时写入当个文件造成日志文件丢失。
logging模块是线程安全的,但并不是进程安全的。
如何解决此问题呢?首先先过一遍Python的logging模块在处理日志回滚的具体实现方法。
2.1 logging模块实现日志回滚
logging中RotatingFileHandler类和TimedRotatingFileHandler类分别实现按照日志文件大小和日志文件时间来切分文件,均继承自BaseRotatingHandler类。
BaseRotatingHandler类中实现了文件切分的触发和执行,具体过程如下:
def emit(self, record):
"""
Emit a record.
Output the record to the file, catering for rollover as described
in doRollover().
"""
try:
if self.shouldRollover(record):
self.doRollover()
logging.FileHandler.emit(self, record)
except Exception:
self.handleError(record)
具体的执行过程shouldRollover(record)和doRollover()函数则在RotatingFileHandler类和TimedRotatingFileHandler类中实现。
以RotatingFileHandler类为例,doRollover()函数流程如下:
def doRollover(self):
if self.stream:
self.stream.close()
self.stream = None
if self.backupCount > 0:
for i in range(self.backupCount - 1, 0, -1): # 从backupCount,依次到1
sfn = self.rotation_filename("%s.%d" % (self.baseFilename, i))
dfn = self.rotation_filename("%s.%d" % (self.baseFilename, i + 1))
if os.path.exists(sfn):
if os.path.exists(dfn):
os.remove(dfn)
os.rename(sfn, dfn) # 实现将xx.log.i->xx.log.i+1
dfn = self.rotation_filename(self.baseFilename + ".1")
# ---------start-----------
if os.path.exists(dfn): # 判断如果xx.log.1存在,则删除xx.log.1
os.remove(dfn)
self.rotate(self.baseFilename, dfn) # 将xx.log->xx.log.1
# ----------end------------
if not self.delay:
self.stream = self._open() # 执行新的xx.log
分析如上过程,整个步骤是:
当前正在处理的日志文件名为self.baseFilename,该值self.baseFilename = os.path.abspath(filename)是设置的日志文件的绝对路径,假设baseFilename为error.log。
当进行文件回滚的时候,会依次将error.log.i重命名为error.log.i+1。
判断error.log.1是否存在,若存在,则删除,将当前日志文件error.log重命名为error.log.1。
self.stream重新指向新建error.log文件。
当程序启动多进程时,每个进程都会执行doRollover过程,若有多个进程进入临界区,则会导致dfn被删除多次等多种混乱操作。
2.2 多进程日志安全输出到同一文件方案
相应的解决方法:
将日志发送到同一个进程中,由该进程负责输出到文件中(使用