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

Python · 發表 2019-01-31 16:40:05

摘要：本文從 Python logging 庫的基礎概念入手，理解 logging 庫的執行流程，以及可能忽視的一些細節。日誌級別 logging 庫預置了 5 個錯誤級別，還有一個 NOTSET 級別，作為 logger 的預設值。 CRITICAL = 50...

本文從 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 物件的作用主要有三個：

為應用暴露出 info、warning、error 等方法，應用可以通過這些方法建立對應級別的日誌。
根據 Filter 和日誌級別的設定，來決定哪些日誌可以被傳入給下一個流程處理，
將日誌傳遞到所有相關的 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