Python中的logger和handler到底是個什麼鬼

標籤：tle   定義   add   就會   內容   tin   切割   複雜   log4   

最近的任務經常涉及到日誌的記錄，特意去又學了一遍logging的記錄方法。跟java一樣，python的日誌記錄也是比較繁瑣的一件事，在寫一條記錄之前，要寫好多東西。典型的日誌記錄的步驟是這樣的：

1. 建立logger
2. 建立handler
3. 定義formatter
4. 給handler添加formatter
5. 給logger添加handler

寫成代碼差不多就是醬嬸的（這個是照別的網頁抄的，參考附註）：

 1 import logging  2  3 # 1、建立一個logger  4 logger = logging.getLogger(‘mylogger‘)  5 logger.setLevel(logging.DEBUG)  6  7 # 2、建立一個handler，用於寫入記錄檔  8 fh = logging.FileHandler(‘test.log‘)  9 fh.setLevel(logging.DEBUG) 10 11 # 再建立一個handler，用於輸出到控制台 12 ch = logging.StreamHandler() 13 ch.setLevel(logging.DEBUG) 14 15 # 3、定義handler的輸出格式（formatter）16 formatter = logging.Formatter(‘%(asctime)s - %(name)s - %(levelname)s - %(message)s‘) 17 18 # 4、給handler添加formatter19 fh.setFormatter(formatter) 20 ch.setFormatter(formatter) 21 22 # 5、給logger添加handler 23 logger.addHandler(fh) 24 logger.addHandler(ch) 

之後才可以正式的開始記錄日誌。Java裡面的java.util.Logging類差不多也是這樣，代碼還要更複雜一點。Golang的日誌相對寫法簡單一些，不過沒有什麼格式，系統記錄一條時間，內容格式完全自己手畫。第三方的日誌庫倒是沒有接觸過，像Java的Log4j，Golang的log4go和seelog等等，不知道用起來會不會簡單一點。我一直都記不住這些，因為不太理解logger和handler為什麼要這樣寫。一直到這次任務中出現的在我看來相當“詭異”的bug，才深入理解了一下。

我的工作是這樣的，要做一個日誌切割的工具，按天將日誌分割開，即每天0點產生一個新日誌，將舊日誌改名。並且，將超過3個月的日誌刪除掉，以保證磁碟空間不會被log佔滿。程式要求可以切割多個目錄中的不同日誌，具體路徑由json中配置。

這裡用到了logging.handlers類中的TimedRotatingFileHandler方法，用以獲得一個handler。大概的寫法為：

1 logger = logging.getLogger() #獲得logger2 handler = logging.handlers.TimedRotatingFileHandler(logfile, ‘S‘, 1, 0) #切割日誌3 handler.suffix = ‘%Y%m%d‘ #切割後的日誌設定尾碼4 logger.addHandler(handler) #把logger添加上handler5 logger.fatal(datetime.datetime.now().strftime(‘%Y-%m-%d‘)) #在新日誌中寫上當天的日期

這裡我沒有設定level和formatter。因為只是分割，對新日誌沒有什麼影響。TimedRotatingFileHandler函數的方法見附註，或查看python的源碼，這個函數是python寫的，可以找到定義。這裡我使用的是每秒產生一個新的記錄檔，之後用Crontab在每天0點調度，然後用for迴圈處理json中的每一個記錄檔。

但是奇怪的是，每次運行程式，第一個切割的日誌產生一個分割後的檔案，而後面的都產生兩個新日誌。百思不得其解。後檢查代碼覺得，可能是程式中設定的時間太短了，每秒產生一個檔案，有可能一秒鐘處理不完，就產生了兩個。雖然這個說法沒有什麼科學根據，但是還是把TimedRotatingFileHandler中的第三個參數改成了60，即每60秒產生一個檔案。完成，靜靜的等待crontab到時間。

 

叮！時間到。趕緊檢查一下結果。一個好訊息和一個壞訊息。好訊息是這次每個日誌都只切割產生了一個新檔案，沒有產生兩個。壞訊息是每個檔案裡面添加的當天的日期的數量見鬼了。我切割了4條日誌，產生的新日誌裡面就分別寫上了一、二、三、四行當天日期。

 

此刻我的內心幾乎是崩潰的。我開始思考為什麼會這樣。很明顯四行日期是調用了4次logger.fatal(‘datetime.datetime.now().strftime(‘%Y-%m-%d‘)) 這個函數。換句話說，我每一次for迴圈都在這個log裡面寫了一句話。可是明明每個for是處理一個日誌，下一次for應該是處理下一個日誌的，為什麼會再處理這個日誌一次？我突然想到，logger.addHandler(handler)是每次迴圈都會啟動並執行，也就是說，logger是同一個logger，添加了4次handler。到第4次迴圈的時候，這個logger中有4個handler，也就會往4個不同的日誌中新增內容了。呃。

 

如果是這樣的話，那麼把上面的程式改改，第一句和最後一句放在迴圈外，迴圈內只用中間的三句。這次OK了。回頭再看log記錄的步驟，也就明白了logger和handler到底是個什麼鬼：logger可以看做是一個記錄日誌的人，對於記錄的每個日誌，他需要有一套規則，比如記錄的格式（formatter），等級（level）等等，這個規則就是handler。使用logger.addHandler(handler)添加多個規則，就可以讓一個logger記錄多個日誌。至於logging.getLogger()方法獲得的root logger和繼承關係，可以詳見附註的網頁，這裡我也只是大概明白了什麼意思，還沒有具體用過。也許將來在架構中使用，要記錄較為複雜的日誌時候會用到吧。

Python中的logger和handler到底是個什麼鬼