gunicorn使用TimedRotatingFileHandler导致日志丢失问题排查&解决

TimedRotatingFileHandler日志滚动原理

python logging模块自带的TimedRotatingFileHandler可以实现日志自动切割，切割这件事的触发和执行逻辑可以从 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)

即当有新的日志需要记录时，会先调用self.shouldRollover()判断是否需要进行日志切分，如果需要切割日志，则会调用self.doRollover()进行日志切割。

TimedRotatingFileHandler中shouldRollover()的实现如下：

def shouldRollover(self, record):
    """
    Determine if rollover should occur.

    record is not used, as we are just comparing times, but it is needed so
    the method signatures are the same
    """
    t = int(time.time())
    if t >= self.rolloverAt:
        return 1
    return 0

可以看到，TimedRotatingFileHandler通过记录一个rolloverAt，保存下一次日志切割的时间，如果当前时间>日志该切割的时间，则会进行日志切割，并更新rolloverAt。
这里可能会产生第一个问题，如果选择when=D按天切割，切割时间不是按照自然日切割，而是根据初始化时间每隔24小时进行一次切割；如果你希望日志按自然日切割，最好指定when=MIDNIGHT。

接下来看看TimedRotatingFileHandler是如何执行日志切割的，简化代码之后，doRollover的逻辑如下：

def doRollover(self):
	# 关闭当前文件
    if self.stream:
        self.stream.close()
        self.stream = None
    # 生成切割日志文件名
    dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
    # 如果切割日志路径已存在，先删除
    if os.path.exists(dfn):
        os.remove(dfn)
    # 将当前base日志文件重命名成切割日志文件名
    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. 新的日志继续写入error.log

问题：如果是多进程环境会如何？

上述代码在单进程下完全没有问题，可是如果是多进程环境，就埋下了一个大坑。
因为每个进程都会执行上述流程，第一个进程完成日志切割，生成了error.log.2016-11-11，紧接着第二个进程会删掉error.log.2016-11-11，然后用当前error.log重命名成新的error.log.2016-11-11，于是就发生了日志丢失的问题。

解决方法

出现日志丢失的根本原因是切割日志时，会尝试先删除重名的旧日志，然后进行重命名。
一种替代的方式是：记录日志时，直接将每条日志写入对应日期的日志文件，当进行日志切割时，只需要切换到新的文件即可，没有删除旧日志的操作，也就不会出现日志丢失的问题，并且能保证进程安全。

参考代码如下：

import codecs
import os
import re
import sys
import logging
import time
from pathlib import Path
from logging.handlers import BaseRotatingHandler


class DailyRotatingFileHandler(BaseRotatingHandler):
    """
    同`logging.TimedRotatingFileHandler`类似，不过这个handler：
    - 可以支持多进程
    - 只支持自然日分割
    - 暂不支持UTC
    """

    def __init__(self, filename, backupCount=0, encoding=None, delay=False, utc=False, **kwargs):
        self.backup_count = backupCount
        self.utc = utc
        self.suffix = "%Y-%m-%d"
        self.base_log_path = Path(filename)
        self.base_filename = self.base_log_path.name
        self.current_filename = self._compute_fn()
        self.current_log_path = self.base_log_path.with_name(self.current_filename)
        BaseRotatingHandler.__init__(self, filename, 'a', encoding, delay)

    def shouldRollover(self, record):
        """
        判断是否该滚动日志，如果当前时间对应的日志文件名与当前打开的日志文件名不一致，则需要滚动日志
        """
        if self.current_filename != self._compute_fn():
            return True
        return False

    def doRollover(self):
        """
        滚动日志
        """
        # 关闭旧的日志文件
        if self.stream:
            self.stream.close()
            self.stream = None

        # 计算新的日志文件
        self.current_filename = self._compute_fn()
        self.current_log_path = self.base_log_path.with_name(self.current_filename)
        # 打开新的日志文件
        if not self.delay:
            self.stream = self._open()

        # 删除过期日志
        self.delete_expired_files()

    def _compute_fn(self):
        """
        计算当前时间对应的日志文件名
        """
        return self.base_filename + "." + time.strftime(self.suffix, time.localtime())

    def _open(self):
        """
        打开新的日志文件，同时更新base_filename指向的软链，修改软链不会对日志记录产生任何影响
        """
        if self.encoding is None:
            stream = open(str(self.current_log_path), self.mode)
        else:
            stream = codecs.open(str(self.current_log_path), self.mode, self.encoding)

        # 删除旧的软链
        if self.base_log_path.exists():
            try:
                # 如果base_log_path不是软链或者指向的日志文件不对，则先删除该软链
                if not self.base_log_path.is_symlink() or os.readlink(self.base_log_path) != self.current_filename:
                    os.remove(self.base_log_path)
            except OSError:
                pass

        # 建立新的软链
        try:
            os.symlink(self.current_filename, str(self.base_log_path))
        except OSError:
            pass
        return stream

    def delete_expired_files(self):
        """
        删除过期的日志
        """
        if self.backup_count <= 0:
            return

        file_names = os.listdir(str(self.base_log_path.parent))
        result = []
        prefix = self.base_filename + "."
        plen = len(prefix)
        for file_name in file_names:
            if file_name[:plen] == prefix:
                suffix = file_name[plen:]
                if re.match(r"^\d{4}-\d{2}-\d{2}(\.\w+)?$", suffix):
                    result.append(file_name)
        if len(result) < self.backup_count:
            result = []
        else:
            result.sort()
            result = result[:len(result) - self.backup_count]

        for file_name in result:
            os.remove(str(self.base_log_path.with_name(file_name)))

优点

1. 进程安全，可以支持多进程
2. 按自然日分割日志，方便日志查询

附上gunicorn日志按天切割配置

access_log_format = '%(h)s %(l)s %(u)s "%(r)s" %(s)s %(b)sB %(M)sms "%(f)s" "%(a)s"'
# gunicorn的logging默认使用的是FileHandler，先把原有的FileHandler流重定向到了/dev/null
accesslog = "/dev/null"
errorlog = "/dev/null"

# 然后添加自己定制的handler
formatter = logging.Formatter('[%(asctime)s] [%(levelname)s]: %(message)s')
access_logger = logging.getLogger('gunicorn.access')
access_handler = DailyRotatingFileHandler("logs/gunicorn_access.log", backupCount=15)
access_handler.setFormatter(formatter)
access_logger.addHandler(access_handler)
access_logger.propagate = False

error_logger = logging.getLogger('gunicorn.error')
error_handler = DailyRotatingFileHandler("logs/gunicorn_error.log", backupCount=15)
error_handler.setFormatter(formatter)
error_logger.addHandler(error_handler)
error_logger.propagate = False

参考链接

以上内容大部分参考自Python TimedRotatingFileHandler 多进程环境下的问题和解决方法