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。

 

python logging模組可能會令人困惑的地方