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 describedin doRollover()."""try:if self.shouldRollover(record):self.doRollover()logging.FileHandler.emit(self, record)except (KeyboardInterrupt, SystemExit):raiseexcept: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 TimeTupledfn = 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 = utcself.suffix = "%Y-%m-%d"self.baseFilename = filenameself.currentFileName = self._compute_fn()BaseRotatingHandler.__init__(self, filename, 'a', encoding, delay)def shouldRollover(self, record):if self.currentFileName != self._compute_fn():return Truereturn Falsedef doRollover(self):if self.stream:self.stream.close()self.stream = Noneself.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:passtry:os.symlink(self.currentFileName, self.baseFilename)except OSError:passreturn stream