本文翻译自 Victor Lin’s Coding notes，原文链接 Good logging practice in Python，作者 Victor Lin。

日志很重要，真的。你转账的时候会产生交易记录；航班运行时，黑匣子（飞行数据记录仪）在记录着一切。如果有地方出了岔子，人们通过阅读日志，就可能找出问题的所在。同样地，在系统的开发、调试和运行中，日志也很重要。如果一个程序崩溃了但却没有日志，你根本就没法理解这其中到底发生了什么。举例来说，如果你在编写一个服务器，日志就是必需的。下图是 EZComet.com 服务器日志文件的截图。

ezcomet_logging.png

没有日志的话，服务挂了我根本就不知道是为啥。不只是服务器，日志对于桌面程序来说也很重要。当你的程序崩溃了，你可以让用户把日志文件发送给你，你就可以从中找到（崩溃的）原因。相信我，你永远无法预料到不同的 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