本篇文章主要對 python logging 的介紹加深理解。更主要是 討論在多程式環境下如何使用logging 來輸出日誌， 如何安全地切分日誌檔案。
1. logging日誌模組介紹
python的logging模組提供了靈活的標準模組，使得任何Python程式都可以使用這個第三方模組來實現日誌記錄。python logging 官方文件
logging框架中主要由四個部分組成：
- Loggers: 可供程式直接呼叫的介面
- Handlers: 決定將日誌記錄分配至正確的目的地
- Filters: 提供更細粒度的日誌是否輸出的判斷
- Formatters: 制定最終記錄列印的格式佈局
2. logging的組成
loggers
loggers 就是程式可以直接呼叫的一個日誌介面，可以直接向logger寫入日誌資訊。logger並不是直接例項化使用的，而是通過logging.getLogger(name)來獲取物件，事實上logger物件是單例模式，logging是多執行緒安全的，也就是無論程式中哪裡需要打日誌獲取到的logger物件都是同一個。但是不幸的是logger並不支援多程式，這個在後面的章節再解釋，並給出一些解決方案。
【注意】loggers物件是有父子關係的，當沒有父logger物件時它的父物件是root，當擁有父物件時父子關係會被修正。舉個例子logging.getLogger("abc.xyz")會建立兩個logger物件，一個是abc父物件，一個是xyz子物件，同時abc沒有父物件所以它的父物件是root。但是實際上abc是一個佔位物件（虛的日誌物件），可以沒有handler來處理日誌。但是root不是佔位物件，如果某一個日誌物件打日誌時，它的父物件會同時收到日誌，所以有些使用者發現建立了一個logger物件時會打兩遍日誌，就是因為他建立的logger打了一遍日誌，同時root物件也打了一遍日誌。
每個logger都有一個日誌的級別。logging中定義瞭如下級別
| Level | Numeric value |
|---|---|
| NOTSET | 0 |
| DEBUG | 10 |
| INFO | 20 |
| WARNING | 30 |
| ERROR | 40 |
| CRITICAL | 50 |
當一個logger收到日誌資訊後先判斷是否符合level，如果決定要處理就將資訊傳遞給Handlers進行處理。
Handlers
Handlers 將logger發過來的資訊進行準確地分配，送往正確的地方。舉個栗子，送往控制檯或者檔案或者both或者其他地方(程式管道之類的)。它決定了每個日誌的行為，是之後需要配置的重點區域。
每個Handler同樣有一個日誌級別，一個logger可以擁有多個handler也就是說logger可以根據不同的日誌級別將日誌傳遞給不同的handler。當然也可以相同的級別傳遞給多個handlers這就根據需求來靈活的設定了。
Filters
Filters 提供了更細粒度的判斷，來決定日誌是否需要列印。原則上handler獲得一個日誌就必定會根據級別被統一處理，但是如果handler擁有一個Filter可以對日誌進行額外的處理和判斷。例如Filter能夠對來自特定源的日誌進行攔截or修改甚至修改其日誌級別（修改後再進行級別判斷）。
logger和handler都可以安裝filter甚至可以安裝多個filter串聯起來。
Formatters
Formatters 指定了最終某條記錄列印的格式佈局。Formatter會將傳遞來的資訊拼接成一條具體的字串，預設情況下Format只會將資訊%(message)s直接列印出來。Format中有一些自帶的LogRecord屬性可以使用，如下表格:
| Attribute | Format | Description |
|---|---|---|
| asctime | %(asctime)s | 將日誌的時間構造成可讀的形式，預設情況下是‘2016-02-08 12:00:00,123’精確到毫秒 |
| filename | %(filename)s | 包含path的檔名 |
| funcName | %(funcName)s | 由哪個function發出的log |
| levelname | %(levelname)s | 日誌的最終等級（被filter修改後的） |
| message | %(message)s | 日誌資訊 |
| lineno | %(lineno)d | 當前日誌的行號 |
| pathname | %(pathname)s | 完整路徑 |
| process | %(process)s | 當前程式 |
| thread | %(thread)s | 當前執行緒 |
一個Handler只能擁有一個Formatter 因此如果要實現多種格式的輸出只能用多個Handler來實現。
3. logging 配置
簡易配置
首先在 loggers 章節裡說明了一點，我們擁有一個預設的日誌物件root，這個root日誌物件的好處是我們直接可以使用logging來進行配置和打日誌。例如：
|
1 2 |
logging.basicConfig(level=logging.INFO,filename='logger.log') logging.info("info message") |
所以這裡的簡易配置所指的就是root日誌物件，隨拿隨用。每個logger都是單例物件所以配置過一遍之後程式內任何地方呼叫都可以。我們只需要呼叫basicConfig就可以對root日誌物件進行簡易的配置，事實上這種方式相當有效易用。它使得呼叫任何logger時保證至少一定會有一個Handler能夠處理日誌。
簡易配置大致可以這麼設定：
|
1 2 3 4 5 |
logging.basicConfig(level=logging.INFO, format='%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s', datefmt='[%Y-%m_%d %H:%M:%S]', filename='../log/my.log', filemode='a') |
程式碼配置
另一種更加細緻地設定方式是在程式碼中配置，但這種設定方式是使用的最少的方式，畢竟誰也不希望把設定寫死到程式碼裡面去。但是這裡也稍微介紹一下，雖然用的不多，在必要的時候也可以用一把。(以後補上)
配置檔案配置
python中logging的配置檔案是基於ConfigParser的功能。也就是說配置檔案的格式也是按照這種方式來編寫。先奉上一個比較一般的配置檔案再細說
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 |
############################################## [loggers] keys=root, log02 [logger_root] level=INFO handlers=handler01 [logger_log02] level=DEBUG handler=handler02 qualname=log02 ############################################## [handlers] keys=handler01,handler02 [handler_handler01] class=FileHandler level=INFO formatter=form01 args=('../log/cv_parser_gm_server.log',"a") [handler_handler02] class=StreamHandler level=NOTSET formatter=form01 args=(sys.stdout,) ############################################## [formatters] keys=form01,form02 [formatter_form01] format=%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(process)d %(message)s datefmt=[%Y-%m-%d %H:%M:%S] [formatter_form02] format=(message)s ############################################## |
相信看一遍以後，也找出規律了，我將幾個大塊用#分了出來。每一個logger或者handler或者formatter都有一個key名字。以logger為例，首先需要在[loggers]配置中加上key名字代表了這個logger。然後用[loggers_xxxx]其中xxxx為key名來具體配置這個logger，在log02中我配置了level和一個handler名，當然你可以配置多個hander。根據這個handler名再去 [handlers]裡面去找具體handler的配置，以此類推。
然後在程式碼中，這樣載入配置檔案即可：
|
1 |
logging.config.fileConfig(log_conf_file) |
在handler中有一個class配置，可能有些讀者並不是很懂。其實這個是logging裡面原先就寫好的一些handler類，你可以在這裡直接呼叫。class指向的類相當於具體處理的Handler的執行者。在logging的文件中可以知道這裡所有的Handler類都是執行緒安全的，大家可以放心使用。那麼問題就來了，如果多程式怎麼辦呢。在下一章我主要就是重寫Handler類，來實現在多程式環境下使用logging。 我們自己重寫或者全部新建一個Handler類，然後將class配置指向自己的Handler類就可以載入自己重寫的Handler了。
4. logging遇到多程式（important）
這部分其實是我寫這篇文章的初衷。python中由於某種歷史原因，多執行緒的效能基本可以無視。所以一般情況下python要實現並行操作或者平行計算的時候都是使用多程式。但是 python 中logging 並不支援多程式，所以會遇到不少麻煩。
本次就以 TimedRotatingFileHandler 這個類的問題作為例子。這個Handler本來的作用是：按天切割日誌檔案。（當天的檔案是xxxx.log 昨天的檔案是xxxx.log.2016-06-01）。這樣的好處是，一來可以按天來查詢日誌，二來可以讓日誌檔案不至於非常大, 過期日誌也可以按天刪除。
但是問題來了，如果是用多程式來輸出日誌，則只有一個程式會切換，其他程式會在原來的檔案中繼續打，還有可能某些程式切換的時候早就有別的程式在新的日誌檔案裡打入東西了，那麼他會無情刪掉之，再建立新的日誌檔案。反正將會很亂很亂，完全沒法開心的玩耍。
所以這裡就想了幾個辦法來解決多程式logging問題
原因
在解決之前，我們先看看為什麼會導致這樣的原因。
先將 TimedRotatingFileHandler 的原始碼貼上來，這部分是切換時所作的操作：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 |
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 |
我們觀察 if os.path.exists(dfn) 這一行開始，這裡的邏輯是如果 dfn 這個檔案存在，則要先刪除掉它，然後將 baseFilename 這個檔案重新命名為 dfn 檔案。然後再重新開啟 baseFilename這個檔案開始寫入東西。那麼這裡的邏輯就很清楚了
- 假設當前日誌檔名為 current.log 切分後的檔名為 current.log.2016-06-01
- 判斷 current.log.2016-06-01 是否存在，如果存在就刪除
- 將當前的日誌檔名 改名為current.log.2016-06-01
- 重新開啟新檔案（我觀察到原始碼中預設是”a” 模式開啟，之前據說是”w”）
於是在多程式的情況下，一個程式切換了，其他程式的控制程式碼還在 current.log.2016-06-01 還會繼續往裡面寫東西。又或者一個程式執行切換了，會把之前別的程式重新命名的 current.log.2016-06-01 檔案直接刪除。又或者還有一個情況，當一個程式在寫東西，另一個程式已經在切換了，會造成不可預估的情況發生。還有一種情況兩個程式同時在切檔案，第一個程式正在執行第3步，第二程式剛執行完第2步，然後第一個程式 完成了重新命名但還沒有新建一個新的 current.log 第二個程式開始重新命名，此時第二個程式將會因為找不到 current 發生錯誤。如果第一個程式已經成功建立了 current.log 第二個程式會將這個空檔案另存為 current.log.2016-06-01。那麼不僅刪除了日誌檔案，而且，程式一認為已經完成過切分了不會再切，而事實上他的控制程式碼指向的是current.log.2016-06-01。
好了這裡看上去很複雜，實際上就是因為對於檔案操作時，沒有對多程式進行一些約束，而導致的問題。
那麼如何優雅地解決這個問題呢。我提出了兩種方案，當然我會在下面提出更多可行的方案供大家嘗試。
解決方案1
先前我們發現 TimedRotatingFileHandler 中邏輯的缺陷。我們只需要稍微修改一下邏輯即可：
- 判斷切分後的檔案 current.log.2016-06-01 是否存在，如果不存在則進行重新命名。（如果存在說明有其他程式切過了，我不用切了，換一下控制程式碼即可）
- 以”a”模式 開啟 current.log
發現修改後就這麼簡單~
talking is cheap show me the code:
123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263class SafeRotatingFileHandler(TimedRotatingFileHandler):def __init__(self, filename, when='h', interval=1, backupCount=0, encoding=None, delay=False, utc=False):TimedRotatingFileHandler.__init__(self, filename, when, interval, backupCount, encoding, delay, utc)"""Override doRolloverlines commanded by "##" is changed by cc"""def doRollover(self):"""do a rollover; in this case, a date/time stamp is appended to the filenamewhen the rollover happens. However, you want the file to be named for thestart 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 removethe one with the oldest suffix.Override, 1. if dfn not exist then do rename2. _open with "a" model"""if self.stream:self.stream.close()self.stream = None# get the time that this sequence started at and make it a TimeTuplecurrentTime = int(time.time())dstNow = time.localtime(currentTime)[-1]t = self.rolloverAt - self.intervalif self.utc:timeTuple = time.gmtime(t)else:timeTuple = time.localtime(t)dstThen = timeTuple[-1]if dstNow != dstThen:if dstNow:addend = 3600else:addend = -3600timeTuple = 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):if not os.path.exists(dfn) and 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.mode = "a"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 houraddend = -3600else: # DST bows out before next rollover, so we need to add an houraddend = 3600newRolloverAt += addendself.rolloverAt = newRolloverAt
不要以為程式碼那麼長，其實修改部分就是 “##” 註釋的地方而已，其他都是照抄原始碼。這個類繼承了 TimedRotatingFileHandler 重寫了這個切分的過程。這個解決方案十分優雅，改換的地方非常少，也十分有效。但有網友提出，這裡有一處地方依然不完美，就是rename的那一步，如果就是這麼巧，同時兩個或者多個程式進入了 if 語句，先後開始 rename 那麼依然會發生刪除掉日誌的情況。確實這種情況確實會發生，由於切分檔案一天才一次，正好切分的時候同時有兩個Handler在操作，又正好同時走到這裡，也是蠻巧的，但是為了完美，可以加上一個檔案鎖，if 之後加鎖，得到鎖之後再判斷一次，再進行rename這種方式就完美了。程式碼就不貼了，涉及到鎖程式碼，影響美觀。
解決方案2
我認為最簡單有效的解決方案。重寫FileHandler類（這個類是所有寫入檔案的Handler都需要繼承的TimedRotatingFileHandler 就是繼承的這個類；我們增加一些簡單的判斷和操作就可以。
我們的邏輯是這樣的：
- 判斷當前時間戳是否與指向的檔名是同一個時間
- 如果不是，則切換 指向的檔案即可
結束，是不是很簡單的邏輯。
talking is cheap show me the code:
123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566class SafeFileHandler(FileHandler):def __init__(self, filename, mode, encoding=None, delay=0):"""Use the specified filename for streamed logging"""if codecs is None:encoding = NoneFileHandler.__init__(self, filename, mode, encoding, delay)self.mode = modeself.encoding = encodingself.suffix = "%Y-%m-%d"self.suffix_time = ""def emit(self, record):"""Emit a record.Always check time"""try:if self.check_baseFilename(record):self.build_baseFilename()FileHandler.emit(self, record)except (KeyboardInterrupt, SystemExit):raiseexcept:self.handleError(record)def check_baseFilename(self, record):"""Determine if builder should occur.record is not used, as we are just comparing times,but it is needed so the method signatures are the same"""timeTuple = time.localtime()if self.suffix_time != time.strftime(self.suffix, timeTuple) or not os.path.exists(self.baseFilename+'.'+self.suffix_time):return 1else:return 0def build_baseFilename(self):"""do builder; in this case,old time stamp is removed from filename anda new time stamp is append to the filename"""if self.stream:self.stream.close()self.stream = None# remove old suffixif self.suffix_time != "":index = self.baseFilename.find("."+self.suffix_time)if index == -1:index = self.baseFilename.rfind(".")self.baseFilename = self.baseFilename[:index]# add new suffixcurrentTimeTuple = time.localtime()self.suffix_time = time.strftime(self.suffix, currentTimeTuple)self.baseFilename = self.baseFilename + "." + self.suffix_timeself.mode = 'a'if not self.delay:self.stream = self._open()
check_baseFilename 就是執行邏輯1判斷；build_baseFilename 就是執行邏輯2換控制程式碼。就這麼簡單完成了。
這種方案與之前不同的是，當前檔案就是 current.log.2016-06-01 ，到了明天當前檔案就是current.log.2016-06-02 沒有重新命名的情況，也沒有刪除的情況。十分簡潔優雅。也能解決多程式的logging問題。
解決方案其他
當然還有其他的解決方案，例如由一個logging程式統一打日誌，其他程式將所有的日誌內容打入logging程式管道由它來打理。還有將日誌打入網路socket當中也是同樣的道理。