日志模块logging


1 什么是日志?

日志是对软件执行时所发生事件的一种追踪方式。软件开发人员对他们的代码添加日志调用,借此来指示某事件的发生。一个事件通过一些包含变量数据的描述信息来描述(比如:每个事件发生时的数据都是不同的)。开发者还会区分事件的重要性,重要性也被称为 等级 或 严重性,也即日志级别。

在工作当中,我们写的程序必须要有记录日志的功能,以便在出现问题时能够更快的定位到问题。而日志是有级别的,级别相关说明如下表:

log level 描述
debug 程序或系统的调试信息
info 一般信息
notice 不影响正常功能,需要注意的消息
warning/warn 可能影响系统功能,需要提醒用户的重要事件
err/error 错误信息
crit 紧急,比较严重的
alert 必须马上处理的
emerg/panic 会导致系统不可用的
* *表示所有的日志级别
none 与*相反,表示啥也没有

以上日志级别从低到高排序,级别越低,信息越详细。

2 什么时候使用日志

对于简单的日志使用来说日志功能提供了一系列便利的函数。它们是 debug(),info(),warning(),error() 和 critical()。想要决定何时使用日志,请看下表,其中显示了对于每个通用任务集合来说最好的工具。

你想要执行的任务 此任务的最好工具
对于命令行或程序的应用,结果显示在控制台 print()
当有诊断目的需要详细输出信息时 logging.debug()函数
在对程序的普通操作发生时提交事件报告
(比如:状态监控和错误调查)
logging.info()函数
提出一个警告信息基于一个特殊的运行时事件 warnings.warn()位于代码库中,该事件是可以避免的,需要修改客户端应用以消除告警
logging.warning()不需要修改客户端应用,但是该事件还是需要引起关注
对一个特殊的运行时事件报告错误 引发异常
报告错误而不引发异常(如在长时间运行中的服务端进程的错误处理) logging.error(),
logging.exception()或
logging.critical()分别适用于特定的错误及应用领域

3 logging模块

3.1 logging日志级别

日志功能应以所追踪事件级别或严重性而定。各级别适用性如下(以严重性递增):

级别 何时使用
DEBUG 细节信息,仅当诊断问题时适用
INFO 确认程序按预期运行
WARNING 表明有已经或即将发生的意外(例如:磁盘空间不足)。程序仍按预期进行
ERROR 由于严重的问题,程序的某些功能已经不能正常执行
CRITICAL 严重的错误,表明程序已不能继续执行

我们来看一个例子:

import logging
logging.debug('debug message')
logging.info('info message')
logging.warning('warning message')
logging.error('error message')
logging.critical('critical message')

其输出如下:

WARNING:root:warning message
ERROR:root:error message
CRITICAL:root:critical message

由此可见,默认情况下Python的logging模块将日志打印到了标准输出中,且只显示了大于等于WARNING级别的日志,默认的日志格式为日志级别:Logger名称:用户输出消息

默认的级别是 WARNING ,意味着只会追踪该级别及以上的事件,除非更改日志配置。

所追踪事件可以以不同形式处理。最简单的方式是输出到控制台。另一种常用的方式是写入磁盘文件。

3.2 记录日志到文件

一种非常常见的情况是将日志事件记录到文件,让我们继续往下看。请确认启动新的Python 解释器,不要在上一个环境中继续操作:

import logging

logging.basicConfig(filename='example.log',level=logging.DEBUG)

logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')

现在,如果我们打开日志文件,我们应当能看到日志信息:

DEBUG:root:This message should go to the log file
INFO:root:So should this
WARNING:root:And this, too

该示例同样展示了如何设置日志追踪级别的阈值。该示例中,由于我们设置的阈值是 DEBUG,所有信息全部打印。

如果多次运行上述脚本,则连续运行的消息将追加到文件 example.log 。 如果你希望每次运行重新开始,而不是记住先前运行的消息,则可以通过将上例中的调用更改为来指定 filemode 参数:

import logging

logging.basicConfig(filename='example.log', filemode='w', level=logging.DEBUG)

logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')

输出将与之前相同,但不再追加进日志文件,因此早期运行的消息将丢失。

3.3 灵活配置日志级别、日志格式与输出位置

import logging

logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s',
                    datefmt='%a, %d %b %Y %H:%M:%S',
                    filename='/tmp/test.log',
                    filemode='w')

logging.debug('debug message')
logging.info('info message')
logging.warning('warning message')
logging.error('error message')
logging.critical('critical message')

输出如下:

➜  ~ cat /tmp/test.log
Thu, 15 Aug 2019 17:48:20 hello.py[line:9] DEBUG debug message
Thu, 15 Aug 2019 17:48:20 hello.py[line:10] INFO info message
Thu, 15 Aug 2019 17:48:20 hello.py[line:11] WARNING warning message
Thu, 15 Aug 2019 17:48:20 hello.py[line:12] ERROR error message
Thu, 15 Aug 2019 17:48:20 hello.py[line:13] CRITICAL critical message

可见在logging.basicConfig()函数中可通过具体参数来更改logging模块默认行为,可用参数有

参数 描述
filename 用指定的文件名创建FiledHandler,这样日志会被存储在指定的文件中
filemode 文件打开方式,在指定了filename时使用这个参数,默认值为a
format 指定handler使用的日志显示格式
datefmt 指定日期时间格式
level 设置rootlogger的日志级别
stream 用指定的stream创建StreamHandler。可以指定输出到sys.stderr,sys.stdout或文件(f=open(’test.log’,’w’)),默认为sys.stderr。若同时列出了filename和stream两个参数,则stream参数会被忽略。

format参数中可能用到的格式化类型

格式化类型 描述
%(name)s Logger的名字
%(levelno)s 数字形式的日志级别
%(levelname)s 文本形式的日志级别
%(pathname)s 调用日志输出函数的模块的完整路径名,可能没有
%(filename)s 调用日志输出函数的模块的文件名
%(module)s 调用日志输出函数的模块名
%(funcName)s 调用日志输出函数的函数名
%(lineno)d 调用日志输出函数的语句所在的代码行
%(created)f 当前时间,用UNIX标准的表示时间的浮点数表示
%(relativeCreated)d 输出日志信息时的,自Logger创建以来的毫秒数
%(asctime)s 字符串形式的当前时间。默认格式是’2019-08-15 17:00:00,896’
逗号后面的是毫秒。
%(thread)d 线程ID。可能没有
%(threadName)s 线程名。可能没有
%(process)d 进程ID。可能没有
%(message)s 用户输出的消息

3.4 logger对象

logging 采用模块化方法,并提供几类组件:记录器、处理程序、过滤器和格式化程序

  • 记录器(Logger)提供了应用程序代码可直接使用的接口
  • 处理程序(Handler)将日志记录(由记录器创建)发送到适当的目标
  • 过滤器(Filter)提供了过滤日志信息的方法,用于确定要输出的日志记录
  • 格式化程序(Formatter)指定最终输出中日志记录的样式

Logger是一个树形层级结构,输出信息之前都要获得一个Logger(如果没有显示的获取则自动创建并使用root Logger)。

logger = logging.getLogger()返回一个默认的Logger也即root Logger,并应用默认的日志级别、Handler和Formatter设置。

import logging

logger = logging.getLogger()
print(logger)       # <RootLogger root (WARNING)>

当然也可以通过Logger.setLevel(level)指定最低的日志级别,可用的日志级别有

  • logging.DEBUG
  • logging.INFO
  • logging.WARNING
  • logging.ERROR
  • logging.CRITICAL

Logger.debug()、Logger.info()、Logger.warning()、Logger.error()、Logger.critical()输出不同级别的日志,只有日志等级大于或等于设置的日志级别的日志才会被输出。

我们先来看一个例子:

import logging

logger = logging.getLogger()

# 创建一个handler,用于写入日志文件
fh = logging.FileHandler('test.log')

# 再创建一个handler,用于输出到控制台
ch = logging.StreamHandler()

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

fh.setFormatter(formatter)
ch.setFormatter(formatter)

logger.addHandler(fh)   # logger对象可以添加多个fh和ch对象
logger.addHandler(ch)

logger.debug('logger debug message')
logger.info('logger info message')
logger.warning('logger warning message')
logger.error('logger error message')
logger.critical('logger critical message')

只输出了:

2019-08-21 17:55:39,958 - root - WARNING - logger warning message
2019-08-21 17:55:39,959 - root - ERROR - logger error message
2019-08-21 17:55:39,959 - root - CRITICAL - logger critical message

从这个输出可以看出logger = logging.getLogger()返回的Logger名为root。这里没有用logger.setLevel(logging.Debug)显示的为logger设置日志级别,所以使用默认的日志级别WARNIING,故结果只输出了大于等于WARNIING级别的信息。

如果我们再创建两个logger对象:

import logging

logger = logging.getLogger()
# 创建一个handler,用于写入日志文件
fh = logging.FileHandler('test.log')

# 再创建一个handler,用于输出到控制台
ch = logging.StreamHandler()

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

fh.setFormatter(formatter)
ch.setFormatter(formatter)

logger.addHandler(fh)   # logger对象可以添加多个fh和ch对象
logger.addHandler(ch)

logger.debug('logger debug message')
logger.info('logger info message')
logger.warning('logger warning message')
logger.error('logger error message')
logger.critical('logger critical message')

##################################################
logger1 = logging.getLogger('mylogger')
logger1.setLevel(logging.DEBUG)

logger2 = logging.getLogger('mylogger')
logger2.setLevel(logging.INFO)

logger1.addHandler(fh)
logger1.addHandler(ch)

logger2.addHandler(fh)
logger2.addHandler(ch)

logger1.debug('logger1 debug message')
logger1.info('logger1 info message')
logger1.warning('logger1 warning message')
logger1.error('logger1 error message')
logger1.critical('logger1 critical message')

logger2.debug('logger2 debug message')
logger2.info('logger2 info message')
logger2.warning('logger2 warning message')
logger2.error('logger2 error message')
logger2.critical('logger2 critical message')

结果输出如下:

2019-08-21 18:05:39,037 - root - WARNING - logger warning message
2019-08-21 18:05:39,038 - root - ERROR - logger error message
2019-08-21 18:05:39,038 - root - CRITICAL - logger critical message
2019-08-21 18:05:39,038 - mylogger - INFO - logger1 info message
2019-08-21 18:05:39,038 - mylogger - INFO - logger1 info message
2019-08-21 18:05:39,039 - mylogger - WARNING - logger1 warning message
2019-08-21 18:05:39,039 - mylogger - WARNING - logger1 warning message
2019-08-21 18:05:39,039 - mylogger - ERROR - logger1 error message
2019-08-21 18:05:39,039 - mylogger - ERROR - logger1 error message
2019-08-21 18:05:39,040 - mylogger - CRITICAL - logger1 critical message
2019-08-21 18:05:39,040 - mylogger - CRITICAL - logger1 critical message
2019-08-21 18:05:39,041 - mylogger - INFO - logger2 info message
2019-08-21 18:05:39,041 - mylogger - INFO - logger2 info message
2019-08-21 18:05:39,041 - mylogger - WARNING - logger2 warning message
2019-08-21 18:05:39,041 - mylogger - WARNING - logger2 warning message
2019-08-21 18:05:39,041 - mylogger - ERROR - logger2 error message
2019-08-21 18:05:39,041 - mylogger - ERROR - logger2 error message
2019-08-21 18:05:39,041 - mylogger - CRITICAL - logger2 critical message
2019-08-21 18:05:39,041 - mylogger - CRITICAL - logger2 critical message

这里有两个问题:

  1. 我们明明通过logger1.setLevel(logging.DEBUG)将logger1的日志级别设置为了DEBUG,为何显示的时候没有显示出DEBUG级别的日志信息,而是从INFO级别的日志开始显示呢?
  2. 为什么logger1、logger2对应的每个输出分别显示两次?

问题1原因:
logger1 和 logger2 对应的是同一个 Logger 实例,只要logging.getLogger(name) 中名称参数 name 相同则返回的Logger实例就是同一个,且仅有一个,即name与Logger实例一一对应。在logger2实例中通过logger2.setLevel(logging.INFO)设置 mylogger 的日志级别为logging.INFO,所以最后logger1的输出遵从了后来设置的日志级别。

问题2原因:
因为我们通过logger = logging.getLogger()显示的创建了root Logger,而logger1 = logging.getLogger('mylogger')创建了root Logger的子Logger(root.)mylogger, logger2同理。而子Logger会将消息分发给他的handler进行处理也会传递给所有的祖先Logger处理。

将以下两行注释掉,我们再来看效果

# logger.addHandler(fh)
# logger.addHandler(ch)

结果输出如下:

logger warning message
logger error message
logger critical message
2019-08-21 18:17:07,576 - mylogger - INFO - logger1 info message
2019-08-21 18:17:07,576 - mylogger - WARNING - logger1 warning message
2019-08-21 18:17:07,577 - mylogger - ERROR - logger1 error message
2019-08-21 18:17:07,577 - mylogger - CRITICAL - logger1 critical message
2019-08-21 18:17:07,577 - mylogger - INFO - logger2 info message
2019-08-21 18:17:07,577 - mylogger - WARNING - logger2 warning message
2019-08-21 18:17:07,577 - mylogger - ERROR - logger2 error message
2019-08-21 18:17:07,577 - mylogger - CRITICAL - logger2 critical message

因为我们注释了root logger对象显示的位置,所以才用了默认方式,即标准输出方式。因为它的父级没有设置文件显示方式,所以在这里只打印了一次。

而子logger可逐层继承来自祖先的日志级别、Handler、Filter设置,也可以通过Logger.setLevel(level)、Logger.addHandler(handler)、Logger.removeHandler(handler)、Logger.addFilter(filter)、Logger.removeFilter(filter)。设置自己特别的日志级别、Handler、Filter。若不设置则使用继承来的值。