logging模块基本使用
深入理解及使用logging模块
源码解读
Loggers、Logging Levels、getEffectiveLevel
Handlers、StreamHandler、FileHandler、Formatters
propagate、Logging Flow等

loguru

logging模块


日志级别

  • 是产生日志的事件的严重程度
  • 日志级别设置后,严重程度( 数值)低于设置值的日志消息将被忽略
  • 默认日志级别是WARNING
日志级别Level 数值Value
CRITICAL 50
ERROR 40
WARNING(默认级别) 30(root = RootLogger(WARNING))
INFO 20
DEBUG 10
NOTSET 0
import logging

logging.critical('critical')
logging.error('error')
logging.warning('warning')
logging.info('info')
logging.debug('debug')
------ 输出结果------
CRITICAL:root:critical    # 默认格式%(levelname)s:%(name)s:%(message)s
ERROR:root:error
WARNING:root:warning
  • 大多时候,使用的是info,即正常运行信息的输出

格式化

logging.basicConfig(**kwargs)

  • 格式化字符串format
属性名 格式 描述
日志消息内容 %(message)s 查看源码,是调用Formatter.format()时设置,且BASIC_FORMAT = "%(levelname)s:%(name)s:%(message)s"
进程ID %(process)d 进程ID
线程ID %(thread)d 线程ID
进程名称 %(processName)s(注意为小坨峰) 进程名称
线程名称 %(threadName)s(注意为小坨峰) 线程名称
asctime %(asctime)s 创建LogRecord时的可读时间。如2018-07-0816:49:45,896(精确到毫秒)
函数名 %(funcName)s(注意为小坨峰) 日志调用所在的函数名
日志级别名称 %(levelname)s 消息的级别名称,如DEBUG、INFO、WARNING、ERROR、CRITICAL
日志级别数值 %(levelno)s 消息的级别数字
行号 %(lineno)d 日志调用所在的源码行号
模块 %(module)s 模块(文件名称)
logger名称 %(name)s logger名称
  • 级别level(默认级别为WARNING)
  • 格式化日期datefmt,其格式与time.strftime()支持的格式相同
  • 输出到文件filename及filemode(默认为'a',即追加模式)
    • 更多关于路径管理相关的可参看文章路径操作
import logging

FORMAT = "%(asctime)s ---> %(process)s %(processName)s %(threadName)s %(message)s"
DATE_FMT = "%Y-%m-%d %H:%M:%S"
LOGFILE = "test.log"
logging.basicConfig(level=logging.INFO, format=FORMAT, datefmt=DATE_FMT, filename=LOGFILE)
logging.info("i'm monkey jerry")
logging.debug('this is a debug message')
logging.error('this is a error messages')

以上即是logging的基本使用方式,如果只是简单日志记录也够用了。但是,如果有更多的需求,如将不同级别的日志记录到不同的文件,日志既想控制台输出,又想输出到文件等情况。这就需要掌握logging模块的高级用法。

深入理解logging模块


官方文档

Logger

先看如下源码:

root = RootLogger(WARNING)
Logger.root = root  # Logger增加属性root


def info(msg, *args, **kwargs):
    """
    Log a message with severity 'INFO' on the root logger. If the logger has
    no handlers, call basicConfig() to add a console handler with a pre-defined
    format.
    """
    if len(root.handlers) == 0:
        basicConfig()
    root.info(msg, *args, **kwargs)

分析可知,调用logging.info其实是调用root.info(其他函数同样),而root是在logging模块加载的时候创建的全局对象,是RootLogger实例(RootLogger继承自Logger),根(root)Logger对象的默认级别被设置成了WARNING(通过怎样的方式设置的,看如下源码)

class RootLogger(Logger):
    """
    A root logger is not that different to any other logger, except that
    it must have a logging level and there is only one instance of it in
    the hierarchy.
    """
    # RootLogger重写了Logger的__init__方法,传入level级别来设置默认级别
    def __init__(self, level):
        """
        Initialize the logger with the name "root".
        """
        Logger.__init__(self, "root", level)

class Logger(Filterer):
#  Logge的默认级别是 level=NOTSET
    def __init__(self, name, level=NOTSET):
        """
        Initialize the logger with a name and an optional level.
        """
        Filterer.__init__(self)
        self.name = name
        self.level = _checkLevel(level)
        self.parent = None
        self.propagate = True
        self.handlers = []
        self.disabled = False

再查看basicConfig源码,其实就是对根Logger进行设置

Logger.manager = Manager(Logger.root)  # 为Logger类增加一个manager类属性

def getLogger(name=None):
    """
    Return a logger with the specified name, creating it if necessary.

    If no name is specified, return the root logger.
    """
    if name:
        return Logger.manager.getLogger(name)
    else:
        return root  # 没有指定名称,返回根logger

通过以上源码的分析,使用工厂方法返回一个Logger实例。指定name,返回一个名称为name的Logger实例。如果再次使用相同的名字,返回同一个实例。其实是使用一个字典保证同一个名称返回同一个Logger实例。如果未指定name,返回根Logger实例。

自定义Logger

  • Logger实例的构建,使用Logger类也行,但推荐getLogger函数
import logging

logger_a1 = logging.getLogger('a')
logger_a2 = logging.getLogger('a')

print(logger_a1, id(logger_a1))
print(logger_a2, id(logger_a2))

logger_a = logging.getLogger()
print(logger_a is logging.root)

Logger的层次结构

  • 使用 .点号分割,如'a'、'a.b'或'a.b.c.d',a是a.b的父parent,a.b是a的子child
import logging

logging.basicConfig(level=logging.INFO)  # 设置root logger

root_logger = logging.getLogger()
print(logging.root is root_logger)
print(root_logger.name, type(root_logger))
print(root_logger.parent)  # 根logger没父logger

logger = logging.getLogger(__name__)  # 模块级logger
print(logger.name, logger, logger.parent)

# logger_child = logging.getLogger(f'{__name__}.child')  # 子logger
logger_child = logging.getLogger(__name__).getChild('child')  # 子logger
print(logger_child.name, logger_child, type(logger_child), logger_child.parent)
print(logger_child.parent is logger)
-------输出结果---------------------
True
root <class 'logging.RootLogger'>
None
__main__ <Logger __main__ (INFO)> <RootLogger root (INFO)>
__main__.child <Logger __main__.child (INFO)> <class 'logging.Logger'> <Logger __main__ (INFO)>
True

从上面的例子看出,仅设置了root logger的等级,为啥子logger的等级也跟root logger一样呢?

logger级别

  • 可通过logger的level属性设置或通过setLevel方法设置
import logging

logging.basicConfig(level=logging.INFO)  # 设置root logger

root_logger = logging.getLogger()
print(1, "root logger level:", root_logger.level)

# root_logger.level = 40  # 等价
# root_logger.setLevel("ERROR")  # 等价
root_logger.setLevel(40)  # 再次修改等级
root_logger.warning('it is a warning message')  # 设置等级为ERROR后则无法输出warning了

logger = logging.getLogger(__name__)
print(logger.parent is root_logger)
print(2.1, "logger level:", logger.level)  # 自定义logger(其父logger为root logger)默认等级是0

print(2.2, "EffectiveLevel:", logger.getEffectiveLevel())
logger.info('it is a info message')

logger.setLevel(1)  # 为什么仅设置了level为1后,logger.info能输出呢?
print(3.1, "logger level:", logger.level)
print(3.2, "EffectiveLevel:", logger.getEffectiveLevel())
logger.info('it is a info message after setLevel 1')
---------输出结果-----------
1 root logger level: 20
True
2.1 logger level: 0
2.2 EffectiveLevel: 40
3.1 logger level: 1
3.2 EffectiveLevel: 1
INFO:__main__:it is a info message after setLevel 1
  • 分析:为什么仅设置了level为1后,logger.info能输出呢?查看源码:
# logger.info 源码
def info(self, msg, *args, **kwargs):
    if self.isEnabledFor(INFO):   # 满足条件才能执行如下日志打印
        self._log(INFO, msg, args, **kwargs)
# isEnabledFor源码
def isEnabledFor(self, level):  # 这里的level为日志的输出级别
    if self.manager.disable >= level:
        return False
    return level >= self.getEffectiveLevel()  # (当前logger实例自身)日志的输出级别level是否大于等于EffectiveLevel
# getEffectiveLevel源码
def getEffectiveLevel(self):
    logger = self
    while logger:
        if logger.level:
            return logger.level   # 如果自身logger设置了level(非0)则该level即为EffectiveLevel
        logger = logger.parent # 否则为父logger的EffectiveLevel(一直往上找(while))

通过分析源码得出如下结论:

  1. 每一个logger实例,都有一个有效的level(EffectiveLevel)
  2. logger对象可以在创建后动态的修改自己的level,如果设置了logger的level(非0)则EffectiveLevel等于该设置的level值,否则一直往上找父logger的有效level
  3. 只有日志输出级别大于等于有效level,日志才“有可能”输出(还与其他因素有关)
  4. 日志输出level要和当前logger的EffectiveLevel比较

handler和handler Formatter

先看如下示例:

import logging

FORMAT = "%(asctime)s [%(name)s] %(message)s"
logging.basicConfig(level=logging.INFO, format=FORMAT, filename='test.log')  # 设置root logger日志输出等级和字符串格式

root_logger = logging.getLogger()

print(root_logger.getEffectiveLevel())
root_logger.info("this is a test info message")  # 满足第一因素:输出日志级别大于等于有效等级

logger = logging.getLogger(__name__)
print(logger.getEffectiveLevel())
logger.info("this is a child logger test info message")  # 子logger的有效等级从父logger获取,因此满足第一条件
-----------输出到文件的结果--------
2021-01-12 11:29:09,676 [root] this is a test info message
2021-01-12 11:29:09,677 [__main__] this is a child logger test info message

由上例可看出:子logger的输出格式跟root logger格式一致,但并没有设置子logger格式,怎么设置的呢?

  • 查看logger.info相关源码
# info源码
def info(self, msg, *args, **kwargs):
    if self.isEnabledFor(INFO):   # 满足条件才能执行如下日志打印
        self._log(INFO, msg, args, **kwargs)
# _log源码
def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False):
    ......
    record = self.makeRecord(self.name, level, fn, lno, msg, args,
                                exc_info, func, extra, sinfo)  # 将格式做record
    self.handle(record)
def handle(self, record):
    if (not self.disabled) and self.filter(record):
        self.callHandlers(record)  # 将recode传入
def callHandlers(self, record): # 真正做日志输出工作的是handler
    c = self
    found = 0
    while c:
        for hdlr in c.handlers: # 遍历handler
            found = found + 1
            if record.levelno >= hdlr.level: # 如果record中的level(即日志输出的等级)大于等于handler的level
                hdlr.handle(record) # 才有可能输出日志
        if not c.propagate:   # 查看propagate属性是否为True,否则logger的handler不向父logger查找
            c = None    #break out
        else:
            c = c.parent  # 如果为True,则一直向上传播(propagate)到父logger的handler
    ......

一直向上传播(propagate)到root logger的handlers,那root logger的handlers是怎么处理输出格式的呢?

  • 继续查看root logger basicConfig相关源码
def basicConfig(**kwargs):
    _acquireLock()
    try:
            ......
            if handlers is None: # handler为None
                filename = kwargs.pop("filename", None)
                mode = kwargs.pop("filemode", 'a')
                if filename:
                    h = FileHandler(filename, mode) # 如果没有设置filename则生成一个FileHandler,可进一步查看FileHandler
                else:
                    stream = kwargs.pop("stream", None)
                    h = StreamHandler(stream) # 否则生成一个StreamHandler
                handlers = [h] # 所有的handler放入list中
            dfs = kwargs.pop("datefmt", None)
            style = kwargs.pop("style", '%')
            if style not in _STYLES:
                raise ValueError('Style must be one of: %s' % ','.join(
                                 _STYLES.keys()))
            fs = kwargs.pop("format", _STYLES[style][1]) # 继续查看源码发现_STYLES[style][1]是 BASIC_FORMAT = "%(levelname)s:%(name)s:%(message)s"
            fmt = Formatter(fs, dfs, style)  # 格式化,将fs格式传入Formatter
            for h in handlers: # 遍历handlers
                if h.formatter is None: # 如果没有设置formatter
                    h.setFormatter(fmt) # 则设置默认fmt
                root.addHandler(h) # 绑定到root
            ......
class FileHandler(StreamHandler):
    def __init__(self, filename, mode='a', encoding=None, delay=False):
        """
        Open the specified file and use it as the stream for logging.
        """
        self.baseFilename = os.path.abspath(filename)
        self.mode = mode
        self.encoding = encoding
        self.delay = delay
        if delay:
            #We don't open the stream, but we still need to call the
            #Handler constructor to set level, formatter, lock etc.
            Handler.__init__(self)
            self.stream = None
        else:
            StreamHandler.__init__(self, self._open())   # 

class StreamHandler(Handler):

    terminator = '\n'

    def __init__(self, stream=None):
        """
        Initialize the handler.

        If stream is not specified, sys.stderr is used.
        """
        Handler.__init__(self)
        if stream is None:
            stream = sys.stderr    # 输出到控台默认是sys.stderr
        self.stream = stream

通过分析源码得出如下结论(1):

  1. 日志输出其实是Handler做的
  2. Handler 控制日志信息的输出目的地,可以是控制台、文件
    • 可以单独设置level
    • 可以单独设置格式
    • 可以设置过滤器
  3. StreamHandler和FileHandler
    • 如果设置文件名,则为根Logger加一个输出到文件的FileHandler
    • 如果没有设置文件名,则为根Logger加一个StreamHandler,且默认输出到sys.stderr。也就是说,根logger一定会至少有一个handler
  4. 如果设置了format参数,就会用它生成一个Formatter对象,否则会生成缺省Formatter,并把这个
    formatter加入到创建的handler上,然后把这些handler加入到root.handlers列表上
  5. 自己添加的handler默认格式是 default_format = '%(message)s'
  6. 也可以为自己添加的handler设置自定义格式setFormatter(fmt)
  7. 日志输出级别需要大于handler的级别才能输出,否则不做处理
# 结论1演示示例
import logging

FORMAT = "%(asctime)s [%(name)s] %(message)s"
logging.basicConfig(level=logging.INFO, format=FORMAT, filename='test.log')  # 设置root logger日志输出等级和字符串格式

root_logger = logging.getLogger()

print(f"1 effective level: {root_logger.getEffectiveLevel()}")
# 输出格式为basicConfig设置的格式
root_logger.info("this is a test info message")  # 满足第一因素:输出日志级别大于等于有效等级
print(2, root_logger.handlers)  # 设置了filename,仅FileHandler

import sys

stream = sys.stdout  # 标准输出
console_handler = logging.StreamHandler(stream)
root_logger.addHandler(console_handler)  # 添加StreamHandler,让日志既可以输出到文件,又可以输出到控制台
print(3, root_logger.handlers)  # 此时有两个handler,FileHandler和StreamHandler,且handler默认级别都是NOTSET
print(4, console_handler.level)  # handler默认级别是0
# 添加的StreamHandler,控制台输出格式仅message;文件格式是basicConfig设置的格式
root_logger.info("this is a test info message to console")  # 既输出到控制台,又输出到文件

# console_handler.setLevel(30)
# console_handler.level = 30
console_handler.setLevel(logging.WARNING)  # 设置StreamHandler级别大于日志输出级别(日志输出级别为info(20))
root_logger.info('this is a test info message after set streamHandler level')  # 仅输出到文件,控制台不再输出
print(root_logger.handlers[0].level)
root_logger.handlers[0].setLevel(logging.WARNING)  # 设置FileHandler级别大于日志输出级别
console_handler.setLevel(10)  # 设置StreamHandler级别大于日志输出级别(日志输出级别为info(20))

# 第二影响日志输出因素:日志的输出级别需要大于handler的级别才能输出
root_logger.info('this is a test info message after set fileHandler level')  # 仅输出到控制台,不输出到文件

file_handler = logging.FileHandler('test1.log', 'w')
root_logger.addHandler(file_handler)  # 再添加一个fileHandler
print(5, root_logger.handlers)
print(6, root_logger.handlers[2].level)
# 添加的FileHandler,输出到文件输出到文件格式仅只包含message
root_logger.info('this is a info message after add another fileHandler')  # 输出到另一个文件和控制台

fmt = logging.Formatter('~~~~%(message)s~~~~~')
file_handler.setFormatter(fmt)  # 为添加的FileHandler设置格式
# 输出到添加的FileHandler格式变化了,不是默认的message格式,而是设置的格式
root_logger.info('this is a info message after add another fileHandler and set fmt')  # 输出到另一个文件和控制台

源码分析结论(2):

  1. 日志记录会交给当前logger的所有handler处理,记录还要和每一个handler的级别分别比较,低的不处
    理,否则按照handler输出日志记录
  2. 当前logger的所有handler处理完后,就要看自己的propagate属性,如果是True表示向父logger传递这个日志记录,否则到此流程结束
  3. 如果日志记录传递到了父logger,不和父logger的level比较,而是直接交给父的所有handler,父logger成为当前logger。重复1、2步骤,直到当前logger的父logger是None退出,也就是说当前logger最后一般是root logger(是否能到root logger要看中间的logger是否允许propagate)
  4. logger实例初始的propagate属性为True,即允许向父logger传递消息
# 结论2验证示例
import logging

FORMAT = "%(asctime)s [%(name)s] %(message)s"
logging.basicConfig(level=logging.INFO, format=FORMAT)  # 设置root logger日志输出等级和字符串格式

root_logger = logging.getLogger()
logger = logging.getLogger(__name__)

print(1, root_logger is logger.parent)
print(2, root_logger.level, root_logger.getEffectiveLevel())
print(3, logger.level, logger.getEffectiveLevel())
print(4, root_logger.propagate, logger.propagate)

print(root_logger.handlers, logger.handlers, sep='\n')
print(5, root_logger.handlers[0].level)

logger.info('this is the child logger info message')
logger.propagate = False  # 不再向上传递
logger.info('this is the child logger info message after set propagate false')  # 不能输出日志,因为没有handler

logger.propagate = True
file_handler = logging.FileHandler('test.log', 'a')
print(6, file_handler.level)
logger.addHandler(file_handler)
print(7, logger.handlers, logger.handlers[0].level)
# 输出到文件是默认格式,输出到控制台使用的是root logger的格式
logger.info('this is the child logger info message after add a fileHandler')

root_logger.setLevel(logging.ERROR)  # 故意提高root的有效等级证明子logger的handler不再跟其比较
root_logger.handlers[0].setLevel(logging.DEBUG)  # 只与root的handler等级比较

logger.setLevel(logging.INFO)  # 如果不设置,则logger的有效级别为root的有效级别
print(8, logger.getEffectiveLevel())  # 20,保证当前logger的日志输出级别大于其有效级别
# 对于输出到控制台的StreamHandler,子logger传递到root后,不和root的level比较,而是和root的handler级别比较,大于则输出
logger.info('this is the child logger info message after set different level to root logger and root handler')

fmt = logging.Formatter("~~~~~[%(name)s]~~~%(message)s~~~~")
print(fmt, fmt._fmt)
import sys
stream_handler = logging.StreamHandler(sys.stdout)
stream_handler.setFormatter(fmt)
logger.addHandler(stream_handler)
print(logger.handlers[1].formatter, logger.handlers[1].formatter._fmt)

# 这条消息会在控制台打印两次,自己的stream handler及父logger即root的stream handler,且两者格式不同
logger.info("this is a test info message after add another formatter stream handler to logger")

# 若非父子关系,消息并不传播
logger1 = logging.getLogger()
# logger1的日志不会传播到logger上,因为两个并非父子关系
logging.error("this is a test info message output by logger1 which is child of root but not logger")

logging flow

  • 官方日志流转图:

大图请参照官方文档

通过以上的分析及logging flow,我们知道log的输出依赖有效级别,handler是否传播,handler的级别。还有是否有Filter过滤器(logger过滤器和handler过滤器),但由于Filter过滤器用的不多,这里仅做简单介绍

Filter

  • handler过滤器:在handler增加过滤器,这种过滤器只影响该handler,不会影响整个处理流程
  • logger过滤器:过滤器增加到logger上,影响主干流程(参看流程图)
  • 分析Filter源码
class Filter(object):
    def __init__(self, name=''):
        self.name = name
        self.nlen = len(name)

    def filter(self, record):
        if self.nlen == 0:  # 如果filter name的长度为0则不过滤
            return True
        elif self.name == record.name:  # 如果filter name 等于 logger的名字则不过滤
            return True
        # 就是loger的名字不但以filter.name开头,而且下一个字符必须是.点号则不过滤,否则返回False,过滤掉
        elif record.name.find(self.name, 0, self.nlen) != 0:  # 如果logger的名字字符串str[0, nlen]未全匹配filter name则过滤
            return False
        return (record.name[self.nlen] == ".")  # 全匹配且logger的名字字符串str[nlen]是点.则不过滤
  • 源码分析结论:
  1. 如果filter name的长度为0则不过滤
  2. 如果filter name 等于 logger的名字则不过滤
  3. loger的名字不但以filter.name开头,而且下一个字符必须是.点号则不过滤,否则返回False,过滤掉
  4. 一个handler可以添加多个过滤器,过滤器是串联过滤的
  • 源码分析结论验证示例:
import logging
import sys

FORMAT = "%(asctime)s [%(name)s] %(message)s"
logging.basicConfig(level=logging.INFO, format=FORMAT)
# root = logging.getLogger()
# root.handlers = []

log1 = logging.getLogger("log1")
log2 = logging.getLogger("log1.log2")
log1.propagate = False

log1_handler = logging.StreamHandler(sys.stdout)
log1.addHandler(log1_handler)

# log1_filter = logging.Filter('log')
# log1_filter = logging.Filter('l')
# log1_filter = logging.Filter()
log1_filter = logging.Filter('log1.log2')
print(log1.name)
print(log1_filter.name, log1_filter.nlen)
log1_handler.addFilter(log1_filter)

log1.info('this is a log1 test info message')  # log1名字不满足"全匹配filter name",则过滤掉
log2.info('this is a log2 test info message')  # log1.log2名字等于filter的名字,不过滤

参考


  • magedu