解決 Django 多進程下，logging 記錄日誌錯亂問題

時間 2020-05-20

標籤解決 django 進程 logging 記錄日誌錯亂問題欄目 Python 简体版

原文原文鏈接

以前寫過一篇文章 Django 中如何優雅的記錄日誌，本覺得代碼上線以後，就能夠愉快的看日誌，經過日誌來分析問題了，但現實老是跟想象不一樣，兩個異常現象紛紛揮起大手，啪啪地打在個人臉上。python

兩個異常以下：git

日誌寫入錯亂；
日誌並無按天分割，並且還會丟失。

在網上查找一些資料，發現了緣由所在：github

Django logging 是基於 Python logging 模塊實現的，logging 模塊是線程安全的，但不能保證多進程安全。個人 Django 項目是經過 uwsgi 啓的多進程，因此就發生了上述兩個問題。django

下面來詳細描述一下這個異常過程，假設咱們天天生成一個日誌文件 error.log，天天凌晨進行日誌分割。那麼，在單進程環境下是這樣的：安全

生成 error.log 文件；
寫入一天的日誌；
零點時，判斷 error.log-2020-05-15 是否存在，若是存在則刪除；若是不存在，將 error.log 文件重命名爲 error.log-2020-05-15；
從新生成 error.log 文件，並將 logger 句柄指向新的 error.log。

再來看看多進程的狀況：微信

生成 error.log 文件；
寫入一天的日誌；
零點時，1 號進程判斷 error.log-2020-05-15 是否存在，若是存在則刪除；若是不存在，將 error.log 文件重命名爲 error.log-2020-05-15；
此時，2 號進程可能還在向 error.log 文件進行寫入，因爲寫入文件句柄已經打開，因此會向 error.log-2020-05-15 進行寫入；
2 號進程進行文件分割操做，因爲 error.log-2020-05-15 已經存在，因此 2 號進程會將它刪除，而後再重命名 error.log，這樣就致使了日誌丟失；
因爲 2 號進程將 error.log 重命名爲 error.log-2020-05-15，也會致使 1 號進程繼續向 error.log-2020-05-15 寫入，這樣就形成了寫入錯亂。

緣由清楚了，那麼，有什麼解決辦法呢？兩個方案：post

使用 concurrent-log-handler 包

這個包經過加鎖的方式實現了多進程安全，而且能夠在日誌文件達到特定大小時，分割文件，可是不支持按時間分割。this

包的源碼我並無仔細研究，也就沒辦法再細說了，你們若是感興趣的話能夠本身找來看。spa

因爲個人需求是按時間進行分割，顯然就不能用了，本身寫吧。線程

重寫 TimedRotatingFileHandler

經過上面的分析能夠知道，出問題的點就是發生在日誌分割時，一是刪文件，二是沒有及時更新寫入句柄。

因此針對這兩點，個人對策就是：一是去掉刪文件的邏輯，二是在切割文件時，及時將寫入句柄更新到最新。

代碼以下：

# 解決多進程日誌寫入混亂問題


import os
import time
from logging.handlers import TimedRotatingFileHandler


class CommonTimedRotatingFileHandler(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):
        """ 是否應該執行日誌滾動操做： 一、存檔文件已存在時，執行滾動操做 二、當前時間 >= 滾動時間點時，執行滾動操做 """
        dfn = self.dfn
        t = int(time.time())
        if t >= self.rolloverAt or os.path.exists(dfn):
            return 1
        return 0

    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.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
複製代碼