本文翻译自 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 语句,然后在完成开发时删掉它们。看起来就像下面这样:

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 内置的标准模块 logginglogging 是一个标准模块,设计优良、易于使用,同时易于扩展,这要归功于 Python 社区。你可以想下面这样使用 日志系统

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 语句有啥区别?呃,好处大概是这几个:

  • 你可以控制消息的级别,从而把没那么重要的内容过滤掉
  • 你可以迟点再决定要输出到哪里,以及怎么输出

有一些不同的级别可供使用:debuginfowarningerror 以及 critical。将级别设置给 logger 或是 handler,你可以只将错误信息输出到特定的日志文件,或是在调试时输出详细的信息。我们来把 logger 的级别设置为 DEBUG 看看:

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 将记录写入到一个文件。

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 循环中算法的内部状态时。

def complex_algorithm(items):
    for i, item in enumerate(items):
        # do some complex algorithm computation

        logger.debug('%s iteration, item=%s', i, item)

我使用 info 级别来记录常规动作,例如处理请求或是服务器状态变更。

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,例如某个用户使用了错误密码登录,或是连接太慢。

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 操作失败,又或者是连接问题。

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 信息。下面是一个例子:

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

import logging

logger = logging.getLogger(__name__)

def foo():
    logger.info('Hi, foo')

class Bar(object):
    def bar(self):
        logger.info('Hi, bar')

main.py

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

[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.fileConfiglogging.dictConfig 默认会禁用已经存在的 logger。这样一来文件里的配置不会对你的 logger 生效。最好是在需要的时候才去获取 logger。要创建或是获取一个 logger 是没什么代价的。可以像这样写:

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 起,fileConfigdictConfig(作为配置集的一个 key) 接受一个新的参数 disable_existing_loggers,设置为 False 时上述问题就可以解决了。例如:

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

{
    "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

---

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 文件中读取日志配置:

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 配置:

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 环境变量来指定从某个路径中加载日志配置。例如:

LOG_CFG=my_logging.json python my_server.py

或者,如果你偏好 YAML:

LOG_CFG=my_logging.yaml python my_server.py

轮换日志处理器

如果你用 FileHandler 来写日志的话,日志文件大小会随时间不断增长。总有一天磁盘会被它占满的。为了避免这种情况,你应该在生产环境中使用 RotatingFileHandler 代替 FileHandler

在有多台服务器的情况下,设置中心日志服务器

当你有多台服务器和多个日志文件的时候,你可以设置一台中心日志服务器来收集所有重要的信息(大部分情况下是警告、错误等)。这样你监视起来会比较简单,出错的时候也更容易注意到。

结论

Python 的 logging 模块设计得很棒,最棒的一点是它是个标准库,你的选择强迫症不用犯了。它很容易扩展,你可以编写自己的处理器和过滤器。当然也有一些第三方的处理器,例如由 pyzmq 提供的 ZeroMQ 处理器,让你可以通过一个 zmq 套接字来发送日志消息。如果你不知道如何正确地记录日志的话,这篇文章也许能帮到你。熟悉了记录日志的正确姿势,你就能更容易地诊断系统出现的问题。划算的投资,不是吗?:D