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

1. 創(chuàng)建logger
2. 創(chuàng)建handler
3. 定義formatter
4. 給handler添加formatter
5. 給logger添加handler

寫成代碼差不多就是醬嬸的（這個(gè)是照別的網(wǎng)頁(yè)抄的，參考附注）：

 1 import logging 
 2 
 3 # 1、創(chuàng)建一個(gè)logger 
 4 logger = logging.getLogger('mylogger') 
 5 logger.setLevel(logging.DEBUG) 
 6 
 7 # 2、創(chuàng)建一個(gè)handler，用于寫入日志文件 
 8 fh = logging.FileHandler('test.log') 
 9 fh.setLevel(logging.DEBUG) 
10 
11 # 再創(chuàng)建一個(gè)handler，用于輸出到控制臺(tái) 
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添加formatter
19 fh.setFormatter(formatter) 
20 ch.setFormatter(formatter) 
21 
22 # 5、給logger添加handler 
23 logger.addHandler(fh) 
24 logger.addHandler(ch) 

之后才可以正式的開始記錄日志。Java里面的java.util.Logging類差不多也是這樣，代碼還要更復(fù)雜一點(diǎn)。Golang的日志相對(duì)寫法簡(jiǎn)單一些，不過(guò)沒(méi)有什么格式，系統(tǒng)記錄一條時(shí)間，內(nèi)容格式完全自己手畫。第三方的日志庫(kù)倒是沒(méi)有接觸過(guò)，像Java的Log4j，Golang的log4go和seelog等等，不知道用起來(lái)會(huì)不會(huì)簡(jiǎn)單一點(diǎn)。我一直都記不住這些，因?yàn)椴惶斫鈒ogger和handler為什么要這樣寫。一直到這次任務(wù)中出現(xiàn)的在我看來(lái)相當(dāng)“詭異”的bug，才深入理解了一下。

我的任務(wù)是這樣的，要做一個(gè)日志切割的工具，按天將日志分割開，即每天0點(diǎn)產(chǎn)生一個(gè)新日志，將舊日志改名。并且，將超過(guò)3個(gè)月的日志刪除掉，以保證磁盤空間不會(huì)被log占滿。程序要求可以切割多個(gè)目錄中的不同日志，具體路徑由json中配置。

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

1 logger = logging.getLogger() #獲得logger
2 handler = logging.handlers.TimedRotatingFileHandler(logfile, 'S', 1, 0) #切割日志
3 handler.suffix = '%Y%m%d' #切割后的日志設(shè)置后綴
4 logger.addHandler(handler) #把logger添加上handler
5 logger.fatal(datetime.datetime.now().strftime('%Y-%m-%d')) #在新日志中寫上當(dāng)天的日期

這里我沒(méi)有設(shè)置level和formatter。因?yàn)橹皇欠指?，?duì)新日志沒(méi)有什么影響。TimedRotatingFileHandler函數(shù)的方法見附注，或查看python的源碼，這個(gè)函數(shù)是python寫的，可以找到定義。這里我使用的是每秒生成一個(gè)新的日志文件，之后用Crontab在每天0點(diǎn)調(diào)度，然后用for循環(huán)處理json中的每一個(gè)日志文件。

但是奇怪的是，每次運(yùn)行程序，第一個(gè)切割的日志生成一個(gè)分割后的文件，而后面的都生成兩個(gè)新日志。百思不得其解。后檢查代碼覺(jué)得，可能是程序中設(shè)置的時(shí)間太短了，每秒生成一個(gè)文件，有可能一秒鐘處理不完，就生成了兩個(gè)。雖然這個(gè)說(shuō)法沒(méi)有什么科學(xué)根據(jù)，但是還是把TimedRotatingFileHandler中的第三個(gè)參數(shù)改成了60，即每60秒生成一個(gè)文件。完成，靜靜的等待crontab到時(shí)間。

叮！時(shí)間到。趕緊檢查一下結(jié)果。一個(gè)好消息和一個(gè)壞消息。好消息是這次每個(gè)日志都只切割生成了一個(gè)新文件，沒(méi)有生成兩個(gè)。壞消息是每個(gè)文件里面添加的當(dāng)天的日期的數(shù)量見鬼了。我切割了4條日志，生成的新日志里面就分別寫上了一、二、三、四行當(dāng)天日期。

此刻我的內(nèi)心幾乎是崩潰的。我開始思考為什么會(huì)這樣。很明顯四行日期是調(diào)用了4次logger.fatal('datetime.datetime.now().strftime('%Y-%m-%d')) 這個(gè)函數(shù)。換句話說(shuō)，我每一次for循環(huán)都在這個(gè)log里面寫了一句話?？墒敲髅髅總€(gè)for是處理一個(gè)日志，下一次for應(yīng)該是處理下一個(gè)日志的，為什么會(huì)再處理這個(gè)日志一次？我突然想到，logger.addHandler(handler)是每次循環(huán)都會(huì)運(yùn)行的，也就是說(shuō)，logger是同一個(gè)logger，添加了4次handler。到第4次循環(huán)的時(shí)候，這個(gè)logger中有4個(gè)handler，也就會(huì)往4個(gè)不同的日志中添加內(nèi)容了。呃。

如果是這樣的話，那么把上面的程序改改，第一句和最后一句放在循環(huán)外，循環(huán)內(nèi)只用中間的三句。這次OK了。回頭再看log記錄的步驟，也就明白了logger和handler到底是個(gè)什么鬼：logger可以看做是一個(gè)記錄日志的人，對(duì)于記錄的每個(gè)日志，他需要有一套規(guī)則，比如記錄的格式（formatter），等級(jí)（level）等等，這個(gè)規(guī)則就是handler。使用logger.addHandler(handler)添加多個(gè)規(guī)則，就可以讓一個(gè)logger記錄多個(gè)日志。至于logging.getLogger()方法獲得的root logger和繼承關(guān)系，可以詳見附注的網(wǎng)頁(yè)，這里我也只是大概明白了什么意思，還沒(méi)有具體用過(guò)。也許將來(lái)在框架中使用，要記錄較為復(fù)雜的日志時(shí)候會(huì)用到吧。

附：本篇博客中參考的幾個(gè)網(wǎng)頁(yè)：

• 《使用python的logging模塊》http://kenby./blog/1162698
• 《python logging現(xiàn)學(xué)現(xiàn)用 – TimedRotatingFileHandler使用方法》http://openexz.sinaapp.com/2011/10/12/python-logging%E7%8E%B0%E5%AD%A6%E7%8E%B0%E7%94%A8-timedrotatingfilehandler%E4%BD%BF%E7%94%A8%E6%96%B9%E6%B3%95/
• 《python 日志模塊 logging 詳解》http://my.oschina.net/leejun2005/blog/126713
• Python源碼logging模塊