python Logging日志记录模块详解

写在篇前
  logging是Python的一个标准库，其中定义的函数和类为应用程序和库的开发实现了一个灵活的事件日志系统。Python logging 的配置由四个部分组成：Logger、Handlers、Filter、Formatter。本篇博客将依次介绍这四个主要部分以及logging的基本应用。

  在开始之前，我们有必要先了解一下，什么时候我们才有必要使用logging模块，什么时候抛出异常(raise Exception)，什么时候使用简单的print函数即可，官方文档给我们总结了一个表格：

 

Task you want to perform    The best tool for the task
命令行终端输出或则程序一般的输出情景    print()
报告程序正常运行期间发生的事件（例如，状态监视或故障调查）    logging.info()(或则 logging.debug() 用于诊断目的细节输出)
发出有关特定运行时事件的警告    warnings.warn() : 用于如果问题是可以避免的，且应修改应用程序以消除警告的情景;logging.warning()用于如果应用程序无法处理该情况，但仍应注意该事件的情景。
报告有关特定运行时事件的错误    Raise an exception
报告在不引发异常的情况下抑制错误（例如，长时间运行的服务器进程中的错误处理程序）    logging.error(), logging.exception()或则logging.critical() 适用于特定错误和应用程序域
Loggers
  logger是暴露给代码进行日志操作的接口。需要注意的是，logger不应该直接实例化，而应通过模块级函数logging.getLogger(name)创建。如果name是具有层级结构的命名方式，则logger之间也会有层级关系。如name为foo.bar，foo.bar.baz， foo.bam 的logger是foo的子孙，默认子logger日志会向父logger传播，可以通过logger.propagate=False禁止；对具有相同名称的getLogger()的多次调用将始终返回同一Logger对象的引用。logger对象的功能包括以下三项：

向应用程序暴露info、debug等方法，用于程序运行时进行日志记录；
根据log level（默认过滤工具）或Filter对象确定要处理的日志消息；
将日志消息传递给所有感兴趣的Log Handler;
  另外，需要理清以下两个概念：

Log Record

Each message that is written to the Logger is a Log Record. 可以使用makeLogRecord()函数创建record对象（一般用不上），record对象常用的属性如下，全部属性请参考官方文档：

record.levelname # record level
record.levelno # record level number
record.msg # record承载的日志消息
record.pathname # emit该日志消息的程序文件
record.lineno # emit该日志消息的程序行号
record.getMessage() # 同record.msg
 从python 3.2起，logging模块提供了工厂函数getLogRecordFactory() 和setLogRecordFactory()方便、支持用户自定义record属性。

old_factory = logging.getLogRecordFactory()

def record_factory(*args, **kwargs):
    record = old_factory(*args, **kwargs)
    record.custom_attribute = 0xdecafbad
    return record

logging.setLogRecordFactory(record_factory)

Log Level

  每个logger都需要设置一个log level，该log level描述了logger将处理日志消息的级别; 每个log record也具有一个log Level，指示该特定日志消息的级别。 log record还可以包含被记录事件的metadata，包括诸如堆栈跟踪或错误代码之类的详细信息。如果设置了logger的log level，系统便只会输出 level 数值大于或等于该 level 的的日志结果，例如我们设置了输出日志 level 为 INFO，那么输出级别小于 INFO 的日志，如DEBUG 和 NOSET 级别的消息不会输出。logger还有一个effective level的概念，如果logger没有显式设置log level，则使用其parent logger的log level作为其effective level，其中root logger的默认log level是WARNING。

NOTEST:lowest level

# Level Num 0
 logger.setLevel(level=logging.NOTEST)

DEBUG: Low level system information for debugging purposes

 # Level Num 10
 logger.setLevel(level=logging.DEBUG
 logger.debug('Debugging')

INFO: General system information

# Level Num 20
 logger.setLevel(level=logging.INFO)
 logger.info('This is a log info')

WARNING: Information describing a minor problem that has occurred.

# Level Num 30，默认是该level
 logger.setLevel(level=logging.WARNING)
 logger.warning('Warning exists')
 logger.warn('Warning exists')  # deprecated

ERROR: Information describing a major problem that has occurred.

# Level Num 40
 logger.setLevel(level=logging.ERROR)
 logger.error('some error occur')

CRITICAL: Information describing a critical problem that has occurred.

# Level Num 50
 logger.setLevel(level=logging.NOTEST)
 
 logger.critical('critical err occur')
 logger.fatal('fatal error occur') 

  上面各个函数还有一个统一的调用方式logger.log(level, msg, exc_info=True)，其中，level是指上面标注的level num，exc_info指示是否打印执行信息；Logger.exception()创建与 Logger.error()相似的日志消息，不同之处是， Logger.exception()同时还记录当前的堆栈追踪，请仅从异常处理程序调用此方法。

  logger对象还有一些其他属性、方法值得关注：

>>>logger = logging.getLogger('main')  # 如果不指定name将会返回root logger
>>>logger.setLevel(level=logging.DEBUG)

>>>logger.disabled  # False
>>>logger.propagate=False
>>>logger.getEffectiveLevel()  # 10
>>>logger.isEnabledFor(20)  # True

>>>logging.disable(20)
>>>logger.isEnabledFor(20)  # False
>>>logger.isEnabledFor(30)  # True

>>>child_logger = logger.getChild('def.ghi')  # <Logger main.def.ghi (DEBUG)>

# Filter
addFilter(filter)
removeFilter(filter)

# handler
logger.hasHandlers()  # False
addHandler(hdlr)
removeHandler(hdlr)

  关于上面各种Level的调用情景，官方文档也给出了相应说明：

Level    When it’s used
DEBUG    Detailed information, typically of interest only when diagnosing problems.
INFO    Confirmation that things are working as expected.
WARNING    An indication that something unexpected happened, or indicative of some problem in the near future (e.g. ‘disk space low’). The software is still working as expected.
ERROR    Due to a more serious problem, the software has not been able to perform some function.
CRITICAL    A serious error, indicating that the program itself may be unable to continue running.
Handlers
 Once a logger has determined that a message needs to be processed, it is passed to a Handler. The handler is the engine that determines what happens to each message in a logger. Like loggers, handlers also have a log level. If the log level of a log record doesn’t meet or exceed the level of the handler, the handler will ignore the message.

  handler对象负责将适当的日志消息（基于日志消息的log level）分发给handler的指定目标，如文件、标准输出流等。logging模块中主要定义了以下Handlers，其中StreamHandler和FileHandler最为常用。

logging.StreamHandler # 日志输出到流，可以是 sys.stderr，sys.stdout 或者文件。
logging.FileHandler  # 日志输出到文件。
logging.handlers.BaseRotatingHandler  # 基本的日志回滚方式。
logging.handlers.RotatingHandler  # 日志回滚方式，支持日志文件最大数量和日志文件回滚。
logging.handlers.TimeRotatingHandler  # 日志回滚方式，在一定时间区域内回滚日志文件。
logging.handlers.SocketHandler  # 远程输出日志到TCP/IP sockets。
logging.handlers.DatagramHandler  # 远程输出日志到UDP sockets。
logging.handlers.SMTPHandler  # 远程输出日志到邮件地址。
logging.handlers.SysLogHandler  # 日志输出到syslog。
logging.handlers.NTEventLogHandler  # 远程输出日志到Windows NT/2000/XP的事件日志。
logging.handlers.MemoryHandler  # 日志输出到内存中的指定buffer。
logging.handlers.HTTPHandler  # 通过”GET”或者”POST”远程输出到HTTP服务器。
logging.NullHandler

  以FileHandler为例，创建Handler对象并设置log Level

>>> handler = logging.FileHandler('result.log')
>>> handler.setLevel(logging.DEBUG)
>>> handler.setFormatter(fmt)  # fmt是一个Formatter对象，下面再讲

# Filter
addFilter(filter)
removeFilter(filter)

Filters
 A filter is used to provide additional control over which log records are passed from logger to handler. Filters can be installed on loggers or on handlers; multiple filters can be used in a chain to perform multiple filtering actions.

  logging标准库只提供了一个base Filter，其构造函数__init__接收name参数，默认的行为是名为name的logger极其子logger的消息能通过过滤，其余皆会被滤掉。当然我们也可以根据具体的业务逻辑自定义Filter，并且也非常简单，只需要继承logging.Filter类重写filter方法即可，filter方法接收record对象作为参数，返回True代表通过过滤，返回False表示该record被过滤。

import logging

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.INFO)
handler = logging.StreamHandler()
handler.setLevel(logging.DEBUG)
handler.set_name('output-log')
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s',
                              datefmt='%Y/%m/%d %H:%M:%S',
                              style='%')


class MyFilter(logging.Filter):
    def filter(self, record):
        if 'result' in record.msg:
            return False
        return True


handler.setFormatter(formatter)
handler.addFilter(MyFilter('aa'))
logger.addHandler(handler)

try:
    result = 10 / 0
except:
    logger.error('Faild to get result')
    logger.error('Faild')

# 输出： 2019/07/13 20:28:51 - __main__ - ERROR - Faild

  从python3.2起，自定义filter也可以不继承logging.Filter，只需要定义一个函数并同样绑定即可：

def _filter(record):
    if 'result' in record.msg:
        return False
    return True


handler.addFilter(_filter)

Formatters
  Formatter用来规定Log record文本的格式，其使用python formatting string来规定具体格式。在默认情况下，logging模块的输出格式如下：

import logging
logging.warning('%s before you %s', 'Look', 'leap!')

# WARNING:root:Look before you leap!

  但是，默认的输出格式不一定能满足我们的需求，我们可以通过Formatter自定义输出格式，在日志中添加更多丰富的信息，一些常见的项(实际上以下都是Log Record的属性)如下所示：

%(levelno)s：打印日志级别的数值。

%(levelname)s：打印日志级别的名称。

%(pathname)s：打印当前执行程序的路径，其实就是sys.argv[0]。

%(filename)s：打印当前执行程序名。

%(funcName)s：打印日志的当前函数。

%(lineno)d：打印日志的当前行号。

%(asctime)s：打印日志的时间。

%(thread)d：打印线程ID。

%(threadName)s：打印线程名称。

%(process)d：打印进程ID。

%(processName)s：打印线程名称。

%(module)s：打印模块名称。

%(message)s：打印日志信息。

  设置Formatter主要包括两种方式，一种是通过Formatter类构建Formatter实例，并将其绑定到特定的handler上；一种是通过logging.basicConfig设置：

import loging
import time

# 1
logging.basicConfig(
                    format='%(asctime)s - %(name)s - %(levelname)s - %(lineno)d - %(funcName)s - %(message)s',
                    datefmt='%Y/%m/%d %H:%M:%S',
                    style='%'  # '%', ‘{‘ or ‘$’
                    )
# 2
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s',
                              datefmt='%Y/%m/%d %H:%M:%S',
                              style='%')
formatter.converter = time.localtime()
formatter.converter = time.gmtime()

  datefmt的设置，请参考time.strftime()

logging config
basicConfig
  使用logging模块的接口函数basicConfig可以非常方便的进行基本的配置。其中需要注意两点该函数stream 、filename以及handlers这三个参数是互斥的。
logging.basicConfig函数是一个one-off simple configuration facility，只有第一次调用会有效，并且它的调用应该在任何日志记录事件之前。

import logging


logging.basicConfig(
                    filename='./log.log',
                    filemode='w',
                    format='%(asctime)s - %(name)s - %(levelname)s - %(lineno)d - %(funcName)s - %(message)s',
                    datefmt='%Y/%m/%d %H:%M:%S',
                    style='%',
                    level=logging.DEBUG
                    )
logger = logging.getLogger(__name__)

try:
    result = 10 / 0
except:
    logger.error('Faild to get result', exc_info=True)

logger.log(50, 'logging critical test')

stepByStepConfig
  这种设计方式条理清晰，但是会但麻烦一点点，配置的逻辑就是：一个logger可以有多个handler；每个handler可以有一个Formatter；handler和logger都需要设置一个log Level；根据需要logger和handler都可以添加多个Filter。

fileConfig
  通过配置文件来配置logging模块，这是web应用中比较常见的一种设置方式

import logging
import logging.config

logging.config.fileConfig('logging.conf', disable_existing_loggers=True)

# 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')

 

[loggers]
keys=root,simpleExample

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG  # can be one of DEBUG, INFO, WARNING, ERROR, CRITICAL or NOTSET
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=

  fileConfig文件的解读主要基于configparser，它必须包含 [loggers], [handlers] 和 [formatters] section。这是一个比较老的API，不支持配置Filter，估计后面也不会更新了，所以建议大家使用dictConfig。

dictConfig
  通过dictConfig配置即可以通过python代码构建一个dict对象，也可以通过yaml、JSON文件来进行配置。字典中必须传入的参数是version，而且目前有效的值也只有1。其他可选的参数包括以下：

formatters

对于formatter,主要搜寻format和datefmt参数，用来构造Formatter实例。

filters

对于filter,主要搜寻name参数(默认为空字符串)，用来构造Formatter实例。

handlers

对于handlers，主要包括以下参数，其他的参数将作为关键字参数传递到handlers的构造函数：

class (mandatory). This is the fully qualified name of the handler class.
level (optional). The level of the handler.
formatter (optional). The id of the formatter for this handler.
filters (optional). A list of ids of the filters for this handler.

 

handlers:
  console:
    class : logging.StreamHandler
    formatter: brief
    level   : INFO
    filters: [allow_foo]
    stream  : ext://sys.stdout
  file:
    class : logging.handlers.RotatingFileHandler
    formatter: precise
    filename: logconfig.log
    maxBytes: 1024
    backupCount: 3

loggers

对于loggers，主要包括以下参数：

level (optional). The level of the logger.
propagate (optional). The propagation setting of the logger.
filters (optional). A list of ids of the filters for this logger.
handlers (optional). A list of ids of the handlers for this logger.
root

这是给root logger的配置项

incremental

是否将此配置文件解释为现有配置的增量, 默认为False

disable_existing_loggers

是否要禁用现有的非 root logger，默认为True

  以下给出一个较为完成的YAML示例，注意体会loggers, handlers, formatters, filters之间的关联性，该配置文件定义了brief和simple两种formatter；定义了console、file、error三个handler,其中console使用brief formatter，file和error使用simple formatter；main.core logger使用file和error handler，root logger使用console handler：

version: 1
formatters:
  brief:
    format: "%(asctime)s - %(message)s"
  simple:
    format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
handlers:
  console:
    class : logging.StreamHandler
    formatter: brief
    level   : INFO
    stream  : ext://sys.stdout
  file:
    class : logging.FileHandler
    formatter: simple
    level: DEBUG
    filename: debug.log
  error:
    class: logging.handlers.RotatingFileHandler
    level: ERROR
    formatter: simple
    filename: error.log
    maxBytes: 10485760
    backupCount: 20
    encoding: utf8
loggers:
  main.core:
    level: DEBUG
    handlers: [file, error]
root:
  level: DEBUG
  handlers: [console]

  将上面的configuration setup可以通过以下方法：

import logging
import yaml
import logging.config
import os

def setup_logging(default_path='config.yaml', default_level=logging.INFO):
    if os.path.exists(default_path):
        with open(default_path, 'r', encoding='utf-8') as f:
            config = yaml.load(f)
            logging.config.dictConfig(config)
    else:
        logging.basicConfig(level=default_level)

  dictConfig通过将dict数据传递给dictConfigClass，然后返回对象调用configure函数使配置生效。

def dictConfig(config):
    """Configure logging using a dictionary."""
    dictConfigClass(config).configure()

User-defined objects
  logging模块 dictConfig为了支持handlers，filters和formatters的用户自定义对象，可以通过助记符()指定一个工厂函数来实例化自定义对象，下面定义的 custom formatter相当于my.package.customFormatterFactory(bar='baz', spam=99.9, answer=42)

formatters:
  brief:
    format: '%(message)s'
  default:
    format: '%(asctime)s %(levelname)-8s %(name)-15s %(message)s'
    datefmt: '%Y-%m-%d %H:%M:%S'
  custom:
      (): my.package.customFormatterFactory
      bar: baz
      spam: 99.9
      answer: 42

Access to external objects
  logging模块 dictConfig为了支持链接外部objects，如sys.stdout，可以使用ext://sys.stderr。内部原理是进行正则匹配^(?P<prefix>[a-z]+)://(?P<suffix>.*)$，如果prefix有意义，则会按照prefix预定义的方式处理suffix；否则保持字符串原样。

Access to internal objects
  logging模块 dictConfig为了支持链接配置文件内部objects，首先，比如logger或则handler中的level值设置DEBUG，配置系统会自动地将其转换成logging.DEBUG；但是，对于logging模块不知道的用户定义对象，需要一种更通用的机制来完成，比如我自定义一个handler，这个handler又需要另一个handler来代理，那么可以这样定义：

handlers:
  file:
    # configuration of file handler goes here

  custom:
    (): my.package.MyHandler
    alternate: cfg://handlers.file

  举一个更复杂的例子，如下面文件所定义YAML配置文件，则cfg://handlers.email.toaddrs[0]会被解析到其值为support_team@domain.tld；subject的值可以通过cfg://handlers.email.subject或者cfg://handlers.email[subject]拿到。

handlers:
  email:
    class: logging.handlers.SMTPHandler
    mailhost: localhost
    fromaddr: my_app@domain.tld
    toaddrs:
      - support_team@domain.tld
      - dev_team@domain.tld
    subject: Houston, we have a problem.

Optimization
  当你不想收集以下信息时，你可以对你的日志记录系统进行一定的优化：

你不想收集的内容    如何避免收集它
有关调用来源的信息    将 logging._srcfile 设置为 None 。这避免了调用 sys._getframe()，如果 PyPy 支持 Python 3.x ,这可能有助于加速 PyPy （无法加速使用了sys._getframe()的代码）等环境中的代码.
线程信息    将 logging.logThreads 置为 0 。
进程信息    将 logging.logProcesses 置为 0 。
  另外，核心的logging模块只包含基本的handlers，如果你不显式导入 logging.handlers 和 logging.config ，它们将不会占用任何内存。

实例运用
  logging模块的落脚点当然是实际项目中的运用，比如对于简单的程序可以参考以下的使用方式，先在一个模块中创建并定义好root logger，在其他模块中调用get_logger函数创建其子logger。

import logging


logger = logging.getLogger('logger')
logger.propagate = False  # wii not pass log messages on to logging.root and its handler
logger.setLevel('INFO')
logger.addHandler(logging.StreamHandler())  # Logs go to stderr
logger.handlers[-1].setFormatter(logging.Formatter('%(message)s'))
logger.handlers[-1].setLevel('INFO')


def get_logger(name):
    """Creates a child logger that delegates to anndata_logger instead to logging.root"""
    return logger.manager.getLogger(name)

  对于更加复杂的场景，用户也可以重载logging模块提供的logger类logging.Logger或者logging.RootLogger的自定义logging Level，实现更加灵活的日志记录功能。比如，以下定义一个新的HINT log Level，通过继承重写logging.RootLogger获得自定义的Logger类。

import logging


HINT = (INFO + DEBUG) // 2
logging.addLevelName(HINT, 'HINT')


class RootLogger(logging.RootLogger):
    def __init__(self, level):
        super().__init__(level)
        self.propagate = False
        RootLogger.manager = logging.Manager(self)

    def log(
        self,
        level: int,
        msg: str,
        *,
        extra: Optional[dict] = None,
        time: datetime = None,
        deep: Optional[str] = None,
    ) -> datetime:
        now = datetime.now(timezone.utc)
        time_passed: timedelta = None if time is None else now - time
        extra = {
            **(extra or {}),
            'deep': deep,
            'time_passed': time_passed
        }
        super().log(level, msg, extra=extra)
        return now

    def critical(self, msg, *, time=None, deep=None, extra=None) -> datetime:
        return self.log(CRITICAL, msg, time=time, deep=deep, extra=extra)

    def error(self, msg, *, time=None, deep=None, extra=None) -> datetime:
        return self.log(ERROR, msg, time=time, deep=deep, extra=extra)

    def warning(self, msg, *, time=None, deep=None, extra=None) -> datetime:
        return self.log(WARNING, msg, time=time, deep=deep, extra=extra)

    def info(self, msg, *, time=None, deep=None, extra=None) -> datetime:
        return self.log(INFO, msg, time=time, deep=deep, extra=extra)

    def hint(self, msg, *, time=None, deep=None, extra=None) -> datetime:
        return self.log(HINT, msg, time=time, deep=deep, extra=extra)

    def debug(self, msg, *, time=None, deep=None, extra=None) -> datetime:
        return self.log(DEBUG, msg, time=time, deep=deep, extra=extra)

写在篇后
  本篇博客基本上涵盖了python logging模块大部分的功能，但是也有一些尚未cover。比如logging模块会默认吞噬除了SystemExit和KeyboardInterrupt的一切异常，因为logging.raiseExceptions默认为True(生产环境也推荐设置为True)；logging.captureWarnings(capture=True)会重定向warning信息到logging模块；另外，可以通过logging.setLoggerClass()决定初始化logger的类型，与之对应的有logging.getLoggerClass()

等等，更多的用法在实践中再慢慢总结经验，吸取教训。
————————————————