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,**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模組產生錯誤的問題請檢視下面的相關連結