浅谈logging模块

最近遇到了个头疼的问题，python的logging进程安全问题，借着这个机会，彻底把logging模块研究了一遍，分享一下心得。
首先介绍一下logging的几个组件，介绍之前先把配置文件放出来，下面会详细介绍：

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "simple": {
            # 简单的输出模式
            'format': '%(asctime)s [%(name)s:%(lineno)d] [%(levelname)s]- %(message)s'
        },
        'standard': {
            # 较为复杂的输出模式，可以进行自定义
            'format': '%(asctime)s [%(threadName)s:%(thread)d] [%(name)s:%(lineno)d] [%(levelname)s]- %(message)s'
        },
    },

    "handlers": {
        # 输出到控制台的handler
        "debug": {
            # 定义输出流的类
            "class": "logging.StreamHandler",
            # handler等级，如果实际执行等级高于此等级，则不触发handler
            "level": "DEBUG",
            # 输出的日志格式
            "formatter": "simple",
            # 流调用系统输出
            "stream": "ext://sys.stdout"
        },
        # 写入到文件的hanler，写入等级为info，命名为request是为了专门记录一些网络请求日志
        "request": {
            # 定义写入文件的日志类，此类为按时间分割日志类，还有一些按日志大小分割日志的类等
            "class": "mlogging.TimedRotatingFileHandler_MP",
            # 日志等级
            "level": "INFO",
            # 日志写入格式，因为要写入到文件后期可能会debug用，所以用了较为详细的standard日志格式
            "formatter": "standard",
            # 要写入的文件名
            "filename":  "./request.log",
            # 分割单位，D日，H小时，M分钟，W星期，一般是以小时或天为单位
            # 比如文件名为test.log，到凌晨0点的时候会自动分离出test.log.yyyy-mm-dd
            "when": 'D',
            "encoding": "utf8"
        },
        # 写入到文件的hanler，写入等级为info
        "info": {
            # 不再赘述，详细见request logger
            "class": "mlogging.TimedRotatingFileHandler_MP",
            "level": "INFO",
            "formatter": "standard",
            "filename": "./info.log"),
            "when": 'D',
            "encoding": "utf8"
        },
        # 写入到文件的hanler，写入等级为warning
        "warning": {
            # 不再赘述，详细见request logger
            "class": "mlogging.TimedRotatingFileHandler_MP",
            "level": "WARNING",
            "formatter": "standard",
            "filename": "./warning.log"),
            "when": 'D',
            "encoding": "utf8"
        },
        # 写入到文件的hanler，写入等级为error
        "error": {
            # 不再赘述，详细见request logger
            "class": "mlogging.TimedRotatingFileHandler_MP",
            "level": "ERROR",
            "formatter": "standard",
            "filename": "./error.log"),
            "when": 'D',
            "encoding": "utf8"
        },
        # 写入到文件的hanler，写入等级为critical（一般有重大错误的时候才会用到此类打印）
        "critical": {
            # 不再赘述，详细见request logger
            "class": "mlogging.TimedRotatingFileHandler_MP",
            "level": "CRITICAL",
            "formatter": "standard",
            "filename": "./critical.log"),
            "when": 'D',
            "encoding": "utf8"
        },
    },
    "loggers": {
        # logger名字
        "debug_logger": {
            # logger集成的handler
            'handlers': ['debug'],
            # logger等级，如果实际执行等级，高于此等级，则不触发此logger，logger中所有的handler均不会被触发
            'level': "DEBUG",
            # 是否继承root日志，如果继承，root的handler会加入到当前logger的handlers中
            'propagate': False
        },
        # 不再赘述，详见debug_logger
        "request_logger": {
            'handlers': ['debug', 'request'],
            'level': "INFO",
            'propagate': False
        },
        # 不再赘述，详见debug_logger
        "info_logger": {
            'handlers': ['debug', 'info'],
            'level': "INFO",
            'propagate': False
        },
        # 不再赘述，详见debug_logger
        "warning_logger": {
            'handlers': ['debug', 'warning'],
            'level': "WARNING",
            'propagate': False
        },
        # 不再赘述，详见debug_logger
        "error_logger": {
            'handlers': ['debug', 'error'],
            'level': "ERROR",
            'propagate': False
        },
        # 不再赘述，详见debug_logger
        "critical_logger": {
            'handlers': ['debug', 'critical'],
            'level': "CRITICAL",
            'propagate': False
        },

    },
    # 基础logger，当不指定logger名称时，默认选择此logger
    "root": {
        'handlers': ['info'],
        'level': "DEBUG",
        'propagate': False
    }
}

# 用LOGGING配置logging
logging.config.dictConfig(LOGGING)
# 获取名为warning_logger的logger
logger = logging.getLogger('warning_logger')
# 打印各种日志
logger.debug('debug log')
logger.request('request log')
logger.info('info log')
logger.warning('warning log')
logger.error('error log')
logger.critical('critical log')

看完上面配置，注释多如狗，相信不用讲也能理解的差不多，不过还是分别讲讲。

logging分为3个组件，分别是：formater，handler和logger（配置文件中的version和disable_existing_loggers一般都是写死的，不用管），这三者的关系是这样的，logger负责调用handler（一个logger可以绑定多个handler），handler的打印或写入的内容则依赖于formater（一个handler只能对应一个formater），举个例子：

# 根据日志名从loggers中获取名为“warning_logger”的logger
logger = logging.getLogger('warning_logger')
# 获取的大概就是这一段，日志有2个handlers，分别是debug和warning
# "warning_logger": {
#     'handlers': ['debug', 'warning'],
#     'level': "WARNING",
#     'propagate': False
# }
# 打印warning日志，此时日志等级为warning，所有低于该等级的都会被打印，待会再讲什么是日志等级
logger.warning("warning log")
# 执行上面一段，会分别调用debug handler和warning handler，debug handler负责打印到控制台上，warning handler负责写入到./warning.log文件中。

以上就是一次简单的调用执行的过程，接下来分别细说下这几个模块。

1、formater
在平时写日志的过程中，很多固定的信息都是要记录的，比如日志时间，日志名称，日志等级，线程、进程信息等，每次都写不仅效率低，而且如果忘了写会导致日志内容的不一致，不容易解析，所以要为日志统一一下格式，正如下面配置文件中的，定义了名为simple的简单输出模式和名为standard复杂输出格式，当然还可以自定义其他格式：

"simple": {
            # 简单的输出模式
            'format': '%(asctime)s [%(name)s:%(lineno)d] [%(levelname)s]- %(message)s'
        },
        'standard': {
            # 较为复杂的输出模式，可以进行自定义
            'format': '%(asctime)s [%(threadName)s:%(thread)d] [%(name)s:%(lineno)d] [%(levelname)s]- %(message)s'

下面介绍下logging集成的输出格式中的一些参数，可以直接使用
asctime %(asctime)s 日志事件发生的时间，如：2003-07-08 16:49:45,896
created %(created)f 日志事件发生的时间--时间戳
msecs %(msecs)d 日志事件发生事件的毫秒部分
levelname %(levelname)s 日志等级
levelno %(levelno)s 日志级别的数字形式
name %(name)s 所使用的日志器名称，默认是'root'
message %(message)s 日志记录的文本内容
pathname %(pathname)s 调用日志记录函数的源码文件的全路径
filename %(filename)s pathname的文件名部分，包含文件后缀
module %(module)s filename的名称部分，不包含后缀
lineno %(lineno)d 调用日志记录函数的源代码所在的行号
funcName %(funcName)s 调用日志记录函数的函数名
process %(process)d 进程ID
processName %(processName)s 进程名称，Python 3.1新增
thread %(thread)d 线程ID
threadName %(thread)s 线程名称

2、handler
我目前了解到的，handler只做2件事情，第一是日志的打印，第二日志的写入和切分操作。

针对打印操作，handler可以调用logging.StreamHandler的类，stream配置为ext://sys.stdout，就可以完成打印到控制台。

针对写入操作，logging可以实现日志文件按大小或时间切割，按大小切割时，需要用到RotatingFileHandler类，并且需要制定文件切割的大小；按时间切割时则需要用到TimedRotatingFileHandler类，需要指定切割的时间点。本文以时间切割为例，需要配置when参数来指定切割时间点，具体配置如下：

“S”: Seconds
“M”: Minutes
“H”: Hours
“D”: Days
“W”: Week day (0=Monday)
“midnight”: Roll over at midnight

3、logger
其实没啥可说的，负责调用自己名下的handler。

最后，谈一下日志等级，包含：debug，info，warning，error，critical 5个等级，等级从左到右依次提升，就是说debug最低，critical最高。高等级的行为会触发低等级的logger或handler。

举个例子，等级为info的info_logger绑定了等级为debug的debug_handler和等级为warning的warning_handler，此时执行info_logger.info('info log')，此时执行等级为info，因自身等级不低于info，所以会被触发，此时依次触发名下的handler，首先是debug_handler，因为等级是deng低于info，所以debug_handler会执行，然后是warning_handler，因为等级高于info，所以不会触发。

再举个例子，比如执行info_logger.warning('info log')，此时执行等级为warning，高于info_logger的等级，所以info_logger不会被触发，尽管info_logger下有等级为warning的warning_handler，但是因为info_logger没有被触发，而其又依赖于info_logger存在，所以其也不会被触发。

本来还想写下如何处理logging的进程安全问题，不过突然觉得累了，简单说下。一个是mlogging模块，一个是ConcurrentLogHandler模块，都分别对此作了实现，或者可以改源码自己实现。大致原理都是借助fcntl模块给文件上锁解决的，亲测用python3的fcntl模块为文件加LOCK_EX锁，不仅其他python3的进程无法获取该文件的LOCK_EX锁，就连python2的进程也无法获取，猜测这个锁应该是系统级别的了。
嗯，先写这么多

更新一版最新的代码

import logging.config
import os
import sys
curr_path = os.path.abspath(os.path.dirname(__file__))
sys.path.append(curr_path)

'''
日志的配置参数，日志对象主要有3个子模块，分别为formater（输出格式），handler（日志操作类型），logger（日志名），要分别进行设置。
其中hadlers为日志的具体执行，依赖于formater和日志操作类型或一些属性，比如按大小分片还是时间分片，是写入还是打印到控制台。
logger负责调用handle，一个logger可以调用多个handler，比如logger.info调用了打印到控制台handler（logging.StreamHandler）
和写入到文件handler（mlogging.TimedRotatingFileHandler_MP），在没有指定logger名字的时候，即logger=logging.get_logger()的时候，
logger会自动选择名为root的logger
'''

# 当前兄弟目录
# log_root_path = os.path.join(str(os.path.abspath(__file__).rsplit('/', 1)[0]), 'logs')

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "simple": {
            # 简单的输出模式
            'format': '%(asctime)s|%(name)s|file:%(filename)s|lineno:%(lineno)d|logger:%(name)s|%(levelname)s - %(message)s'
        },
        'standard': {
            # 较为复杂的输出模式，可以进行自定义
            'format': '%(asctime)s threadId:%(thread)d|processId:%(process)d:|file:%(filename)s|lineno:%(lineno)d|func:%(funcName)s|module:%(module)s|logger:%(name)s|%(levelname)s - %(message)s'
        },
    },

    # 过滤器
    "filters": {
        'debug_filter': {
            '()': 'log_filters.DebugFilter'
        },
        'info_filter': {
            '()': 'log_filters.InfoFilter'
        },
        'warning_filter': {
            '()': 'log_filters.WarningFilter'
        },
        'error_filter': {
            '()': 'log_filters.ErrorFilter'
        },
        'critical_filter': {
            '()': 'log_filters.CriticalFilter'
        },
        'no_debug_filter': {
            '()': 'log_filters.NoDebugFilter'
        }
    },

    "handlers": {
        # 写入到文件的hanler，写入等级为info，命名为request是为了专门记录一些网络请求日志
        "request": {
            # 定义写入文件的日志类，此类为按时间分割日志类，还有一些按日志大小分割日志的类等
            "class": "mlogging.TimedRotatingFileHandler_MP",
            # 日志等级
            "level": "INFO",
            # 日志写入格式，因为要写入到文件后期可能会debug用，所以用了较为详细的standard日志格式
            "formatter": "standard",
            # 要写入的文件名
            "filename": os.path.join(log_root_path, 'default', 'request.log'),
            # 分割单位，D日，H小时，M分钟，W星期，一般是以小时或天为单位
            # 比如文件名为test.log，到凌晨0点的时候会自动分离出test.log.yyyy-mm-dd
            "when": 'D',
            "encoding": "utf8",
        },
        # 输出到控制台的handler
        "debug": {
            # 定义输出流的类
            "class": "logging.StreamHandler",
            # handler等级，如果实际执行等级高于此等级，则不触发handler
            "level": "DEBUG",
            # 输出的日志格式
            "formatter": "simple",
            # 流调用系统输出
            "stream": "ext://sys.stdout"
        },
        # 写入到文件的hanler，写入等级为info，命名为request是为了专门记录一些网络请求日志
        "info": {
            # 定义写入文件的日志类，此类为按时间分割日志类，还有一些按日志大小分割日志的类等
            "class": "mlogging.TimedRotatingFileHandler_MP",
            # 日志等级
            "level": "INFO",
            # 日志写入格式，因为要写入到文件后期可能会debug用，所以用了较为详细的standard日志格式
            "formatter": "standard",
            # 要写入的文件名
            "filename": os.path.join(log_root_path, 'default', 'info.log'),
            # 分割单位，D日，H小时，M分钟，W星期，一般是以小时或天为单位
            # 比如文件名为test.log，到凌晨0点的时候会自动分离出test.log.yyyy-mm-dd
            "when": 'D',
            "encoding": "utf8",
            "filters": ["info_filter"]
        },
        # 写入到文件的hanler，写入等级为warning
        "warning": {
            # 不再赘述，详细见request logger
            "class": "mlogging.TimedRotatingFileHandler_MP",
            "level": "WARNING",
            "formatter": "standard",
            "filename": os.path.join(log_root_path, 'default', 'warning.log'),
            "when": 'D',
            "encoding": "utf8",
            "filters": ["info_filter"]
        },
        # 写入到文件的hanler，写入等级为error
        "error": {
            # 不再赘述，详细见request logger
            "class": "mlogging.TimedRotatingFileHandler_MP",
            "level": "ERROR",
            "formatter": "standard",
            "filename": os.path.join(log_root_path, 'default', 'error.log'),
            "when": 'D',
            "encoding": "utf8",
            "filters": ["info_filter"]
        },
        # 写入到文件的hanler，写入等级为critical（一般有重大错误的时候才会用到此类打印）
        "critical": {
            # 不再赘述，详细见request logger
            "class": "mlogging.TimedRotatingFileHandler_MP",
            "level": "CRITICAL",
            "formatter": "standard",
            "filename": os.path.join(log_root_path, 'default', 'critical.log'),
            "when": 'D',
            "encoding": "utf8",
            "filters": ["info_filter"]
        },
    },
    "loggers": {
        # logger名字
        "my_logger": {
            # logger集成的handler
            'handlers': ['debug', 'info', 'warning', 'error', 'critical'],
            # logger等级，如果实际执行等级，高于此等级，则不触发此logger，logger中所有的handler均不会被触发
            'level': "DEBUG",
            # 是否继承root日志，如果继承，root的handler会加入到当前logger的handlers中
            'propagate': False
        },
        # logger名字
        "my_request_logger": {
            # logger集成的handler
            'handlers': ['debug', 'request', 'warning', 'error', 'critical'],
            # logger等级，如果实际执行等级，高于此等级，则不触发此logger，logger中所有的handler均不会被触发
            'level': "DEBUG",
            # 是否继承root日志，如果继承，root的handler会加入到当前logger的handlers中
            'propagate': False
        },
    },
    # 基础logger，当不指定logger名称时，默认选择此logger
    "root": {
        'handlers': ['info'],
        'level': "DEBUG",
        'propagate': False
    }
}


# 定义日志类
class Logger:

    # 单例模式存储对象
    __instance = {}
    __is_init = False

    # 对于每个app name单例模式
    def __new__(cls, app_name='default', *args, **kwargs):
        if app_name not in cls.__instance:
            cls.__instance[app_name] = super().__new__(cls)
        return cls.__instance[app_name]

    # 初始化logger，通过LOGGING配置logger
    def __init__(self, app_name='default', is_debug=True):
        if self.__is_init is True:
            return
        global log_root_path
        log_file_dir = os.path.join(log_root_path, app_name)
        print("app名为%s的日志被初始化了，日志会写入到：%s 文件夹下" % (app_name, log_file_dir))
        self.__is_init = True
        self.is_debug = is_debug

        # 初始化logging配置参数
        global LOGGING
        # 默认路径为当前文件所在目录的兄弟目录logs下的default目录 ./logs/default
        self.default_log_path = os.path.join(log_root_path, 'default')
        # # 默认路径为当前文件所在目录的兄弟目录logs下的app_name目录 ./logs/${app_name}
        self.log_root_path = os.path.join(log_root_path, app_name)
        # 不存在就创建default目录
        if not os.path.exists(self.log_root_path):
            os.makedirs(self.log_root_path)
        # 不存在就创建当前app_name对应的目录
        if not os.path.exists(self.default_log_path):
            os.makedirs(self.default_log_path)

        # 日志名和日志等级的映射
        log_levels = ['debug', 'info', 'warning', 'error',  'critical']

        # 根据app_name动态更新LOGGING配置，为每个app_name创建文件夹，配置handler
        for level in log_levels:
            # handler名称，如default_debug
            handler_name = '%s_%s' % (app_name, level)
            if level == 'debug':
                LOGGING['handlers'][handler_name] = self.get_console_handler_conf()
                # 日志名称，如default_debug_logger
            else:
                # handler 对应文件名，如 logs/default/request.log
                filename = os.path.join(self.log_root_path, (level + '.log'))
                # 日志等级转大写
                lev_up = level.upper()
                LOGGING['handlers'][handler_name] = self.get_file_handler_conf(filename=filename, level=lev_up)
                # 日志名称，如default_error_logger
        # 单独初始化request handler
        request_filename = os.path.join(self.log_root_path, 'request.log')
        request_handler_name = '%s_request' % app_name
        # 绑定request handler
        LOGGING['handlers'][request_handler_name] = self.get_file_handler_conf(filename=request_filename, level="INFO")

        # 添加app logger及app_request logger
        logger_name = '%s_logger' % app_name
        LOGGING['loggers'][logger_name] = self.get_logger_conf(app_name=app_name)
        request_logger_name = '%s_request_logger' % app_name
        LOGGING['loggers'][request_logger_name] = self.get_request_logger_conf(app_name=app_name)

        # import json
        # print(json.dumps(LOGGING, indent=2))

        # 将LOGGING中的配置信息更新到logging中
        logging.config.dictConfig(LOGGING)
        # 这里之所以要分6种logger，而不是只写一种logger，是为了将不同等级的日志信息，写入到不同的文件中，方便后期的debug和统计
        # 获取debug日志，用于只打印到控制台，不写入文件的日志，一般用于打印较长的sql，或是一大段json字符串
        self.debug_logger = logging.getLogger("%s_debug_logger" % app_name)
        # 获取request日志，一般用于记录请求日志，可以在用户开始访问和访问成功的时间点分别记录日志，可以统计访问的成功率
        self.request_logger = logging.getLogger("%s_request_logger" % app_name)
        # 获取info日志，也是最长用的一种日志，用于记录日常业务中的各种行为，是最灵活，使用最广泛的一种日志
        self.info_logger = logging.getLogger("%s_info_logger" % app_name)
        # 获取warning日志，一般用于有一些小错误或瑕疵，但不影响程序运行的行为的警告
        self.warning_logger = logging.getLogger("%s_warning_logger" % app_name)
        # 获取error日志，一般用于主动的错误提示，或者被动的捕获异常时的异常记录日志，常和try。。。except一起使用
        self.error_logger = logging.getLogger("%s_error_logger" % app_name)
        # 获取critical日志，用于重大异常，可能影响整体项目运行的异常
        self.critical_logger = logging.getLogger("%s_critical_logger" % app_name)

    # 控制台输出handler配置
    def get_console_handler_conf(self):
        console_handler_conf = {
            # 定义输出流的类
            "class": "logging.StreamHandler",
            # handler等级，如果实际执行等级高于此等级，则不触发handler
            "level": "DEBUG",
            # 输出的日志格式
            "formatter": "simple",
            # 流调用系统输出
            "stream": "ext://sys.stdout"
        }
        if self.is_debug:
            console_handler_conf['filters'] = ['debug_filter']
        else:
            console_handler_conf['filters'] = ['no_debug_filter']
        return console_handler_conf

    @staticmethod
    # 写入文件handler配置
    def get_file_handler_conf(filename: str, level='INFO'):
        file_handler_conf = {
            # 定义写入文件的日志类，此类为按时间分割日志类，还有一些按日志大小分割日志的类等
            "class": "mlogging.TimedRotatingFileHandler_MP",
            # 日志等级
            "level": "",
            # 日志写入格式，因为要写入到文件后期可能会debug用，所以用了较为详细的standard日志格式
            "formatter": "standard",
            # 要写入的文件名
            "filename": '',
            # 分割单位，D日，H小时，M分钟，W星期，一般是以小时或天为单位
            # 比如文件名为test.log，到凌晨0点的时候会自动分离出test.log.yyyy-mm-dd
            "when": 'D',
            "encoding": "utf8",
            "filters": []
        }
        filters = ['%s_filter' % (level.lower())]
        update_dict = {'filename': filename, 'level': level, 'filters': filters}
        file_handler_conf.update(update_dict)
        return file_handler_conf

    @staticmethod
    # logger 配置
    def get_logger_conf(app_name='default'):
        logger_conf = {
            'handlers': [],
            'level': "DEBUG",
            'propagate': False
        }
        # 如果只是debug级别logger，只配置打印handler，不会记录到文件中
        log_levels = ['debug', 'info', 'warning', 'error', 'critical']
        logger_conf['handlers'] = ['%s_%s' % (app_name, level) for level in log_levels]
        return logger_conf

    @staticmethod
    # request logger配置
    def get_request_logger_conf(app_name='default'):
        logger_conf = {
            'handlers': [],
            'level': "DEBUG",
            'propagate': False
        }
        log_levels = ['debug', 'request', 'warning', 'error', 'critical']
        logger_conf['handlers'] = ['%s_%s' % (app_name, level) for level in log_levels]
        return logger_conf


# 获取日常logger
def get_logger(app_name: str, is_debug=True):
    Logger(app_name, is_debug=is_debug)
    logger_name = '%s_logger' % app_name
    logger = logging.getLogger(logger_name)
    return logger


# 获取request logger
def get_request_logger(app_name: str, is_debug=True):
    Logger(app_name, is_debug=is_debug)
    logger_name = '%s_request_logger' % app_name
    logger = logging.getLogger(logger_name)
    return logger


if __name__ == '__main__':
    # 单例模式测试
    logger = get_request_logger('lr_test', is_debug=True)

    logger.debug('debug log')
    logger.debug('debug log')
    logger.debug('debug log')

filter代码：

import logging


class NoDebugFilter(logging.Filter):

    def filter(self, record):
        return False


class DebugFilter(logging.Filter):

    def filter(self, record):
        level = record.levelname.upper()
        if level == 'DEBUG':
            return True
        return False


class InfoFilter(logging.Filter):

    def filter(self, record):
        level = record.levelname.upper()
        if level in {'INFO', 'WARNING', 'ERROR'}:
            return True
        return False


class WarningFilter(logging.Filter):

    def filter(self, record):
        level = record.levelname.upper()
        if level == 'WARNING':
            return True
        return False


class ErrorFilter(logging.Filter):

    def filter(self, record):
        level = record.levelname.upper()
        if level == 'ERROR':
            return True
        return False


class CriticalFilter(logging.Filter):

    def filter(self, record):
        level = record.levelname.upper()
        if level == 'CRITICAL':
            return True
        return False