python的logging 模塊淺析

0x00 python logging的繼承關係

使用python作日誌輸出時，首先咱們須要一個建立一個Logger對象：import logging; logger = logging.getLogger()。而後，咱們就能夠用logger.info/debug/error(msg)來輸出日誌了。

若是隻是單純地打印日誌，這樣作和醜陋的print沒有任何區別。咱們指望log能有必定的格式，這時你就會用到logging.Formatter；咱們還但願日誌不只在console中輸出，還要向文件輸出；這樣你須要給咱們的logger添加handler，一個handler指向標準輸出流，一個handler指向文件handler。logging.handlers提供了一些這些經常使用的handler。

而後，你但願對這些不一樣的輸出流進行精準的控制，好比：在console中只輸出某些高級別的日誌，而在文件日誌中輸出全部日誌。在console中，使用一種輸出formatter，在文件輸出中使用另外一種formatter。你不知足於python提供的DEBUG/INFO/WARNING/ERROR/CRITICAL的控制粒度，想要更精細地控制日誌。你就須要理解日誌是如何流轉、繼承地。

這是python官方提供的一張log輸出圖

也就是說，咱們有能夠從以下幾個層面控制日誌的輸出：

1. Logger 輸出級別控制
2. Logger 的filter控制
3. Handler 的級別控制
4. Handler 的filter控制

此外，咱們要注意到日誌的輸出是流式的，只要有一個地方日誌被過濾掉了，他就不能輸出了。再設計多級別的日誌系統時，尤爲要注意這點。若是咱們要設置過濾條件，要在上圖所示的日誌流中，逐漸提升level級別。

0x01 爲日誌增長默認屬性

python日誌支持的默認字段比較少：

其實Filter隱含了一個比較dirty的接口，讓你可以修改logRecord的屬性。讓你可以給日誌增長一個新的字段。代碼以下：

class ContextFilter(logging.Filter):
    hostname = os.getenv('HOSTNAME')

    def filter(self, record):
        record.hostname = self.hostname
        return True

將ContextFilter添加到你的某個handler，而後給這個handler增長一個這樣的formatter: [%(asctime)s] [%(levelname)s] [HOSTNAME: %(hostname)s] %(message)s；這個handler就能夠輸出主機名了。固然，這樣作實際上是有悖於fileter的本意的。不過我尚未找到更好的辦法。

0x02 更細的日誌粒度

python的日誌粒度以下：

若是咱們向定義一個比debug級別更低的日誌怎麼辦呢？代碼以下：

VERBOSE_LOG_LEVEL = 5
def VERBOSE(self, message, *args, **kwargs):
    if self.isEnabledFor(VERBOSE_LOG_LEVEL):
        self._log(VERBOSE_LOG_LEVEL, message, args, **kwargs)


logging.Logger.VERB = VERBOSE

這樣咱們就定義了一個級別爲5的輸出。這樣作的好處是，好比有些特別瑣碎的、系統級別的輸出，你不但願框架使用者看到，而只是做爲日誌分析用。你能夠定義一個很是低的日誌級別。而後把絕大多數的handler的控制級別設置的都比5高，只留一個接口給日誌收集者。這樣，就能夠大大提高框架使用者的體驗。

0x03 一個小bug

偶然的緣由復現了別人的一個bug.

觸發錯誤的代碼很簡單：

import requests
import logging

logger = logging.getLogger()
logStdOut = logging.StreamHandler()
LOGFORMATCNSL=logging.Formatter("%(asctime)s %(message)s %(aVar)s %(bVar)s")
logStdOut.setFormatter(LOGFORMATCNSL)
logStdOut.setLevel(logging.DEBUG)
logger.setLevel(logging.NOTSET)
logger.addHandler(logStdOut)

def tryThis():
    logger.error("deneme", extra={"aVar": "aVal", "bVar": "bVal"})
    conn = requests.get("http://www.google.com")
    conn.close()

tryThis()

錯誤最終定位到了在urllib3/connectionpool.py下的日誌打印命令

log.debug("%s://%s:%s \"%s %s %s\" %s %s", self.scheme, self.host, self.port,
                  method, url, http_version, httplib_response.status,
                  httplib_response.length)

經過debug模式，咱們能夠看到，在這裏，RootLogger被賦予了一個formatter， '%(asctime)s %(message)s %(aVar)s %(bVar)s'。

RootLogger是什麼？是一個python程序內全局惟一的，全部Logger對象的祖先。它是怎麼產生的呢？

logger = logging.getLogger()，這個logger就是RootLogger。咱們對logger的設定，天然會影響到全部的日誌輸出。

所以，直接修改RootLogger是危險的。而若是咱們給getLogger傳一個參數，它會生成一個非root的Logger。問題就解決了。

修正後的代碼以下：

import requests
import logging

# code with out bug
logger = logging.getLogger("__abc__")
# code will trigger the keyError bug
# logger = logging.getLogger()

logStdOut = logging.StreamHandler()
print(isinstance(logger, logging.RootLogger))
LOGFORMATCNSL=logging.Formatter("%(asctime)s %(message)s %(aVar)s %(bVar)s")
logStdOut.setFormatter(LOGFORMATCNSL)
logStdOut.setLevel(logging.DEBUG)
logger.setLevel(logging.NOTSET)
logger.addHandler(logStdOut)


def tryThis():
    logger.error("deneme", extra={"aVar": "aVal", "bVar": "bVal"})
    conn = requests.get("http://www.baidu.com")
    conn.close()

tryThis()

尬聊