Python日志最佳实践


日志对于系统开发的开发、调试和运行整个过程中都起着很重要的作用,调试阶段需要查看日志来明确问题所在,运行阶段如果程序崩溃,日志可以记录程序崩溃的相关原因。 刚初学Python的时候,想调试代码基本靠print, 导致项目代码多了之后,print也不知到具体是那部分的。而且print打印日志也不符合PEP8的规范,到调试成功后还得一行行地把print删除,所以logging标准库很好地解决了这个问题,。

日志的作用

通过记录日志,可以了解系统、程序的运行情况;某些情况下,日志还可以记录用户的操作行为、类型爱好等可以用来分析。日志可以在程序发现问题后让开发人员或运维人员快速定位问题所在。总而言是,日志在开发调试、定位故障、了解程序运行情况等方面发挥重要作用。

简单示例

记录日志最简单正确的方式就是使用logging内置模块来实现。最简单一个例子如下:

import logging

# filename 指定日志存放文件,level 指定logging级别
logging.basicConfig(filename="out.log", level=logging.INFO)

logging.debug("hello, debug")
logging.info("hello, info")

logging.info("finsh, info")

运行结果如下:

INFO:root:hello, info
INFO:root:finsh, info

如上三行代码就可以把日志记录到文件中。有没有好奇为什么第一条logging没有存入日志文件中,这就和我们指定的level有关了,如下指定了日志的级别是INFO级别:

logging.basicConfig(filename="out.log", level=logging.INFO)

下面是logging模块的几种级别和对应的权重:

logging_level.png

从图中就可以解释为什么上面第一条logging没有记录到日志文件中了,因为INFO的级别比DEBUG大,而日志记录只会记录级别比INFO大或相等级别的日志。也就是说我们可以自己控制消息的级别,来保证重要的消息显示,或者说过滤掉一些不重要的日志,而且你还可以决定输出到哪里,输出的格式等等。不同等级一般适用于不同的用途,比如开发环境中,我们需要调试程序,通常需要看到具体详细的日志信息来定位问题;而生产环境中,我们就不需要太过于详细的日志,一般只需要异常、错误等级的日志信息,这样避免日志文件很大导致定位问题难,还可以减轻服务器的IO压力。

常见示例

import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)

# 创建 handler 输出到文件
handler = logging.FileHandler("file.log", mode='w')
handler.setLevel(logging.INFO)

# handler 输出到控制台
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# 创建 logging format
formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
handler.setFormatter(formatter)
ch.setFormatter(formatter)

# add the handlers to the logger
logger.addHandler(handler)
logger.addHandler(ch)

logger.info("hello, guoweikuang")
logger.debug("print to debug")
logger.error("error logging")
logger.warning("warning logging")
logger.critical("critical logging")

运行结果如下:

2018-04-11 09:30:25,354 - __main__ - INFO - hello, guoweikuang
2018-04-11 09:30:25,354 - __main__ - ERROR - error logging
2018-04-11 09:30:25,354 - __main__ - WARNING - warning logging
2018-04-11 09:30:25,354 - __main__ - CRITICAL - critical logging

logging模块有很多handler处理器,例如StreamHandler、RotatingFileHandler、TimedRotatingFileHandler等。

  • StreamHandler 可用来输出到控制台
  • RotatingFileHandler 基于文件大小切分日志, 防止一个日志文件过大
  • TimedRotatingFileHandler 基于时间间隔切分日志,防止一个日志文件过大

__name__ 作为logger对象名称

还有上面例子中getLogger(__name__)里面的__name__是什么作用呢?
这里贴一下官方文档的解释:

The name is potentially a period-separated hierarchical value, like foo.bar.baz 
(though it could also be just plain foo, for example). Loggers that are further 
down in the hierarchical list are children of loggers higher up in the list. 
For example, given a logger with a name of foo, loggers with names of foo.bar, 
foo.bar.baz, and foo.bam are all descendants of foo. The logger name hierarchy is 
analogous to the Python package hierarchy,and identical to it if you organise 
your loggers on a per-module basis using the recommended construction logging.getLogger(__name__). 
That’s because in a module, __name__ is the module’s name in the Python package namespace.

也就是说,logger对象名字的层级和python包的层级是相似的,并且如果你使用推荐的结构logging.getLogger(__name__)来管理你的loggers对象的话,那就与python包的层级结构是一模一样的。因为在一个模块中__name__是一个在python包中名字空间的模块的名称。
例如,你在模块 foo.bar.my_module 里调用 logging.getLogger(__name__),那么其实等价于 logging.getLogger('foo.bar.my_module')。这样做的目的是,你设置logger时候指定了foo包后,该包下的所有模块日志都是使用同一logger的配置,方便后期日志查看时清楚是那个模块的记录。

捕获异常,记录异常信息

# -*- coding: utf-8 -*-
import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

# handler 输出到控制台
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# 创建 logging format
formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
ch.setFormatter(formatter)

logger.addHandler(ch)


if __name__ == '__main__':
    try:
        open("/home/guoweikuang/fuck.log", 'rb')
    except (SystemExit, KeyboardInterrupt):
        raise

    except Exception as e:
        logger.error("failed to open file, ", exc_info=True)

运行结果如下:

2018-04-11 10:03:44,905 - __main__ - ERROR - failed to open file,
Traceback (most recent call last):
  File "logging_learn.py", line 20, in <module>
    open("/home/guoweikuang/fuck.log", 'rb')
IOError: [Errno 2] No such file or directory: '/home/guoweikuang/fuck.log'

指定了exc_info=True 参数后,traceback 信息将会被存入日志中,还有另外两个可设置参数,分别是stack_infoextra,其中stack_info 参数默认为False。如果为True,则将堆栈信息添加到日志记录消息中,包括实际的日志调用。第三个关键字参数是extra,可用于传递一个字典,用于填充为具有用户定义属性的日志记录事件创建的LogRecord的__dict__。具体了解请到官方文档查看。

未完待续。。。。。。。。。

推荐阅读更多精彩内容