每一個 Python 程序員都要知道的日誌實踐

在現實生活中，記錄日誌很是重要。銀行轉帳時會有轉帳記錄；飛機飛行過程當中，會有黑盒子（飛行數據記錄器）記錄飛行過程當中的一切。若是有出現什麼問題，人們能夠經過日誌數據來搞清楚到底發生了什麼。

對於系統開發、調試以及運行，記錄日誌都是一樣的重要。若是沒有日誌記錄，程序崩潰時你幾乎就沒辦法弄明白到底發生了什麼事情。舉個例子，當你在寫一個服務器程序時，記錄日誌是很是有必要的。下面展現的就是 EZComet.com 服務器的日誌文件截圖。

 

服務崩潰後，若是沒有日誌，我幾乎沒辦法知道到底發生了錯誤。日誌不只對於服務器很重要，對於桌面圖形應用一樣十分重要。好比，當你的客戶的 PC 機程序崩潰時，你可讓他們把日誌文件發給你，這樣你就能夠找到問題到底出在哪兒。相信我，在不一樣的 PC 環境下，你永遠不會知道會有怎樣奇怪的問題。我曾經就接收到過這樣的錯誤日誌。

Python

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 語句，開發結束後再將這些語句移除。就像這樣:

Python

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 社區將日誌作成了一個標準模塊。它很是簡單易用且十分靈活。你能夠像這樣使用日誌系統：

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')
運行的時候就可看到：

Python

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 再看一下輸出結果：

Python

1
logging.basicConfig(level=logging.DEBUG)
輸出變成了：

Python

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 把記錄寫進文件中：

Python

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 獲取詳細的調試信息，特別是當數據量很大或者頻率很高的時候，好比算法內部每一個循環的中間狀態。

Python

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 等級。

Python

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 。好比，當用戶登陸密碼錯誤時，或者鏈接變慢時。

Python

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 操做失敗或者鏈接問題等。

Python

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 把它們記錄下來。好比下面這個例子：

Python

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 中。你能夠看到下面的結果：

Python

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

Python

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

Python

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

Python

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 的成本很低。你能夠這樣寫你的代碼：

Python

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，上面提到的問題就能夠解決了。例如：

Python

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

Python

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

Python

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 文件中讀入日誌的配置信息：

Python

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 配置文件：

Python

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 從指定路徑加載日誌配置。例如：

Python

1
LOG_CFG=my_logging.json python my_server.py
若是你喜歡 YAML：

Python

1
LOG_CFG=my_logging.yaml python my_server.py
使用旋轉文件句柄

若是你用 FileHandler 寫日誌，文件的大小會隨着時間推移而不斷增大。最終有一天它會佔滿你全部的磁盤空間。爲了不這種狀況出現，你能夠在你的生成環境中使用 RotatingFileHandler 替代 FileHandler。

若是你有多個服務器能夠啓用一個專用的日誌服務器

當你有多個服務器和不一樣的日誌文件時，你能夠建立一個集中式的日誌系統來收集重要的（大多數狀況是警告或者錯誤消息）信息。而後經過監測這些日誌信息，你就能夠很容易地發現系統中的問題了。

總結

Python 的日誌庫設計得如此之好，真是讓人欣慰，我以爲這是標準庫中最好的一部分了，你不得不選擇它。它很靈活，你能夠用你本身的 handler 或者 filter。已經有不少的第三方的 handler 了，好比 pyzmq 提供的 ZeroMQ 日誌句柄，它容許你經過 zmq 套接字發送日誌消息。若是你還不知道怎麼正確的使用日誌系統，這篇文章將會很是有用。有了很好的日誌記錄實踐，你就能很是容易地發現系統中的問題。這是很很是值得投資的。:)