Python 日誌庫 logging 的理解和實踐經驗

本文從 Python logging 庫的基礎概念入手，理解 logging 庫的執行流程，以及可能忽視的一些細節。

日誌級別

logging 庫預置了 5 個錯誤級別，還有一個 NOTSET 級別，做爲 logger 的默認值。

CRITICAL = 50
ERROR = 40
WARNING = 30
INFO = 20
DEBUG = 10
NOTSET = 0
複製代碼

logging 庫也支持自定義錯誤級別，經過上面的源碼能夠看到，在不一樣級別的錯誤中間預留了 10 個數字的位置，方便咱們在預置錯誤級別的基礎上添加更細緻的錯誤級別。

import logging


logging.addLevelName(31, 'SERIOUS WARNING')
logger = logging.getLogger('log')
logger.warn('warn info')
logger.log(logging.getLevelName('SERIOUS_WARNING'), 'serious warn')
複製代碼

例如添加一個 SERIOUS WARNING 類型的錯誤，值爲 31，就能夠用 log 方法輸出該級別的錯誤。

也能夠覆蓋 logging 預置的錯誤級別，例如將 WARNING 修改成 SERIOUS WARNING。

logging.addLevelName(30, 'SERIOUS WARNING')
logger = logging.getLogger('log')
print(logging.getLevelName(30))  # SERIOUS WARNING
複製代碼

LogRecord、Formatter

logging 庫中的每一條 log 都以 LogRecord 的形式存在，當調用 logger 打印 log 時候，都會有一條 LogRecord 被自動建立出來，LogRecord 中包含了大量的和該條日誌相關的屬性，也包含用戶傳入的 message。

屬性名	格式	描述
asctime	%(asctime)s	以可讀格式表示的日誌建立時間
created	%(created)f	經過 time.time() 函數獲取的日誌建立時間
filename	%(filename)s	pathname 中的文件名稱部分
funcName	%(funcName)s	日誌輸出位置的函數名稱
levelname	%(levelname)s	字符串形式的日誌級別
levelno	%(levelno)s	數字形式的日誌級別
lineno	%(lineno)d	輸出日誌的源碼行號
message	%(message)s	用戶傳入的通過格式化的日誌內容
module	%(module)s	filename 中的模塊名部分
msecs	%(msecs)d	日誌建立時間的毫秒部分
name	%(name)s	logger 的名稱
pathname	%(pathname)s	源碼的路徑
process	%(process)d	進程 ID
processName	%(processName)s	進程名
relativeCreated	%(relativeCreated)d	相對於 logging 模塊加載時間的毫秒數
thread	%(thread)d	線程 ID
threadName	%(threadName)s	線程名

logger = logging.getLogger('log')
logger.warning('a warning message')  # a warning message
複製代碼

執行上述代碼，會發現，logger 並無輸出列表中列出的 LogRecord 的各類屬性，只有 message 內容。由於 LogRecord 只是承載每條日誌內容和屬性的對象，在一條 log 產生的時候就被建立了，而日誌的輸出格式則是在被輸出時才肯定，由 Formatter 來控制。Formatter 負責將一條 log（以 LogRecord 對象的形式存在）轉換爲可讀的字符串，默認狀況下，格式是%(message)s，因此當沒有指定 Formatter 時，只輸出用戶傳入的內容。

Logger、Handler、Filter

Logger 對象是 logging 庫中最爲經常使用的對象，Logger 對象的做用主要有三個：

1. 爲應用暴露出 info、warning、error 等方法，應用能夠經過這些方法建立對應級別的日誌。
2. 根據 Filter 和日誌級別的設置，來決定哪些日誌能夠被傳入給下一個流程處理，
3. 將日誌傳遞到全部相關的 Handler 中。

同時 Logger 對象還能夠繼承，一個 Logger 能夠把 LogRecord 傳遞給父級的 Logger。

Handler 負責將日誌寫入到最終的歸宿，可能文件、電子郵件、內存、隊列... 因爲一個 Logger 能夠有多個 Handler，因此每一個 Handler 均可以設置接收日誌的級別和 Filter，換句話說，不一樣級別的日誌能夠輸出到不一樣的歸宿。

Python 官方文檔提供了 logging 處理日誌的邏輯流程圖。

這裏咱們可能會有一個疑問，爲 Logger 和 Handler 設置日誌級別已經能夠表示處理哪些日誌，不處理哪些日誌，爲何還須要 Filter 呢？

相比於日誌級別，Filter 可定製性更豐富，能夠在 Logger 和 Handler 上實現顆粒度更細的控制。例如但願只記錄長度大於 10 的日誌，能夠用以下的代碼實現。

class CustomFilter(logging.Filterer):
    def filter(self, record):
        return len(record.msg) > 10


logger = logging.getLogger('log')
filter = CustomFilter()
logger.addFilter(filter)
logger.warning('a warning message')  # a warning message
logger.warning('a warn')
logger.warning('another warning message')  # another warning message
複製代碼

長度小於 10 的第二條 log 並不會被輸出。

實踐中的一些經驗

在使用 Python logging 庫的過程當中，咱們發現了一些容易容易忽視的細節，這些細節可能會致使一些預期以外的狀況，在此作以總結。

Logger 的繼承鏈

Logger 對象是有一條繼承鏈的，使用 logging.getLogger() 方法獲取 logger 時，獲取的是 root logger。若是爲 getLogger 方法傳入參數，獲取的是子 logger。

root_logger = logging.getLogger()
sub_logger = logging.getLogger('log')
print(sub_logger.parent == root_logger)  # True
複製代碼

logging 的官方文檔中推薦使用 __name__ 做爲 getLogger 的參數，__name__ 是 module 的路徑名，例如在 utils.log 包中使用 logging.getLogger(__name___) 至關於執行 logging.getLogger('base.db')，這樣就建立了一個名爲 base.db 的 logger，這個 db 包的 logger 繼承自 root logger。

若是咱們在 base 中也建立一個 logger，logger.getLogger('base')，這時候，base logger 也繼承自 root logger，可是 db logger 的繼承順序則被修改爲了繼承自 base logger。

root_logger = logging.getLogger()
db_logger = logging.getLogger('base.db')
print(db_logger.name)  # base.db
print(db_logger.parent.name)  # root
base_logger = logging.getLogger('base')  # base
print(db_logger.name)  # base.db
print(db_logger.parent.name)  # base
複製代碼

換句話說咱們能夠經過 xxx.xxx 的形式獲取任何一級的 logger，可是這些中間層的 logger 並不必定是存在的。

Logger 奇葩的默認行爲

root_logger = logging.getLogger()
root_logger.info('root info')
複製代碼

執行上面的代碼，會發現沒有任何輸出，可是若是打一個 warning 級別的 log，是能夠輸出的。

root_logger = logging.getLogger()
sub_logger = logging.getLogger('sub')

print(root_logger.level)  # 30 = WARNING
print(sub_logger.level)  # 0 = NOTSET
複製代碼

打印一下 root logger 的默認級別，會發現 30 對應的是 WARNING，也就是說，只有比 WARNING 高的級別纔會被輸出出來，而 INFO 對應值是 20， 比 WARNING 低，因此默認狀況下 root logger 將不會接受 INFO 級別的錯誤。

可是隻有 root logger 的默認級別是 WARNING，其餘 logger 的默認級別 是 NOTSET = 0。

root_logger = logging.getLogger()
sub_logger = logging.getLogger('sub')

root_logger.info('root info')
sub_logger.info('sub info')
複製代碼

執行上面代碼，會發現依然沒有任何輸出，既然其餘 logger 的默認級別是 NOTSET，爲何比 NOTSET 高的 INFO 仍是不會輸出呢？

當一個 logger 的 level 被設置爲 NOTSET 時，若是有父 logger，會將 log 傳遞給父 logger 處理，只有在 logger 是 root logger 或 propagate 屬性設置爲 False 時，纔會由本身處理。接下來再修改一下上面的代碼。

sub_logger = logging.getLogger('sub')
sub_logger.propagate = False

sub_logger.info('sub info')
sub_logger.warning('sub warn')  # sub warn
複製代碼

上面的代碼中禁用了 logger 的傳遞功能，因此 logger 會本身處理錯誤，可是 INFO 級別的日誌依然沒有被輸出，若是輸出一下 sub_logger.handlers 屬性，會發現默認狀況下 logger 並無任何的 handlers，這能解釋爲何沒法輸出日誌，可是下一行代碼輸出了 WARNING 級別的日誌，顯然又是和這個猜想違背的，緣由究竟是什麼呢？

跟蹤源碼會發現，當一個 logger 須要本身處理日誌時且沒有任何一個 handler 時，會嘗試使用 lastResort 屬性所存儲的 handler 來處理。

文檔中是這樣定義 lastResort 的。

A 「handler of last resort」 is available through this attribute. This is a StreamHandler writing to sys.stderr with a level of WARNING, and is used to handle logging events in the absence of any logging configuration. The end result is to just print the message to sys.stderr. This replaces the earlier error message saying that 「no handlers could be found for logger XYZ」. If you need the earlier behaviour for some reason, lastResort can be set to None.

因此，當一個 logger 沒有任何 handler 的時候，依然能輸出 WARNING 及以上級別的日誌。

參考資料

Python日誌庫logging總結-多是目前爲止將logging庫總結的最好的一篇文章 - 掘金

logging — Logging facility for Python

Logging HOWTO

關注知乎專欄【Python私房菜】