一、问题描述
项目中,使用RotatingFileHandler根据日志文件大小来切分日志。设置文件的MaxBytes为1GB, backupCount大小为5。
经查看,发现日志文件的大小均小于10MB,且每个回滚日志文件的写入时间也都比较接近。
二、分析
日志文件过小,猜测是代码有问题,或者是文件内容有丢失;日志写入时间接近猜测是同时写入的问题。
经检查,代码没有问题,排除此原因。考虑当前使用gunicorn的多进程启动程序,多半是多个进程同时写入当个文件造成日志文件丢失。
logging模块是线程安全的,但并不是进程安全的。
如何解决此问题呢?首先先过一遍Python的logging模块在处理日志回滚的具体实现方法。
2.1 logging模块实现日志回滚
logging中RotatingFileHandler类和TimedRotatingFileHandler类分别实现按照日志文件大小和日志文件时间来切分文件,均继承自BaseRotatingHandler类。
BaseRotatingHandler类中实现了文件切分的触发和执行,具体过程如下:
def emit(self, record):
"""
try:
if self.shouldRollover(record):
except Exception:
复制代码
具体的执行过程shouldRollover(record)和doRollover()函数则在RotatingFileHandler类和TimedRotatingFileHandler类中实现。
以RotatingFileHandler类为例,doRollover()函数流程如下:
def doRollover(self):
if self.stream:
None
if self.backupCount > 0:
for i in range(self.backupCount - 1, 0, -1): # 从backupCount,依次到1
"%s.%d" % (self.baseFilename, i))
"%s.%d" % (self.baseFilename,
1))
if os.path.exists(sfn):
if os.path.exists(dfn):
# 实现将xx.log.i->xx.log.i+1
".1")
# ---------start-----------
if os.path.exists(dfn): # 判断如果xx.log.1存在,则删除xx.log.1
# 将xx.log->xx.log.1
# ----------end------------
if not self.delay:
# 执行新的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 多进程日志安全输出到同一文件方案
相应的解决方法:
将日志发送到同一个进程中,由该进程负责输出到文件中(使用Queue和QueueHandler将所有日志事件发送至一个进程中)
对日志输出加锁,每个进程在执行日志输出时先获得锁(用多处理模块中的Lock类来序列化对进程的文件访问)
让所有进程都将日志记录至一个SocketHandler,然后用一个实现了套接字服务器的单独进程一边从套接字中读取一边将日志记录至文件(Python手册中提供)
三、解决方案