python日志记录系列教程，内置logging模块（一）——直接使用logging模块的基础日志记录

前言：成熟的软件开发不可避免的要进行日志记录，python内置模块logging提供了强大的日志记录能力，本文将从多个角度，由浅入深的介绍logging的常见使用方法和一些基本概念，本此系列文章分为两篇，本文为系列文章第一篇，介绍实用logging模块进行基本的日志记录操作。本文主要都是直接使用 logging.xxxx() 的方式，这是最简单初步的日志记录，不涉及任何复杂的类和对象，这些将会在下一篇文章中来说明。

一、什么是日志记录

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

1.1 什么时候使用 Logging

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

你想要执行的任务	此任务最好的工具
对于命令行或程序的应用，结果显示在控制台。	print()，这是我们自己常用的，显示某一些信息，直接打印结果，但是比较低级
在对程序的普通操作发生时提交事件报告(比如：状态监控和错误调查)	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模块初识

import logging

logging.debug("this is debug.")
logging.info("this is info.")
logging.warning("this is warning.")  # 默认只会显示warning以及更严重的
logging.error("this is error.")
logging.critical("this is critical.")
'''
WARNING:root:this is warning.
ERROR:root:this is error.
CRITICAL:root:this is critical.
'''

二、logging模块的常规基础操作

2.1 logging日志记录的基本配置

函数原型如下：

logging.basicConfig(**kwargs)

该函数支持以下关键字参数。

格式	描述
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，可以重新指定，比如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 将日志写入文件

logging.basicConfig(filename="./write.logs",filemode="a",level=logging.INFO)

logging.debug("this is debug.")
logging.info("this is info.")    # 改变了默认的level，会记录info以及更严重的到日志文件
logging.warning("this is warning.")  
logging.error("this is error.")
logging.critical("this is critical.")

2.3 多个模块中使用日志记录

如果你的程序包含多个模块，这里有一个如何组织日志记录的示例:

# myapp.py
import logging
import mylib  # 自己定义的模块

def main():
    logging.basicConfig(filename='myapp.log', level=logging.INFO)
    logging.info('Started')
    mylib.do_something()
    logging.info('Finished')

if __name__ == '__main__':
    main()

# mylib.py
import logging

def do_something():
    logging.info('Doing something')

  如果你运行 myapp.py ，你应该在 myapp.log 中看到：

INFO:root:Started
INFO:root:Doing something
INFO:root:Finished

我们发现，不同模块中所记录的日志信息都被保存到了同一个日志文件里面了。

2.4 格式化输出以及记录相关的变量值到日志文件

前面有文章专门介绍了python中的字符串格式化的几种方法，包括使用百分号%、str.format、string.Template模板等方法，可以参考前面的文章：

python字符串格式化深入详解（四种方法）

所以，要定义自己的字符串输出格式，要记录相关的变量到字符串中，我们可以这样做。

要记录变量数据，请使用格式字符串作为事件描述消息，并将变量数据作为参数附加。 例如:

import logging
logging.warning('%s before you %s', 'Look', 'leap!')
a=100
b=200.0
logging.warning("the value of a is %d ,the value of b is %f .",a,b)
'''
WARNING:root:Look before you leap!
WARNING:root:the value of a is 100 ,the value of b is 200.000000 .
'''

如你所见，

logging日志记录的字符串格式化，将数据合并到字符串中所采用的方式是 百分号% 的形式，

但是如果我想要使用其他的字符串格式化的方法怎么办呢？就需要通过指定style参数来决定了，

style的取值可以是三个，即

• '%':这是默认的，即默认使用百分号%格式的字符串格式化方法；
• '{'：表示使用str.format()的字符串格式化方法；
• '$':表示使用string.Template的格式化方法；

为什么是默认使用百分号 % 格式化工具呢？主要是因为logging的出现时间比这两种格式化方法要早一些，但是并不是说完全不支持，现在完全有其他的方法让logging支持str.format()和string.Template()这些格式，只需要设置不同的style参数值即可。

三、logging模块的格式化设置以及时间格式化

当我们看之前的记录日志的时候，我们发现，记录的日志总是下面的格式，如下：

ERROR:root:this is error.

即所谓的：

日志类别严重程度：root：message

这样的格式，那么能不能进行更改呢？这个自然是可以的，怎么更改呢，如下：

3.1 消息显示的格式设置——basicConfig的 format 参数

要更改用于显示消息的格式，你需要指定要使用的格式:

import logging

# 通过设置format参数来实现消息的格式设置
logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.DEBUG)

logging.debug('This message should appear on the console')
logging.info('So should this')
logging.warning('And this, too')

这将输出：

DEBUG:This message should appear on the console
INFO:So should this
WARNING:And this, too

请注意，前面示例中出现的“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：创建日志记录的时间（以毫秒为单位）

借助于这些格式，我们可以自定义日志记录，比如显示时间：

import logging

logging.basicConfig(level=logging.INFO,filename='test.log',format="%(levelname)s:%(asctime)s:%(message)s")
logging.error("出现了错误")
logging.info("打印信息")
logging.warning("警告信息")
'''
ERROR:2020-06-05 14:21:59,597:出现了错误
INFO:2020-06-05 14:21:59,597:打印信息
WARNING:2020-06-05 14:21:59,598:警告信息
'''

这样，日志中除了记录消息等级、消息信息外，还会记录上消息创建的时间。

3.2 设置日志记录的时间显示的格式——basicConfig的datefmt参数

前面说了在日志记录中可以显示日志在创建的时候的时间，在上面的例子中，我们发现它默认的格式是如下：

2020-06-05 14:21:59,597

那我们可不可以更改时间显示的格式呢？这个自然是能的，

日期/时间显示的默认格式（如上所示）类似于 ISO8601 或 RFC 3339 。 如果你需要更多地控制日期/时间的格式，请为 basicConfig 提供 datefmt 参数，

需要格外注意的是：datefmt 参数的格式与 time.strftime() 支持的格式相同。

如下例所示:

import logging
logging.basicConfig(format='%(asctime)s %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p')
logging.warning('is when this event was logged.')
'''
12/12/2010 11:46:36 AM is when this event was logged.
'''

那到底有哪一些格式呢？可以参考官网：https://docs.python.org/zh-cn/3.7/library/time.html#time.strftime 

函数原型为：

time.strftime(format[, t])

转换一个元组或 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	时区名称（如果不存在时区，则不包含字符）。
%%	字面的 '%' 字符。

注释:

1. 当与 strptime() 函数一起使用时，如果使用 %I 指令来解析小时， %p 指令只影响输出小时字段。

2. 范围真的是 0 到 61 ；值 60 在表示 leap seconds 的时间戳中有效，并且由于历史原因支持值 61 。

3. 当与 strptime() 函数一起使用时， %U 和 %W 仅用于指定星期几和年份的计算。

下面是一个示例，一个与 RFC 2822 Internet电子邮件标准以兼容的日期格式。 

from time import gmtime, strftime
strftime("%a, %d %b %Y %H:%M:%S +0000", gmtime())
'''
'Thu, 28 Jun 2001 14:17:15 +0000'
'''

个人总结：

个人习惯使用的格式为，年月日，时分秒，星期数，如下：

%y 两位数的年份表示（00-99）
%Y 四位数的年份表示（000-9999）
%m 月份（01-12）
%d 月内中的一天（0-31）

%H 24小时制小时数（0-23）
%I 12小时制小时数（01-12）
%M 分钟数（00=59）
%S 秒（00-59）

%a 本地简化星期名称
%A 本地完整星期名称

四、日志记录的堆栈追踪

前面都是一些最简单的日志记录操作与格式设置，但是我们在编写python代码的时候，往往涉及到多个函数之间的调用，我们需要跟踪函数调用的堆栈信息，这样才能定位到到底是哪一个函数的哪一个位置出现了错误，这才更加合理。

再次回顾日志记录实际上是做一件什么事？

• 即当满足什么条件的时候、或者是当某一件事情发生的时候，开始记录日志，明白这思想很重要
• 现在我们要做的就是，在程序执行出发了异常的时候，就开始记录日志，并且记录程序的堆栈信息，思想是相通的，只不过条件现在变成了，在异常发生的时候。

首先其实我们发现，logging.xxx()的几个函数（info、debug、warning、error、critical）他们的参数格式是一样的，以error为例：

logging.error(msg: Any, 
        *args: Any, 
        exc_info: Union[None, bool, Union[Tuple[type, BaseException, TracebackType], Tuple[None, None, None]], BaseException], 
        stack_info: bool, 
        extra: Dict[str, Any], 
        **kwargs: Any) -> None

有两个非常关键的参数，它们是

• stack_info:
• exc_info:

下面将分别来说明这两个参数各自的作用

（1）exc_info=True——出现异常时记录堆栈调用信息

先从一个简单的函数调用例子来看

有一个math_func.py模块，实现了两个函数，如下：

# math_func.py
def add(x,y):
    return x+y

def divide(x,y):
    return x/y

然后有一个operation_func.py模块，再进一步对这两个函数进行包装，以便进行选择性的调用哪一个函数，如下：

# operation_func.py
from math_func import add,divide

def math_operation(x,y,name = "add"):
    if name=="add":
        return add(x,y)
    elif name=="divide":
        return divide(x,y)
    else:
        return 0

最后再主模块main.py里面进行调用，如下：

main.py
import logging

from operation_func import math_operation
# 记录到日志文件
logging.basicConfig(filename="./math.logs",filemode="a",level=logging.INFO)

try:
    result = math_operation(100,0,"divide")
    print(result)

except Exception as e:
    # 当初触发异常得时候才进行日志记录，并且记录堆栈调用信息
    logging.error("error accured when execute 'math_operation'", exc_info=True)

运行之后，打开日志文件，得到如下的结果

ERROR:root:error accured when execute 'math_operation'
Traceback (most recent call last):
  File "c:\Users\Administrator\Desktop\python_logging\main.py", line 9, in <module>
    result = math_operation(100,0,"divide")
  File "c:\Users\Administrator\Desktop\python_logging\operation_func.py", line 7, in math_operation
    return divide(x,y)
  File "c:\Users\Administrator\Desktop\python_logging\math_func.py", line 5, in divide
    return x/y
ZeroDivisionError: division by zero

从上面我们发现，错误信息以及堆栈信息全部清楚地记录在了里面。这对于程序调试是至关重要的。

以上就是出现错误的时候logging堆栈追踪的全部实现，一般的调用模板如下：

try:
    # 函数的调用
except Exception as e:
    logging.error("执行xxx函数报错", exc_info=True)

前面提到了由两个参数，那么这两个参数到底有什么区别呢？现总结如下：

• exe_info参数：在搜索异常处理程序时，跟踪异常而打开的堆栈帧的信息，这个是专门针对异常发生的时候记录日志的；
• stack_info参数：默认为 False。如果为 True，则将堆栈信息添加到日志消息中，包括实际的日志调用。请注意，这与通过指定 exc_info 显示的堆栈信息不同：他主要是从堆栈底部到当前线程中的日志记录调用的堆栈帧，什么意思呢？即使在未引发任何异常的情况下，也可以显示如何到达代码中的特定点。堆栈帧在标题行（即每一句日志记录行）之后打印：
• stack_info：简单来说就是，根据每一个日志记录语句所在的位置，打印出这一句日志记录信息，并且在后面显示这句日志记录所在的函数堆栈的位置是在哪里。

（2）stack_info=True——记录每一句日志记录语句所在代码中的堆栈信息

参考下面的例子：

def a(x,y):
    logging.warning("y can't is 0.",stack_info=True)
    return x+y

def b(x,y):
    logging.warning("execute a function.",stack_info=True)
    return a(x,y)

logging.warning("execute b function.",stack_info=True)

# 调用函数
b(200,100)

调用b函数，b中有调用a函数，得到下面的日志信息：

WARNING:root:execute b function.  # 第一条日志记录的位置，main.py中的24行
Stack (most recent call last):
  File "c:\Users\Administrator\Desktop\python_logging\main.py", line 24, in <module>
    logging.warning("execute b function.",stack_info=True)



WARNING:root:execute a function.  # 第二条日志记录的位置
Stack (most recent call last):
  File "c:\Users\Administrator\Desktop\python_logging\main.py", line 27, in <module>
    b(200,100)
  File "c:\Users\Administrator\Desktop\python_logging\main.py", line 21, in b
    logging.warning("execute a function.",stack_info=True)


  
WARNING:root:y can't is 0.       # 第三条日志记录的位置
Stack (most recent call last):
  File "c:\Users\Administrator\Desktop\python_logging\main.py", line 27, in <module>
    b(200,100)
  File "c:\Users\Administrator\Desktop\python_logging\main.py", line 22, in b
    return a(x,y)
  File "c:\Users\Administrator\Desktop\python_logging\main.py", line 17, in a
    logging.warning("y can't is 0.",stack_info=True)

从上面可以看出，stack_info它会详细记录每一条日志打印语句所在的位置，然后在日志信息后面加以显示，这跟exe_info是有显著区别的。

（3）补充参数说明——extra参数的说明

前面的3.1中在说明日志记录的格式的时候，给出了很多预先定义好的格式，比如

• %(asctime)s：日志创建时的普通时间；
• %(created)f：日志创建时的时间（由time.time()返回）；
• %(filename)s：文件名；

等等，有时候我们想定义自己的信息怎么办呢？可以采用下面的方式，extra参数接受的参数是一个字典类型，如下例子所示：

FORMAT = '%(asctime)s : %(clientip)s : %(user)s : %(work)s : %(message)s'
logging.basicConfig(format=FORMAT)
d = {'clientip': '192.168.0.1', 'user': 'my_zoe', 'work': 'student'}
logging.warning('Protocol problem: %s', 'connection reset', extra=d)
'''
2020-06-05 16:32:06,020 : 192.168.0.1 : my_zoe : student : Protocol problem: connection reset
'''

我们发现，自己定义的clientip、user、work都显示了出来！

实际上，上面的这种操作称之为，向日志输出中添加上下文信息

除了传递给日志记录函数的参数外，有时候我们还想在日志输出中包含一些额外的上下文信息。比如，在一个网络应用中，可能希望在日志中记录客户端的特定信息，如：远程客户端的IP地址和用户名。这里我们来介绍以下几种实现方式：

• 通过向日志记录函数传递一个extra参数引入上下文信息
• 使用LoggerAdapters引入上下文信息
• 使用Filters引入上下文信息

具体说明请参考博文 《Python之向日志输出中添加上下文信息》

关于Python logging的更多高级用法，请参考文档<< Logging CookBook >>。