關於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輸出的時候，常常會發現，莫名奇妙的會輸出重複的內容，主要有如下幾個可能的緣由：
一、前面說過，任何自定義的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的。 二、有人可能會說，上面這個狀況不太可能會發生，由於我直接設置一個子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之後，會莫名其妙重複屢次輸出日誌了吧？ 三、還有一種狀況，也堪稱巨坑。當使用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'這個自定義的字段了。

原文出處：https://www.cnblogs.com/telecomshy/p/10630888.html