前言:成熟的软件开发不可避免的要进行日志记录,python内置模块logging提供了强大的日志记录能力,本文将从多个角度,由浅入深的介绍logging的常见使用方法和一些基本概念,本此系列文章分为两篇,本文为系列文章第一篇,介绍实用logging模块进行基本的日志记录操作。本文主要都是直接使用 logging.xxxx() 的方式,这是最简单初步的日志记录,不涉及任何复杂的类和对象,这些将会在下一篇文章中来说明。
一、什么是日志记录
所谓的日志记录就是对软件执行时所发生事件的一种追踪方式。软件开发人员对他们的代码添加日志调用,借此来指示某事件的发生。一个事件通过一些包含变量数据的描述信息来描述(比如:每个事件发生时的数据都是不同的)。开发者还会区分事件的重要性,重要性也被称为 等级 或 严重性
1.1 什么时候使用 Logging
对于简单的日志使用来说日志功能提供了一系列便利的函数。它们是 debug()
,info()
,warning()
,error()
和 critical()
。想要决定何时使用日志,请看下表,其中显示了对于每个通用任务集合来说最好的工具。
你想要执行的任务 | 此任务最好的工具 |
---|---|
对于命令行或程序的应用,结果显示在控制台。 | print(),这是我们自己常用的,显示某一些信息,直接打印结果,但是比较低级 |
在对程序的普通操作发生时提交事件报告(比如:状态监控和错误调查) | http://logging.info() 函数(当有诊断目的需要详细输出信息时使用 logging.debug() 函数) |
提出一个警告信息基于一个特殊的运行时事件 | warnings.warn() 位于代码库中,该事件是可以避免的,需要修改客户端应用以消除告警 logging.warning() 不需要修改客户端应用,但是该事件还是需要引起关注 |
对一个特殊的运行时事件报告错误 | 引发异常 |
报告错误而不引发异常(如在长时间运行中的服务端进程的错误处理) | logging.error(), logging.exception() 或 logging.critical() 分别适用于特定的错误及应用领域 |
1.2 日志记录的5个等级
日志功能应以所追踪事件级别或严重性而定。各级别适用性如下(以严重程度递增):
级别 | 何时使用 |
---|---|
DEBUG | 细节信息,仅当诊断问题时适用。 |
INFO | 确认程序按预期运行,但是要提示一些相关的信息, |
WARNING | 表明有已经或即将发生的意外(例如:磁盘空间不足)。程序仍按预期进行,但是会有警告,可能出现什么错误。 |
ERROR | 由于严重的问题,程序的某些功能已经不能正常执行 |
CRITICAL | 严重的错误,表明程序已不能继续执行 |
以及严重程度排序为:
debug<info<warning<error<critical
默认的级别是``WARNING``,意味着只会追踪该级别以及该级别以上的事件,当然我们可以更改日志配置,重新设置默认值。
另外,我们需要查看所记录的日志,一般日志输出会有两种形式,
所追踪事件可以以不同形式处理。最简单的方式是输出到控制台。另一种常用的方式是写入磁盘文件。默认情况下,日志输出信息会显示在控制台上。下面也会以这两种方式来加以说明。
1.3 logging模块初识
二、logging模块的常规基础操作
2.1 logging日志记录的基本配置
函数原型如下:
该函数支持以下关键字参数。
格式 | 描述 |
---|---|
filename | 使用指定的文件名而不是 StreamHandler 创建 FileHandler。在需要将日志写入到日志文件的时候使用 |
filemode | 日志文件的写入模式.,默认的是"a",默认是追加的方式,若要每一次都重新写入,则使用"w" |
format | 使用的指定格式字符串。 |
datefmt | 时间格式的字符串 |
style | If format is specified, use this style for the format string. One of '%', '{' or '$' for printf-style, str.format() or string.Template respectively. Defaults to '%'. 字符串的格式化方式的选择,参考下面的style参数详解。 |
level | 设置根记录器级别去指定 level.默认的是warning,可以重新指定,比如http://logging.INFO logging.DEBUG 等等, |
stream | Use the specified stream to initialize the StreamHandler. Note that this argument is incompatible with filename - if both are present, a ValueError is raised.(后面用到了再说) |
handlers | If specified, this should be an iterable of already created handlers to add to the root logger. Any handlers which don't already have a formatter set will be assigned the default formatter created in this function. Note that this argument is incompatible with filename or stream - if both are present, a ValueError is raised.(后面用到了再说) |
对basicConfig的调用应该在 debug、info等函数的前面。因为它被设计为一次性的配置,只有第一次调用会进行操作,随后的调用不会产生有效操作。
2.2 将日志写入文件
2.3 多个模块中使用日志记录
如果你的程序包含多个模块,这里有一个如何组织日志记录的示例:
如果你运行 myapp.py ,你应该在 myapp.log 中看到:
我们发现,不同模块中所记录的日志信息都被保存到了同一个日志文件里面了。
2.4 格式化输出以及记录相关的变量值到日志文件
前面有文章专门介绍了python中的字符串格式化的几种方法,包括使用百分号%、str.format、string.Template模板等方法,可以参考前面的文章:
python字符串格式化深入详解(四种方法)
所以,要定义自己的字符串输出格式,要记录相关的变量到字符串中,我们可以这样做。
要记录变量数据,请使用格式字符串作为事件描述消息,并将变量数据作为参数附加。 例如:
如你所见,
logging日志记录的字符串格式化,将数据合并到字符串中所采用的方式是 百分号% 的形式,
但是如果我想要使用其他的字符串格式化的方法怎么办呢?就需要通过指定style参数来决定了,style的取值可以是三个,即
- '%':这是默认的,即默认使用百分号%格式的字符串格式化方法;
- '{':表示使用str.format()的字符串格式化方法;
- '$':表示使用string.Template的格式化方法;
为什么是默认使用百分号 % 格式化工具呢?主要是因为logging的出现时间比这两种格式化方法要早一些,但是并不是说完全不支持,现在完全有其他的方法让logging支持str.format()和string.Template()这些格式,只需要设置不同的style参数值即可。
三、logging模块的格式化设置以及时间格式化
当我们看之前的记录日志的时候,我们发现,记录的日志总是下面的格式,如下:
即所谓的:
日志类别严重程度:root:message
这样的格式,那么能不能进行更改呢?这个自然是可以的,怎么更改呢,如下:
3.1 消息显示的格式设置——basicConfig的 format 参数
要更改用于显示消息的格式,你需要指定要使用的格式:
这将输出:
请注意,前面示例中出现的“root”已消失。
对于可以出现在格式字符串中的全部内容,你可以参考以下文档 LogRecord 属性 ,在后面的系列文章第二篇中,还会深入探讨日志记录的高级主题,来说明的。
下面是常见的格式设置的字段标识:
- %(asctime)s:日志创建时的普通时间;
- %(created)f:日志创建时的时间(由time.time()返回);
- %(filename)s:文件名;
- %(funcName)s:调用日志记录的函数;
- %(levelname)s:日志消息的文本级别;
- %(levelno)s:日志消息的数字级别;
- %(lineno)d:调用日志消息的行号;
- %(msecs)d:创建时间的毫秒部分;
- %(message)s:日志消息;
- %(name)s:日志器的名称;
- %(pathname)s:记录日志的源文件的路径名;
- %(process)d:进程ID;
- %(processName)s:进程名;
- %(thread)d:线程ID;
- %(threadName)s:线程名;
- %(relativeCreated)d:创建日志记录的时间(以毫秒为单位)
借助于这些格式,我们可以自定义日志记录,比如显示时间:
这样,日志中除了记录消息等级、消息信息外,还会记录上消息创建的时间。
3.2 设置日志记录的时间显示的格式——basicConfig的datefmt参数
那我们可不可以更改时间显示的格式呢?这个自然是能的,
日期/时间显示的默认格式(如上所示)类似于 ISO8601 或 RFC 3339 。 如果你需要更多地控制日期/时间的格式,请为 basicConfig
提供 datefmt 参数,
需要格外注意的是:datefmt 参数的格式与 time.strftime()
支持的格式相同。
如下例所示:
那到底有哪一些格式呢?可以参考官网:https://docs.python.org/zh-cn/3.7/library/time.html#time.strftime
函数原型为:
转换一个元组或 struct_time
表示的由 gmtime()
或 localtime()
返回的时间到由 format 参数指定的字符串。如果未提供 t ,则使用由 localtime()
返回的当前时间。 format 必须是一个字符串。如果 t 中的任何字段超出允许范围,则引发 ValueError
。
0是时间元组中任何位置的合法参数;如果它通常是非法的,则该值被强制改为正确的值。
以下指令可以嵌入 format 字符串中。它们显示时没有可选的字段宽度和精度规范,并被 strftime()
结果中的指示字符替换:
指令 | 含义 | 注释 |
---|---|---|
%a | 本地化的缩写星期中每日的名称。 | |
%A | 本地化的星期中每日的完整名称。 | |
%b | 本地化的月缩写名称。 | |
%B | 本地化的月完整名称。 | |
%c | 本地化的适当日期和时间表示。 | |
%d | 十进制数 [01,31] 表示的月中日。 | |
%H | 十进制数 [00,23] 表示的小时(24小时制)。 | |
%I | 十进制数 [01,12] 表示的小时(12小时制)。 | |
%j | 十进制数 [001,366] 表示的年中日。 | |
%m | 十进制数 [01,12] 表示的月。 | |
%M | 十进制数 [00,59] 表示的分钟。 | |
%p | 本地化的 AM 或 PM 。 | (1) |
%S | 十进制数 [00,61] 表示的秒。 | (2) |
%U | 十进制数 [00,53] 表示的一年中的周数(星期日作为一周的第一天)作为。在第一个星期日之前的新年中的所有日子都被认为是在第0周。 | (3) |
%w | 十进制数 [0(星期日),6] 表示的周中日。 | |
%W | 十进制数 [00,53] 表示的一年中的周数(星期一作为一周的第一天)作为。在第一个星期一之前的新年中的所有日子被认为是在第0周。 | (3) |
%x | 本地化的适当日期表示。 | |
%X | 本地化的适当时间表示。 | |
%y | 十进制数 [00,99] 表示的没有世纪的年份。 | |
%Y | 十进制数表示的带世纪的年份。 | |
%z | 时区偏移以格式 +HHMM 或 -HHMM 形式的 UTC/GMT 的正或负时差指示,其中H表示十进制小时数字,M表示小数分钟数字 [-23:59, +23:59] 。 | |
%Z | 时区名称(如果不存在时区,则不包含字符)。 | |
%% | 字面的 '%' 字符。 |
注释:
- 当与
strptime()
函数一起使用时,如果使用%I
指令来解析小时,%p
指令只影响输出小时字段。 - 范围真的是
0
到61
;值60
在表示 leap seconds 的时间戳中有效,并且由于历史原因支持值61
。 - 当与
strptime()
函数一起使用时,%U
和%W
仅用于指定星期几和年份的计算。
下面是一个示例,一个与 RFC 2822 Internet电子邮件标准以兼容的日期格式。
个人总结:
个人习惯使用的格式为,年月日,时分秒,星期数,如下:
四、日志记录的堆栈追踪
前面都是一些最简单的日志记录操作与格式设置,但是我们在编写python代码的时候,往往涉及到多个函数之间的调用,我们需要跟踪函数调用的堆栈信息,这样才能定位到到底是哪一个函数的哪一个位置出现了错误,这才更加合理。
再次回顾日志记录实际上是做一件什么事?
- 即当满足什么条件的时候、或者是当某一件事情发生的时候,开始记录日志,明白这思想很重要
- 现在我们要做的就是,在程序执行出发了异常的时候,就开始记录日志,并且记录程序的堆栈信息,思想是相通的,只不过条件现在变成了,在异常发生的时候。
首先其实我们发现,http://logging.xxx()的几个函数(info、debug、warning、error、critical)他们的参数格式是一样的,以error为例:
有两个非常关键的参数,它们是
- stack_info:
- exc_info:
下面将分别来说明这两个参数各自的作用
(1)exc_info=True——出现异常时记录堆栈调用信息
先从一个简单的函数调用例子来看
有一个math_func.py模块,实现了两个函数,如下:
然后有一个operation_func.py模块,再进一步对这两个函数进行包装,以便进行选择性的调用哪一个函数,如下:
最后再主模块main.py里面进行调用,如下:
运行之后,打开日志文件,得到如下的结果
从上面我们发现,错误信息以及堆栈信息全部清楚地记录在了里面。这对于程序调试是至关重要的。
以上就是出现错误的时候logging堆栈追踪的全部实现,一般的调用模板如下:
前面提到了由两个参数,那么这两个参数到底有什么区别呢?现总结如下:
- exe_info参数:在搜索异常处理程序时,跟踪异常而打开的堆栈帧的信息,这个是专门针对异常发生的时候记录日志的;
- stack_info参数:默认为
False
。如果为True
,则将堆栈信息添加到日志消息中,包括实际的日志调用。请注意,这与通过指定 exc_info 显示的堆栈信息不同:他主要是从堆栈底部到当前线程中的日志记录调用的堆栈帧,什么意思呢?即使在未引发任何异常的情况下,也可以显示如何到达代码中的特定点。堆栈帧在标题行(即每一句日志记录行)之后打印: - stack_info:简单来说就是,根据每一个日志记录语句所在的位置,打印出这一句日志记录信息,并且在后面显示这句日志记录所在的函数堆栈的位置是在哪里。
(2)stack_info=True——记录每一句日志记录语句所在代码中的堆栈信息
参考下面的例子:
调用b函数,b中有调用a函数,得到下面的日志信息:
从上面可以看出,stack_info它会详细记录每一条日志打印语句所在的位置,然后在日志信息后面加以显示,这跟exe_info是有显著区别的。
(3)补充参数说明——extra参数的说明
前面的3.1中在说明日志记录的格式的时候,给出了很多预先定义好的格式,比如
- %(asctime)s:日志创建时的普通时间;
- %(created)f:日志创建时的时间(由time.time()返回);
- %(filename)s:文件名;
等等,有时候我们想定义自己的信息怎么办呢?可以采用下面的方式,extra参数接受的参数是一个字典类型,如下例子所示:
我们发现,自己定义的clientip、user、work都显示了出来!
实际上,上面的这种操作称之为,向日志输出中添加上下文信息
除了传递给日志记录函数的参数外,有时候我们还想在日志输出中包含一些额外的上下文信息。比如,在一个网络应用中,可能希望在日志中记录客户端的特定信息,如:远程客户端的IP地址和用户名。这里我们来介绍以下几种实现方式:
- 通过向日志记录函数传递一个
extra
参数引入上下文信息 - 使用LoggerAdapters引入上下文信息
- 使用Filters引入上下文信息
具体说明请参考博文 《Python之向日志输出中添加上下文信息》
关于Python logging的更多高级用法,请参考文档<< Logging CookBook >>。