python logging时间戳格式 python logging timedrotating

我前面有篇文章已经详细介绍了一下 Python 的日志模块。Python 提供了非常多的可以运用在各种不同场景的 Log Handler.

TimedRotatingFileHandler 是 Python 提供的一个可以基于时间自动切分日志的 Handler 类，他继承自 BaseRotatingHandler -> logging.FileHandler

但是他有一个缺点就是没有办法支持多进程的日志切换，多进程进行日志切换的时候可能会因为重命名而丢失日志数据。

来看下他的实现(我默认大家已经知道了 FileHandler 的实现和 logging 模块的调用机制 如果还不清楚可以先去看下我前面那篇文章 )：

def doRollover(self):
    """
    do a rollover; in this case, a date/time stamp is appended to the filename
    when the rollover happens.  However, you want the file to be named for the
    start of the interval, not the current time.  If there is a backup count,
    then we have to get a list of matching filenames, sort them and remove
    the one with the oldest suffix.
    """
    if self.stream:
        self.stream.close()
        self.stream = None
    # get the time that this sequence started at and make it a TimeTuple
    currentTime = int(time.time())
    dstNow = time.localtime(currentTime)[-1]
    t = self.rolloverAt - self.interval
    if self.utc:
        timeTuple = time.gmtime(t)
    else:
        timeTuple = time.localtime(t)
        dstThen = timeTuple[-1]
        if dstNow != dstThen:
            if dstNow:
                addend = 3600
            else:
                addend = -3600
            timeTuple = time.localtime(t + addend)
    dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
    if os.path.exists(dfn):
        os.remove(dfn)
    # Issue 18940: A file may not have been created if delay is True.
    if os.path.exists(self.baseFilename):
        os.rename(self.baseFilename, dfn)
    if self.backupCount > 0:
        for s in self.getFilesToDelete():
            os.remove(s)
    if not self.delay:
        self.stream = self._open()
    newRolloverAt = self.computeRollover(currentTime)
    while newRolloverAt <= currentTime:
        newRolloverAt = newRolloverAt + self.interval
    #If DST changes and midnight or weekly rollover, adjust for this.
    if (self.when == 'MIDNIGHT' or self.when.startswith('W')) and not self.utc:
        dstAtRollover = time.localtime(newRolloverAt)[-1]
        if dstNow != dstAtRollover:
            if not dstNow:  # DST kicks in before next rollover, so we need to deduct an hour
                addend = -3600
            else:           # DST bows out before next rollover, so we need to add an hour
                addend = 3600
            newRolloverAt += addend
    self.rolloverAt = newRolloverAt

doRollover 其实就是 rotate 的具体实现。在具体详细分析为什么会出现多进程问题的时候我先来说下 rotate 的原理。

首先日志会被打印在一个叫 baseFilename 名字的文件中。然后在 Rotate 的时候会根据你想要打印的参数生成对应新文件的名字也就是上面函数的 dfn 的值。

然后会将现在的文件重命名为 dfn 的值。之后在重新创建一个 baseFilename 的文件。然后继续往这个文件里面写。

举个例子，我们一直往 info.log 中写日志。现在该 rotate 了我们会把 info.log rename 成 info.log.2018-10-23 然后再创建一个 info.log 继续写日志，过程就是这样。

 

让我们来注意导致多进程问题的最关键的几句话：

if os.path.exists(dfn):
        os.remove(dfn)
    # Issue 18940: A file may not have been created if delay is True.
    if os.path.exists(self.baseFilename):
        os.rename(self.baseFilename, dfn)

我们就根据上面的例子继续来描述。比如现在 dfn 就是 info.log.2018-10-23 。那么我会看有没有存在这个文件，如果有我就会先删除掉，然后再看下 info.log 是否存在，如果存在就执行 rename.

所以问题就很明确了，如果同时有多个进程进入临界区，那么会导致 dfn 文件被删除多次，另外下面的 rename 可能也会产生混乱。

现在我们要做的就是首先认为文件存在即是已经有人 rename 成功过了，并且在判断文件不存在的时候只允许一个人去 rename ，其他进程如果正好进入临界区就等一等。

让我们来实现这个函数：

class MultiCompatibleTimedRotatingFileHandler(TimedRotatingFileHandler):

    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
        currentTime = int(time.time())
        dstNow = time.localtime(currentTime)[-1]
        t = self.rolloverAt - self.interval
        if self.utc:
            timeTuple = time.gmtime(t)
        else:
            timeTuple = time.localtime(t)
            dstThen = timeTuple[-1]
            if dstNow != dstThen:
                if dstNow:
                    addend = 3600
                else:
                    addend = -3600
                timeTuple = time.localtime(t + addend)
        dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
        # 兼容多进程并发 LOG_ROTATE
        if not os.path.exists(dfn):
            f = open(self.baseFilename, 'a')
            fcntl.lockf(f.fileno(), fcntl.LOCK_EX)
            if os.path.exists(self.baseFilename):
                os.rename(self.baseFilename, dfn)
        if self.backupCount > 0:
            for s in self.getFilesToDelete():
                os.remove(s)
        if not self.delay:
            self.stream = self._open()
        newRolloverAt = self.computeRollover(currentTime)
        while newRolloverAt <= currentTime:
            newRolloverAt = newRolloverAt + self.interval
        # If DST changes and midnight or weekly rollover, adjust for this.
        if (self.when == 'MIDNIGHT' or self.when.startswith('W')) and not self.utc:
            dstAtRollover = time.localtime(newRolloverAt)[-1]
            if dstNow != dstAtRollover:
                if not dstNow:  # DST kicks in before next rollover, so we need to deduct an hour
                    addend = -3600
                else:  # DST bows out before next rollover, so we need to add an hour
                    addend = 3600
                newRolloverAt += addend
        self.rolloverAt = newRolloverAt

我们判断一下如果该文件不存在，我们就进入临界区，然后利用 linux 的 fcntl 用阻塞模式获得一把文件锁。然后判断一下 info.log 是否已经被 rename 过了(这里用于同时进入临界区的其他进程判断前面持锁人是否已经结束完成了文件的 rename)。如果文件还在说明是第一个进来的进程则执行 rename 操作。将 info.log -> info.log.2018-10-23 。完成了之后这个时候 info.log 就已经暂时不存在于当前目录了。而且 dfn 文件已经创建。所以后面进来的进程会跳过这个判断直接执行下面的逻辑 open 一个新的基于 self.baseFilename 的文件。这里同时打开就无所谓了，因为 FileHandler 默认使用的 mode 是 'a' appending 模式，所以当 open 的时候就不会存在覆盖的情况了。

 

到此就补偿了无法兼容多进程的问题。这里还想多提一句，在写这个的时候经过了很长时间对 fcntl 模块的调研。他是一个基于 linux 的 voluntary 锁。也就是说是一把自愿锁。虽然我在调用的时候加了强制排它锁，但是其他不自愿的比如我再开一个 vim 去编辑该文件是可以绕过这个锁的这个一定要注意。