Python logging 模块实践

󰃭 2017-03-02

原创作品：首发u3v3, 转载请保留

地址：https://www.u3v3.com/ar/1271

作者ID：noomrevils

首发日期：2017.3.2

简介

log的目的

  • 审计, 业务流水, 流程管控
  • 记录异常和错误，方便调试和定位错误

logging vs print

相信大多数人在写代码的时候都有加入很多print语句的习惯，诚然对于简单的脚本，或实现调试阶段， print简单直接。但是对于结构层次复杂，流程冗长的项目来说，print输出缺乏对信息层级的控制，而且难以维护。

logging虽然使用起来相对较重,但是也有对应功能上带来的好处

  • 通过控制logging的层级来过滤重要的信息
  • 定义一致的输出结构，方便解析，抽取信息
  • 指定输出的位置和归档的方式

log的等级

  • debug: 记录的数据非常详细, 频率很高 (比如算法中时间复杂度的统计)
  • info: 运行状态变化，业务逻辑流程, 比如用户请求，服务器运行状态
  • warning: 警告值得重视的信息, 比如尝试破解密码等
  • error: 程序发生异常, 比如IO操作发生失败，数据无法连接
  • critial: 致命的问题可能导致宕机, 比如内存泄漏，磁盘空间不足

使用场景

基本场景

import logging
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)
logger.info('use logger to log')

# output
INFO:__main__: use logger to log


import logging
import sys
logging.basicConfig(stream=sys.stdout, level=logging.DEBUG)
logger.info('use root logger to log')

# ouput
INFO:root: use root logger to log

上面两个是最简单的场景，但是仔细观察发现其中一些差异: 在第一个代码片段中，通过getLogger函数拿到了一个名字为__name__(__main__)的logger实例。

第二个代码片段中，没有显式的获取logger实例，而是直接使用logging模块来记录，这里实际使用的是root logger，这可以从输出中看出，

在一个项目中针对不同的功能模块记日志，比如数据库，和网络请求，这个时候如果都公用一个root logger显然是不合理的，所以推荐采用第一种方式来记log，但是需要指出的是，假如getLogger函数没有穿参数，默认返回的也是root logger。

更多设置

上面提到最基本的使用方法，要达到前面提到的强大的功能，还需要做进一步的设置。


import logging

# 获取logger
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)

# 创建一个 file handler
handler = logging.FileHandler('example.log')
handler.setLevel(logging.INFO)

# 指定logger的格式，并应用到定义的file handler上
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)

# 将这个file handler加到logger实例上，一个logger可以对应多个类型的handler
logger.addHandler(handler)

logger.info('Hello World')

这里建议getLogger的缺省参数使用 __name__，这样可以定位log产生的具体模块。当然如果需要在不同的module中共享一个logger，可以另行自定义。

当在捕获异常的时候，使用logger的，可以通过增加exc_info=True来将异常的堆栈信息导入到日志中。这在调试的时候非常的有用。

    
    try:
        open('/path/to/does/not/exist', 'rb')
    except (SystemExit, KeyboardInterrupt):
        raise
    except Exception, e:
        logger.error('Failed to open file', exc_info=True)

格式化输出

logging.warning('name:%s msg:%s','BeginMan','Hi')               #方式一

logging.warning('name:%s msg:%s' %('BeginMan','Hi'))            #方式二

logging.warning('name:{0} msg:{1}'.format('BeginMan','Hi'))     #方式三

from string import Template                                     #方式四
msg = Template('name:$who msg:$what')
logging.warning(msg.substitute(who='BeginMan',what='Hi'))

log.debug('%s, %s, %s', *('error', 'debug', 'info'))            #方式五

log.debug('%(module)s, %(info)s', {'module': 'log', 'info': 'error'}) #方式六

madlib = " I {verb} the {object} off the {place} ".format(verb="took", object="cheese", place="table")  #方式七

推荐最后一种，可读性好，易于维护。

最佳实践

获取logger的场景

import logging
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)

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

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

在前面的例子中，单个文件中我们直接获取了logger，如果这个文件作为一个模块，被其他模块引用，假如这个模块的导入在logging配置之前，这样会产生一个问题, 在模块中定义的logger并没有生效, 这是python内在的机制：禁止已经存在的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')

方法二：

在指定logging配置参数的时候，显式的指定 disable_existing_loggers=False

logging.config.fileConfig('logging.ini', disable_existing_loggers=False)

使用dict配置logging

在代码中指定logging配置，或者采用较早fileConfig的方式都不太好维护，在Python2.7之后，logging的配置支持了dict的方式，这样，我们可以通过dict或者加载json文件来配置logging


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