在現實生活中，記錄日誌非常重要。銀行轉賬時會有轉賬記錄；飛機飛行過程中，會有黑盒子（飛行資料記錄器）記錄飛行過程中的一切。如果有出現什麼問題，人們可以通過日誌資料來搞清楚到底發生了什麼。
對於系統開發、除錯以及執行，記錄日誌都是同樣的重要。如果沒有日誌記錄，程式崩潰時你幾乎就沒辦法弄明白到底發生了什麼事情。舉個例子，當你在寫一個伺服器程式時，記錄日誌是非常有必要的。下面展示的就是 EZComet.com 伺服器的日誌檔案截圖。
服務崩潰後，如果沒有日誌，我幾乎沒辦法知道到底發生了錯誤。日誌不僅對於伺服器很重要，對於桌面圖形應用同樣十分重要。比如，當你的客戶的 PC 機程式崩潰時，你可以讓他們把日誌檔案發給你，這樣你就可以找到問題到底出在哪兒。相信我，在不同的 PC 環境下，你永遠不會知道會有怎樣奇怪的問題。我曾經就接收到過這樣的錯誤日誌。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
2011-08-22 17:52:54,828 - root - ERROR - [Errno 10104] getaddrinfo failed Traceback (most recent call last): File "<string>", line 124, in main File "<string>", line 20, in __init__ File "h:workspaceprojectbuildpyi.win32mrdjoutPYZ1.pyz/wx._core", line 7978, in __init__ File "h:workspaceprojectbuildpyi.win32mrdjoutPYZ1.pyz/wx._core", line 7552, in _BootstrapApp File "<string>", line 84, in OnInit File "h:workspaceprojectbuildpyi.win32mrdjoutPYZ1.pyz/twisted.internet.wxreactor", line 175, in install File "h:workspaceprojectbuildpyi.win32mrdjoutPYZ1.pyz/twisted.internet._threadedselect", line 106, in __init__ File "h:workspaceprojectbuildpyi.win32mrdjoutPYZ1.pyz/twisted.internet.base", line 488, in __init__ File "h:workspaceprojectbuildpyi.win32mrdjoutPYZ1.pyz/twisted.internet.posixbase", line 266, in installWaker File "h:workspaceprojectbuildpyi.win32mrdjoutPYZ1.pyz/twisted.internet.posixbase", line 74, in __init__ File "h:workspaceprojectbuildpyi.win32mrdjoutPYZ1.pyz/socket", line 224, in meth gaierror: [Errno 10104] getaddrinfo failed |
我最終發現，這個客戶的 PC 機被一種病毒感染，導致了呼叫 gethostname 函式失敗。看吧，如果沒有日誌可以查你怎麼可能知道這些。
列印輸出不是個好辦法
儘管記錄日誌非常重要，但是並不是所有的開發者都能正確地使用它。我曾看到一些開發者是這樣記錄日誌的，在開發的過程中插入 print 語句，開發結束後再將這些語句移除。就像這樣:
|
1 2 3 4 5 6 |
print 'Start reading database' records = model.read_recrods() print '# records', records print 'Updating record ...' model.update_records(records) print 'done' |
這種方式對於簡單指令碼型程式有用，但是如果是複雜的系統，你最好不要使用這樣的方式。首先，你沒辦法做到在日誌檔案中只留下極其重要的訊息。你會看到大量的訊息日誌。但是你卻找不到任何有用的資訊。你除了移除這輸出語句這外，沒別的辦法控制程式碼，但是極有可能的是你忘記了移出那些沒用的輸出。再者，print 輸出的所有資訊都到了標準輸出中，這將嚴重影響到你從標準輸出中檢視其它輸出資料。當然，你也可以把訊息輸出到 stderr ，但是用 print 做日誌記錄的方式還是不好。
使用 python 的標準日誌模組
那麼，怎麼樣記錄日誌才是正確的呢？其實非常簡單，使用 python 的標準日誌模組。多虧 python 社群將日誌做成了一個標準模組。它非常簡單易用且十分靈活。你可以像這樣使用日誌系統：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 |
import logging logging.basicConfig(level=logging.INFO) logger = logging.getLogger(__name__) logger.info('Start reading database') # read database here records = {'john': 55, 'tom': 66} logger.debug('Records: %s', records) logger.info('Updating records ...') # update records here logger.info('Finish updating records') |
執行的時候就可看到：
|
1 2 3 |
INFO:__main__:Start reading database INFO:__main__:Updating records ... INFO:__main__:Finish updating records |
你可能會問這與使用 print 有什麼不同呢。它有以下的優勢：
- 你可以控制訊息的級別，過濾掉那些並不重要的訊息。
- 你可決定輸出到什麼地方，以及怎麼輸出。
有許多的重要性別級可供選擇，debug、info、warning、error 以及 critical。通過賦予 logger 或者 handler 不同的級別，你就可以只輸出錯誤訊息到特定的記錄檔案中，或者在除錯時只記錄除錯資訊。讓我們把 logger 的級別改成 DEBUG 再看一下輸出結果：
|
1 |
logging.basicConfig(level=logging.DEBUG) |
輸出變成了：
|
1 2 3 4 |
INFO:__main__:Start reading database DEBUG:__main__:Records: {'john': 55, 'tom': 66} INFO:__main__:Updating records ... INFO:__main__:Finish updating records |
正如看到的那樣，我們把 logger 的等級改為 DEBUG 後，除錯記錄就出現在了輸出當中。你也可以選擇怎麼處理這些訊息。例如，你可以使用 FileHandler 把記錄寫進檔案中：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 |
import logging logger = logging.getLogger(__name__) logger.setLevel(logging.INFO) # create a file handler handler = logging.FileHandler('hello.log') handler.setLevel(logging.INFO) # create a logging format formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s') handler.setFormatter(formatter) # add the handlers to the logger logger.addHandler(handler) logger.info('Hello baby') |
標準庫模組中提供了許多的 handler ，你可以將記錄傳送到郵箱甚至傳送到一個遠端的伺服器。你也可以實現自己的記錄 handler 。這裡將不具體講述實現的細節，你可以參考官方文件：Basci Turial、Advanced Tutorial 與 Logging Cookbook。
以合適的等級輸出日誌記錄
有了靈活的日誌記錄模組後，你可以按適當的等級將日誌記錄輸出到任何地方然後配置它們。那麼你可能會問，什麼是合適的等級呢？在這兒我將分享一些我的經驗。
大多數的情況下，你都不想閱讀日誌中的太多細節。因此，只有你在除錯過程中才會使用 DEBUG 等級。我只使用 DEBUG 獲取詳細的除錯資訊，特別是當資料量很大或者頻率很高的時候，比如演算法內部每個迴圈的中間狀態。
|
1 2 3 4 5 |
def complex_algorithm(items): for i, item in enumerate(items): # do some complex algorithm computation logger.debug('%s iteration, item=%s', i, item) |
在處理請求或者伺服器狀態變化等日常事務中，我會使用 INFO 等級。
|
1 2 3 4 5 6 7 8 9 10 11 |
def handle_request(request): logger.info('Handling request %s', request) # handle request here result = 'result' logger.info('Return result: %s', result) def start_service(): logger.info('Starting service at port %s ...', port) service.start() logger.info('Service is started') |
當發生很重要的事件，但是並不是錯誤時，我會使用 WARNING 。比如，當使用者登入密碼錯誤時，或者連線變慢時。
|
1 2 3 4 5 |
def authenticate(user_name, password, ip_address): if user_name != USER_NAME and password != PASSWORD: logger.warn('Login attempt to %s from IP %s', user_name, ip_address) return False # do authentication here |
有錯誤發生時肯定會使用 ERROR 等級了。比如丟擲異常，IO 操作失敗或者連線問題等。
|
1 2 3 4 5 6 |
def get_user_by_id(user_id): user = db.read_user(user_id) if user is None: logger.error('Cannot find user with user_id=%s', user_id) return user return user |
我很少使用 CRITICAL 。當一些特別糟糕的事情發生時，你可以使用這個級別來記錄。比方說，記憶體耗盡，磁碟滿了或者核危機（希望永遠別發生 :S）。
使用 __name__ 作為 logger 的名稱
雖然不是非得將 logger 的名稱設定為 __name__ ，但是這樣做會給我們帶來諸多益處。在 python 中，變數 __name__ 的名稱就是當前模組的名稱。比如，在模組 “foo.bar.my_module” 中呼叫 logger.getLogger(__name__) 等價於呼叫logger.getLogger(“foo.bar.my_module”) 。當你需要配置 logger 時，你可以配置到 “foo” 中，這樣包 foo 中的所有模組都會使用相同的配置。當你在讀日誌檔案的時候，你就能夠明白訊息到底來自於哪一個模組。
捕捉異常並使用 traceback 記錄它
出問題的時候記錄下來是個好習慣，但是如果沒有 traceback ，那麼它一點兒用也沒有。你應該捕獲異常並用 traceback 把它們記錄下來。比如下面這個例子：
|
1 2 3 4 5 6 |
try: open('/path/to/does/not/exist', 'rb') except (SystemExit, KeyboardInterrupt): raise except Exception, e: logger.error('Failed to open file', exc_info=True) |
使用引數 exc_info=true 呼叫 logger 方法, traceback 會輸出到 logger 中。你可以看到下面的結果：
|
1 2 3 4 5 |
ERROR:__main__:Failed to open file Traceback (most recent call last): File "example.py", line 6, in <module> open('/path/to/does/not/exist', 'rb') IOError: [Errno 2] No such file or directory: '/path/to/does/not/exist' |
你也可以呼叫 logger.exception(msg, _args)，它等價於 logger.error(msg, exc_info=True, _args)。
千萬不要在模組層次獲取 Logger，除非 disable_existing_loggers 被設定為 False
你可以看到很多在模組層次獲取 logger 的例子（在這篇文章我也使用了很多，但這僅僅為了讓示例更短一些）。它們看上去沒什麼壞處，但事實上，這兒是有陷阱的 – 如果你像這樣在模組中使用 Logger，Python 會保留從檔案中讀入配置前所有建立的所有 logger。
my_module.py
|
1 2 3 4 5 6 7 8 9 10 |
import logging logger = logging.getLogger(__name__) def foo(): logger.info('Hi, foo') class Bar(object): def bar(self): logger.info('Hi, bar') |
main.py
|
1 2 3 4 5 6 7 8 9 10 |
import logging logger = logging.getLogger(__name__) def foo(): logger.info('Hi, foo') class Bar(object): def bar(self): logger.info('Hi, bar') |
logging.ini
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
[loggers] keys=root [handlers] keys=consoleHandler [formatters] keys=simpleFormatter [logger_root] level=DEBUG handlers=consoleHandler [handler_consoleHandler] class=StreamHandler level=DEBUG formatter=simpleFormatter args=(sys.stdout,) [formatter_simpleFormatter] format=%(asctime)s - %(name)s - %(levelname)s - %(message)s datefmt= |
本應該在日誌中看到記錄，但是你卻什麼也沒有看到。為什麼呢？這就是因為你在模組層次建立了 logger，然後你又在載入日誌配置檔案之前就匯入了模組。logging.fileConfig 與 logging.dictConfig 預設情況下會使得已經存在的 logger 失效。所以，這些配置資訊不會應用到你的 Logger 上。你最好只在你需要 logger 的時候才獲得它。反正建立或者取得 logger 的成本很低。你可以這樣寫你的程式碼：
|
1 2 3 4 5 6 7 8 9 10 11 12 |
import logging def foo(): logger = logging.getLogger(__name__) logger.info('Hi, foo') class Bar(object): def __init__(self, logger=None): self.logger = logger or logging.getLogger(__name__) def bar(self): self.logger.info('Hi, bar') |
這樣，logger 就會在你載入配置後才會被建立。這樣配置資訊就可以正常應用。
python2.7 之後的版本中 fileConfg 與 dictConfig 都新新增了 “disable_existing_loggers” 引數，將其設定為 False，上面提到的問題就可以解決了。例如：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 |
import logging import logging.config logger = logging.getLogger(__name__) # load config from file # logging.config.fileConfig('logging.ini', disable_existing_loggers=False) # or, for dictConfig logging.config.dictConfig({ 'version': 1, 'disable_existing_loggers': False, # this fixes the problem 'formatters': { 'standard': { 'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s' }, }, 'handlers': { 'default': { 'level':'INFO', 'class':'logging.StreamHandler', }, }, 'loggers': { '': { 'handlers': ['default'], 'level': 'INFO', 'propagate': True } } }) logger.info('It works!') |
使用 JSON 或者 YAML 記錄配置
雖然你可以在 python 程式碼中配置你的日誌系統，但是這樣並不夠靈活。最好的方法是使用一個配置檔案來配置。在 Python2.7 及之後的版本中，你可以從字典中載入 logging 配置。這也就意味著你可以從 JSON 或者 YAML 檔案中載入日誌的配置。儘管你還能用原來 .ini 檔案來配置，但是它既很難讀也很難寫。下面我給你們看一個用 JSON 和 YAML 檔案配置的例子:
logging.json
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 |
{ "version": 1, "disable_existing_loggers": false, "formatters": { "simple": { "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s" } }, "handlers": { "console": { "class": "logging.StreamHandler", "level": "DEBUG", "formatter": "simple", "stream": "ext://sys.stdout" }, "info_file_handler": { "class": "logging.handlers.RotatingFileHandler", "level": "INFO", "formatter": "simple", "filename": "info.log", "maxBytes": 10485760, "backupCount": 20, "encoding": "utf8" }, "error_file_handler": { "class": "logging.handlers.RotatingFileHandler", "level": "ERROR", "formatter": "simple", "filename": "errors.log", "maxBytes": 10485760, "backupCount": 20, "encoding": "utf8" } }, "loggers": { "my_module": { "level": "ERROR", "handlers": ["console"], "propagate": "no" } }, "root": { "level": "INFO", "handlers": ["console", "info_file_handler", "error_file_handler"] } } |
logging.yaml
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 |
--- version: 1 disable_existing_loggers: False formatters: simple: format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s" handlers: console: class: logging.StreamHandler level: DEBUG formatter: simple stream: ext://sys.stdout info_file_handler: class: logging.handlers.RotatingFileHandler level: INFO formatter: simple filename: info.log maxBytes: 10485760 # 10MB backupCount: 20 encoding: utf8 error_file_handler: class: logging.handlers.RotatingFileHandler level: ERROR formatter: simple filename: errors.log maxBytes: 10485760 # 10MB backupCount: 20 encoding: utf8 loggers: my_module: level: ERROR handlers: [console] propagate: no root: level: INFO handlers: [console, info_file_handler, error_file_handler] ... |
接下來將展示怎樣從 JSON 檔案中讀入日誌的配置資訊：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
import json import logging.config def setup_logging( default_path='logging.json', default_level=logging.INFO, env_key='LOG_CFG' ): """Setup logging configuration """ path = default_path value = os.getenv(env_key, None) if value: path = value if os.path.exists(path): with open(path, 'rt') as f: config = json.load(f) logging.config.dictConfig(config) else: logging.basicConfig(level=default_level) |
使用 JSON 的一個優點就是 json是一個標準庫，你不需要額外安裝它。但是從我個人來說，我比較喜歡 YAML 一些。它無論是讀起來還是寫起來都比較容易。你也可以使用下面的方法來載入一個 YAML 配置檔案：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 |
import os import logging.config import yaml def setup_logging( default_path='logging.yaml', default_level=logging.INFO, env_key='LOG_CFG' ): """Setup logging configuration """ path = default_path value = os.getenv(env_key, None) if value: path = value if os.path.exists(path): with open(path, 'rt') as f: config = yaml.load(f.read()) logging.config.dictConfig(config) else: lo |
接下來，你就可以在執行程式的時候呼叫 setup_logging 來啟動日誌記錄了。它預設會讀取 logging.json 或 logging.yaml 檔案 。你也可以設定環境變數 LOG_CCFG 從指定路徑載入日誌配置。例如：
|
1 |
LOG_CFG=my_logging.json python my_server.py |
如果你喜歡 YAML：
|
1 |
LOG_CFG=my_logging.yaml python my_server.py |
使用旋轉檔案控制程式碼
如果你用 FileHandler 寫日誌，檔案的大小會隨著時間推移而不斷增大。最終有一天它會佔滿你所有的磁碟空間。為了避免這種情況出現，你可以在你的生成環境中使用 RotatingFileHandler 替代 FileHandler。
如果你有多個伺服器可以啟用一個專用的日誌伺服器
當你有多個伺服器和不同的日誌檔案時，你可以建立一個集中式的日誌系統來收集重要的（大多數情況是警告或者錯誤訊息）資訊。然後通過監測這些日誌資訊，你就可以很容易地發現系統中的問題了。
總結
Python 的日誌庫設計得如此之好，真是讓人欣慰，我覺得這是標準庫中最好的一部分了，你不得不選擇它。它很靈活，你可以用你自己的 handler 或者 filter。已經有很多的第三方的 handler 了，比如 pyzmq 提供的 ZeroMQ 日誌控制程式碼，它允許你通過 zmq 套接字傳送日誌訊息。如果你還不知道怎麼正確的使用日誌系統，這篇文章將會非常有用。有了很好的日誌記錄實踐，你就能非常容易地發現系統中的問題。這是很非常值得投資的。:)