Python TimedRotatingFileHandler 多进程环境下的问题和解决方法

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。即执行流程为：

1. 判断准备切入的文件是否存在，如果是，删掉之
2. 然后把 error.log 重命名为 error.log.2016-11-11
3. 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