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))
通过分析源码得出如下结论:
- 每一个logger实例,都有一个有效的level(EffectiveLevel)
- logger对象可以在创建后动态的修改自己的level,如果设置了logger的level(非0)则EffectiveLevel等于该设置的level值,否则一直往上找父logger的有效level
- 只有日志输出级别大于等于有效level,日志才“有可能”输出(还与其他因素有关)
- 日志输出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):
- 日志输出其实是Handler做的
- Handler 控制日志信息的输出目的地,可以是控制台、文件
- 可以单独设置level
- 可以单独设置格式
- 可以设置过滤器
- StreamHandler和FileHandler
- 如果设置文件名,则为根Logger加一个输出到文件的FileHandler
- 如果没有设置文件名,则为根Logger加一个StreamHandler,且默认输出到sys.stderr。也就是说,根logger一定会至少有一个handler
- 如果设置了format参数,就会用它生成一个Formatter对象,否则会生成缺省Formatter,并把这个
formatter加入到创建的handler上,然后把这些handler加入到root.handlers列表上 - 自己添加的handler默认格式是 default_format = '%(message)s'
- 也可以为自己添加的handler设置自定义格式setFormatter(fmt)
- 日志输出级别需要大于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):
- 日志记录会交给当前logger的所有handler处理,记录还要和每一个handler的级别分别比较,低的不处
理,否则按照handler输出日志记录 - 当前logger的所有handler处理完后,就要看自己的propagate属性,如果是True表示向父logger传递这个日志记录,否则到此流程结束
- 如果日志记录传递到了父logger,不和父logger的level比较,而是直接交给父的所有handler,父logger成为当前logger。重复1、2步骤,直到当前logger的父logger是None退出,也就是说当前logger最后一般是root logger(是否能到root logger要看中间的logger是否允许propagate)
- 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]是点.则不过滤
- 源码分析结论:
- 如果filter name的长度为0则不过滤
- 如果filter name 等于 logger的名字则不过滤
- loger的名字不但以filter.name开头,而且下一个字符必须是.点号则不过滤,否则返回False,过滤掉
- 一个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