Python logging 非理想的日志输出

1.logging简介

logging是python的内置库，主要用于进行格式化内容输出，可将格式化内容输出到文件，也可输出到屏幕。我们在开发过程中常用print函数来进行调试，但是实际应用部署时我们要将日志的信息要输出到文件中，方便后续查找以及备份。在我们使用日志管理时，我们还可以将日志格式化成json对象转存到ELK中方便图形化查看及管理。前面说的这些，我们都可以通过logging所包含的功能以及提供扩展的方式来完成。

2.logging工作流程及组件介绍

通过流程图可以看到

1、判断是否enabled，实质就是看记录的level（logger.info，logger.debug等）和当前logger对象设置的level是否满足（比如logger设置的lever是Info，记录时使用的logger.debug，那么就会不满足，所以不会记录日志）

2、查看logger的过滤器是否满足。filter通过之后，交给logger的handler来记录日志，一个logger是可以设置多个handler。

3、交给Handlers实际记录日志

注：在整个应用中可以有多个logger，使用logging.getLogger时通过指定name来获取对象，实际logging中还存在一个Manager类，由Manager来进行多logger的单例模式管理。

4、组成框架：

• 1、框架的主要组成部分：
  Loggers: 可供程序直接调用的接口，app通过调用提供的api来记录日志
  Handlers: 决定将日志记录分配至正确的目的地
  Filters:对日志信息进行过滤， 提供更细粒度的日志是否输出的判断
  Formatters: 制定最终记录打印的格式布局

• 2、各部分详细介绍：

  Loggers：loggers 就是程序可以直接调用的一个日志接口，可以直接向logger写入日志信息。logger并不是直接实例化使用的，而是通过logging.getLogger(name)来获取对象，事实上logger对象是单例模式，logging是多线程安全的，也就是无论程序中哪里需要打日志获取到的logger对象都是同一个。

  Handlers：Handlers 将logger发过来的信息进行准确地分配，送往正确的地方。举个栗子，送往控制台或者文件或者both或者其他地方(进程管道之类的)。它决定了每个日志的行为，是之后需要配置的重点区域。每个Handler同样有一个日志级别，一个logger可以拥有多个handler也就是说logger可以根据不同的日志级别将日志传递给不同的handler。当然也可以相同的级别传递给多个handlers这就根据需求来灵活的设置了。

  Filters：Filters 提供了更细粒度的判断，来决定日志是否需要打印。原则上handler获得一个日志就必定会根据级别被统一处理，但是如果handler拥有一个Filter可以对日志进行额外的处理和判断。例如Filter能够对来自特定源的日志进行拦截or修改甚至修改其日志级别（修改后再进行级别判断）。logger和handler都可以安装filter甚至可以安装多个filter串联起来。

  Formatters：Formatters 指定了最终某条记录打印的格式布局。Formatter会将传递来的信息拼接成一条具体的字符串，默认情况下Format只会将信息%(message)s直接打印出来。Format中有一些自带的LogRecord属性可以使用，如下表格:
  

3.logging模块简单使用

代码如下（日志文件为test_logging5.py，一会下面的例子会用到）：

import logging


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

输出结果：

思考：为什么日志等级为debug,info的日志信息没有输出呢？我们接下来看一下这个代码的进一步改良！

import logging

print(logging.getLogger())
logging.getLogger().setLevel(logging.DEBUG)
logging.debug('logger debug message')
logging.info('logger info message')
logging.warning('logger warning message')
logging.error('logger error message')
logging.critical('logger critical message')

输出结果：

思考：为什么此时日志等级小于warning的日志信息被输出了呢？

答：原因在于默认情况下我们使用的logger为root（这里有疑问的小伙伴可以看一下日志模块关于logger的知识），它的默认等级为warning，至此问题解决。

4.日志模块使用进阶：

正常情况下我们的日志信息都是要输出到一个特定的地方用于保存日志信息，不会说只让它仅仅输出到控制台的（上面例子test_logging5.py就是仅仅输出到了控制台），下面介绍一个将日志信息同时输出到文件及控制台的源码，代码如下：

import logging
logger1 = logging.getLogger('test')
logger1.setLevel(logging.DEBUG)
# 创建一个handler，用于写入日志文件
fh = logging.FileHandler('./test.log')
# 再创建一个handler，用于输出到控制台
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
# 定义handler的输出格式formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)

logger1.addHandler(fh)
logger1.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')

控制台输出结果：

文件输出结果：

5.模块间导入导致的日志输出问题

代码如下（当前代码文件为test_logging4.py，代码中我们导入test_logging5.py）：

import logging
from tool import test_logging5
logger1 = logging.getLogger('test')
logger1.setLevel(logging.DEBUG)
# 创建一个handler，用于写入日志文件
fh = logging.FileHandler('./test.log')
# 再创建一个handler，用于输出到控制台
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
# 定义handler的输出格式formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)

logger1.addHandler(fh)
logger1.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')

输出结果：

思考：我输出的日志信息只有五条为什么实际输出结果多了这么多呢？

答：我们仔细看看我们导入的test_logging5，发现它并没有生成logger。上面说过不生成logger默认使用的就是root，这就是造成以上现象的主要原因，接下来我们通过图片详细讲解。

总结：真正想要弄清楚上述现象，我们就的熟悉logger在logging模块中的真正作用。其实在我们导入test_logging5的时候，就已经创建了一个名为root的logger（为什么已经创建了root，详情看标题3），而名为root的logger又是所有logger的祖宗。logger的机制又是子代输出日志的同时，父带同样会输出，那么问题来了，我该怎么搞才能避免这个重复的问题呢？我们只需要在test_logging5里面生成一个logger，不让它使用root就行了。下面我们接着改一下test_logging5.py，代码如下：

import logging

logging = logging.getLogger("xiao")
logging.debug('logger debug message')
logging.info('logger info message')
logging.warning('logger warning message')
logging.error('logger error message')
logging.critical('logger critical message')

在运行test_logging4.py，结果如下：

我们发现小鬼没了，但是为什么还有别的日志信息呢？因为在我们导入test_logging5时候，test_logging5.py文件里有相应的日志信息输出。

切记：在我们使用logging模块的时候一定要把握力度，切勿用力过猛（使用logger最高级root）。