python logging模塊主要是python提供的通用日志系統(tǒng)，使用的方法其實挺簡單的，這塊就不多介紹。下面主要會講到在使用python logging模塊的時候，涉及到多個python文件的調(diào)用，而每個文件設(shè)置了對應(yīng)的logging方式不同，可能會產(chǎn)生的令人困惑的現(xiàn)象。

下面以自己在開發(fā)的時候遇到的問題作為敘述的背景：

有三個python模塊A、B、C。主模塊A會import B和C模塊，主模塊有對應(yīng)的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的方式很簡單，創(chuàng)建一個RotatingFileHandler，通過RotatingFileHandler回滾logging的方式來控制LOG文件的個數(shù)和每個LOG文件的上限大小。并創(chuàng)建一個Formatter對象來設(shè)置LOG文件的格式。在程序中使用這種方式產(chǎn)生的logging對象來打LOG，很顯然使用這種方式的話，LOG都會打印到對應(yīng)的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模塊默認(rèn)logging的方式跟A差不多，只是B選擇logging的方式是往一個LOG文件中打LOG。A其實在實際使用B模塊對應(yīng)的函數(shù)和類的時候并沒有直接用B的logging方式，而是對B logging進(jìn)行了一個重定向，這個可以從SetLogger函數(shù)的作用可以函數(shù)。A直接會把已經(jīng)logging對象傳給B，這樣B也可以和A共享同一個logging對象，并把LOG打到A設(shè)定的文件中。這對于一個主模塊調(diào)用多個子模塊的邏輯、而且每個子模塊都有對應(yīng)的logging使用方式、打到不同文件中進(jìn)行統(tǒng)一還是挺有好處的，這樣可以有效的控制總的LOG文件大小和數(shù)量。

但是沒有注意C模塊，然后發(fā)現(xiàn)的情況是，A程序在運行過程中會把A、B模塊的LOG信息直接打到屏幕上，而且LOG文件中也有對應(yīng)的LOG。這些挺讓人困惑的，把對B模塊的調(diào)用注釋掉，依然會發(fā)現(xiàn)有A的LOG直接打到屏幕上。但是把A程序中設(shè)置logging對象的那段代碼單獨拿出來，一切都正常。

根據(jù)當(dāng)時的情景，只能懷疑是C模塊中有什么設(shè)置，會導(dǎo)致A、B模塊打LOG的方式有些轉(zhuǎn)變。后來意識到，C模塊中并沒有設(shè)置logging的對象，而是直接使用logging.info去打LOG。把這部分的邏輯注釋掉，發(fā)現(xiàn)A、B打LOG的方式又恢復(fù)正常，再也不會往屏幕上打LOG。

通過參閱python logging模塊的代碼，發(fā)現(xiàn)一些有趣的現(xiàn)象：

1. logging對象其實是一個樹形結(jié)構(gòu)，每個創(chuàng)建的logging對象都是root logging對象的孩子結(jié)點。當(dāng)使用logging模塊的getLogger(name=None)函數(shù)構(gòu)造logging對象的時候，如果name為None，這樣會產(chǎn)生一個root logging對象。如果name中含有.，比如name = 'a.b.c'，通過這種方式會產(chǎn)生3個logging對象，分別為c、b、a，c->b->a->root，root樹的根結(jié)點，a為root的孩子結(jié)點，b為a的孩子結(jié)點，c為a的孩子結(jié)點，依次類推。

2. root結(jié)點是全局的，雖然這過程中涉及到多個模塊，但是它們會共享一個root結(jié)點。

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文件中有對應(yīng)的LOG，但是屏幕中并沒有對象的顯示呢？

其實，如果對這個過程有些好奇，對直接很習(xí)以為常的方式有些懷疑，而且抱著這樣的好奇心去探索，相信肯定會有更多的收獲。

所以，比較困惑的是，為什么我調(diào)用A模塊產(chǎn)生的sLogger.info打出的LOG，只有LOG文件中有，而root logging為什么不打LOG打到屏幕上。為什么root logging不起作用。這個時候，可以看下logging __init__.py的代碼，會發(fā)現(xiàn)，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的方式有關(guān)。因此，print len(root.handlers)，發(fā)現(xiàn)結(jié)果為0。也就是說，默認(rèn)的root logging對應(yīng)的handlers為[]，這樣導(dǎo)致的結(jié)果是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

運行程序，得到如下運行結(jié)果：

0 []

1 [<logging.StreamHandler instance at 0x7f066e3eef80>]。

第一行結(jié)果為0 []很好的解釋了，為什么正常情況下，root logging對象為什么沒有打出LOG。

而調(diào)用logging.info('Bad')之后，root.handlers對象為StreamHandler對象。通過這個程序可以看到調(diào)用logging.info對象前后root logging對象發(fā)生的變化。

還有一點需要驗證，就是logging調(diào)用前后正常模塊logging的方式。

在__main__中寫下如下代碼：

if __name__ == '__main__':
 
  for i in xrange(0, 2):
 
    sLogger.info('OK')
 
    logging.info('Bad')

根據(jù)之前分析的，第一次調(diào)用sLogger.info('OK')是不會打LOG的，而logging.info本身是由于不到WARNING級別，所以也沒有打LOG，而第二次會打LOG在屏幕中。所以，看到的結(jié)果是，LOG文件中有三條LOG，而屏幕上有一條INFO:batch:OK。跟之前猜想到的挺吻合的。

 為什么調(diào)用了logging.info之后，會發(fā)生如此轉(zhuǎn)變？

繼續(xù)看完上面root logging info，并對照著下面的basicConfig代碼。會注意到len(root.handlers) == 0會去調(diào)用basicConfig，這個時候就可以注意下，basicConfig這個模塊的實現(xiàn)。

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)

可以看出，當(dāng)root.handlers的長度為0的時候，會創(chuàng)建一個默認(rèn)的StreamHandler對象，而這個對象設(shè)置的模式導(dǎo)致的情況是LOG會打到屏幕上。這個跟之前打出的logging.root.handlers的結(jié)果挺吻合。通過這些想必明白了，為什么我之前遇到的C文件中調(diào)用logging.info的方式會影響到上層模塊以及其調(diào)用的子模塊。

通過我遇到的問題，以及對logging的這相關(guān)部分的分析，想必會對logging模塊有更深刻的認(rèn)識。最關(guān)鍵的一點，如果想盡可能精確的控制logging方式，一定要注意，主模塊以及對應(yīng)的子模塊中具體不要直接使用logging打LOG。

更多關(guān)于多個python文件調(diào)用logging模塊產(chǎn)生錯誤的問題請查看下面的相關(guān)鏈接

最新評論