PyCon 2018: 利用logging模組輕鬆地進行Python日誌記錄

崔慶才丨靜覓發表於2018-06-03
Python

在 PyCon 2018 上，Mario Corchero 介紹了在開發過程中如何更方便輕鬆地記錄日誌的流程。

PyCon 2018: 利用logging模組輕鬆地進行Python日誌記錄

整個演講的內容包括：

  • 為什麼日誌記錄非常重要
  • 日誌記錄的流程是怎樣的
  • 怎樣來進行日誌記錄
  • 怎樣進行日誌記錄相關配置
  • 日誌記錄使用常見誤區

下面我們來梳理一下整個演講的過程，其實其核心就是介紹了 logging 模組的使用方法和一些配置。

日誌記錄的重要性

在開發過程中，如果程式執行出現了問題，我們是可以使用我們自己的 Debug 工具來檢測到到底是哪一步出現了問題，如果出現了問題的話，是很容易排查的。但程式開發完成之後，我們會將它部署到生產環境中去，這時候程式碼相當於是在一個黑盒環境下執行的，我們只能看到其執行的效果，是不能直接看到程式碼執行過程中每一步的狀態的。在這個環境下，執行過程中難免會在某個地方出現問題，甚至這個問題可能是我們開發過程中未曾遇到的問題，碰到這種情況應該怎麼辦？

如果我們現在只能得知當前問題的現象，而沒有其他任何資訊的話，如果我們想要解決掉這個問題的話，那麼只能根據問題的現象來試圖復現一下，然後再一步步去除錯，這恐怕是很難的，很大的概率上我們是無法精準地復現這個問題的，而且 Debug 的過程也會耗費巨多的時間，這樣一旦生產環境上出現了問題，修復就會變得非常棘手。但這如果我們當時有做日誌記錄的話，不論是正常執行還是出現報錯，都有相關的時間記錄，狀態記錄，錯誤記錄等，那麼這樣我們就可以方便地追蹤到在當時的執行過程中出現了怎樣的狀況，從而可以快速排查問題。

因此，日誌記錄是非常有必要的，任何一款軟體如果沒有標準的日誌記錄，都不能算作一個合格的軟體。作為開發者，我們需要重視並做好日誌記錄過程。

日誌記錄的流程框架

那麼在 Python 中，怎樣才能算作一個比較標準的日誌記錄過程呢？或許很多人會使用 print 語句輸出一些執行資訊，然後再在控制檯觀察，執行的時候再將輸出重定向到檔案輸出流儲存到檔案中，這樣其實是非常不規範的，在 Python 中有一個標準的 logging 模組，我們可以使用它來進行標註的日誌記錄，利用它我們可以更方便地進行日誌記錄，同時還可以做更方便的級別區分以及一些額外日誌資訊的記錄，如時間、執行模組資訊等。

接下來我們先了解一下日誌記錄流程的整體框架。

PyCon 2018: 利用logging模組輕鬆地進行Python日誌記錄

如圖所示，整個日誌記錄的框架可以分為這麼幾個部分：

  • Logger：即 Logger Main Class，是我們進行日誌記錄時建立的物件，我們可以呼叫它的方法傳入日誌模板和資訊，來生成一條條日誌記錄，稱作 Log Record。
  • Log Record：就代指生成的一條條日誌記錄。
  • Handler：即用來處理日誌記錄的類，它可以將 Log Record 輸出到我們指定的日誌位置和儲存形式等，如我們可以指定將日誌通過 FTP 協議記錄到遠端的伺服器上，Handler 就會幫我們完成這些事情。
  • Formatter：實際上生成的 Log Record 也是一個個物件，那麼我們想要把它們儲存成一條條我們想要的日誌文字的話，就需要有一個格式化的過程，那麼這個過程就由 Formatter 來完成，返回的就是日誌字串，然後傳回給 Handler 來處理。
  • Filter：另外儲存日誌的時候我們可能不需要全部儲存，我們可能只需要儲存我們想要的部分就可以了，所以儲存前還需要進行一下過濾，留下我們想要的日誌，如只儲存某個級別的日誌，或只儲存包含某個關鍵字的日誌等，那麼這個過濾過程就交給 Filter 來完成。
  • Parent Handler：Handler 之間可以存在分層關係，以使得不同 Handler 之間共享相同功能的程式碼。

以上就是整個 logging 模組的基本架構和物件功能，瞭解了之後我們詳細來了解一下 logging 模組的用法。

日誌記錄的相關用法

總的來說 logging 模組相比 print 有這麼幾個優點：

  • 可以在 logging 模組中設定日誌等級，在不同的版本（如開發環境、生產環境）上通過設定不同的輸出等級來記錄對應的日誌，非常靈活。
  • print 的輸出資訊都會輸出到標準輸出流中，而 logging 模組就更加靈活，可以設定輸出到任意位置，如寫入檔案、寫入遠端伺服器等。
  • logging 模組具有靈活的配置和格式化功能，如配置輸出當前模組資訊、執行時間等，相比 print 的字串格式化更加方便易用。

下面我們初步來了解下 logging 模組的基本用法，先用一個例項來感受一下：

import logging

logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')
logger = logging.getLogger(__name__)

logger.info('This is a log info')
logger.debug('Debugging')
logger.warning('Warning exists')
logger.info('Finish')
複製程式碼

在這裡我們首先引入了 logging 模組，然後進行了一下基本的配置，這裡通過 basicConfig 配置了 level 資訊和 format 資訊，這裡 level 配置為 INFO 資訊，即只輸出 INFO 級別的資訊，另外這裡指定了 format 格式的字串，包括 asctime、name、levelname、message 四個內容，分別代表執行時間、模組名稱、日誌級別、日誌內容，這樣輸出內容便是這四者組合而成的內容了，這就是 logging 的全域性配置。

接下來宣告瞭一個 Logger 物件，它就是日誌輸出的主類，呼叫物件的 info() 方法就可以輸出 INFO 級別的日誌資訊，呼叫 debug() 方法就可以輸出 DEBUG 級別的日誌資訊，非常方便。在初始化的時候我們傳入了模組的名稱，這裡直接使用 __name__ 來代替了，就是模組的名稱，如果直接執行這個指令碼的話就是 __main__，如果是 import 的模組的話就是被引入模組的名稱，這個變數在不同的模組中的名字是不同的，所以一般使用 __name__ 來表示就好了，再接下來輸出了四條日誌資訊，其中有兩條 INFO、一條 WARNING、一條 DEBUG 資訊，我們看下輸出結果：

2018-06-03 13:42:43,526 - __main__ - INFO - This is a log info
2018-06-03 13:42:43,526 - __main__ - WARNING - Warning exists
2018-06-03 13:42:43,526 - __main__ - INFO - Finish
複製程式碼

可以看到輸出結果一共有三條日誌資訊，每條日誌都是對應了指定的格式化內容，另外我們發現 DEBUG 的資訊是沒有輸出的，這是因為我們在全域性配置的時候設定了輸出為 INFO 級別，所以 DEBUG 級別的資訊就被過濾掉了。

這時如果我們將輸出的日誌級別設定為 DEBUG，就可以看到 DEBUG 級別的日誌輸出了：

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')
複製程式碼

輸出結果：

2018-06-03 13:49:22,770 - __main__ - INFO - This is a log info
2018-06-03 13:49:22,770 - __main__ - DEBUG - Debugging
2018-06-03 13:49:22,770 - __main__ - WARNING - Warning exists
2018-06-03 13:49:22,770 - __main__ - INFO - Finish
複製程式碼

由此可見，相比 print 來說，通過剛才的程式碼，我們既可以輸出時間、模組名稱，又可以輸出不同級別的日誌資訊作區分並加以過濾，是不是靈活多了？

當然這只是 logging 模組的一小部分功能，接下來我們首先來全面瞭解一下 basicConfig 的引數都有哪些：

  • filename：即日誌輸出的檔名，如果指定了這個資訊之後，實際上會啟用 FileHandler，而不再是 StreamHandler，這樣日誌資訊便會輸出到檔案中了。
  • filemode：這個是指定日誌檔案的寫入方式，有兩種形式，一種是 w，一種是 a，分別代表清除後寫入和追加寫入。
  • format：指定日誌資訊的輸出格式，即上文示例所示的引數，詳細引數可以參考：docs.python.org/3/library/l…，部分引數如下所示：
    • %(levelno)s：列印日誌級別的數值。
    • %(levelname)s：列印日誌級別的名稱。
    • %(pathname)s：列印當前執行程式的路徑，其實就是sys.argv[0]。
    • %(filename)s：列印當前執行程式名。
    • %(funcName)s：列印日誌的當前函式。
    • %(lineno)d：列印日誌的當前行號。
    • %(asctime)s：列印日誌的時間。
    • %(thread)d：列印執行緒ID。
    • %(threadName)s：列印執行緒名稱。
    • %(process)d：列印程式ID。
    • %(processName)s：列印執行緒名稱。
    • %(module)s：列印模組名稱。
    • %(message)s：列印日誌資訊。
  • datefmt：指定時間的輸出格式。
  • style：如果 format 引數指定了，這個引數就可以指定格式化時的佔位符風格，如 %、{、$ 等。
  • level：指定日誌輸出的類別，程式會輸出大於等於此級別的資訊。
  • stream：在沒有指定 filename 的時候會預設使用 StreamHandler，這時 stream 可以指定初始化的檔案流。
  • handlers：可以指定日誌處理時所使用的 Handlers，必須是可迭代的。

下面我們再用一個例項來感受一下：

import logging

logging.basicConfig(level=logging.DEBUG,
                    filename='output.log',
                    datefmt='%Y/%m/%d %H:%M:%S',
                    format='%(asctime)s - %(name)s - %(levelname)s - %(lineno)d - %(module)s - %(message)s')
logger = logging.getLogger(__name__)

logger.info('This is a log info')
logger.debug('Debugging')
logger.warning('Warning exists')
logger.info('Finish')
複製程式碼

這裡我們指定了輸出檔案的名稱為 output.log，另外指定了日期的輸出格式，其中年月日的格式變成了 %Y/%m/%d，另外輸出的 format 格式增加了 lineno、module 這兩個資訊，執行之後便會生成一個 output.log 的檔案，內容如下：

2018/06/03 14:43:26 - __main__ - INFO - 9 - demo3 - This is a log info
2018/06/03 14:43:26 - __main__ - DEBUG - 10 - demo3 - Debugging
2018/06/03 14:43:26 - __main__ - WARNING - 11 - demo3 - Warning exists
2018/06/03 14:43:26 - __main__ - INFO - 12 - demo3 - Finish
複製程式碼

可以看到日誌便會輸出到檔案中，同時輸出了行號、模組名稱等資訊。

以上我們通過 basicConfig 來進行了一些全域性的配置，我們同樣可以使用 Formatter、Handler 進行更靈活的處理，下面我們來了解一下。

Level

首先我們來了解一下輸出日誌的等級資訊，logging 模組共提供瞭如下等級，每個等級其實都對應了一個數值，列表如下：

等級 數值
CRITICAL 50
FATAL 50
ERROR 40
WARNING 30
WARN 30
INFO 20
DEBUG 10
NOTSET 0

這裡最高的等級是 CRITICAL 和 FATAL，兩個對應的數值都是 50，另外對於 WARNING 還提供了簡寫形式 WARN，兩個對應的數值都是 30。

我們設定了輸出 level，系統便只會輸出 level 數值大於或等於該 level 的的日誌結果，例如我們設定了輸出日誌 level 為 INFO，那麼輸出級別大於等於 INFO 的日誌，如 WARNING、ERROR 等，DEBUG 和 NOSET 級別的不會輸出。

import logging

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.WARN)

# Log
logger.debug('Debugging')
logger.critical('Critical Something')
logger.error('Error Occurred')
logger.warning('Warning exists')
logger.info('Finished')
複製程式碼

這裡我們設定了輸出級別為 WARN，然後對應輸出了五種不同級別的日誌資訊，執行結果如下：

Critical Something
Error Occurred
Warning exists
複製程式碼

可以看到只有 CRITICAL、ERROR、WARNING 資訊輸出了，DEBUG、INFO 資訊沒有輸出。

Handler

下面我們先來了解一下 Handler 的用法，看下面的例項：

import logging

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.INFO)
handler = logging.FileHandler('output.log')
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)

logger.info('This is a log info')
logger.debug('Debugging')
logger.warning('Warning exists')
logger.info('Finish')
複製程式碼

這裡我們沒有再使用 basicConfig 全域性配置，而是先宣告瞭一個 Logger 物件，然後指定了其對應的 Handler 為 FileHandler 物件，然後 Handler 物件還單獨指定了 Formatter 物件單獨配置輸出格式，最後給 Logger 物件新增對應的 Handler 即可，最後可以發現日誌就會被輸出到 output.log 中，內容如下：

2018-06-03 14:53:36,467 - __main__ - INFO - This is a log info
2018-06-03 14:53:36,468 - __main__ - WARNING - Warning exists
2018-06-03 14:53:36,468 - __main__ - INFO - Finish
複製程式碼

另外我們還可以使用其他的 Handler 進行日誌的輸出，logging 模組提供的 Handler 有：

  • StreamHandler：logging.StreamHandler；日誌輸出到流，可以是 sys.stderr，sys.stdout 或者檔案。
  • FileHandler：logging.FileHandler；日誌輸出到檔案。
  • BaseRotatingHandler：logging.handlers.BaseRotatingHandler；基本的日誌回滾方式。
  • RotatingHandler：logging.handlers.RotatingHandler；日誌回滾方式，支援日誌檔案最大數量和日誌檔案回滾。
  • TimeRotatingHandler：logging.handlers.TimeRotatingHandler；日誌回滾方式，在一定時間區域內回滾日誌檔案。
  • SocketHandler：logging.handlers.SocketHandler；遠端輸出日誌到TCP/IP sockets。
  • DatagramHandler：logging.handlers.DatagramHandler；遠端輸出日誌到UDP sockets。
  • SMTPHandler：logging.handlers.SMTPHandler；遠端輸出日誌到郵件地址。
  • SysLogHandler：logging.handlers.SysLogHandler；日誌輸出到syslog。
  • NTEventLogHandler：logging.handlers.NTEventLogHandler；遠端輸出日誌到Windows NT/2000/XP的事件日誌。
  • MemoryHandler：logging.handlers.MemoryHandler；日誌輸出到記憶體中的指定buffer。
  • HTTPHandler：logging.handlers.HTTPHandler；通過"GET"或者"POST"遠端輸出到HTTP伺服器。

下面我們使用三個 Handler 來實現日誌同時輸出到控制檯、檔案、HTTP 伺服器：

import logging
from logging.handlers import HTTPHandler
import sys

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.DEBUG)

# StreamHandler
stream_handler = logging.StreamHandler(sys.stdout)
stream_handler.setLevel(level=logging.DEBUG)
logger.addHandler(stream_handler)

# FileHandler
file_handler = logging.FileHandler('output.log')
file_handler.setLevel(level=logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)

# HTTPHandler
http_handler = HTTPHandler(host='localhost:8001', url='log', method='POST')
logger.addHandler(http_handler)

# Log
logger.info('This is a log info')
logger.debug('Debugging')
logger.warning('Warning exists')
logger.info('Finish')
複製程式碼

執行之前我們需要先啟動 HTTP Server，並執行在 8001 埠，其中 log 介面是用來接收日誌的介面。

執行之後控制檯輸出會輸出如下內容：

This is a log info
Debugging
Warning exists
Finish
複製程式碼

output.log 檔案會寫入如下內容：

2018-06-03 15:13:44,895 - __main__ - INFO - This is a log info
2018-06-03 15:13:44,947 - __main__ - WARNING - Warning exists
2018-06-03 15:13:44,949 - __main__ - INFO - Finish
複製程式碼

HTTP Server 會收到控制檯輸出的資訊。

這樣一來，我們就通過設定多個 Handler 來控制了日誌的多目標輸出。

另外值得注意的是，在這裡 StreamHandler 物件我們沒有設定 Formatter，因此控制檯只輸出了日誌的內容，而沒有包含時間、模組等資訊，而 FileHandler 我們通過 setFormatter() 方法設定了一個 Formatter 物件，因此輸出的內容便是格式化後的日誌資訊。

另外每個 Handler 還可以設定 level 資訊，最終輸出結果的 level 資訊會取 Logger 物件的 level 和 Handler 物件的 level 的交集。

Formatter

在進行日誌格式化輸出的時候，我們可以不借助於 basicConfig 來全域性配置格式化輸出內容，可以藉助於 Formatter 來完成，下面我們再來單獨看下 Formatter 的用法：

import logging

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.WARN)
formatter = logging.Formatter(fmt='%(asctime)s - %(name)s - %(levelname)s - %(message)s', datefmt='%Y/%m/%d %H:%M:%S')
handler = logging.StreamHandler()
handler.setFormatter(formatter)
logger.addHandler(handler)

# Log
logger.debug('Debugging')
logger.critical('Critical Something')
logger.error('Error Occurred')
logger.warning('Warning exists')
logger.info('Finished')
複製程式碼

在這裡我們指定了一個 Formatter，並傳入了 fmt 和 datefmt 引數，這樣就指定了日誌結果的輸出格式和時間格式，然後 handler 通過 setFormatter() 方法設定此 Formatter 物件即可，輸出結果如下：

2018/06/03 15:47:15 - __main__ - CRITICAL - Critical Something
2018/06/03 15:47:15 - __main__ - ERROR - Error Occurred
2018/06/03 15:47:15 - __main__ - WARNING - Warning exists
複製程式碼

這樣我們可以每個 Handler 單獨配置輸出的格式，非常靈活。

捕獲 Traceback

如果遇到錯誤，我們更希望報錯時出現的詳細 Traceback 資訊，便於除錯，利用 logging 模組我們可以非常方便地實現這個記錄，我們用一個例項來感受一下：

import logging

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.DEBUG)

# Formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# FileHandler
file_handler = logging.FileHandler('result.log')
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)

# StreamHandler
stream_handler = logging.StreamHandler()
stream_handler.setFormatter(formatter)
logger.addHandler(stream_handler)

# Log
logger.info('Start')
logger.warning('Something maybe fail.')
try:
    result = 10 / 0
except Exception:
    logger.error('Faild to get result', exc_info=True)
logger.info('Finished')
複製程式碼

這裡我們在 error() 方法中新增了一個引數，將 exc_info 設定為了 True，這樣我們就可以輸出執行過程中的資訊了，即完整的 Traceback 資訊。

執行結果如下：

2018-06-03 16:00:15,382 - __main__ - INFO - Start print log
2018-06-03 16:00:15,382 - __main__ - DEBUG - Do something
2018-06-03 16:00:15,382 - __main__ - WARNING - Something maybe fail.
2018-06-03 16:00:15,382 - __main__ - ERROR - Faild to get result
Traceback (most recent call last):
  File "/private/var/books/aicodes/loggingtest/demo8.py", line 23, in <module>
    result = 10 / 0
ZeroDivisionError: division by zero
2018-06-03 16:00:15,383 - __main__ - INFO - Finished
複製程式碼

可以看到這樣我們就非常方便地記錄下來了報錯的資訊，一旦出現了錯誤，我們也能非常方便地排查。

配置共享

在寫專案的時候，我們肯定會將許多配置放置在許多模組下面，這時如果我們每個檔案都來配置 logging 配置那就太繁瑣了，logging 模組提供了父子模組共享配置的機制，會根據 Logger 的名稱來自動載入父模組的配置。

例如我們這裡首先定義一個 main.py 檔案：

import logging
import core

logger = logging.getLogger('main')
logger.setLevel(level=logging.DEBUG)

# Handler
handler = logging.FileHandler('result.log')
handler.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)

logger.info('Main Info')
logger.debug('Main Debug')
logger.error('Main Error')
core.run()
複製程式碼

這裡我們配置了日誌的輸出格式和檔案路徑，同時定義了 Logger 的名稱為 main，然後引入了另外一個模組 core，最後呼叫了 core 的 run() 方法。

接下來我們定義 core.py，內容如下：

import logging

logger = logging.getLogger('main.core')

def run():
    logger.info('Core Info')
    logger.debug('Core Debug')
    logger.error('Core Error')
複製程式碼

這裡我們定義了 Logger 的名稱為 main.core，注意這裡開頭是 main，即剛才我們在 main.py 裡面的 Logger 的名稱，這樣 core.py 裡面的 Logger 就會複用 main.py 裡面的 Logger 配置，而不用再去配置一次了。

執行之後會生成一個 result.log 檔案，內容如下：

2018-06-03 16:55:56,259 - main - INFO - Main Info
2018-06-03 16:55:56,259 - main - ERROR - Main Error
2018-06-03 16:55:56,259 - main.core - INFO - Core Info
2018-06-03 16:55:56,259 - main.core - ERROR - Core Error
複製程式碼

可以看到父子模組都使用了同樣的輸出配置。

如此一來，我們只要在入口檔案裡面定義好 logging 模組的輸出配置，子模組只需要在定義 Logger 物件時名稱使用父模組的名稱開頭即可共享配置，非常方便。

檔案配置

在開發過程中，將配置在程式碼裡面寫死並不是一個好的習慣，更好的做法是將配置寫在配置檔案裡面，我們可以將配置寫入到配置檔案，然後執行時讀取配置檔案裡面的配置，這樣是更方便管理和維護的，下面我們以一個例項來說明一下，首先我們定義一個 yaml 配置檔案：

version: 1
formatters:
  brief:
    format: "%(asctime)s - %(message)s"
  simple:
    format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
handlers:
  console:
    class : logging.StreamHandler
    formatter: brief
    level   : INFO
    stream  : ext://sys.stdout
  file:
    class : logging.FileHandler
    formatter: simple
    level: DEBUG
    filename: debug.log
  error:
    class: logging.handlers.RotatingFileHandler
    level: ERROR
    formatter: simple
    filename: error.log
    maxBytes: 10485760
    backupCount: 20
    encoding: utf8
loggers:
  main.core:
    level: DEBUG
    handlers: [console, file, error]
root:
  level: DEBUG
  handlers: [console]
複製程式碼

這裡我們定義了 formatters、handlers、loggers、root 等模組，實際上對應的就是各個 Formatter、Handler、Logger 的配置，引數和它們的構造方法都是相同的。

接下來我們定義一個主入口檔案，main.py，內容如下：

import logging
import core
import yaml
import logging.config
import os


def setup_logging(default_path='config.yaml', default_level=logging.INFO):
    path = default_path
    if os.path.exists(path):
        with open(path, 'r', encoding='utf-8') as f:
            config = yaml.load(f)
            logging.config.dictConfig(config)
    else:
        logging.basicConfig(level=default_level)


def log():
    logging.debug('Start')
    logging.info('Exec')
    logging.info('Finished')


if __name__ == '__main__':
    yaml_path = 'config.yaml'
    setup_logging(yaml_path)
    log()
    core.run()
複製程式碼

這裡我們定義了一個 setup_logging() 方法，裡面讀取了 yaml 檔案的配置，然後通過 dictConfig() 方法將配置項傳給了 logging 模組進行全域性初始化。

另外這個模組還引入了另外一個模組 core，所以我們定義 core.py 如下：

import logging

logger = logging.getLogger('main.core')

def run():
    logger.info('Core Info')
    logger.debug('Core Debug')
    logger.error('Core Error')
複製程式碼

這個檔案的內容和上文是沒有什麼變化的。

觀察配置檔案，主入口檔案 main.py 實際上對應的是 root 一項配置，它指定了 handlers 是 console，即只輸出到控制檯。另外在 loggers 一項配置裡面，我們定義了 main.core 模組，handlers 是 console、file、error 三項，即輸出到控制檯、輸出到普通檔案和回滾檔案。

這樣執行之後，我們便可以看到所有的執行結果輸出到了控制檯：

2018-06-03 17:07:12,727 - Exec
2018-06-03 17:07:12,727 - Finished
2018-06-03 17:07:12,727 - Core Info
2018-06-03 17:07:12,727 - Core Info
2018-06-03 17:07:12,728 - Core Error
2018-06-03 17:07:12,728 - Core Error
複製程式碼

在 debug.log 檔案中則包含了 core.py 的執行結果：

2018-06-03 17:07:12,727 - main.core - INFO - Core Info
2018-06-03 17:07:12,727 - main.core - DEBUG - Core Debug
2018-06-03 17:07:12,728 - main.core - ERROR - Core Error
複製程式碼

可以看到，通過配置檔案，我們可以非常靈活地定義 Handler、Formatter、Logger 等配置，同時也顯得非常直觀，也非常容易維護，在實際專案中，推薦使用此種方式進行配置。

以上便是 logging 模組的基本使用方法，有了它，我們可以方便地進行日誌管理和維護，會給我們的工作帶來極大的方便。

日誌記錄使用常見誤區

在日誌輸出的時候經常我們會用到字串拼接的形式，很多情況下我們可能會使用字串的 format() 來構造一個字串，但這其實並不是一個好的方法，因為還有更好的方法，下面我們對比兩個例子：

import logging

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# bad
logging.debug('Hello {0}, {1}!'.format('World', 'Congratulations'))
# good
logging.debug('Hello %s, %s!', 'World', 'Congratulations')
複製程式碼

這裡有兩種列印 Log 的方法，第一種使用了字串的 format() 的方法進行構造，傳給 logging 的只用到了第一個引數，實際上 logging 模組提供了字串格式化的方法，我們只需要在第一個引數寫上要列印輸出的模板，佔位符用 %s、%d 等表示即可，然後在後續引數新增對應的值就可以了，推薦使用這種方法。

執行結果如下：

2018-06-03 22:27:51,220 - root - DEBUG - Hello World, Congratulations!
2018-06-03 22:27:51,220 - root - DEBUG - Hello World, Congratulations!
複製程式碼

PyCon 2018: 利用logging模組輕鬆地進行Python日誌記錄

另外在進行異常處理的時候，通常我們會直接將異常進行字串格式化，但其實可以直接指定一個引數將 traceback 列印出來，示例如下：

import logging

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

try:
    result = 5 / 0
except Exception as e:
    # bad
    logging.error('Error: %s', e)
    # good
    logging.error('Error', exc_info=True)
    # good
    logging.exception('Error')
複製程式碼

如果我們直接使用字串格式化的方法將錯誤輸出的話，是不會包含 Traceback 資訊的，但如果我們加上 exc_info 引數或者直接使用 exception() 方法列印的話，那就會輸出 Traceback 資訊了。

執行結果如下：

2018-06-03 22:24:31,927 - root - ERROR - Error: division by zero
2018-06-03 22:24:31,927 - root - ERROR - Error
Traceback (most recent call last):
  File "/private/var/books/aicodes/loggingtest/demo9.py", line 6, in <module>
    result = 5 / 0
ZeroDivisionError: division by zero
2018-06-03 22:24:31,928 - root - ERROR - Error
Traceback (most recent call last):
  File "/private/var/books/aicodes/loggingtest/demo9.py", line 6, in <module>
    result = 5 / 0
ZeroDivisionError: division by zero
複製程式碼

PyCon 2018: 利用logging模組輕鬆地進行Python日誌記錄

以上便是整個對 logging 模組的介紹。嗯，是時候拋棄 print 了，開始體驗下 logging 的便利吧！

參考內容

相關文章