我前面有篇文章已經詳細介紹了一下 Python 的日志模塊。Python 提供了非常多的可以運用在各種不同場景的 Log Handler.
TimedRotatingFileHandler 是 Python 提供的一個可以基於時間自動切分日志的 Handler 類，他繼承自 BaseRotatingHandler -> logging.FileHandler
但是他有一個缺點就是沒有辦法支持多進程的日志切換，多進程進行日志切換的時候可能會因為重命名而丟失日志數據。
來看下他的實現(我默認大家已經知道了 FileHandler 的實現和 logging 模塊的調用機制 如果還不清楚可以先去看下我前面那篇文章 https://www.cnblogs.com/piperck/p/9634133.html)：
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 not os.path.exists(dfn): os.rename(self.baseFilename, dfn)
# 釋放鎖 釋放老 log 句柄
f.close() 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 去編輯該文件是可以繞過這個鎖的這個一定要注意。
Reference:
https://gavv.github.io/blog/file-locks/ File locking in Linux
https://www.cnblogs.com/gide/p/6811927.html python中給程序加鎖之fcntl模塊的使用
http://blog.jobbole.com/104331/ Linux 中 fcntl()、lockf、flock 的區別