python日志库介绍

站内链接:

logging 知识点

处理流程

python 日志库采用模块化的方式, 并提供如下几个组件共同完成日志的记录:

logger(记录器): 日志系统的实体, 提供应用程序进行日志打印的接口
handler(处理程序): 将有 logger 记录的日志记录发送到适当的地方
filter(过滤器): 在 logger 和 handler 之后, 提供更加精细化的附加功能(自定义), 确定输出的日志记录
formater(格式化): 指定了最终日志记录输出格式

一条日志记录会在 logger, handler, filter, formater 之间传递. 官网提供了日志事件信息流程:

日志处理流程

从上述的图示可知, 整个日志事件信息流程如下:

记录器判断当前日志 LEVEL 是否合规, 如果合规创建日志记录, 否则结束
过滤器 filter 返回 True/False 来判断是否合规, 一般自定义实现
处理程序中也存在 LEVEL 和 filter, 在过滤之后将日志记录发送到文件/终端/邮件等目的地
格式化器将日志记录以指定的格式输出

日志记录

每一个日志记录都是一个集合数据, 包含:日志等级, 错误记录, 栈信息等 meta 数据.
从 1.1 节内容可知, 日志记录在整个日志处理流程中以基本数据单位被各个流程处理.

logger

一个记录器就相当于日志系统的实体, logging 模块默认存在一个root logger, 记录器提供应用
程序日志打印接口, 一个 logger 对象主要有三个任务:

对应用程序公开接口以便在运行时记录日志信息
根据 LEVEL, 过滤器来确定要处理的日志消息
将日志信息传递给相关的 handler 做进一步的处理

记录器常见的配置方法如下:

logger.setLevel: 指定记录器的最低严重性日志消息
logger.addHandler()和 logger.removeHandler(): 添加或者删除 Handler
logger.addFilter()和 logger.removeFilter(): 添加和删除 Filter

记录器通过下面的一些方法来进行消息的发送或者消息的创建:

import logging

logger = logging.getLogger()
logger.info('~~~~~~')
logging.exception('栈追踪')

关于 logger, 经常会对子记录器, 父记录器, 默认记录器的概念有一些疑惑, 就比如上面的
实例中, 为什么logging.exception()可以直接调用? logging.getLogger()参数为空的时候
返回什么呢? 实际上两者都是调用默认记录器--root logger.

子记录器和父记录器的关系:

子记录器默认接受父级记录器的配置信息, 逐层往上继承, 比如 LEVEL, handler 等信息
子记录器的日志记录消息会默认传播到父记录器上, 如果父记录器存在 Handler, 会重复进行日志的处理.
子记录器可以设置propagate=False来关闭日志记录的传播

下面让我们看一些日志记录器的实例:

# 测试日志记录消息的传播功能
import logging

parent_logger = logging.getLogger('parent')
parent_logger.setLevel(logging.INFO)

f_handler = logging.FileHandler('/data/tmp/p.log')
f_handler.setLevel(logging.INFO)
parent_logger.addHandler(f_handler)
parent_logger.info('This is a record for parent logger only')

# 设置子记录器记录日志到终端
child_logger = parent_logger.getChild('children')
s_handler = logging.StreamHandler()
s_handler.setLevel(logging.INFO)
child_logger.addHandler(s_handler)
child_logger.info('This is a recorf for children.')

上面代码的执行结果如下:

1. 终端上的输出:

This is a recorf for children.

2. 文件/data/tmp/p.log输出:

This is a record for parent logger only
This is a recorf for children.

从输出结果可以看出子记录器的消息被传递到父记录器上, 而且在执行中会发现, 如果重复
执行上述代码(完整代码重新执行多遍), 会发现日志记录打印会出现多条, 这是为什么?
如果 child_logger 未添加 Handler, 会发现终端没有日志输出了, 但是日志文件仅仅有一条
记录, 这是为什么呢?

Handler

Handler 对象负责将适当的日志消息(基于严重等级)分派相应处理程序进行后续处理. logger 对象
和 Handler 对象是多对多关系, 一个 logger 对象可以拥有多个 handler 对象, 而且这些 handler 对象
还可以是重复的, 一条日志信息会逐个重复的分发到所有的 handler 对象上已进行后续的判断处理.

如果一个 logger 没有 handler, 则会默认向父记录器寻找所有可用的 handler, 直到找到为止, 此时
仍然不会停下, 这条日志记录消息会一直往上传播, 直到root logger为止.
这样就能解释上一节的日志重复打印问题, 日志传播问题等.

根据 1.1 节的图示可用直到, logger 和 handler 都各自存在严重性等级判断机制, 所以 handler 也
存在setLevel函数, 同时也存在setFormatter, addFilter等函数.

# 测试没有handler的子记录器
import logging

parent_logger = logging.getLogger('parent')
parent_logger.setLevel(logging.INFO)
s_handler = logging.StreamHandler()
s_handler.setLevel(logging.INFO)
parent_logger.addHandler(s_handler)

child_logger = parent_logger.getChild('children')
child_logger.info('Children logging')  # 此时仅仅输出一行日志

# 2. handler的formatter设置, 关于filter见下面介绍
formatter = logging.Formatter(
    '[%(asctime)s] %(levelname)s - %(filename)s:%(lineno)d - %(message)s',
    '%Y-%m-%d %X')
s_handler.setFormatter(formatter)
child_logger.info('Children formatter logging')

目前可用的 Handler 子类有:

StreamHandler: 消息输出到流
FileHandler: 消息输出到硬盘文件中
RotatingFileHandler: BaseRotatingHandler 子类, 支持最大日志文件大小和日志文件轮换
TimedRotatingFileHandler: BaseRotatingHandler 子类, 支持以特定的时间间隔轮换日志文件
SocketHandler: 消息输出到 TCP/IP 套接字, 支持 UNIX 套接字
DatagramHandler: 消息输出到 UDP 套接字, 支持 UNIX 套接字
QueueHandler: 消息输出到 queue 或 multiprocessing 模块中实现的队列
其他

下面简单的介绍几种基本的 Handler 用法:

# 1. 流
import logging

parent_logger = logging.getLogger('parent')
parent_logger.setLevel(logging.INFO)
s_handler = logging.StreamHandler()
s_handler.setLevel(logging.INFO)
parent_logger.addHandler(s_handler)
parent_logger.info(s_handler)

# 2. 文件
f_handler = logging.FileHandler('/data/tmp/p.log')
f_handler.setLevel(logging.INFO)
pfile = logging.getLogger('pfile')
pfile.addHandler(f_handler)
pfile.info('FileHandler logging')

# 3. 最大日志文件大小, 最大文件个数
# RotatingFileHandler(filename, mode='a', maxBytes=0, backupCount=0, encoding=False,
#            delay=False, errors=None)
from logging.handlers import RotatingFileHandler
f_r_handler = RotatingFileHandler('/data/tmp/t_r.log', maxBytes=100, backupCount=5)
p_rfile = logging.getLogger('p_rfile')
p_rfile.setLevel(logging.INFO)
p_rfile.addHandler(f_r_handler)
for i in range(40):
    p_rfile.info('prfile logging~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~{}'.format(i))

# 4. 特定时间轮换
# TimedRotatingFileHandler(filename, when='h', interval=1,backupCount=0,
#               encoding=None, delay=False, utc=False, atTime=None, errors=None)
from logging.handlers import TimedRotatingFileHandler
f_t_handler = TimedRotatingFileHandler('/data/tmp/t_t.log', when='midnight')
p_tfile = logging.getLogger('p_tfile')
p_tfile.setLevel(logging.INFO)
p_tfile.addHandler(f_t_handler)
p_tfile.info('ptfile logging')

查看上述所有 Handlers 子类的源代码, 可以知道大部分子类都实现了emit函数, 轮换类还
实现了 doRollover 已进行日志的轮换.
emit必须由子类实现, 已完成记录输出到目的地的功能.

Filter

Filter 过滤器可以让开发者设置自定义的过滤规则, 从而过滤所需日志信息. logger 和 handler
可以通过addFilter和removeFilter来增/删过滤器. 一般而言, Filter 都需要我们重新继承
覆盖以便自定义设置, 主要是重写方法filter:

import logging


class MyFilter(logging.Filter)
    def filter(self, record):
        """ record: 日志消息记录, 类实例对象LogRecord, 有如下属性:
            name--初始化loggger传入的名字
            level, pathname, lineno, msg, args, exc_info
        @return:
            True: 表示记录日志消息
            False: 表示过滤, 不记录
        """
        if record.name == 'parent.children':
            return False
        if record.getMessage().startswith('Parent'):
            return False
        return True

同理, 一个 handler 也可以添加多个 Filter 来进行多个过滤机制, 相当于一个过滤链条.

Formatter

Formatter 格式化程序对象配置日志消息最终输出的顺序, 结构, 内容. 其中格式化类的定义
如下:

1 2	# 默认情况下datefmt格式为: %Y-%m-%d %H:%M:%S logging.Formatter.__init__(fmt=None, datefmt=None, style='%')

logging 配置

配置方法

从上一章节我们已经了解到 logging 中基本的日志配置信息, 通过显示的创建 handler, filter,
formatter 实例来进行日志的过滤, 指向目标, 格式化来控制日志输出, 那么是否还存在其他方式呢?
开发者可以通过如下三种方式来进行日志配置:

上章所述显示的调用来创建 logger, handler, filter
创建日志配置文件, 最后通过 fileConfig()函数来读取它
创建日志配置字典, 最后通过 dictConfig()函数来读取它

下面就让我们简单的了解下后面两种方法的使用.

读取配置文件

配置函数:fileConfig(fname, defaults=None, disable_existing_loggers=True), 从一个
configparser格式文件中读取日志记录配置.

例如, 根据官网介绍, file.conf文件:

[loggers]
keys=root,simpleExample

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_simpleExample]
level=DEBUG
handlers=consoleHandler
qualname=simpleExample
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

读取配置并记录日志:

import logging
import logging.config

logging.config.fileConfig('logging.conf')

# create logger
logger = logging.getLogger('simpleExample')

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

读取配置字典

dictConfig(config)读取字典配置信息进行日志配置, 其中字典配置中有几个注意事项:

必须配置 version 值, 唯一有效值:1
formatters: 对应一个字典信息
filters: 对应的值将是一个字典
handlers: 字典

比如如下实例:

import logging
from logging.config import dictConfig


LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'verbose': {
            'format': ('[%(asctime)s] %(levelname)s - %(filename)s:%(lineno)s '
                       '- %(process)d %(thread)d - %(message)s')
        },
    },
    'filters': {},
    'handlers': {
        "booking_api": {
            "formatter": "verbose",
            "filename": "/data/apiv1//logs/booking_api.log",
            "when": "midnight",
            "class": "clogtimehandler.ConcurrentTimeRotatingFileHandler",
            "level": "DEBUG"
        }
    },
    'loggers': {
        "booking_api": {
            "level": "DEBUG",
            "propagate": true,
            "handlers": [
                "booking_api"
            ]
        }
    },
}
dictConfig(LOGGING)

logger = logging.getLogger('book_api')
logger.info('DictConfig logging')

basicConfig

另外, logging 中还存在一种简单的配置方式basicConfig(**kwargs), 他实际上属于 2.1 节所述的
第一种方式, 他简单的 loggers, handlers 和 formatters 的配置函数进行了封装. 该函数使用默认的
Formatter 创建一个 StreamHandler 并键入到root logger来为日志系统执行基本配置.
其中 kwargs 参数可以指定多个参数:

filename: 和 stream 不能兼容
filemode: ‘a’
format
datefmt:
style:
level:
stream: 指定的流
handler
其他

下面让我们看下简单的例子:

# 1. 基本
import logging

logging.basicConfig(level=logging.DEBUG)
logging.debug('This is a debug log.')

# 2. 添加参数
LOG_FORMAT = '%(asctime)s - %(levelname)s - %(message)s'
logging.basicConfig(filename='my.log', level=logging.DEBUG, format=LOG_FORMAT)
logging.debug('Format debug log')

多进程按天分割日志

需求

在开发 API 项目的时候团队有一个需求:

保证多进程情况下日志的安全写入
确保日志文件能够按天进行分割处理
希望日志的切割不引入 shell, 减少外部代码依赖

先不管这个需求是否合理(一般来说, 日志的切割可以凭借 shell 文件在凌晨 3~4 进行安全切割),
为了实现这个目的, 查看了 python 自带的 TimedRotatingFileHandler 源代码, 并简单研究了下
Python 包concurrent-log-handler中的类ConcurrentRotatingFileHandler.
TimedRotatingFileHandler是线程安全的按照时间分割的类, ConcurrentRotatingFileHandler
是多进程安全的按照文件大小进行切割的类, 但是不能按照时间进行分割日志.
考虑到需求, 所以想着将两者结合到一起, 完成一个在一定限定条件下, 一定并发数量条件下
的多进程按时间分割安全写入日志.

改进思路

首先, 让我们看下TimedRotatingFileHandler类的基本实现:

class BaseRotatingHandler(logging.FileHandler):
    def emit(self, record):
        """
        所有日志 Handler都继承该类, 实现原理都类似:
            1. 提交日志到目标之前进行判断是否进行轮转切割
            2. 如果需要, 进行轮转
            3. 提交
        """
        try:
            if self.shouldRollover(record):
                self.doRollover()
            logging.FileHandler.emit(self, record)
        except (KeyboardInterrupt, SystemExit):
            raise
        except:
            self.handleError(record)

class TimedRotatingFileHandler(BaseRotatingHandler):
    def __init__(self, filename, when='h', interval=1, backupCount=0, encoding=None,
        delay=False, utc=False):
        BaseRotatingHandler.__init__(self, filename, 'a', encoding, delay)
        pass
    def computeRollover(self, currentTime):
        """ 计算并返回下一次进行日志文件切割的时间点 """
        pass
    def shouldRollover(self, record):
        """ 计算当前时间点是否需要进行切割操作. 1-准备切割 """
        pass
    def getFilesToDelete(self):
        """ 删除额外的日志文件 """
        pass
    def doRollover(self):
        """ 进行切割操作 """
        pass

根据上面的伪代码可以知晓, 是否决定进行日志切割操作在shouldRollover中进行判定,
执行日志轮转切割操作在doRollover中完成, 其中 TimedRotatingFileHandler 中没有对
doRollover做多进程安全操作, 那么ConcurrentRotatingFileHandler呢

class ConcurrentRotatingFileHandler(BaseRotatingHandler):
    def emit(self, record):
            """
            利用portalocker文件锁机制来确保多进程的安全, 每次提交日志记录前:
                1. 判断是否已经锁
                2. 判断是否需要轮转
                3. 进行轮转切割操作
                4. 进行写入操作
                5. 释放文件锁
            """
            try:
                msg = self.format(record)
                try:
                    self._do_lock()

                    try:
                        if self.shouldRollover(record):
                            self.doRollover()
                    except Exception as e:
                        self._console_log("Unable to do rollover: %s" % (e,), stack=True)
                        # Continue on anyway

                    self.do_write(msg)

                finally:
                    self._do_unlock()
            except (KeyboardInterrupt, SystemExit):
                raise
            except Exception:
                self.handleError(record)