Python TimedRotatingFileHandler 多进程环境下的问题和解决方法（如flask logging按时间自动切割）

1. 问题

在多进程下使用python的logging模块，经常会遇到“另一个程序正在使用此文件，进程无法访问。”的错误。

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 又给删掉了之类的问题。

2. 解决方法

最简单直接的一种方法其实是：把多进程的 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

3. 运用

app.py

import logging
import json
import time
from datetime import datetime
from logging.handlers import RotatingFileHandler

from flask import Flask, g, request
from flask import jsonify
from handlers import MidnightRotatingFileHandler


app = Flask(__name__)


def register_log():
    fmt =  "%(asctime)s - %(name)s - %(levelname)s - %(message)s"

    if False:
        handler = logging.StreamHandler(sys.stdout)
    else:
        handler = MidnightRotatingFileHandler('access.log')
        # handler = RotatingFileHandler("access1.log", maxBytes=100 * 1024, backupCount=5)

    logging.basicConfig(
        level=logging.DEBUG,
        format=fmt,
        datefmt='%Y-%m-%d %H:%M:%S',
        handlers=[handler]
    )
    logging.getLogger(__name__).setLevel(logging.WARNING)


register_log()

logger = logging.getLogger(__name__)

# 记录日志
@app.route("/")
def index():
    logger.info("123")
    logger.debug("456")
    logger.warning("789")
    logger.error("101112")
    return 'ok'

# 记录带返回参数的日志
@app.route("/json")
def test_json():
    data = {
        "data": 123,
        "name": "fanzone"
    }
    return jsonify(data)


if __name__ == '__main__':
    app.run(debug=True, port=5001)

handlers.py

# coding:utf-8

import codecs
import datetime
import os
from logging.handlers import BaseRotatingHandler


class MidnightRotatingFileHandler(BaseRotatingHandler):
    def __init__(self, filename):
        self.suffix = "%Y-%m-%d"
        self.date = datetime.date.today()
        super(BaseRotatingHandler, self).__init__(filename, mode='a', encoding=None, delay=0)

    def shouldRollover(self, record):
        return self.date != datetime.date.today()

    def doRollover(self):
        if self.stream:
            self.stream.close()
            self.stream = None
        self.date = datetime.date.today()

    def _open(self):
        filename = '%s.%s' % (self.baseFilename, self.date.strftime(self.suffix))
        if self.encoding is None:
            stream = open(filename, self.mode)
        else:
            stream = codecs.open(filename, self.mode, self.encoding)
        if os.path.exists(self.baseFilename):
            try:
                os.remove(self.baseFilename)
            except OSError:
                pass
        try:
            os.symlink(filename, self.baseFilename)
        except OSError:
            pass
        return stream

参考：
https://my.oschina.net/lionets/blog/796438