本文翻译自 Victor Lin’s Coding notes，原文链接 Good logging practice in Python，作者 Victor Lin。
日志很重要，真的。你转账的时候会产生交易记录；航班运行时，黑匣子（飞行数据记录仪）在记录着一切。如果有地方出了岔子，人们通过阅读日志，就可能找出问题的所在。同样地，在系统的开发、调试和运行中，日志也很重要。如果一个程序崩溃了但却没有日志，你根本就没法理解这其中到底发生了什么。举例来说，如果你在编写一个服务器，日志就是必需的。下图是 EZComet.com 服务器日志文件的截图。
没有日志的话，服务挂了我根本就不知道是为啥。不只是服务器，日志对于桌面程序来说也很重要。当你的程序崩溃了，你可以让用户把日志文件发送给你，你就可以从中找到（崩溃的）原因。相信我，你永远无法预料到不同的 PC 环境会造成什么样稀奇古怪的问题。我有一次收到下面这样一份错误日志：
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:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/wx._core", line 7978, in __init__
File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/wx._core", line 7552, in _BootstrapApp
File "<string>", line 84, in OnInit
File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/twisted.internet.wxreactor", line 175, in install
File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/twisted.internet._threadedselect", line 106, in __init__
File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/twisted.internet.base", line 488, in __init__
File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/twisted.internet.posixbase", line 266, in installWaker
File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/twisted.internet.posixbase", line 74, in __init__
File "h:\workspace\project\build\pyi.win32\mrdj\outPYZ1.pyz/socket", line 224, in meth
gaierror: [Errno 10104] getaddrinfo failed
最终我搞清楚了，是因为用户的电脑被病毒感染，导致 gethostname 调用失败。看看，如果没有日志的话你可能连这些一点都不知道呢吧？
print 不是个好主意
虽然日志那么重要，但并不是所有开发者都知道如何正确地记录日志。我见过一些开发者在开发过程中往代码里插入 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 语句，除非去修改源代码。你可能会忘记删除没用的 print。以及，所有的消息都会被输出到 stdout，如果你的数据也是输出到 stdout 的话这简直糟透了。当然，你也可以把 print 的消息输出到 stderr，但这已然不是记录日志的好习惯。
使用 logging 标准库
那么，怎么样才算是记录日志的正确姿势？很简单，使用 Python 内置的标准模块 logging。logging 是一个标准模块，设计优良、易于使用，同时易于扩展，这要归功于 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')
|
运行一下，你会看到：
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)
|
输出：
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')
|
有很多不同的处理器，你也可以选择将记录发送到你的邮箱，甚至发送到一个远程服务器。你也可以自己编写个性化的处理器。我不会教你这些细节，如果你想那么做的话，参考这些官方文档：基础教程，高级教程以及 Logging Cookbook。
使用合适的级别来记录
logging 模块提供了十分灵活的方式来记录日志，你可以随处记录日志，只要级别合适，之后可以再配置它们。你可能会问，「什么是合适的级别？」那么我说一说我的经验。
大部分情况下，你不想在日志文件中记录太多的细节。那么 debug 级别只应当在调试的时候被激活。我只在需要获取详细的调试信息时打开它，尤其是数据量很大，或是请求过于频繁，例如在调试 for 循环中算法的内部状态时。
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 名称
没人强迫你这么做，但它有些好处。__name__ 变量在 Python 里是当前模块的名字。例如，你在模块 foo.bar.my_module 里调用 logging.getLogger(__name__)，那么其实等价于 logging.getLogger('foo.bar.my_module')。当你需要设置 logger 的时候，设置为 foo，那么 foo 包里的所有模块都会共享同一套设置。这样的话你在阅读日志的时候，也比较容易理解这是哪个模块记录的日志信息。
捕获异常，记录跟踪信息
出错的时候记录日志是好的，但是没有 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)
|
调用 logger 来记录日志时，指定 exc_info=True 参数，traceback 信息将会被存入日志中。结果是这样的：
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, *args, exc_info=True) 是一样的。
除非 disable_existing_logger == False，不然不要在模块级别获取 logger
在网络上可以找到很多例子（这篇文章中我也特意举了这么一个例子），它们在模块级别获取 logger。看起来无害，但实际上是有隐患的——Python 的 logging 模块，在从文件中读取设置之前，对所有 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
11
12
13
|
import logging
# load my module
import my_module
# load the logging configuration
logging.config.fileConfig('logging.ini')
my_module.foo()
bar = my_module.Bar()
bar.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 会在你加载配置之后才创建，那些配置就会生效。
从 Python 2.7 起，fileConfig 和 dictConfig（作为配置集的一个 key） 接受一个新的参数 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 代码中配置你的日志系统，但似乎不是那么灵活。更好的方式是用配置文件。在 Python 2.7 之后，你可以从一个字典中加载日志配置了。这意味着你可以从 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
74
75
76
77
78
79
|
---
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
22
|
import os
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:
logging.basicConfig(level=default_level)
|
现在，要设置日志记录的话，在程序启动的时候调用 setup_logging 就行了。它默认读取 logging.json 或是 logging.yaml。你可以设置 LOG_CFG 环境变量来指定从某个路径中加载日志配置。例如：
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 的 logging 模块设计得很棒，最棒的一点是它是个标准库，你的选择强迫症不用犯了。它很容易扩展，你可以编写自己的处理器和过滤器。当然也有一些第三方的处理器，例如由 pyzmq 提供的 ZeroMQ 处理器，让你可以通过一个 zmq 套接字来发送日志消息。如果你不知道如何正确地记录日志的话，这篇文章也许能帮到你。熟悉了记录日志的正确姿势，你就能更容易地诊断系统出现的问题。划算的投资，不是吗？:D