django 多进程下,日志写入错乱问题

问题:使用django自带logging配置记录日志时发现,日志丢失与日志写入错乱

原因:django logging 的实现,是基于python logging模块实现,而logging模块仅仅是线程安全的;而使用uwsgi启动项目时,是启动多个进程的;logging模块并没有保证多进程安全

如果我们设定每个小时生成一个logger文件,设定写入的logger文件为info.log。这样他们的执行流程为:
在1个进程下,日志的写入原理是:
1、生成info.log;
2、写入1小时日志;
3、1小时之后,判定info.log-2018-11-30-1文件是否存在;如果存在则删除,然么重命名info.log为info.log-2018-11-30-1;
4、重新生成info.log并将logger的文件句柄指向新的info.log文件;

在2个进程下,日志的写入就会出现下面的现象:
1、生成info.log;
2、写入1小时日志;
3、1号进程先判定info.log-2018-11-30-1文件是否存在,如果存在则删除,然么重命名info.log为info.log-2018-11-30-1;
4、此时可能2号进程还在向info.log文件进行写入,由于写入流已经打开,所以他会继续向info.log-2018-11-30-1中写入。
5、等到2号进程开始重命名操作,此时info.log-2018-11-30-1已经存在,然后他会进行删除操作,这样就会导致日志丢失。
6、2号进程此时将info.log重命名为info.log-2018-11-30-1,也会导致1号进行继续向info.log-2018-11-30-1写入,这样就导致了日志错乱。

解决方案

  • 引入第三方包,使用别人重写的loging handlers模块
  • 自己写logging handlers 模块

1、引入第三方包,使用别人重写的loging handlers模块
这里网上找到两个包

此包的最后更新时间是 2013.7,可见很久没有人维护了。之后在这个官网又找到了这个包的升级版本concurrent-log-handler,即下面这个包

安装: pip install concurrent-log-handler
这个包目前还在有人维护。
此包不足之处:
只有RotatingFileHandler的改动,也就是说,只对大小分割文件的handler 做了优化,并没有对TimeRotatingFileHandler优化

2、自己写logging handlers 模块
因为我项目里面的log是按照time进行分割的,按大小分割不利于日志的查找,然后就没有用这两个包,开始思考如何自己实现。
本来想仿照concurrent-log-handler写个对TimeRotatingFileHandler的优化,怎奈在下才疏学浅,看不懂concurrent-log-handler里面的原码。只能自己想方案解决了。

思路如下:
1、既然每个进程下,可能会出现向已归档日志写入日志问题,那么就 在每次操作写日志前,判断log是否已进行归档。如果已进行归档就更新文件操作句柄为最新,这样再进行写操作时,可保证日志写入最新log文件
2、既然每个进程下,当操作日志滚动时,会删除已存在归档文件,那么就 把此删除操作去掉

代码实现:


# 解决多进程日志写入混乱问题


import os
import time
from logging.handlers import TimedRotatingFileHandler


class HxTimedRotatingFileHandler(TimedRotatingFileHandler):

    @property
    def dfn(self):
        currentTime = int(time.time())
        # get the time that this sequence started at and make it a TimeTuple
        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.rotation_filename(self.baseFilename + "." + time.strftime(self.suffix, timeTuple))

        return dfn

    def shouldRollover(self, record):
        """
        是否应该执行日志滚动操作:
        1、存档文件已存在时,执行滚动操作
        2、当前时间 >= 滚动时间点时,执行滚动操作
        """
        dfn = self.dfn
        t = int(time.time())
        if t >= self.rolloverAt or os.path.exists(dfn):
            return 1
        return 0

    def doRollover(self):
        """
        执行滚动操作
        1、文件句柄更新
        2、存在文件处理
        3、备份数处理
        4、下次滚动时间点更新
        """
        if self.stream:
            self.stream.close()
            self.stream = None
        # get the time that this sequence started at and make it a TimeTuple

        dfn = self.dfn

        # 存档log 已存在处理
        if not os.path.exists(dfn):
            self.rotate(self.baseFilename, dfn)

        # 备份数控制
        if self.backupCount > 0:
            for s in self.getFilesToDelete():
                os.remove(s)

        # 延迟处理
        if not self.delay:
            self.stream = self._open()

        # 更新滚动时间点
        currentTime = int(time.time())
        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]
            dstNow = time.localtime(currentTime)[-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

在settings 配置handlers引入class时,指定到上面的class即可。

注意:HxTimedRotatingFileHandler 是按时间进行切割的,理论上只适用于when='midnight' 模式,因为midnight模式下,每个进程的日志切割时间点是一样的;其他模式不知道会不会出问题。

有问题请留言

参考:
https://kommmy.github.io/2018/02/11/page/
https://blog.csdn.net/qq_20690231/article/details/84644939
https://www.jianshu.com/p/def0a24974e4

推荐阅读更多精彩内容