Python 學習筆記 : 日誌 (logging) 模組測試

通常在開發 Python 程式時會用 print() 在疑似出錯的地方輸出變數值來進行除錯, 但這種方式有個問題, 就是當程式開發完成後必須將這些除錯用的 print() 刪除, 對小程式而言還不會形成負擔, 但對中大型軟體來說可是個麻煩的大工程.

Python 內建的 logging 模組可取代 print() 的除錯功能, 開發完成後只要用 logging.disable(50) 指令取消日誌輸出功能即可, 不需刪除日誌指令. 此外, 日誌除了輸出到螢幕顯示外, 還可以輸出到檔案保存, 這是 print() 做不到的. 總之, 使用 logging 功能可以輕易地在程式中輸出自訂訊息, 若執行時部分訊息沒有輸出的話, 表示相關的部分程式碼段被跳過沒有執行.

以下測試參考了下列書籍 :

1.  Python 3 技術手冊 (碁峰, 黃書逸) - 第 11-28 節
2.  Python 自動化的樂趣 (碁峰, AL Sweigart) - 第 10 章
3.  Python 網路爬蟲實戰 (松崗, 胡松濤) -第 4-2 節
4.  Python 3 程式庫參考手冊 (碁峰, 陳建勳) - 第 9-10 節
5.  Python 入門邁向高手之路-王者歸來 (深石, 洪錦魁) - 第 15-7 節

本系列之前之測試紀錄參考 :

# Python 學習筆記 : 安裝執行環境與 IDLE 基本操作
# Python 學習筆記 : 檔案處理

logging 模組是一個非常有彈性的日誌系統, 可將程式執行中發生的事件, 錯誤, 或警告依據安全等級予以過濾後輸出至螢幕 (標準輸出) 或檔案中保存. logging 模組為內建, 使用前只要 import 即可.

D:\Python\test>python
Python 3.6.4 (v3.6.4:d48eceb, Dec 19 2017, 06:54:40) [MSC v.1900 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import logging

說明文件參考 :

# https://docs.python.org/3/library/logging.html

logging 模組預先定義了如下 6 種安全等級常數以及對應之日誌輸出函數 (但 logging.NOTSET 無對應之輸出函數), 其中 DEBUG 等級最低也最不重要, 用來輸出除錯訊息; INFO 用來記錄一般事件; WARNING 用來輸出目前無礙程式執行, 但未可能使程式無法執行之潛在警訊; ERROR 用來記錄已經發生之程式錯誤; CRITICAL 等級最高, 用來記錄會使程式停止或當掉的致命性錯誤 :

安全等級	數值	說明	輸出函數
logging.NOTSET	0	未設定	x
logging.DEBUG	10	除錯等級	logging.debug()
logging.INFO	20	訊息等級	logging.info()
logging.WARNING	30	警告等級	logging.warning()
logging.ERROR	40	錯誤等級	logging.error()
logging.CRITICAL	50	嚴重錯誤等級	logging.critical()

查詢 logging 之安全等級如下, 傳回值為代表等級高低之數值 :

>>> logging.NOTSET 
0
>>> logging.DEBUG 
10
>>> logging.INFO 
20
>>> logging.WARNING 
30
>>> logging.ERROR 
40
>>> logging.CRITICAL   
50

這 6 種安全等級是 logging 模組預設的等級, 基本上足敷一般使用需求. 如果要自訂等級也可以呼叫 logging.addLevelName(level, levelName) 來新增自己的安全等級, 其中 level 為與嚴重性成正比之正整數, 而 levelName 則為其對應之等級名稱. 呼叫 logging.getLevelName(level) 則會傳回等級值 level 之等級名稱, 例如 :

>>> logging.addLevelName(35, 'MINOR')   #新增自訂之等級名稱 'MINOR'
>>> logging.getLevelName(35)                       #傳回等級名稱
'MINOR'
>>> logging.getLevelName(0)
'NOTSET'
>>> logging.getLevelName(10)
'DEBUG'
>>> logging.getLevelName(20)
'INFO'
>>> logging.getLevelName(30)
'WARNING'
>>> logging.getLevelName(40)
'ERROR'
>>> logging.getLevelName(50)
'CRITICAL'

呼叫日誌輸出函數 (須傳入自訂訊息) 會依據日誌之安全等級設定來自動決定是否要紀錄或輸出該訊息, logging 模組預設安全等級為 WARNING, 大於或等於 WARNING 等級之訊息才會被記錄, 例如 :

>>> logging.debug("debug message")             #小於安全層級 : 不輸出
>>> logging.info("info message")                    #小於安全層級 : 不輸出
>>> logging.warning("warning message")     #大於等於安全層級 : 輸出
WARNING:root:warning message
>>> logging.error("error message")                #大於等於安全層級 : 輸出
ERROR:root:error message
>>> logging.critical("critical message")          #大於等於安全層級 : 輸出
CRITICAL:root:critical message

可見預設情況下, 只有等級大於或等於 WARNING 的才會被記錄.

其中安全等級為 DEBUG, INFO, ... CRITICAL 等, 使用者為電腦之使用者帳號, 最後才是自訂訊息. 利用 logging 模組的 basicConfig() 函數可以設定日誌之安全層級, 只要將安全等級以 level 參數傳進去即可 (亦可傳入數值), 例如 :

>>> logging.basicConfig(level=logging.DEBUG)   #設定日誌安全等級為 DEBUG
>>> logging.debug("debug message") 
DEBUG:root:debug message
>>> logging.info("info message")
INFO:root:info message
>>> logging.warning("warning message") 
WARNING:root:warning message
>>> logging.error("error message") 
ERROR:root:error message
>>> logging.critical("critical message") 
CRITICAL:root:critical message

可見將日誌安全等級降到最低的 DEBUG 後, 所有比 DEBUG 等級還要高的訊息都會被記錄. 如果只對 ERROR 層級以上的訊息有興趣, 則只要將 level 設為 40 (logging.ERROR) 即可, 但一個訊息之重要性屬於哪一個安全等級還是需要寫程式的人自行判定要呼叫哪一個輸出函數.

logging.basicConfig() 有 8 個參數如下表所示 :

參數	說明
level	日誌之安全等級 (0, 10, 20, 40, 50)
format	控制輸出訊息的格式化字串
filename	用來儲存輸出訊息的日誌檔案名稱
filemode	開啟日誌檔案之模式, 如 'a' (預設), 'w' 等
datefmt	輸出日期時間 asctime 之格式字串, 與 time.strftime()
style	格式化字串的標示字元, 有三種 : % (預設), {, 或 $
handlers	加入至根日誌之處理器, 不可與 stream, filename 同時存在
stream	標準輸出之串流

其中 filename 參數是當要將日誌紀錄於日誌檔案時用來指定檔案名稱的. 而 datefmt 則是用來設定 format 參數的格式化字串中 asctime 之日期時間格式, 與 time.strftime() 函數一樣, 常用格式如下 :

參數	說明
%Y	長年份格式, 例如 2018
%y	短年份格式, 例如 18
%m	月份 01~12
%d	日期 01~31
%H	小時 00~23
%w	星期 0~6 (0=星期日)
%M	分鐘 00~59
%S	秒 00~59

關於 basicConfig() 參考 :

# https://docs.python.org/3/library/logging.html#logging.basicConfig

輸出的訊息除了自訂之字串外, 還可以加上其他相關資訊, 例如事件發生時間, 安全等級名稱, 執行此程式之使用者帳號等, 這可在傳入參數 format 中以如下特定之格式化字串來設定 :

格式化字串	說明
%(asctime)s	日期時間, 格式為 YYYY-MM-DD HH:mm:SS,ms (毫秒)
%(message)s	使用者自訂訊息
%(levelname)s	日誌安全等級
%(levelno)s	日誌安全等級之數值
%(name)s	使用者名稱 (帳號)
%(lineno)d	日誌輸出函數呼叫於程式中所在之列數
%(filename)s	日誌輸出函數之模組的檔名
%(module)s	日誌輸出函數之模組名稱
%(pathname)s	日誌輸出函數之模組之完整路徑
%(funcName)s	日誌輸出函數之名稱
%(threrad)d	執行緒 ID
%(threradName)s	執行緒名稱
%(process)d	程序 ID
%(created)f	以 UNIX 標準表示之現在時間 (浮點數)

如果沒有傳入 format 參數, 則預設之輸出訊息格式為 :

安全等級:使用者:自訂訊息

即格式化字串預設為 format='%(levelname)s:%(name)s:%(message)s'

例如 :

>>> import logging
>>> logging.warning("Warning message")     #預設安全層級 : WARNING
WARNING:root:Warning message
>>> logging.basicConfig(level=logging.DEBUG,format='%(asctime)s - %(levelname)s : %(message)s')
>>> logging.debug('Debug message')
2018-04-24 18:18:19,848 - DEBUG : Debug message
>>> logging.Warning('Warning message') 
2018-04-24 18:22:24,796 - WARNING : Warning message
>>> logging.info('Info message') 
2018-04-24 18:27:01,729 - INFO : Info message
>>> logging.error('Error message') 
2018-04-24 18:27:31,980 - ERROR : Error message
>>> logging.critical('Critical message') 
2018-04-24 18:28:02,600 - CRITICAL : Critical message

注意, asctime 的預設格式為 '%Y-%m-%d %H:%M:%S,', 毫秒部分另外用 '%s,%03d' 格式 (參考 formatTime). 這可用 datefmt 參數來自訂格式, 例如 :

>>> import logging
>>> logging.basicConfig(level=logging.DEBUG,
...                     format='%(asctime)s - %(levelname)s : %(message)s',
...                     datefmt='%Y%m%dT%H%M%S')
>>> logging.info('Info message')
20180424T193715 - INFO : Info message


可見時間格式已經改為自訂格式了. 我在 Windows 下測試發現, 連續用 logging.basicConfig() 更改設定有時候並無效果, 這時只要用 exit() 跳出 IDLE 重新啟動再執行 logging.basicConfig() 即可.

如果要將日誌輸出到檔案, 則須傳入 filename 參數, 傳入值為可含路徑之檔案名稱字串, 例如 :

>>> import logging 
>>> logging.basicConfig(level=logging.DEBUG, 
...                     format='%(asctime)s - %(levelname)s : %(message)s', 
...                     filename='mylog.txt') 
>>> logging.critical("critical message") 
>>> logging.debug("debug message") 
>>> logging.info("info message") 
>>> logging.warning("warning message") 
>>> logging.error("error message") 
>>> logging.critical("critical message") 

此處是將訊息輸出到目前目錄下的 mylog.txt 日誌檔裡. 可見使用 filename 參數將訊息輸出至日誌檔案後, 就不會輸出至標準輸出 (螢幕) 了. 開啟 mylog.txt 果然訊息都記錄在輸出檔 :

日誌檔的預設寫入模式為 'a' (append), 亦即新的輸出訊息會被記錄在日誌檔尾端. 如果要改為其他寫入模式例如 'w', 則須傳入參數 filemode='w'.

Python 的 logging 模組可以同時紀錄多個日誌, 上面的範例中直接使用 logging 模組輸出日誌訊息使用的是預設之根日誌 (Root Logger), 因此預設之輸出訊息中的 %(name) 顯示使用者為 'root'. 不傳入參數直接呼叫 logging.getLogger() 會傳回根日誌 RootLogger 物件, 它是 Logger 物件的一個特例, 提供如下幾個常用方法 :

Logger 物件方法	說明
setLevel(level)	設定日誌安全等級
getEffectiveLevel()	傳回目前設定之安全等級
isEnabledFor(level)	檢查傳入之 level 是否會被處理 (依據目前等級), 傳回 True/False
debug(msg)	輸出 debug 等級之訊息
info(msg)	輸出 info 等級之訊息
warning(msg)	輸出 warning 等級之訊息
error(msg)	輸出 error 等級之訊息
critical(msg)	輸出 critical 等級之訊息
log(level, msg)	輸出指定等級 level 之訊息
addHandler(handler)	加入處理器 handler

說明文件參考 :

# https://docs.python.org/3/library/logging.html#logging.Logger
# https://docs.python.org/2.4/lib/minimal-example.html

例如 :

>>> import logging
>>> rootlogger=logging.getLogger()      #傳回根日誌 RootLogger 物件
>>> type(rootlogger)                                #型態為 RootLogger
<class 'logging.RootLogger'> 
>>> rootlogger.getEffectiveLevel()         #傳回目前根日誌安全等級=WARNING
30
>>> rootlogger.setLevel(logging.ERROR)       #設定根日誌安全等級=ERROR
>>> rootlogger.getEffectiveLevel()                   #傳回目前根日誌安全等級=ERROR
40
>>> rootlogger.isEnabledFor(logging.DEBUG)        #DEBUG 低於 ERROR
False
>>> rootlogger.isEnabledFor(logging.WARNING)   #WARNING 低於 ERROR
False
>>> rootlogger.isEnabledFor(logging.ERROR)         #等於 ERROR : True
True
>>> rootlogger.isEnabledFor(logging.CRITICAL)    #大於 ERROR : False
True
>>> rootlogger.debug("debug message")            #低於 ERROR : 不輸出
>>> rootlogger.warning("warning message")    #低於 ERROR : 不輸出
>>> rootlogger.error("error message")               #等於 ERROR : 輸出
error message
>>> rootlogger.critical("critical message")         #大於 ERROR : 輸出
critical message
>>> rootlogger.log(logging.CRITICAL,"critical message")   #通用之日誌輸出函數
critical message

如果要使用自訂的日誌而非根日誌, 可在呼叫 logging.getLogger() 函數時傳入日誌名稱字串, 傳回值是一個 Logger 物件, 呼叫 Logger 物件的 debug(), info(), warning(), error(), critical() 或 log() 方法即可將訊息輸出至該自訂日誌而非根日誌, 例如 :

>>> import logging
>>> tonylogger=logging.getLogger('Tony')    #設定名為 Tony 之自訂日誌
>>> type(tonylogger)                                         #傳回 Logger 物件
<class 'logging.Logger'> 
>>> tonylogger.getEffectiveLevel()                  #傳回 Tony 日誌安全等級=WARNIMG
30
>>> tonylogger.setLevel(40)                              #設定 Tony 日誌安全等級=ERROR
>>> tonylogger.getEffectiveLevel()                   #傳回 Tony 日誌安全等級=ERROR
40
>>> tonylogger.debug("debug message")            #低於 ERROR : 不輸出
>>> tonylogger.warning("warning message")     #低於 ERROR : 不輸出
>>> tonylogger.error("error message")               #等於 ERROR : 輸出
error message 
>>> tonylogger.critical("critical message")          #大於 ERROR : 輸出
critical message

可見不論使用 Logger 或 RootLogger 物件輸出日誌訊息, 預設格式只有訊息本身, 如果要同時記錄使用者, 安全等級與日期時間等訊息, 須依下列順序設定 :

1. 呼叫 logging.Formatter() 建立 Formatter 格式化物件
2. 呼叫 logging.StreamHandler() 建立 StreamHandler 輸出串流處理物件
3. 呼叫 Handler 物件之 setFormatter() 方法設定處理器之輸出格式
4. 呼叫 Logger 物件之 addHandler() 加入處理器物件

以上面建立的 Tony 日誌為例說明如下 :

>>> formatter=logging.Formatter('%(levelname)s:%(name)s:%(message)s')  #格式化
>>> type(formatter)                                              #傳回 Formatter 物件
<class 'logging.Formatter'>   
>>> streamhandler=logging.StreamHandler()   #傳回 StreamHandler 物件
>>> type(streamhandler) 
<class 'logging.StreamHandler'>
>>> streamhandler.setFormatter(formatter)      #為處理器指定格式化物件
>>> tonylogger.addHandler(streamhandler)      #為自訂日誌添加處理器

>>> tonylogger.log(logging.WARNING,"warning message")   #低於 ERROR : 不輸出

>>> tonylogger.log(logging.ERROR,"error message")   

ERROR:Tony:error message   

>>> tonylogger.log(logging.CRITICAL,"critical message")   

CRITICAL:Tony:critical message

可見使用 StreamHandler 與 Formatter 後日誌訊息已能依照格式輸出了. 上面範例是輸出到標準輸出 (螢幕), 需使用 StreamHandler, 若要輸出到日誌檔, 則需使用 FileHandler 物件, 如下所示 :

>>> format='%(asctime)s:%(levelname)s:%(name)s:%(message)s'
>>> formatter=logging.Formatter(format)                       #傳回 Formatter 物件
>>> type(formatter) 
<class 'logging.Formatter'>
>>> logfilehandler=logging.FileHandler('./tonylog.txt')   #傳回 FileHandler 物件
>>> type(logfilehandler) 
<class 'logging.FileHandler'>
>>> filehandler.setFormatter(formatter)      #為處理器指定格式化物件
>>> tonylogger.addHandler(filehandler)      #為自訂日誌添加處理器
>>> tonylogger.log(logging.WARNING,"warning message")   #低於 ERROR : 不輸出
>>> tonylogger.log(logging.ERROR,"error message") 
ERROR:Tony:error message
>>> tonylogger.log(logging.CRITICAL,"critical message")   
CRITICAL:Tony:critical message

開啟日誌檔案 tonylog.txt 內容如下 :

2018-04-25 14:59:56,069:ERROR:Tony:error message
2018-04-25 15:00:04,043:CRITICAL:Tony:critical message

可見與上面使用根日誌時不同之處在於, 日誌訊息同時輸出到螢幕與日誌檔, 這是因為我們同時在自訂日誌 tonylogger 中開啟了 StreamHandler (給螢幕) 與 FileHandler (給檔案) 之故. 使用自訂日誌雖然較麻煩, 但彈性比較大.

上面我們是武斷地為自訂日誌取名 ('Tony'), 事實上若以目前登入者帳號為名可能較實用, 這可以用 Python 內建 getpass 模組之 getuser() 來取得使用者名稱, 例如 :

>>> import getpass 
>>> user=getpass.getuser()            #傳回登入者帳號 (字串)
>>> user 
'user'
>>> type(user)                                 #getuser() 傳回值為字串
<class 'str'>
>>> import logging
>>> logger=logging.getLogger(user)    #建立以使用者為名之日誌物件
>>> type(logger)                                   
<class 'logging.Logger'>
>>> logger.getEffectiveLevel()     #查詢目前安全等級之值
30                                                                    #30=logging.WARNING


為了使用日誌方便, 可將所需日誌格式寫成一個類別, 在 "Python 網路爬蟲實戰" 的 4-2-2 節有介紹一個自訂日誌類別寫法, 我將其改寫如下 :

#myLog.py
import logging
import getpass

class MyLog(object):
    def __init__(self):
        user=getpass.getuser()
        self.logger=logging.getLogger(user)
        self.logger.setLevel(logging.DEBUG)
        format='%(asctime)s - %(levelname)s -%(name)s : %(message)s'
        formatter=logging.Formatter(format)
        streamhandler=logging.StreamHandler()
        streamhandler.setFormatter(formatter)
        self.logger.addHandler(streamhandler)
        logfile='./' + user + '.log'
        filehandler=logging.FileHandler(logfile)
        filehandler.setFormatter(formatter)
        self.logger.addHandler(filehandler)
    def debug(self, msg):
        self.logger.debug(msg)
    def info(self, msg):
        self.logger.info(msg)
    def warning(self, msg):
        self.logger.warning(msg)
    def error(self, msg):
        self.logger.error(msg)
    def critical(self, msg):
        self.logger.critical(msg)
    def log(self, level, msg):
        self.logger.log(level, msg)
    def setLevel(self, level):
        self.logger.setLevel(level)
    def disable(self):
        logging.disable(50)

將此類別存成 myLog.py 檔案, 用 from myLog import MyLog 匯入 MyLog 類別後呼叫 MyLog() 建構式建立物件, 然後就可以呼叫此物件之 debug(), info(), warning(), error(), critical(), 以及 log() 等方法來記錄日誌訊息於螢幕與日誌檔 "使用者名稱.log" 了, 例如 :

>>> from myLog import MyLog 
>>> mylog=MyLog() 
>>> mylog.error("error message")      #預設安全等級=DEBUG
2018-04-25 18:17:07,364 - ERROR -Tony : error message 
>>> mylog.debug("debug message") 
2018-04-25 18:25:03,276 - DEBUG -Tony : debug message
>>> mylog.info("info message") 
2018-04-25 18:30:28,747 - INFO -Tony : info message
>>> mylog.warning("warning message") 
2018-04-25 18:30:41,814 - WARNING -Tony : warning message
>>> mylog.error("error message") 
2018-04-25 18:31:08,937 - ERROR -Tony : error message
>>> mylog.critical("critical message") 
2018-04-25 18:31:27,330 - CRITICAL -Tony : critical message
>>> mylog.log(40, "error message") 
2018-04-25 18:40:15,587 - ERROR -Tony : error message

可見使用這個 MyLog 類別讓紀錄日誌簡單多了. 此類別預設安全等級為 DEBUG (根日誌預設是 WARNING), 因此每一種等級之資訊都會輸出. 日誌同時會記錄到以使用者為名之 .log 檔案, 此處使用者為 Tony, 因此開啟目前目錄下之 Tony.log 會發現與螢幕輸出完全一樣之內容 :

2018-04-25 18:25:03,276 - DEBUG -Tony : debug message
2018-04-25 18:30:28,747 - INFO -Tony : info message
2018-04-25 18:30:41,814 - WARNING -Tony : warning message
2018-04-25 18:31:08,937 - ERROR -Tony : error message
2018-04-25 18:31:27,330 - CRITICAL -Tony : critical message
2018-04-25 18:40:15,587 - ERROR -Tony : error message

此類別預設安全等級為 10 (DEBUD), 因此每一種訊息都會輸出紀錄, 呼叫 setLevel() 方法傳入 10, 20, 30, 40, 50 可以更改安全等級設定 (不要用 logging.DEBUG 等, 會出現錯誤) :

>>> mylog.setLevel(30)                   #安全等級由預設之 DEBUG 改為 WARNING
>>> mylog.info("info message")    #低於 WARNING : 不輸出
>>> mylog.warning("warning message")    #等於 WARNING : 輸出
2018-04-25 18:44:20,290 - WARNING -Tony : warning message

此處將安全等級改為 30 (WARNING) 後, INFO 等級以下的就不會輸出了, 要等於或大於 WARNING 的才會輸出.

最後, 程式開發除錯結束後, 在根日誌可以呼叫 logging.disable(50) 或 logging.disable(logging.CRITICAL) 來關閉日誌輸出功能, 不需要將程式中所有日誌輸出指令刪除, 例如 :

>>> logging.disable(50)    #關閉日誌輸出功能
>>> logging.debug("debug message")      #無輸出
>>> logging.critical("critical message")    #無輸出

可見關閉後即使是 CRITICAL 的訊息也不會輸出了.

使用上面的自訂日誌類別的話, 只要呼叫 mylog.disable() 就可以了 :

>>> from myLog import MyLog 
>>> mylog=MyLog() 
>>> mylog.warning("warning message")   
2018-04-25 19:16:43,426 - WARNING -Tony : warning message
>>> mylog.disable()                                      #關閉日誌功能
>>> mylog.warning("warning message")   
>>> mylog.critical("critical message")   
>>>

可見日誌功能被關閉後, 全部日誌都不會被記錄.

參考 :

# 6.29.2 Basic example
# https://docs.python.org/3/howto/logging-cookbook.html
# [Python] logging 教學