python logging模塊主要是python提供的通用日志系統,使用的方法其實挺簡單的,這塊就不多介紹。下面主要會講到在使用python logging模塊的時候,涉及到多個python文件的調用,而每個文件設置了對應的logging方式不同,可能會產生的令人困惑的現象。
下面以自己在開發的時候遇到的問題作為敘述的背景:
有三個python模塊A、B、C。主模塊A會import B和C模塊,主模塊有對應的logging方式,
A使用logging的模塊的方式為:
import logging
import logging.handlers
def CreateLogger(logFile = 'batch'):
handler = logging.handlers.RotatingFileHandler(str(logFile) + '.LOG', maxBytes = 1024 * 1024 * 500, backupCount = 5)
fmt = '%(asctime)s - %(filename)s:%(lineno)s - %(name)s - %(message)s'
formatter = logging.Formatter(fmt)
handler.setFormatter(formatter)
logger = logging.getLogger(str(logFile))
logger.addHandler(handler)
logger.setLevel(logging.INFO)
return logger
sLogger = CreateLogger()
其實A模塊使用logging的方式很簡單,創建一個RotatingFileHandler,通過RotatingFileHandler回滾logging的方式來控制LOG文件的個數和每個LOG文件的上限大小。並創建一個Formatter對象來設置LOG文件的格式。在程序中使用這種方式產生的logging對象來打LOG,很顯然使用這種方式的話,LOG都會打印到對應的LOG文件中去。
B使用logging模塊的方式為
def GetLogger(testName):
logger = logging.getLogger(testName)
logger.setLevel(logging.INFO)
hdlr = logging.FileHandler(testName + '.LOG')
hdlr.setLevel(logging.INFO)
formatter = logging.Formatter("[%(asctime)s]\t[%(levelname)s]\t[%(thread)d]\t[%(pathname)s:%(lineno)d]\t%(message)s")
hdlr.setFormatter(formatter)
logger.addHandler(hdlr)
return logger
logger = GetLogger('OK')
def SetLogger(log):
global logger
logger = log
B模塊默認logging的方式跟A差不多,只是B選擇logging的方式是往一個LOG文件中打LOG。A其實在實際使用B模塊對應的函數和類的時候並沒有直接用B的logging方式,而是對B logging進行了一個重定向,這個可以從SetLogger函數的作用可以函數。A直接會把已經logging對象傳給B,這樣B也可以和A共享同一個logging對象,並把LOG打到A設定的文件中。這對於一個主模塊調用多個子模塊的邏輯、而且每個子模塊都有對應的logging使用方式、打到不同文件中進行統一還是挺有好處的,這樣可以有效的控制總的LOG文件大小和數量。
但是沒有注意C模塊,然後發現的情況是,A程序在運行過程中會把A、B模塊的LOG信息直接打到屏幕上,而且LOG文件中也有對應的LOG。這些挺讓人困惑的,把對B模塊的調用注釋掉,依然會發現有A的LOG直接打到屏幕上。但是把A程序中設置logging對象的那段代碼單獨拿出來,一切都正常。
根據當時的情景,只能懷疑是C模塊中有什麼設置,會導致A、B模塊打LOG的方式有些轉變。後來意識到,C模塊中並沒有設置logging的對象,而是直接使用logging.info去打LOG。把這部分的邏輯注釋掉,發現A、B打LOG的方式又恢復正常,再也不會往屏幕上打LOG。
通過參閱python logging模塊的代碼,發現一些有趣的現象:
1. logging對象其實是一個樹形結構,每個創建的logging對象都是root logging對象的孩子結點。當使用logging模塊的getLogger(name=None)函數構造logging對象的時候,如果name為None,這樣會產生一個root logging對象。如果name中含有.,比如name = 'a.b.c',通過這種方式會產生3個logging對象,分別為c、b、a,c->b->a->root,root樹的根結點,a為root的孩子結點,b為a的孩子結點,c為a的孩子結點,依次類推。
2. root結點是全局的,雖然這過程中涉及到多個模塊,但是它們會共享一個root結點。
3. 每個logging對象打LOG的時候,也會把LOG信息傳遞到傳遞到上層logging對象中,對於c->b->a->root這種情況,這個LOG其實會打4次,以c、b、a、root循序依次打一個LOG。
可能有人會問,像我之前一般用A模塊或者B模塊那樣的方式去初始化一個logging對象,這樣初始化的對象也會是root logging對象的一個孩子,而root logging對象通常會把LOG打到屏幕上,那按理說,正常情況下打LOG都會打兩份,一份會打到文件中,一份會打到屏幕中。那為什麼實際情況是,只有LOG文件中有對應的LOG,但是屏幕中並沒有對象的顯示呢?
其實,如果對這個過程有些好奇,對直接很習以為常的方式有些懷疑,而且抱著這樣的好奇心去探索,相信肯定會有更多的收獲。
所以,比較困惑的是,為什麼我調用A模塊產生的sLogger.info打出的LOG,只有LOG文件中有,而root logging為什麼不打LOG打到屏幕上。為什麼root logging不起作用。這個時候,可以看下logging __init__.py的代碼,會發現,root logging info的代碼如下:
def info(msg, *args, **kwargs):
"""
Log a message with severity 'INFO' on the root logger.
"""
if len(root.handlers) == 0:
basicConfig()
root.info(msg, *args, **kwargs)
上面的代碼中涉及到root.handlers,懷疑root.handlers跟打LOG的方式有關。因此,print len(root.handlers),發現結果為0。也就是說,默認的root logging對應的handlers為[],這樣導致的結果是sLogger打LOG的時候,root logging並不會打任何LOG。在__main__中添加如下代碼:
if __name__ == '__main__':
sLogger.info('OK')
print len(logging.root.handlers), logging.root.handlers
logging.info('Bad')
print len(logging.root.handlers), logging.root.handlers
運行程序,得到如下運行結果:
0 []
1 [<logging.StreamHandler instance at 0x7f066e3eef80>]。
第一行結果為0 []很好的解釋了,為什麼正常情況下,root logging對象為什麼沒有打出LOG。
而調用logging.info('Bad')之後,root.handlers對象為StreamHandler對象。通過這個程序可以看到調用logging.info對象前後root logging對象發生的變化。
還有一點需要驗證,就是logging調用前後正常模塊logging的方式。
在__main__中寫下如下代碼:
if __name__ == '__main__':
for i in xrange(0, 2):
sLogger.info('OK')
logging.info('Bad')
根據之前分析的,第一次調用sLogger.info('OK')是不會打LOG的,而logging.info本身是由於不到WARNING級別,所以也沒有打LOG,而第二次會打LOG在屏幕中。所以,看到的結果是,LOG文件中有三條LOG,而屏幕上有一條INFO:batch:OK。跟之前猜想到的挺吻合的。
為什麼調用了logging.info之後,會發生如此轉變?
繼續看完上面root logging info,並對照著下面的basicConfig代碼。會注意到len(root.handlers) == 0會去調用basicConfig,這個時候就可以注意下,basicConfig這個模塊的實現。
def basicConfig(**kwargs):
if len(root.handlers) == 0:
filename = kwargs.get("filename")
if filename:
mode = kwargs.get("filemode", 'a')
hdlr = FileHandler(filename, mode)
else:
stream = kwargs.get("stream")
hdlr = StreamHandler(stream)
fs = kwargs.get("format", BASIC_FORMAT)
dfs = kwargs.get("datefmt", None)
fmt = Formatter(fs, dfs)
hdlr.setFormatter(fmt)
root.addHandler(hdlr)
level = kwargs.get("level")
if level is not None:
root.setLevel(level)
可以看出,當root.handlers的長度為0的時候,會創建一個默認的StreamHandler對象,而這個對象設置的模式導致的情況是LOG會打到屏幕上。這個跟之前打出的logging.root.handlers的結果挺吻合。通過這些想必明白了,為什麼我之前遇到的C文件中調用logging.info的方式會影響到上層模塊以及其調用的子模塊。
通過我遇到的問題,以及對logging的這相關部分的分析,想必會對logging模塊有更深刻的認識。最關鍵的一點,如果想盡可能精確的控制logging方式,一定要注意,主模塊以及對應的子模塊中具體不要直接使用logging打LOG。
--------------------------------------分割線 --------------------------------------
CentOS上源碼安裝Python3.4 http://www.linuxidc.com/Linux/2015-01/111870.htm
《Python核心編程 第二版》.(Wesley J. Chun ).[高清PDF中文版] http://www.linuxidc.com/Linux/2013-06/85425.htm
《Python開發技術詳解》.( 周偉,宗傑).[高清PDF掃描版+隨書視頻+代碼] http://www.linuxidc.com/Linux/2013-11/92693.htm
Python腳本獲取Linux系統信息 http://www.linuxidc.com/Linux/2013-08/88531.htm
在Ubuntu下用Python搭建桌面算法交易研究環境 http://www.linuxidc.com/Linux/2013-11/92534.htm
Python 語言的發展簡史 http://www.linuxidc.com/Linux/2014-09/107206.htm
Python 的詳細介紹:請點這裡
Python 的下載地址:請點這裡