关于logging的那些坑

时间  2020-05-10 标签 关于 logging 那些

python的logging日志记录模块很是强大，使用也很简单，可是特别容易出各类意外情况，打印各类出乎意料的log。最近对logging的一些原理进行了学习，再此作个记录，以备忘。
首先全面的了解一下总体的结构。logging默认就有一个root的Logger对象，输入logging.root能够看到，默认为warning级别：html

>>> logging.root
<RootLogger root (WARNING)>

用户自行建立的全部logger对象，都是root的子对象。python

>>> logger = logging.getLogger('logger')
>>> logger.parent
<RootLogger root (WARNING)>

须要注意的是，当getLogger()不带参数时，返回的就是rootLogger对象自己。编程

>>> logger = logging.getLogger()
>>> logger
<RootLogger root (WARNING)>
>>> logger is logging.root
True

建立了Logger对象，接下来咱们须要建立handler对象，handler对象是用来配置处理log时用的格式，级别等等特性的，咱们能够根据需求建立各类不一样的handler，好比将log记录保存在文件的FileHandler，将log输出到屏幕的StreamHandler，支持日志根据时间回滚的TimedRotatingFileHandler，根据文件大小回滚的RotatingFileHandler等等（回滚不太好理解，根据时间或文件大小回滚其实就是根据时间或者文件大小来保存日志，好比只保存3天的日志，超过3天的就自动删除，或者设置日志文件只能为必定大小，超过就删除）。
各类handler网上各类文章都有介绍，或者查官方文档，这里就不列举了。稍微一提的是，最经常使用的FileHandler和StreamHandler在logging下，其它的handler在logging.handlers下。另外，logger和handler的level能够分别设置，以知足不一样的需求。
建立了handler，就要把它添加到logger对象中去，logger对象有一个handlers属性，其实就是一个简单的列表，能够看到全部添加给它的hanlder。以下：函数

>>> logger = logging.getLogger('spam')
>>> handler = logging.StreamHandler()
>>> logger.addHandler(handler)
>>> logger.handlers
[<StreamHandler <stderr> (NOTSET)>]

可见，logger对象添加了handler，是一个输出到stderr，级别未设置的handler。此时，就能够经过logger对象输出各类logger了，如：工具

>>> logger = logging.getLogger('spam')
>>> handler = logging.StreamHandler()
>>> formatter = logging.Formatter("%(asctime)s-%(levelname)s-%(message)s")
>>> handler.setFormatter(formatter)
>>> handler.setLevel(logging.INFO)
>>> logger.addHandler(handler)
>>> logger.handlers
[<StreamHandler <stderr> (INFO)>]
>>> logger.setLevel(logging.INFO)
>>> logger.info('info')
2019-03-31 11:59:41,933-INFO-info

对总体有个大致的了解，接下来就能够谈谈常见的大坑了。
首先，平时在log输出的时候，常常会发现，莫名奇妙的会输出重复的内容，主要有如下几个可能的缘由：
一、前面说过，任何自定义的logger对象都是rootLogger的子对象，就像这样，rootLogger(parent)->Logger(child)，而当你使用自定义的logger记录日志的时候，它会从子到父，从左到右依次执行全部的handler来输出，看代码：学习

>>> rootLogger = logging.getLogger()
>>> rootLogger.setLevel(logging.INFO)
>>> roothandler = logging.StreamHandler()
>>> fmt = logging.Formatter("%(name)s-%(levelname)s-%(message)s")
>>> roothandler.setLevel(logging.INFO)
>>> roothandler.setFormatter(fmt)
>>> rootLogger.addHandler(roothandler)
>>> rootLogger.handlers
[<StreamHandler <stderr> (INFO)>]
>>> childLogger = logging.getLogger("child")
>>> childLogger.setLevel(logging.INFO)
>>> childhandler = logging.StreamHandler()
>>> childhandler.setLevel(logging.INFO)
>>> childhandler.setFormatter(fmt)
>>> childLogger.addHandler(childhandler)
>>> childLogger.handlers
[<StreamHandler <stderr> (INFO)>]
>>> childLogger.info('i am child')
child-INFO-i am child
child-INFO-i am child

日志输出了2次，注意输出的logger name，虽然有一个是rootLogger的handler输出的，可是name仍是子logger的。 二、有人可能会说，上面这个状况不太可能会发生，由于我直接设置一个子logger就ok了，是这样没错，but，当你直接使用logging.basicConfig对rootLogger对象进行配置或者在建立本身的logger对象以前，用logging.info等命令输出过日志的时候，logging会自动的（偷偷摸摸的）给你建立一个streamhandler，以下：spa

>>> root = logging.getLogger()
>>> root.handlers
[]
>>> logging.basicConfig(level=logging.INFO)
>>> root.handlers
[<StreamHandler <stderr> (NOTSET)>]
>>> root = logging.getLogger()
>>> root.handlers
[]
>>> logging.info('i am root')
>>> root.handlers
[<StreamHandler <stderr> (NOTSET)>]

如今明白为何有时候建立了一个logger之后，会莫名其妙重复屡次输出日志了吧？ 三、还有一种状况，也堪称巨坑。当使用IDE工具编程的时候，整个IDE会话不结束，logger的handlers列表不清空！这就致使反复运行程序的时候，handler会反复添加，结果你会发现log输出愈来愈多。。。。。以下： 第一次运行，一个handler，第二次运行，变2个了，怎么办呢？能够在程序结尾加一行代码root.removeHandler(handler)，或者简单粗暴一点，直接root.handlers=[]，每次程序运行完，将handlers列表全清空。
差很少就这些吧，最后还有一个小知识点，有些同窗会问，为啥我自定义的logger啥handler都没加的时候，也有输出呢？好比：日志

>>> import logging
>>> logger = logging.getLogger('child')
>>> logger.handlers
[]
>>> logging.root.handlers
[]
>>> logger.warning('i am child')
i am child

由于logging模块有一个默认的hanlder，能够经过logging.lastResort查看，以下：code

>>> logging.lastResort
<_StderrHandler <stderr> (WARNING)>

这个handler没有和任何logger关联，专门处理用户啥都没配置的状况，可见，默认级别是warning，默认输出是stderr（注意是stderr而不是标准的stdout，所以若是你采起这种方式输出日志又进行了重定向，颇有可能达不到想要的效果），仅仅输出一个message，其它啥都没有。
最后总结：logging确实很好用，可是我的以为有些过于灵活了，不少事情私底下偷偷摸摸的作了，反而会给用户带来困扰。
原创不易，转载请注明出处。orm

====================================

2019年4月1日补充更新： 除了定制不一样级别的level，logger还能够添加filter对象来对输出进行更加复杂的控制。filter和handler同样，先进行配置，而后再添加到logger对象中。全部日志在输出以前，都会先经过filter进行过滤。建立filter要先建立一个继承自logging.Filter的类，代码以下：

import logging
import sys


class ContextFilter(logging.Filter):
    def filter(self, record):
        if record.role == "admin":
            return True
        else:
            return False


if __name__ == '__main__':
    logger = logging.getLogger("Wechat")
    logger.setLevel(logging.DEBUG)
    handler = logging.StreamHandler(sys.stdout)
    formatter = logging.Formatter(
                    '%(asctime)s %(levelname)s:%(message)s Role:%(role)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)

    f = ContextFilter()
    logger.addFilter(f)
    logger.info('An info message with %s', 'some parameters',
                extra={"role": "admin"})
    logger.info('An info message with %s', 'some parameters',
                extra={"role": "hacker"})

从3.2之后，不必定非要建立一个logging.Filter子类，只要是有filter属性的任何对象或者函数都行，后台会检查这个对象是否有filter属性，若是有，则会调用这个对象的filter()方法，没有的话就把它看成一个callable对象，直接执行，而且把records看成一个参数传递给这个callable对象。

import logging
import sys


def myfilter(record):
    if record.role == "admin":
        return True
    else:
        return False


if __name__ == '__main__':
    logger = logging.getLogger("Wechat")
    logger.setLevel(logging.DEBUG)
    handler = logging.StreamHandler(sys.stdout)
    formatter = logging.Formatter(
            '%(asctime)s %(levelname)s: %(message)s Role: %(role)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    logger.addFilter(myfilter)
    logger.info('An info message with %s', 'some parameters',
                extra={"role":"admin"})
    logger.info('An info message with %s', 'some parameters',
                extra={"role":"hacker"}

部分代码参考https://www.cnblogs.com/progor/p/9269230.html，特此申明。

4.5日新增： 继续谈谈filter，须要注意的是，若是使用上面的例子，那么在每一条日志记录里面，都须要加上一条extra={"role":"xxx"}，由于全部的日志record对象都会先经过filter过滤，此时会检查record是否有role属性，若是没有设置，显然会报错。
其实除了过滤这一种用法，filter还能够经过在函数里面给record添加属性，方便的增长自定义的字段。仍是看例子：

def myfilter(record):
	record.user = 'telecomshy'
	return True

>>> logger = logging.getLogger()
>>> logger.addFilter(myfilter)
>>> import sys
>>> fmt = logging.Formatter("%(levelname)s-%(asctime)s-%(message)s-%(user)s")
>>> handler = logging.StreamHandler(sys.stdout)
>>> handler.setLevel("DEBUG")
>>> handler.setFormatter(fmt)
>>> logger.addHandler(handler)
>>> logger.setLevel("DEBUG")
>>> logger.info('hello world')
INFO-2019-04-05 11:55:28,764-hello world-telecomshy

如上，经过使用filter，如今能够在formatter里面使用'user'这个自定义的字段了。

原文出处：https://www.cnblogs.com/telecomshy/p/10630888.html

联系我们 沪ICP备13005482号-10