还在用 print？试一试 logging 的强大！

最新推荐文章于 2024-02-21 11:19:25 发布

IT农民工1

最新推荐文章于 2024-02-21 11:19:25 发布

阅读量488

点赞数 1

原文链接：https://www.aiyc.top/archives/515.html

版权

作者：AI悦创

来源：AI悦创

你好，我是悦创。

这次呢？我给大家带来了 logging 的用法，这也是为以后我分享案例做准备，因为以后我的代码不会经常使用 print 来做命令行输出提示，那真的太 low 了，但不能否认，我用了 print 好久而且貌似还挺满足的，可是当自己的代码放在实际的工程开发之中，或者大佬面前根本不是入眼了，这还真不能怪那些大佬或者实际工作需求高，而是我们看到 “烂代码” 的时候，表示一秒我都不想在这样的代码上多浪费时间，比如该换行的不换行、变量的命名各种各样、函数名也是，或者赋值符号两边不加空格、不符合软件工程规范：高内聚低耦合啥的，这类还有很多，培训班出来的有很大一部分都这样，这么说不是没有原因的，培训班老师自己偷懒或者本身就不会，写代码的时候不注意规范，但至少提一下吧！

这或许就是我个人的代码洁癖， 「有些东西是要符合规范的，这里不是要挑战整个培训行业，毕竟存在了这么久的培训含义是有它的道理，」 而是想给大家提个醒：做教育的，是给大部分小白来教的（也就是割韭菜），不要为了便利而把整体的规范落下。「技术的学习是需要以工程的角度来学习的，什么是工程的角度？」 本文如果 「在看」 超过 20 我就发。

❝
上面说的有点义正言辞了，不过由衷希望，大家的技术能更上一层楼！
❞

不扯别的了，直接步入正题，日志有什么作用？为什么需要日志？

1. 日志记录的重要性

在开发过程中，如果程序运行出现了问题，我们是可以使用我们自己的 Debug 工具来检测到到底是哪一步出现了问题，如果出现了问题的话，是很容易排查的。但程序开发完成之后，我们会将它部署到生产环境中去，这时候代码相当于是在一个黑盒环境下运行的，我们只能看到其运行的效果，是不能直接看到代码运行过程中每一步的状态的。在这个环境下，运行过程中难免会在某个地方出现问题，甚至这个问题可能是我们开发过程中未曾遇到的问题，碰到这种情况应该怎么办？

有人说，用邮件通知呀！，不过你得知道，邮件通知是通知，并不是其他！

如果我们现在只能得知当前问题的现象，而没有其他任何信息的话，如果我们想要解决掉这个问题的话，那么只能根据问题的现象来试图复现一下，然后再一步步去调试，这恐怕是很难的，很大的概率上我们是无法精准地复现这个问题的，而且 Debug 的过程也会耗费巨多的时间，这样一旦生产环境上出现了问题，修复就会变得非常棘手。但这如果我们当时有做日志记录的话，不论是正常运行还是出现报错，都有相关的时间记录，状态记录，错误记录等，那么这样我们就可以方便地追踪到在当时的运行过程中出现了怎样的状况，从而可以快速排查问题。

❝
因此，日志记录是非常有必要的，任何一款软件如果没有标准的日志记录，都不能算作一个合格的软件。作为开发者，我们需要重视并做好日志记录过程。
❞

2. 日志概述

「百度百科的日志概述」：

Windows 网络操作系统都设计有各种各样的日志文件，如应用程序日志，安全日志、系统日志、Scheduler 服务日志、FTP 日志、WWW 日志、DNS 服务器日志等等，这些根据你的系统开启的服务的不同而有所不同。我们在系统上进行一些操作时，这些日志文件通常会记录下我们操作的一些相关内容，这些内容对系统安全工作人员相当有用。比如说有人对系统进行了 IPC 探测，系统就会在安全日志里迅速地记下探测者探测时所用的IP、时间、用户名等，用 FTP 探测后，就会在 FTP 日志中记下IP、时间、探测所用的用户名等。

「我映像中的日志」：

查看日志是开发人员日常获取信息、排查异常、发现问题的最好途径，日志记录中通常会标记有异常产生的原因、发生时间、具体错误行数等信息，这极大的节省了我们的排查时间，无形中提高了编码效率。这个其实就是我上面在日志的重要性所做出的回答。

「日志分类」

我们可以按照输出终端进行分类，也可以按照日志级别进行分类。输出终端指的是将日志在控制台输出显示和将日志存入文件；
日志级别指的是 Debug、Info、WARNING、ERROR 以及 CRITICAL 等严重等级进行划分。

2. 日志的记录流程

「那么在 Python 中，怎样才能算作一个比较标准的日志记录过程呢？」

在想之前呢，我们需要了解一个信息，就是我们一般小白和机构中最经常用，那就是 print 这个函数来输出一些运行的信息，然后在控制台观察，如果需要还可以在输出的时候重定向到文件输出流保存到文件中，这样其实是非常不规范的，这是为什么呢？

这其实就是要说到，这个 print 输出虽然能满足入门级别的小项目应用，但是对于工作来说是不行的；
这个 print 里面的数据其实都是我们自己敲打定义的；
没有优先级之分，当然你可以自行加各种各样的代码设定来设定 info 的优先级，当这显然不是我们所需要的；
运行模块信息等信息；

在 Python 中有一个标准的 logging 模块，我们可以使用它来进行标注的日志记录，利用它我们可以更方便地进行日志记录，同时还可以做更方便的级别区分以及一些额外日志信息的记录，如时间、运行模块信息等。

这里我就不写日志记录的流程整体框架，有兴趣的小伙伴们可以访问该链接了解：Python 日志记录流程的整体框架：https://www.aiyc.top/archives/514.html

3. 日志记录的相关用法

logging 提供了一组便利的日志函数，它们分别是：debug()、 info()、 warning()、 error() 和 critical()。logging函数根据它们用来跟踪的事件的级别或严重程度来命名。标准级别及其适用性描述如下（以严重程度递增排序）：

级别	何时使用	每个级别对应的数字值为
NOTSET	不设置	0
DEBUG	详细信息，一般只在调试问题的时候使用	10
INFO	证明事情按照预期工作	20
WARNING	某些没有预料到的事件的提示，或者在将来可能会出现的问题提示。例如：磁盘空间不足，但是软件还是会照常运行。	30
ERROR	由于更严重的问题，软件已不能执行一些功能了。	40
CRITICAL	严重错误，表明软件已经不能继续运行了。	50

Python 中日志的默认等级是 WARNING，DEBUG 和 INFO 级别的日志将不会得到显示，在 logging 中更改设置。

「那说了这么多，还是没有讲到 logging 的优点，到底好在哪呢？」

总的来说 logging 模块相比 print 有这么几个优点：

可以在 logging 模块中设置日志等级，在不同的版本（如开发环境、生产环境）上通过设置不同的输出等级来记录对应的日志，非常灵活。
print 的输出信息都会输出到标准输出流中，而 logging 模块就更加灵活，可以设置输出到任意位置，如写入文件、写入远程服务器等。
logging 模块具有灵活的配置和格式化功能，如配置输出当前模块信息、运行时间等，相比 print 的字符串格式化更加方便易用。

下面我们初步来了解下 logging 模块的基本用法，先用一个实例来感受一下：

import logging

logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')
logger = logging.getLogger(__name__)

logger.info('This is a log info')
logger.debug('Debugging')
logger.warning('Warning exists')
logger.info('Finish')

在这里我们首先引入了 logging 模块，然后进行了一下基本的配置，这里通过 basicConfig 配置了 level 信息和 format 信息。

这里 level 配置为 INFO 信息，即只输出 INFO 级别的信息；
另外这里指定了 format 格式的字符串，包括 asctime、name、levelname、message 四个内容，分别代表运行时间、模块名称、日志级别、日志内容，这样输出内容便是这四者组合而成的内容了，这就是 logging 的全局配置。

名称	含义
asctime	运行时间
name	模块名称
levelname	日志级别
message	日志内容

接下来声明了一个 logger 对象，它就是日志输出的主类：

调用对象的 info() 方法就可以输出 INFO 级别的日志信息；
调用 debug() 方法就可以输出 DEBUG 级别的日志信息，非常方便。

在初始化的时候我们传入了模块的名称，这里直接使用 __name__ 来代替了，就是模块的名称。
如果直接运行这个脚本的话就是 __main__ ；
如果是 import 的模块的话就是被引入模块的名称，这个变量在不同的模块中的名字是不同的，所以一般使用 __name__ 来表示就好了，再接下来输出了四条日志信息，其中有两条 INFO、一条 WARNING、一条 DEBUG 信息，我们看下输出结果：

2020-05-23 20:41:57,990 - __main__ - INFO - This is a log info
2020-05-23 20:41:57,990 - __main__ - WARNING - Warning exists
2020-05-23 20:41:57,990 - __main__ - INFO - Finish
[Finished in 0.2s]

可以看到输出结果一共有三条日志信息，每条日志都是对应了指定的格式化内容，「另外我们发现 DEBUG 的信息是没有输出的，这是为什么呢？」

这是因为我们在全局配置的时候设置了输出为 INFO 级别，所以 DEBUG 级别的信息就被过滤掉了。

❝
其实也就是，info 级别就是 20 ，那该代码就不会输出 info 分数之下的数据了。
❞

这时如果我们将输出的日志级别设置为 DEBUG，就可以看到 DEBUG 级别的日志输出了，代码如下：

import logging

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')
logger = logging.getLogger(__name__)

logger.info('This is a log info')
logger.debug('Debugging')
logger.warning('Warning exists')
logger.info('Finish')

运行结果如下：

2020-05-23 20:45:18,567 - __main__ - INFO - This is a log info
2020-05-23 20:45:18,567 - __main__ - DEBUG - Debugging
2020-05-23 20:45:18,567 - __main__ - WARNING - Warning exists
2020-05-23 20:45:18,567 - __main__ - INFO - Finish
[Finished in 0.2s]

由此可见，相比 print 来说，通过刚才的代码，我们既可以输出时间、模块名称，又可以输出不同级别的日志信息作区分并加以过滤，是不是灵活多了？

当然这只是 logging 模块的一小部分功能，接下来我们首先来全面了解一下 basicConfig 的参数都有哪些：

filename ：即日志输出的文件名，如果指定了这个信息之后，实际上会启用 FileHandler ，而不再是 StreamHandler，这样日志信息便会输出到文件中了。
filemode ：这个是指定日志文件的写入方式，有两种形式，一种是 w，一种是 a，分别代表清除后写入和追加写入。
format：指定日志信息的输出格式，即上文示例所示的参数，详细参数可以参考：https://docs.python.org/3/library/logging.html?highlight=logging%20threadname#logrecord-attributes，部分参数如下所示：
- %(levelno)s ：打印日志级别的数值。
- %(levelname)s ：打印日志级别的名称。
- %(pathname)s ：打印当前执行程序的路径，其实就是 sys.argv[0] 。
- %(filename)s ：打印当前执行程序名。
- %(funcName)s ：打印日志的当前函数。
- %(lineno)d ：打印日志的当前行号。
- %(asctime)s ：打印日志的时间。
- %(thread)d ：打印线程ID。
- %(threadName)s ：打印线程名称。
- %(process)d ：打印进程ID。
- %(processName)s ：打印线程名称。
- %(module)s ：打印模块名称。
- %(message)s ：打印日志信息。
datefmt ：指定时间的输出格式。
style ：如果 format 参数指定了，这个参数就可以指定格式化时的占位符风格，如 %、{、$ 等。
level ：指定日志输出的类别，程序会输出大于等于此级别的信息。
stream ：在没有指定 filename 的时候会默认使用 StreamHandler ，这时 stream 可以指定初始化的文件流。
handlers ：可以指定日志处理时所使用的 Handlers ，必须是 「可迭代」 的。

下面我们再用一个实例来感受一下：

# -*- coding: utf-8 -*-
# @Author: clela
# @Date:   2020-05-23 21:02:19
# @Last Modified by:   clela
# @Last Modified time: 2020-05-23 21:02:22
import logging

logging.basicConfig(level=logging.DEBUG,
                    filename='output.log',
                    datefmt='%Y/%m/%d %H:%M:%S',
                    format='%(asctime)s - %(name)s - %(levelname)s - %(lineno)d - %(module)s - %(message)s')
logger = logging.getLogger(__name__)

logger.info('This is a log info')
logger.debug('Debugging')
logger.warning('Warning exists')
logger.info('Finish')

这里我们指定了输出文件的名称为 output.log，另外指定了日期的输出格式，其中年月日的格式变成了 %Y/%m/%d，另外输出的 format 格式增加了 lineno、module 这两个信息，运行之后便会生成一个 output.log 的文件，内容如下：

2020/05/23 21:14:41 - __main__ - INFO - 14 - tete - This is a log info
2020/05/23 21:14:41 - __main__ - DEBUG - 15 - tete - Debugging
2020/05/23 21:14:41 - __main__ - WARNING - 16 - tete - Warning exists
2020/05/23 21:14:41 - __main__ - INFO - 17 - tete - Finish

可以看到日志便会输出到文件中，同时输出了行号、模块名称等信息。

以上我们通过 basicConfig 来进行了一些全局的配置，我们同样可以使用 Formatter、Handler 进行更灵活的处理，下面我们来了解一下。

4. 强大的 logging

logging 所提供的模块级别的日志记录函数是对 logging 日志系统相关类的封装

logging 模块提供了两种记录日志的方式：

使用 logging 提供的模块级别的函数
使用 Logging 日志系统的四大组件

这里提到的级别函数就是上面所用的 DEBGE、ERROR 等级别，而四大组件则是指 loggers、handlers、filters 和 formatters 这几个组件，下表简单明了的阐述了它们各自的作用：

组件名称	对应类名	功能描述
日志器	Logger	提供了应用程序可一直使用的接口
处理器	Handler	将 logger 创建的日志记录发送到合适的目的输出
过滤器	Filter	提供了更细粒度的控制工具，来决定输出哪条日志记录，丢弃哪条日志记录
格式器	Formatters	决定日志记录的最终输出格式

日志器（logger）是入口，真正工作的是处理器（handler），处理器（handler）还可以通过过滤器（filter）和格式器（formatter）对要输出的日志内容做过滤和格式化等处理操作。

下面介绍下与logging四大组件相关的类：Logger, Handler, Filter, Formatter。

5. Logger 类

上面其实已经对于 Logger 进行了使用和部分讲解，接下来我们系统的介绍四大模块。

Logger 对象有 3 个工作要做：

向应用程序代码暴露几个方法，使应用程序可以在运行时记录日志消息；
基于日志严重等级（默认的过滤设施）或 filter 对象来决定要对哪些日志进行后续处理；
将日志消息传送给所有感兴趣的日志 handlers。

Logger 对象最常用的方法分为两类：配置方法和消息发送方法

最常用的配置方法如下：

方法	描述
Logger.setLevel()	设置日志器将会处理的日志消息的最低严重级别
logger.addHandler() 和 logger.removeHandler()	为该 logger 对象添加和移除一个 handler 对象
logger.addFilter() 和 logger.removeFilter()	为该 logger 对象添加和移除一个 filter 对象

「关于 Logger.setLevel() 方法的说明：」

内建等级中，级别最低的是 DEBUG，级别最高的是 CRITICAL。例如 setLevel(logging.INFO)，此时函数参数为INFO，那么该 logger 将只会处理 INFO、WARNING、ERROR和CRITICAL 级别的日志，而 DEBUG 级别的消息将会被忽略/丢弃。

logger 对象配置完成后，可以使用下面的方法来创建日志记录：

方法	描述
logger.debug() 、logger.info() 、logger.warning() 、logger.error() 、logger.critical()	创建一个与它们的方法名对应等级的日志记录
logger.exception()	创建一个类似于 logger.error() 的日志消息
logger.log()	需要获取一个明确的日志 level 参数来参数来创建一个日志记录

5. Level

上面我分享了一个日志等级对应的数值，接下来我们来详细的来了解一下。

首先我们来了解一下输出日志的等级信息，logging 模块共提供了如下等级，每个等级其实都对应了一个数值，列表如下：

等级	数值
CRITICAL	50
FATAL	50
ERROR	40
WARNING	30
WARN	30
INFO	20
DEBUG	10
NOTSET	0

这里最高的等级是 CRITICAL 和 FATAL，两个对应的数值都是 50，另外对于 WARNING 还提供了简写形式 WARN，两个对应的数值都是 30。

我们设置了输出 level，系统便只会输出 level 数值大于或等于该 level 的的日志结果，例如我们设置了输出日志 level 为 INFO，那么输出级别大于等于 INFO 的日志，如 WARNING、ERROR 等，DEBUG 和 NOSET 级别的不会输出。

import logging

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.WARN)

# Log
logger.debug('Debugging')
logger.critical('Critical Something')
logger.error('Error Occurred')
logger.warning('Warning exists')
logger.info('Finished')

这里我们设置了输出级别为 WARN，然后对应输出了五种不同级别的日志信息，运行结果如下：

Critical Something
Error Occurred
Warning exists
[Finished in 0.2s]

可以看到只有 CRITICAL、ERROR、WARNING 信息输出了，DEBUG、INFO 信息没有输出。

6. Handler

下面我们先来了解一下 Handler 的用法，看下面的实例：

import logging

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.INFO)
handler = logging.FileHandler('output.log')
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)

logger.info('This is a log info')
logger.debug('Debugging')
logger.warning('Warning exists')
logger.info('Finish')

这里我们没有再使用 basicConfig 全局配置，而是先声明了一个 logger 对象，然后指定了其对应的 Handler 为 FileHandler 对象，然后 Handler 对象还单独指定了 Formatter 对象单独配置输出格式，最后给 Logger 对象添加对应的 Handler 即可，最后可以发现日志就会被输出到 output.log 中，内容如下：

2020-05-23 22:02:51,201 - __main__ - INFO - This is a log info
2020-05-23 22:02:51,201 - __main__ - WARNING - Warning exists
2020-05-23 22:02:51,201 - __main__ - INFO - Finish

下面我们使用三个 Handler 来实现日志同时输出到控制台、文件、HTTP 服务器：

import logging
from logging.handlers import HTTPHandler
import sys

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

# StreamHandler
stream_handler = logging.StreamHandler(sys.stdout)
stream_handler.setLevel(level=logging.DEBUG)
logger.addHandler(stream_handler)

# FileHandler
file_handler = logging.FileHandler('output.log')
file_handler.setLevel(level=logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)

# HTTPHandler
http_handler = HTTPHandler(host='localhost:8001', url='log', method='POST')
logger.addHandler(http_handler)

# Log
logger.info('This is a log info')
logger.debug('Debugging')
logger.warning('Warning exists')
logger.info('Finish')

运行之前我们需要先启动 HTTP Server，并运行在 8001 端口，其中 log 接口是用来接收日志的接口。

运行之后控制台输出会输出如下内容：

This is a log info
Debugging
Warning exists
Finish

output.log 文件会写入如下内容：

2020-05-23 15:13:44,895 - __main__ - INFO - This is a log info
2020-05-23 15:13:44,947 - __main__ - WARNING - Warning exists
2020-05-23 15:13:44,949 - __main__ - INFO - Finish

HTTP Server 会收到控制台输出的信息。

这样一来，我们就通过设置多个 Handler 来控制了日志的多目标输出。

另外值得注意的是，在这里 StreamHandler 对象我们没有设置 Formatter，因此控制台只输出了日志的内容，而没有包含时间、模块等信息，而 FileHandler 我们通过 setFormatter() 方法设置了一个 Formatter 对象，因此输出的内容便是格式化后的日志信息。

另外每个 Handler 还可以设置 level 信息，最终输出结果的 level 信息会取 Logger 对象的 level 和 Handler 对象的 level 的交集。

7. Formatter

在进行日志格式化输出的时候，我们可以不借助于 basicConfig 来全局配置格式化输出内容，可以借助于 Formatter 来完成，下面我们再来单独看下 Formatter 的用法：

import logging

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.WARN)
formatter = logging.Formatter(fmt='%(asctime)s - %(name)s - %(levelname)s - %(message)s', datefmt='%Y/%m/%d %H:%M:%S')
handler = logging.StreamHandler()
handler.setFormatter(formatter)
logger.addHandler(handler)

# Log
logger.debug('Debugging')
logger.critical('Critical Something')
logger.error('Error Occurred')
logger.warning('Warning exists')
logger.info('Finished')

在这里我们指定了一个 Formatter，并传入了 fmt 和 datefmt 参数，这样就指定了日志结果的输出格式和时间格式，然后 handler 通过 setFormatter() 方法设置此 Formatter 对象即可，输出结果如下：

2020/05/23 22:03:58 - __main__ - CRITICAL - Critical Something
2020/05/23 22:03:58 - __main__ - ERROR - Error Occurred
2020/05/23 22:03:58 - __main__ - WARNING - Warning exists

这样我们可以每个 Handler 单独配置输出的格式，非常灵活。

8. 捕获 Traceback

如果遇到错误，我们更希望报错时出现的详细 Traceback 信息，便于调试，利用 logging 模块我们可以非常方便地实现这个记录，我们用一个实例来感受一下：

import logging

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

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

# FileHandler
file_handler = logging.FileHandler('result.log')
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)

# StreamHandler
stream_handler = logging.StreamHandler()
stream_handler.setFormatter(formatter)
logger.addHandler(stream_handler)

# Log
logger.info('Start')
logger.warning('Something maybe fail.')
try:
    result = 10 / 0
except Exception:
    logger.error('Faild to get result', exc_info=True)
logger.info('Finished')

这里我们在 error() 方法中添加了一个参数，将 exc_info 设置为了 True，这样我们就可以输出执行过程中的信息了，即完整的 Traceback 信息。

运行结果如下：

2020-05-23 22:10:18,983 - __main__ - INFO - Start
2020-05-23 22:10:18,983 - __main__ - WARNING - Something maybe fail.
2020-05-23 22:10:18,984 - __main__ - ERROR - Faild to get result
Traceback (most recent call last):
  File "C:\Users\clela\Desktop\代理\Base.py", line 23, in <module>
    result = 10 / 0
ZeroDivisionError: division by zero
2020-05-23 22:10:18,985 - __main__ - INFO - Finished

可以看到这样我们就非常方便地记录下来了报错的信息，一旦出现了错误，我们也能非常方便地排查。

9. 配置共享

在写项目的时候，我们肯定会将许多配置放置在许多模块下面，这时如果我们每个文件都来配置 logging 配置那就太繁琐了，logging 模块提供了父子模块共享配置的机制，会根据 Logger 的名称来自动加载父模块的配置。

例如我们这里首先定义一个 main.py 文件：

import logging
import core

logger = logging.getLogger('main')
logger.setLevel(level=logging.DEBUG)

# Handler
handler = logging.FileHandler('result.log')
handler.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)

logger.info('Main Info')
logger.debug('Main Debug')
logger.error('Main Error')
core.run()

这里我们配置了日志的输出格式和文件路径，同时定义了 Logger 的名称为 main，然后引入了另外一个模块 core，最后调用了 core 的 run() 方法。

接下来我们定义 core.py，内容如下：

import logging

logger = logging.getLogger('main.core')

def run():
    logger.info('Core Info')
    logger.debug('Core Debug')
    logger.error('Core Error')

这里我们定义了 Logger 的名称为 main.core，注意这里开头是 main，即刚才我们在 main.py 里面的 Logger 的名称，这样 core.py 里面的 Logger 就会复用 main.py 里面的 Logger 配置，而不用再去配置一次了。

运行之后会生成一个 result.log 文件，内容如下：

2020-05-23 22:09:55,375 - main - INFO - Main Info
2020-05-23 22:09:55,375 - main - ERROR - Main Error
2020-05-23 22:09:55,375 - main.core - INFO - Core Info
2020-05-23 22:09:55,375 - main.core - ERROR - Core Error

可以看到父子模块都使用了同样的输出配置。

如此一来，我们只要在入口文件里面定义好 logging 模块的输出配置，子模块只需要在定义 Logger 对象时名称使用父模块的名称开头即可共享配置，非常方便。

10. 文件配置

在开发过程中，将配置在代码里面写死并不是一个好的习惯，更好的做法是将配置写在配置文件里面，我们可以将配置写入到配置文件，然后运行时读取配置文件里面的配置，这样是更方便管理和维护的，下面我们以一个实例来说明一下，首先我们定义一个 yaml 配置文件：

version: 1
formatters:
  brief:
    format: "%(asctime)s - %(message)s"
  simple:
    format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
handlers:
  console:
    class : logging.StreamHandler
    formatter: brief
    level   : INFO
    stream  : ext://sys.stdout
  file:
    class : logging.FileHandler
    formatter: simple
    level: DEBUG
    filename: debug.log
  error:
    class: logging.handlers.RotatingFileHandler
    level: ERROR
    formatter: simple
    filename: error.log
    maxBytes: 10485760
    backupCount: 20
    encoding: utf8
loggers:
  main.core:
    level: DEBUG
    handlers: [console, file, error]
root:
  level: DEBUG
  handlers: [console]

这里我们定义了 formatters、handlers、loggers、root 等模块，实际上对应的就是各个 Formatter、Handler、Logger 的配置，参数和它们的构造方法都是相同的。

接下来我们定义一个主入口文件，main.py，内容如下：

import logging
import core
import yaml
import logging.config
import os

def setup_logging(default_path='config.yaml', default_level=logging.INFO):
    path = default_path
    if os.path.exists(path):
        with open(path, 'r', encoding='utf-8') as f:
            config = yaml.load(f)
            logging.config.dictConfig(config)
    else:
        logging.basicConfig(level=default_level)

def log():
    logging.debug('Start')
    logging.info('Exec')
    logging.info('Finished')

if __name__ == '__main__':
    yaml_path = 'config.yaml'
    setup_logging(yaml_path)
    log()
    core.run()

这里我们定义了一个 setup_logging() 方法，里面读取了 yaml 文件的配置，然后通过 dictConfig() 方法将配置项传给了 logging 模块进行全局初始化。

另外这个模块还引入了另外一个模块 core，所以我们定义 core.py 如下：

import logging

logger = logging.getLogger('main.core')

def run():
    logger.info('Core Info')
    logger.debug('Core Debug')
    logger.error('Core Error')

这个文件的内容和上文是没有什么变化的。

观察配置文件，主入口文件 main.py 实际上对应的是 root 一项配置，它指定了 handlers 是 console，即只输出到控制台。另外在 loggers 一项配置里面，我们定义了 main.core 模块，handlers 是 console、file、error 三项，即输出到控制台、输出到普通文件和回滚文件。

这样运行之后，我们便可以看到所有的运行结果输出到了控制台：

2020-05-23 17:07:12,727 - Exec
2020-05-23 17:07:12,727 - Finished
2020-05-23 17:07:12,727 - Core Info
2020-05-23 17:07:12,727 - Core Info
2020-05-23 17:07:12,728 - Core Error
2020-05-23 17:07:12,728 - Core Error

在 debug.log 文件中则包含了 core.py 的运行结果：

2020-05-23 17:07:12,727 - main.core - INFO - Core Info
2020-05-23 17:07:12,727 - main.core - DEBUG - Core Debug
2020-05-23 17:07:12,728 - main.core - ERROR - Core Error

可以看到，通过配置文件，我们可以非常灵活地定义 Handler、Formatter、Logger 等配置，同时也显得非常直观，也非常容易维护，在实际项目中，推荐使用此种方式进行配置。

以上便是 logging 模块的基本使用方法，有了它，我们可以方便地进行日志管理和维护，会给我们的工作带来极大的方便。

11. 日志记录使用常见误区

在日志输出的时候经常我们会用到字符串拼接的形式，很多情况下我们可能会使用字符串的 format() 来构造一个字符串，但这其实并不是一个好的方法，因为还有更好的方法，下面我们对比两个例子：

import logging

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# bad
logging.debug('Hello {0}, {1}!'.format('World', 'Congratulations'))
# good
logging.debug('Hello %s, %s!', 'World', 'Congratulations')

这里有两种打印 Log 的方法，第一种使用了字符串的 format() 的方法进行构造，传给 logging 的只用到了第一个参数，实际上 logging 模块提供了字符串格式化的方法，我们只需要在第一个参数写上要打印输出的模板，占位符用 %s、%d 等表示即可，然后在后续参数添加对应的值就可以了，推荐使用这种方法。

运行结果如下：

2020-05-23 22:11:37,114 - root - DEBUG - Hello World, Congratulations!
2020-05-23 22:11:37,114 - root - DEBUG - Hello World, Congratulations!

另外在进行异常处理的时候，通常我们会直接将异常进行字符串格式化，但其实可以直接指定一个参数将 traceback 打印出来，示例如下：

import logging

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')

try:
    result = 5 / 0
except Exception as e:
    # bad
    logging.error('Error: %s', e)
    # good
    logging.error('Error', exc_info=True)
    # good
    logging.exception('Error')

如果我们直接使用字符串格式化的方法将错误输出的话，是不会包含 Traceback 信息的，但如果我们加上 exc_info 参数或者直接使用 exception() 方法打印的话，那就会输出 Traceback 信息了。

运行结果如下：

2020-05-23 22:11:47,405 - root - ERROR - Error: division by zero
2020-05-23 22:11:47,405 - root - ERROR - Error
Traceback (most recent call last):
  File "C:\Users\clela\Desktop\Base.py", line 6, in <module>
    result = 5 / 0
ZeroDivisionError: division by zero
2020-05-23 22:11:47,406 - root - ERROR - Error
Traceback (most recent call last):
  File "C:\Users\clela\Desktop\Base.py", line 6, in <module>
    result = 5 / 0
ZeroDivisionError: division by zero
[Finished in 0.2s]

以上便是整个对 logging 模块的介绍。嗯，是时候抛弃 print 了，开始体验下 logging 的便利吧！

12. 实战演练

上面文绉绉的说了(复制/粘贴)那么多，现在应该动手实践了。

「现在我需要既将日志输出到控制台、又能将日志保存到文件，我应该怎么办？」

利用刚才所学的知识，我们可以构思一下：

「看起来好像也不难，挺简单的样子，但是实际如此吗？」

在实际的工作或应用中，我们或许还需要指定文件存放路径、用随机数作为日志文件名、显示具体的信息输出代码行数、日志信息输出日期和日志写入方式等内容。再构思一下：

具体代码如下：

import os
import logging
import uuid
from logging import Handler, FileHandler, StreamHandler


class PathFileHandler(FileHandler):
    def __init__(self, path, filename, mode='a', encoding=None, delay=False):

        filename = os.fspath(filename)
        if not os.path.exists(path):
            os.mkdir(path)
        self.baseFilename = os.path.join(path, filename)
        self.mode = mode
        self.encoding = encoding
        self.delay = delay
        if delay:
            Handler.__init__(self)
            self.stream = None
        else:
            StreamHandler.__init__(self, self._open())


class Loggers(object):
    # 日志级别关系映射
    level_relations = {
        'debug': logging.DEBUG, 'info': logging.INFO, 'warning': logging.WARNING,
        'error': logging.ERROR, 'critical': logging.CRITICAL
    }

    def __init__(self, filename='{uid}.log'.format(uid=uuid.uuid4()), level='info', log_dir='log',
                 fmt='%(asctime)s - %(filename)s[line:%(lineno)d] - %(levelname)s: %(message)s'):
        self.logger = logging.getLogger(filename)
        abspath = os.path.dirname(os.path.abspath(__file__))
        self.directory = os.path.join(abspath, log_dir)
        format_str = logging.Formatter(fmt)  # 设置日志格式
        self.logger.setLevel(self.level_relations.get(level))  # 设置日志级别
        stream_handler = logging.StreamHandler()  # 往屏幕上输出
        stream_handler.setFormatter(format_str)
        file_handler = PathFileHandler(path=self.directory, filename=filename, mode='a')
        file_handler.setFormatter(format_str)
        self.logger.addHandler(stream_handler)
        self.logger.addHandler(file_handler)


if __name__ == "__main__":
    txt = "关注公众号【AI悦创】"
    log = Loggers(level='debug')
    log.logger.info(4)
    log.logger.info(5)
    log.logger.info(txt)

文件保存后运行，运行结果如下所示：

2020-05-23 22:19:20,049 - data.py[line:49] - INFO: 4
2020-05-23 22:19:20,049 - data.py[line:50] - INFO: 5
2020-05-23 22:19:20,049 - data.py[line:51] - INFO: 关注公众号【AI悦创】

日志确实在控制台输出了，再来看一下目录内是否生成有指定的文件和文件夹：