關於logging的那些坑

python的logging日志記錄模塊非常強大，使用也很簡單，但是特別容易出各種意外狀況，打印各種出乎意料的log。最近對logging的一些原理進行了學習，再此做個記錄，以備忘。
首先全面的了解一下整體的結構。logging默認就有一個root的Logger對象，輸入logging.root可以看到，默認為warning級別：

>>> logging.root
<RootLogger root (WARNING)>

用戶自行創建的所有logger對象，都是root的子對象。

>>> logger = logging.getLogger('logger')
>>> logger.parent
<RootLogger root (WARNING)>

需要注意的是，當getLogger()不帶參數時，返回的就是rootLogger對象本身。

>>> logger = logging.getLogger()
>>> logger
<RootLogger root (WARNING)>
>>> logger is logging.root
True

創建了Logger對象，接下來我們需要創建handler對象，handler對象是用來配置處理log時用的格式，級別等等特性的，我們可以根據需求創建各種不同的handler，比如將log記錄保存在文件的FileHandler，將log輸出到屏幕的StreamHandler，支持日志根據時間回滾的TimedRotatingFileHandler，根據文件大小回滾的RotatingFileHandler等等（回滾不太好理解，根據時間或文件大小回滾其實就是根據時間或者文件大小來保存日志，比如只保存3天的日志，超過3天的就自動刪除，或者設置日志文件只能為一定大小，超過就刪除）。
各種handler網上各種文章都有介紹，或者查官方文檔，這里就不列舉了。稍微一提的是，最常用的FileHandler和StreamHandler在logging下，其它的handler在logging.handlers下。另外，logger和handler的level可以分別設置，以滿足不同的需求。
創建了handler，就要把它添加到logger對象中去，logger對象有一個handlers屬性，其實就是一個簡單的列表，可以看到所有添加給它的hanlder。如下：

>>> logger = logging.getLogger('spam')
>>> handler = logging.StreamHandler()
>>> logger.addHandler(handler)
>>> logger.handlers
[<StreamHandler <stderr> (NOTSET)>]

可見，logger對象添加了handler，是一個輸出到stderr，級別未設置的handler。此時，就可以通過logger對象輸出各種logger了，如：

>>> logger = logging.getLogger('spam')
>>> handler = logging.StreamHandler()
>>> formatter = logging.Formatter("%(asctime)s-%(levelname)s-%(message)s")
>>> handler.setFormatter(formatter)
>>> handler.setLevel(logging.INFO)
>>> logger.addHandler(handler)
>>> logger.handlers
[<StreamHandler <stderr> (INFO)>]
>>> logger.setLevel(logging.INFO)
>>> logger.info('info')
2019-03-31 11:59:41,933-INFO-info

對整體有個大體的了解，接下來就可以談談常見的大坑了。
首先，平時在log輸出的時候，經常會發現，莫名奇妙的會輸出重復的內容，主要有以下幾個可能的原因：
1、前面說過，任何自定義的logger對象都是rootLogger的子對象，就像這樣，rootLogger(parent)->Logger(child)，而當你使用自定義的logger記錄日志的時候，它會從子到父，從左到右依次執行所有的handler來輸出，看代碼：

>>> rootLogger = logging.getLogger()
>>> rootLogger.setLevel(logging.INFO)
>>> roothandler = logging.StreamHandler()
>>> fmt = logging.Formatter("%(name)s-%(levelname)s-%(message)s")
>>> roothandler.setLevel(logging.INFO)
>>> roothandler.setFormatter(fmt)
>>> rootLogger.addHandler(roothandler)
>>> rootLogger.handlers
[<StreamHandler <stderr> (INFO)>]
>>> childLogger = logging.getLogger("child")
>>> childLogger.setLevel(logging.INFO)
>>> childhandler = logging.StreamHandler()
>>> childhandler.setLevel(logging.INFO)
>>> childhandler.setFormatter(fmt)
>>> childLogger.addHandler(childhandler)
>>> childLogger.handlers
[<StreamHandler <stderr> (INFO)>]
>>> childLogger.info('i am child')
child-INFO-i am child
child-INFO-i am child

日志輸出了2次，注意輸出的logger name，雖然有一個是rootLogger的handler輸出的，但是name還是子logger的。
2、有人可能會說，上面這個情況不太可能會發生，因為我直接設置一個子logger就ok了，是這樣沒錯，but，當你直接使用logging.basicConfig對rootLogger對象進行配置或者在創建自己的logger對象之前，用logging.info等命令輸出過日志的時候，logging會自動的（偷偷摸摸的）給你創建一個streamhandler，如下：

>>> root = logging.getLogger()
>>> root.handlers
[]
>>> logging.basicConfig(level=logging.INFO)
>>> root.handlers
[<StreamHandler <stderr> (NOTSET)>]

>>> root = logging.getLogger()
>>> root.handlers
[]
>>> logging.info('i am root')
>>> root.handlers
[<StreamHandler <stderr> (NOTSET)>]

現在明白為什么有時候創建了一個logger以后，會莫名其妙重復多次輸出日志了吧？
3、還有一種情況，也堪稱巨坑。當使用IDE工具編程的時候，整個IDE會話不結束，logger的handlers列表不清空！這就導致反復運行程序的時候，handler會反復添加，結果你會發現log輸出越來越多。。。。。如下：

第一次運行，一個handler，第二次運行，變2個了，怎么辦呢？可以在程序結尾加一行代碼root.removeHandler(handler)，或者簡單粗暴一點，直接root.handlers=[]，每次程序運行完，將handlers列表全清空。
差不多就這些吧，最后還有一個小知識點，有些同學會問，為啥我自定義的logger啥handler都沒加的時候，也有輸出呢？比如：

>>> import logging
>>> logger = logging.getLogger('child')
>>> logger.handlers
[]
>>> logging.root.handlers
[]
>>> logger.warning('i am child')
i am child

因為logging模塊有一個默認的hanlder，可以通過logging.lastResort查看，如下：

>>> logging.lastResort
<_StderrHandler <stderr> (WARNING)>

這個handler沒有和任何logger關聯，專門處理用戶啥都沒配置的情況，可見，默認級別是warning，默認輸出是stderr（注意是stderr而不是標准的stdout，因此如果你采取這種方式輸出日志又進行了重定向，很有可能達不到想要的效果），僅僅輸出一個message，其它啥都沒有。
最后總結：logging確實很好用，但是個人覺得有些過於靈活了，很多事情私底下偷偷摸摸的做了，反而會給用戶帶來困擾。
原創不易，轉載請注明出處。

====================================

2019年4月1日補充更新：
除了定制不同級別的level，logger還可以添加filter對象來對輸出進行更加復雜的控制。filter和handler一樣，先進行配置，然后再添加到logger對象中。所有日志在輸出之前，都會先通過filter進行過濾。創建filter要先創建一個繼承自logging.Filter的類，代碼如下：

import logging
import sys


class ContextFilter(logging.Filter):
    def filter(self, record):
        if record.role == "admin":
            return True
        else:
            return False


if __name__ == '__main__':
    logger = logging.getLogger("Wechat")
    logger.setLevel(logging.DEBUG)
    handler = logging.StreamHandler(sys.stdout)
    formatter = logging.Formatter(
                    '%(asctime)s %(levelname)s:%(message)s Role:%(role)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)

    f = ContextFilter()
    logger.addFilter(f)
    logger.info('An info message with %s', 'some parameters',
                extra={"role": "admin"})
    logger.info('An info message with %s', 'some parameters',
                extra={"role": "hacker"})

從3.2以后，不一定非要創建一個logging.Filter子類，只要是有filter屬性的任何對象或者函數都行，后台會檢查這個對象是否有filter屬性，如果有，則會調用這個對象的filter()方法，沒有的話就把它當作一個callable對象，直接執行，並且把records當作一個參數傳遞給這個callable對象。

import logging
import sys


def myfilter(record):
    if record.role == "admin":
        return True
    else:
        return False


if __name__ == '__main__':
    logger = logging.getLogger("Wechat")
    logger.setLevel(logging.DEBUG)
    handler = logging.StreamHandler(sys.stdout)
    formatter = logging.Formatter(
            '%(asctime)s %(levelname)s: %(message)s Role: %(role)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    logger.addFilter(myfilter)
    logger.info('An info message with %s', 'some parameters',
                extra={"role":"admin"})
    logger.info('An info message with %s', 'some parameters',
                extra={"role":"hacker"}

部分代碼參考https://www.cnblogs.com/progor/p/9269230.html，特此申明。

4.5日新增：
繼續談談filter，需要注意的是，如果使用上面的例子，那么在每一條日志記錄里面，都需要加上一條extra={"role":"xxx"}，因為所有的日志record對象都會先通過filter過濾，此時會檢查record是否有role屬性，如果沒有設置，顯然會報錯。
其實除了過濾這一種用法，filter還可以通過在函數里面給record添加屬性，方便的增加自定義的字段。還是看例子：

def myfilter(record):
	record.user = 'telecomshy'
	return True

>>> logger = logging.getLogger()
>>> logger.addFilter(myfilter)
>>> import sys
>>> fmt = logging.Formatter("%(levelname)s-%(asctime)s-%(message)s-%(user)s")
>>> handler = logging.StreamHandler(sys.stdout)
>>> handler.setLevel("DEBUG")
>>> handler.setFormatter(fmt)
>>> logger.addHandler(handler)
>>> logger.setLevel("DEBUG")
>>> logger.info('hello world')
INFO-2019-04-05 11:55:28,764-hello world-telecomshy

如上，通過使用filter，現在可以在formatter里面使用'user'這個自定義的字段了。