歡迎來到Linux教程網
Linux教程網
Linux教程網
Linux教程網
您现在的位置: Linux教程網 >> UnixLinux >  >> Linux編程 >> Linux編程

Python logging模塊可能會令人困惑的地方

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 的下載地址:請點這裡

Copyright © Linux教程網 All Rights Reserved