Python TimedRotatingFileHandler 多进程环境下的问题和解决方法
原文:https://my.oschina.net/lionets/blog/796438
Python 自带了一个 handler 可以实现每天自动切割日志文件的功能(其实支持各种按时间切割的方法,不过按日期切割是最常用的一种)。
切割 这件事的触发和执行逻辑可以从 BaseRotatingHandler(logging.FileHandler)
里看到:
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 (KeyboardInterrupt, SystemExit):
raise
except:
self.handleError(record)
而 TimedRotatingFileHandler
只不过是依自己的逻辑实现了 self.shouldRollover
和 self.doRollover
方法。
共所周知的,这个 handler 在多进程环境下会有问题,比如丢失日志。这对于 web server 来说简直是个灾难。而这个问题的原因来自于它切割文件的方式,即 doRollover
方法。简化掉多余的代码后它看起来是这样的:
def doRollover(self):
if self.stream:
self.stream.close()
self.stream = None
# get the time that this sequence started at and make it a TimeTuple
dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
if os.path.exists(dfn):
os.remove(dfn)
if os.path.exists(self.baseFilename):
os.rename(self.baseFilename, dfn)
self.rolloverAt = newRolloverAt
假设配置的文件名是 error.log
,日志正准备从 11.11 切换到 11.12。那么 self.baseFilename
就是 error.log
,dfn
就是 error.log.2016-11-11
。即执行流程为:
- 判断准备切入的文件是否存在,如果是,删掉之
- 然后把
error.log
重命名为error.log.2016-11-11
- doRollover 结束,FileHandler.emit 将消息写入
error.log
(新建)
单进程环境中这个流程没问题,但是多进程下因为每个进程都会调用一次 doRollover
,就可能会发生像一个进程已经 rollover 完成,但是下一个进程把之前的 error.log
又给删掉了之类的问题。
解决方法
最简单直接的一种方法其实是:把多进程的 log handler 配置改为一个 TimedRotatingFileHandler
+ N 个 FileHandler
,这样就绕过了 多进程 这个环境,其余的进程只负责向 error.log
文件写。
这需要实现进程间的不同配置,可以通过一个锁来实现,第一个成功 acquire 到这个锁的进程进行 rollover。
然而这存在一个切割不精确的问题,即在切割进程成功进行 rollover 之前,其他进程会把新日志写进旧文件。因此更好的办法是去修改 TimedRotatingFileHandler
。改这个类的方法多种多样,我的做法是抛弃文件重命名这个操作,将 rollover 的实现变为进程无冲的。方法为:写文件时始终向带日期后缀的文件写,然后做一个 error.log
的软链接,指向最新的一条日志。
这样就抛弃了重命名的过程,行为和 FileHandler
更加类似。软连接的删除和新建也不存在进程间冲突。
code(可以直接用,但没有处理 utc):
class MultiProcessSafeDailyRotatingFileHandler(BaseRotatingHandler):
"""Similar with `logging.TimedRotatingFileHandler`, while this one is
- Multi process safe
- Rotate at midnight only
- Utc not supported
"""
def __init__(self, filename, encoding=None, delay=False, utc=False, **kwargs):
self.utc = utc
self.suffix = "%Y-%m-%d"
self.baseFilename = filename
self.currentFileName = self._compute_fn()
BaseRotatingHandler.__init__(self, filename, 'a', encoding, delay)
def shouldRollover(self, record):
if self.currentFileName != self._compute_fn():
return True
return False
def doRollover(self):
if self.stream:
self.stream.close()
self.stream = None
self.currentFileName = self._compute_fn()
def _compute_fn(self):
return self.baseFilename + "." + time.strftime(self.suffix, time.localtime())
def _open(self):
if self.encoding is None:
stream = open(self.currentFileName, self.mode)
else:
stream = codecs.open(self.currentFileName, self.mode, self.encoding)
# simulate file name structure of `logging.TimedRotatingFileHandler`
if os.path.exists(self.baseFilename):
try:
os.remove(self.baseFilename)
except OSError:
pass
try:
os.symlink(self.currentFileName, self.baseFilename)
except OSError:
pass
return stream