记python logging非进程安全踩得坑

背景

有两个python进程A和B复用同一个logger创建模块，往同一个文件里写日志，用的是TimedRotatingFileHandler，并且每天午夜进行文件rollover，保留15天的文件

现象

偶尔会发现某一天的日志里记录的时间是后一天的，并且只有几行

原因

虽然官方文档中说logging handler提供的类都是多线程安全的，但并不是多进程安全的，通过分析源码发现事实也确实如此。logging模块利用handler来负责日志文件的rollover，下面以TimedRotatingFileHandler为例来看下它的rollover是如何实现的：

• 所有打log的函数都会在Handler类中调用handle函数，然后调用emit函数：

    def handle(self, record):
        """
        Conditionally emit the specified logging record.

        Emission depends on filters which may have been added to the handler.
        Wrap the actual emission of the record with acquisition/release of
        the I/O thread lock. Returns whether the filter passed the record for
        emission.
        """
        rv = self.filter(record)
        if rv:
            self.acquire()
            try:
                self.emit(record)
            finally:
                self.release()
        return rv

• 在TimedRotatingFileHandler的父类BaseRotatingHandler中重载了emit函数：

    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)

可以看到其中利用shouldRollover判断是否需要rollover，利用doRollover来执行rollover

• TimedRotatingFileHandler中实现了这两个函数：

    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
        #print "No need to rollover: %d, %d" % (t, self.rolloverAt)
        return 0
      
    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 = -