Python logging 最佳实践-译

Python Logging 最佳实践

背景

最近在工作中要新增一个服务,需要处理服务日志,之前每次使用 logging 都是很简单的配置,没有
了解过最佳实践, google 到了 fangpenlin 写的一篇博客(https://fangpenlin.com/posts/2012/08/26/good-logging-practice-in-python/),
很受用,因此翻译过来便于自己以后回顾使用,也希望大家能够正确配置日志,对运维同学友好些~

Good Logging practice in Python

在显示中,日志是重要的。当你在转账时,它们是转账记录。当飞机起飞时,黑匣子会记录所有事情。
如果某些事情发生了错误,人们可以通过阅读日志有机会弄清楚发生了什么。同样,在系统开发、排查
和运行中日志也是重要的。当你编写了一个服务,日志就是必须品。如果没有日志,我几乎不可能发现
错误如果服务已经挂掉。不仅仅是服务,日志对于桌面应用也是重要的。举个例子,当你的程序在你
客户电脑崩溃了,你可以让他们发送日志文件给你,你才有可能去查找为什么崩溃。相信我,你永远
不知道在不同的电脑环境中会发生什么奇怪的问题.

尽管日志很重要,但是不是所有的开发者都知道如何正确的使用。我见过一些开发者在开发过程中插入
一些 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 信息都将输出到标准输出中,这个是要禁止的。当然你可以输出到标准错误输出中,但是
这仍不是记录日志的最佳实践。

使用 Python 标准库 Logging

所以,如何正确的记录日志? 很简单,使用标准库中的 logging 模块。感谢 Python 社区,logging
在标准库中,它被设计的灵活且易用。你可以使用 logging 像下面这样:

1
2
3
4
5
6
7
8
9
10
11
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。
通过设置不同的日志级别,你可以只输出错误信息到指定的日志文件中,或者在 debug
时输出调试的详细信息。尝试改变日志级别为 debug 再观察下输出结果:

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

像你所看到的那样,我们调整日志级别为 DEBUG,调试记录输出在日志中。你也可以决定
如何处理这些信息.举个例子你可以使用 FileHandler 让日志输出到一个文件中:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
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')

有很多种不同的处理方式,你可以发送日志到你的消息中心,甚至是一个远端的服务器。
你也可以自定义日志处理方式,更多信息可以参考: Basic Tutorial, Advanced Tutorial and Logging Cookbook.

设置正确的日志级别

由于 logging 的灵活性,你可以在任何地方配置适当的日志级别去记录日志,可以再之后配置他们。
你可能会问,什么是正确的日志级别,这里我将分享我的经验。

在大多数场景下,在日志中不希望去看到大量的详细信息。因此,debug 级别只是在你
调试过程中开启。我只使用调试级别来获取详细的调试信息,特别是当数据量很大或者频率
很高的时候,比如在一个 for 循环中记录某些内部的状态变化。

1
2
3
4
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
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')

当一个状态比较重要,但是又没有处于 error 状态时,我会使用 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 级别,比如抛出异常,I/O 操作失败或者连接失败:

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

我很少使用严重级别,你可以在某些事情真的发生时,你可以使用它。比如内存泄露,
磁盘空间不足.

使用 name 作为 logger 名称

你不需要讲 logger 名称设置为 name ,但是如果这样做,会带来一些好处。
name 变量在 Python 中是当前模块名称。举个例子,你可以调用
logger.getLogger(name) 在模块 “foo.bar.my_module”中,这相当于
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 会被记录到日志中,你可以
看到这样的结果:

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)。

除非 disable_existing_loggers == False,否则不要在模块级别获取 logger

你可以看到很多的例子(包括这篇文章)在模块级别获取 logger。这看上去是无害的,
但是实际上,这是一个陷阱 - 在你从一个文件加载配置前,logging 模块会遵守所有
已经创建的 logger,如果你在模块级别获取 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
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 配置之前导入该模块。 logging.fileConfig 和 logging.dictConfig
默认禁用已经存在的 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 开始,添加一个新的参数名为 “disable_existing_loggers” 到 fileConfig 和
dictConfig,通过将其设置为 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
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 配置 logging

你可以再 Python 代码中配置 logging 参数,但是这不够灵活。更好的方式
是使用 logging 配置文件。在 Python2.7 之后,你可以加载 logging 配置
从一个字典,这意味着你可以从 JSON 或 YAML 文件中加载 logging 配置。
虽然你可以通过 old.ini 方式加载 logging 配置,但是这对于可读性和可编辑
来说是困难的。这里我将展示通过 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
---
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 文件中读取 logging 配置:

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.safe_load(f.read())
logging.config.dictConfig(config)
else:
logging.basicConfig(level=default_level)

现在,要配置 logging,你可以在程序启动时调用 setup_logging。这将读取 logging.json 或者
logging.yaml。你也可以设置 LOG_CFG 环境变量去从指定的路径下加载配置文件。比如:

LOG_CFG=my_logging.json python my_server.py

或者

LOG_CFG=my_logging.yaml python my_server.py

配置文件轮询

如果你使用 FileHandler 去写日志,随着时间的增加日志文件大小也会增长,某一天,会撑爆你的磁盘。
为了避免这种情况,你应该在生产环境中使用 RotatingFileHandler 替换 FileHandler 。

配置日志中心

当你有多台服务器和不同的日志文件时,你可以配置一个日志中心去手机所有重要的文件。这样你可以
更方便的监控和通知你的系统发生了哪些报错。

结论

我很开心 Python logging 库设置的很好,最好的是它是标准库中的一员,你无须选择。
它非常灵活,你可以编辑自己的处理器和过滤器。还有第三方程序比如 pyzmq 提供的 ZeroMQ 日志处理,
它允许你通过 zmq socket 发送日志信息。
如果你不知道如何正确的使用 logging,那么本文对你会有所帮助。通过良好的日志记录练习,
你可以更轻松的找到系统中的问题。