Python的logging模块

我们知道一个良好的系统，日志模块是必不可少的，Python的基础日志模块便是logging模块。

这一篇文章，我们从源码去看下logging模块的组成。

1. 开始

最开始，我们用最短的代码体验一下logging的基本功能

In [30]: import logging

In [31]: loger = logging.getLogger()

In [32]: logging.basicConfig()

In [33]: loger.setLevel("DEBUG")

In [34]: loger.debug('logsomething')
DEBUG:root:logsomething

第一步：通过logging.getLoger函数，获得一个loger对象，但这个对象暂时是无法使用的。

第二步：logging.basicConfig函数，进行一系列默认的配置，包括format、handler等。

第三步：loger调用setLevel函数定义日志级别为DEBUG

最后：logger调用debug函数，输出一条debug级别的message，显示在了标准输出上

2. logging中的日志级别

logging在生成日志的时候，有一个日志级别的机制，默认有以下几个日志级别：

CRITICAL = 50
FATAL = CRITICAL
ERROR = 40
WARNING = 30
WARN = WARNING
INFO = 20
DEBUG = 10
NOTSET = 0

每一个logger对象，都有一个日志级别，它只会输出大于等于它level的日志。如果一个logger的level是INFO，那么调用logger.debug()是无法输出日志的，而logger.warning()能够输出。

一般来说，以上的6个日志级别完全满足我们日常使用了。

3. logging中的基础类

logging是python中的一个基础模块，它在python中的源码位置如下：

python3.7/logging/__init__.py # 主干代码
python3.7/logging/config.py # 扩展的handler和config
python3.7/logging/handlers.py

组成logging的主干的几个基础类都在__init__.py中

3.1 第一个基础类 LogRecord

一个LogRecord对象，对应了日志中的一行数据。通常包含：时间、日志级别、message信息、当前执行的模块、行号、函数名……这些信息都包含在一个LogRecord对象里。

LogRecord对象可以想象成一个大字典

class LogRecord(object):
    """
    A LogRecord instance represents an event being logged.
    代表一个事件被记录的实例
    """
    def __init__(self, name, level, pathname, lineno,
                 msg, args, exc_info, func=None, sinfo=None, **kwargs):
        ct = time.time()
        self.name = name
        self.msg = msg

    def getMessage(self):
        """
        Return the message for this LogRecord.
        返回日志的具体信息
        """
        msg = str(self.msg)
        if self.args:
            msg = msg % self.args
        return msg
      
def makeLogRecord(dict):
    """
    这个方法很重要，生成一个空的LogRecord，然后通过一个字典，直接更新LogRecord中的成员变量
    """
    rv = _logRecordFactory(None, None, "", 0, "", (), None, None)
    rv.__dict__.update(dict)
    return rv

3.2 第二个基础类 Formatter

Formatter对象是用来定义日志格式的，LogRecord保存了很多信息，但是打日志的时候我们只需要其中几个，Formatter就提供了这样的功能，它依赖于python的字符串的格式化：

# 通过字典的方式,输出格式化字符串
print('%(name)s:%(num)d' % {'name':'my_name','num': 100})
out>>my_name:100

如果说LogRecord是后面的那个字典，那么Formatter就是前面的那个格式字符串……的抽象

重要的代码：

class PercentStyle(object):

    default_format = '%(message)s'
    asctime_format = '%(asctime)s'
    asctime_search = '%(asctime)'

    def __init__(self, fmt):
        self._fmt = fmt or self.default_format

    def usesTime(self):
        return self._fmt.find(self.asctime_search) >= 0

    def format(self, record):
      	"""
      	真正格式化日志的函数
      	"""
        return self._fmt % record.__dict__
        
_STYLES = {
    '%': (PercentStyle, BASIC_FORMAT),
    '{': (StrFormatStyle, '{levelname}:{name}:{message}'),
    '$': (StringTemplateStyle, '${levelname}:${name}:${message}'),
}

class Formatter(object):
    """
    Formatter instances are used to convert a LogRecord to text.
    """

    converter = time.localtime

    def __init__(self, fmt=None, datefmt=None, style='%'):
        """
        Initialize the formatter with specified format strings.
        """
        if style not in _STYLES:
            raise ValueError('Style must be one of: %s' % ','.join(
                             _STYLES.keys()))
            
        self._style = _STYLES[style][0](fmt) # 默认的format
        self._fmt = self._style._fmt
        self.datefmt = datefmt
        
    def formatMessage(self, record):
      	# 调用 PercentStyle 或者PercentStyle子类的 format
        return self._style.format(record)

    def format(self, record):
        """
        Format the specified record as text.
        """
        record.message = record.getMessage()
        if self.usesTime():
            record.asctime = self.formatTime(record, self.datefmt)
        
        # 格式化信息
        s = self.formatMessage(record)

        return s

3.3 第三个基础类 Filter和Filterer

Filter类，功能很简单。Flter.filter()函数传入一个LogRecord对象，通过筛选返回True，否则返回False。从代码中可以看到，其实是对LogRecord.name的筛选。

Filterer类中有一个Filter对象的列表，它是一组Filter的抽象。

重要的代码如下：

class Filter(object):
    """
    Filter instances are used to perform arbitrary filtering of LogRecords.

    Loggers and Handlers can optionally use Filter instances to filter
    records as desired. The base filter class only allows events which are
    below a certain point in the logger hierarchy. For example, a filter
    initialized with "A.B" will allow events logged by loggers "A.B",
    "A.B.C", "A.B.C.D", "A.B.D" etc. but not "A.BB", "B.A.B" etc. If
    initialized with the empty string, all events are passed.
    """
    def __init__(self, name=''):
        """
        Initialize a filter.

        """
        self.name = name
        self.nlen = len(name)

    def filter(self, record):
        """
        Determine if the specified record is to be logged.

        Is the specified record to be logged? Returns 0 for no, nonzero for
        yes. If deemed appropriate, the record may be modified in-place.
        """
        # 返回True表示record通过，False表示record不通过
        if self.nlen == 0:
            return True
        elif self.name == record.name:
            return True
        # record.name不是以filter开头
        elif record.name.find(self.name, 0, self.nlen) != 0:
            return False
        # record.name 最后一位是否为.
        return (record.name[self.nlen] == ".")

针对return (record.name[self.nlen] == ".")这句话可以举例：

"A.B"能够通过的是"A.B."

class Filterer(object):
    """
    A base class for loggers and handlers which allows them to share
    common code.
    """
    def __init__(self):
        """
        Initialize the list of filters to be an empty list.
        定义了一个self.filters=[]的列表管理多个filter
        """
        self.filters = []

    def addFilter(self, filter):
        """
        Add the specified filter to this handler.
        """
        if not (filter in self.filters):
            self.filters.append(filter)

    def removeFilter(self, filter):
        """
        Remove the specified filter from this handler.
        """
        if filter in self.filters:
            self.filters.remove(filter)

    def filter(self, record):
        """
        Determine if a record is loggable by consulting all the filters.

        The default is to allow the record to be logged; any filter can veto
        this and the record is then dropped. Returns a zero value if a record
        is to be dropped, else non-zero.

				使用列表中所有的filter进行筛选，任何一个失败都会返回0
				例如:
				filter1.name='A',filter2.name='A.B',filter3.name='A.B.C'
				此时record.name='A.B.C.D'这样的record才能通过所有filter的筛选
        """
        rv = True
        for f in self.filters:
            if hasattr(f, 'filter'):
                result = f.filter(record)
            else:
                result = f(record) # assume callable - will raise if not
            if not result:
                rv = False
                break
        return rv

4. logging中的高级类

有了以上三个基础的类，就可以拼凑一些更重要的高级类了，高级类可以实现logging的重要功能。

4.1 Handler——抽象了log的输出过程

• Handler类继承自Filterer。Handler类是log输出这个过程的抽象
• 同时Handler类具有一个成员变量self.level,在第二节讨论的日志级别的机制，就是在Handler中实现的。
• Handler有一个emit(record)函数，这个函数负责输出log，必须在Handler的子类中实现。

重要代码如下：

class Handler(Filterer):
    """
    Handler instances dispatch logging events to specific destinations.
    """
    def __init__(self, level=NOTSET):
        """
        Initializes the instance - basically setting the formatter to None
        and the filter list to empty.
        """
        Filterer.__init__(self)
        self._name = None
        self.level = _checkLevel(level) # handler必须有level属性
        self.formatter = None
        # Add the handler to the global _handlerList (for cleanup on shutdown)
        _addHandlerRef(self)
        self.createLock()

    def get_name(self):
        return self._name

    def set_name(self, name):
        _acquireLock()
        try:
            if self._name in _handlers:
                del _handlers[self._name]
            self._name = name
            if name:
                _handlers[name] = self
        finally:
            _releaseLock()

    name = property(get_name, set_name)

    def createLock(self):
        """
        Acquire a thread lock for serializing access to the underlying I/O.
        """
        self.lock = threading.RLock()
        _register_at_fork_acquire_release(self)

    def acquire(self):
        """
        Acquire the I/O thread lock.
        """
        if self.lock:
            self.lock.acquire()

    def release(self):
        """
        Release the I/O thread lock.
        """
        if self.lock:
            self.lock.release()

    def setLevel(self, level):
        """
        Set the logging level of this handler.  level must be an int or a str.
        """
        self.level = _checkLevel(level)

    def format(self, record):
        """
        Format the specified record.

        If a formatter is set, use it. Otherwise, use the default formatter
        for the module.
        """
        if self.formatter:
            fmt = self.formatter
        else:
            fmt = _defaultFormatter
        return fmt.format(record)

    def emit(self, record):
        """
        需要子类实现
        """
        raise NotImplementedError('emit must be implemented '
                                  'by Handler subclasses')

    def handle(self, record):
        """
        Conditionally emit the specified logging record.

        Emission depends on filters which may have been added to the handler.
        Wrap the actual emission of the record with acquisition/release of
        the I/O thread lock. Returns whether the filter passed the record for
        emission.
        """
        # 如果通过filter的筛选，则emit这条log
        # 这个过程是线程安全的
        rv = self.filter(record)
        if rv:
            self.acquire()
            try:
                self.emit(record)
            finally:
                self.release()
        return rv

    def setFormatter(self, fmt):
        """
        Set the formatter for this handler.
        """
        self.formatter = fmt

    def flush(self):
        """
        Ensure all logging output has been flushed.
        """
        pass

接下来看两个简单的handler的子类，其实在logging源码中，有一个handler.py专门定义了很多更复杂的handler，有的可以将log缓存在内存中，有的可以将log做rotation等.

4.1.1 StreamHandler

最简单的handler实现，将log写入一个流中，默认的stream是sys.stderr

重要的代码如下：

class StreamHandler(Handler):
    """
    A handler class which writes logging records, appropriately formatted,
    to a stream. Note that this class does not close the stream, as
    sys.stdout or sys.stderr may be used.
    """

    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
        self.stream = stream

    def flush(self):
        """
        Flushes the stream.
        """
        self.acquire()
        try:
            if self.stream and hasattr(self.stream, "flush"):
                self.stream.flush()
        finally:
            self.release()

    def emit(self, record):
        """
        Emit a record.

        If a formatter is specified, it is used to format the record.
        The record is then written to the stream with a trailing newline.  If
        exception information is present, it is formatted using
        traceback.print_exception and appended to the stream.  If the stream
        has an 'encoding' attribute, it is used to determine how to do the
        output to the stream.
        """
        try:
            msg = self.format(record)
            stream = self.stream
            # issue 35046: merged two stream.writes into one.
            # 将record的信息写入流中
            stream.write(msg + self.terminator)  # 每条日志都有换行
            self.flush()
        except Exception:
            self.handleError(record)

    def setStream(self, stream):
        """
        Sets the StreamHandler's stream to the specified value,
        if it is different.

        Returns the old stream, if the stream was changed, or None
        if it wasn't.
        """
        if stream is self.stream:
            result = None
        else:
            result = self.stream
            self.acquire()
            try:
                self.flush()
                self.stream = stream
            finally:
                self.release()
        return result

4.1.2 FileHandler

将log输出到文件的handler，继承自StreamHandler

重要代码如下：

class FileHandler(StreamHandler):
    """
    A handler class which writes formatted logging records to disk files.
    """
    def __init__(self, filename, mode='a', encoding=None, delay=False):
        """
        Open the specified file and use it as the stream for logging.
        """
        # Issue #27493: add support for Path objects to be passed in
        filename = os.fspath(filename)
        #keep the absolute path, otherwise derived classes which use this
        #may come a cropper when the current directory changes
        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())

    def close(self):
        """
        Closes the stream.
        """
        self.acquire()
        try:
            try:
                if self.stream:
                    try:
                        self.flush()
                    finally:
                        stream = self.stream
                        self.stream = None
                        if hasattr(stream, "close"):
                            stream.close()
            finally:
                # Issue #19523: call unconditionally to
                # prevent a handler leak when delay is set
                StreamHandler.close(self)
        finally:
            self.release()

    def _open(self):
        """
        Open the current base file with the (original) mode and encoding.
        Return the resulting stream.
        """
        # append方式，打开一个文件
        return open(self.baseFilename, self.mode, encoding=self.encoding)

    def emit(self, record):
        """
        Emit a record.

        If the stream was not opened because 'delay' was specified in the
        constructor, open it before calling the superclass's emit.
        """
        # 和streamhandler保持一致
        if self.stream is None:
            self.stream = self._open()
        StreamHandler.emit(self, record)

4.2 Logger —— 一个独立的log管道

什么是logger？

• logger类继承自Filterer，
• logger对象有logger.level日志级别
• logger对象控制多个handler：logger.handlers=[]
• logger对象之间存在父子关系

简单的来说，logger这个类，集中了我们以上所有的LogRecord类、Filter类、Formatter类、handler类。首先，logger根据输入生成一个LogRecord对象，经过Filter和Formatter之后，再通过self.handlers列表中的所有handler，把log发送出去。一个logger中可能有多个handler，可以实现把一份log放到多个任意的位置。

重要代码：

class Logger(Filterer):

    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 = []  # handler列表
        self.disabled = False
        self._cache = {}


    def log(self, level, msg, *args, **kwargs):
        """
        Log 'msg % args' with the integer severity 'level'.

        To pass exception information, use the keyword argument exc_info with
        a true value, e.g.

        logger.log(level, "We have a %s", "mysterious problem", exc_info=1)
        """
        if not isinstance(level, int):
            if raiseExceptions:
                raise TypeError("level must be an integer")
            else:
                return
        if self.isEnabledFor(level):
            self._log(level, msg, args, **kwargs)

    def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False):
        """
        Low-level logging routine which creates a LogRecord and then calls
        all the handlers of this logger to handle the record.
        """

        #在_log函数中创建了一个LogRecord对象
        record = self.makeRecord(self.name, level, fn, lno, msg, args,
                                 exc_info, func, extra, sinfo)
        #交给handle函数
        self.handle(record)

    def handle(self, record):
        """
        Call the handlers for the specified record.

        This method is used for unpickled records received from a socket, as
        well as those created locally. Logger-level filtering is applied.
        """
        # 进行filter，然后调用callHandlers
        if (not self.disabled) and self.filter(record):
            self.callHandlers(record)

    def addHandler(self, hdlr):
        """
        Add the specified handler to this logger.
        """
        _acquireLock()
        try:
            if not (hdlr in self.handlers):
                self.handlers.append(hdlr)
        finally:
            _releaseLock()

    def removeHandler(self, hdlr):
        """
        Remove the specified handler from this logger.
        """
        _acquireLock()
        try:
            if hdlr in self.handlers:
                self.handlers.remove(hdlr)
        finally:
            _releaseLock()

    def hasHandlers(self):
        """
        See if this logger has any handlers configured.

        Loop through all handlers for this logger and its parents in the
        logger hierarchy. Return True if a handler was found, else False.
        Stop searching up the hierarchy whenever a logger with the "propagate"
        attribute set to zero is found - that will be the last logger which
        is checked for the existence of handlers.
        """
        c = self
        rv = False
        while c:
            if c.handlers:
                rv = True
                break
            if not c.propagate:
                break
            else:
                c = c.parent
        return rv

    def callHandlers(self, record):
        """
        Pass a record to all relevant handlers.

        Loop through all handlers for this logger and its parents in the
        logger hierarchy. If no handler was found, output a one-off error
        message to sys.stderr. Stop searching up the hierarchy whenever a
        logger with the "propagate" attribute set to zero is found - that
        will be the last logger whose handlers are called.
        
        # 从当前logger到所有的父logger，递归的handle 传入的record
        """
        c = self
        found = 0
        while c:
            for hdlr in c.handlers:
                found = found + 1
                if record.levelno >= hdlr.level:
                    hdlr.handle(record) #进入handler的emit函数发送log
            if not c.propagate:
                c = None    #break out
            else:
                c = c.parent
        if (found == 0):
            if lastResort:
                if record.levelno >= lastResort.level:
                    lastResort.handle(record)
            elif raiseExceptions and not self.manager.emittedNoHandlerWarning:
                sys.stderr.write("No handlers could be found for logger"
                                 " \"%s\"\n" % self.name)
                self.manager.emittedNoHandlerWarning = True

4.3 Manager —— 管理logger的类

Manager这个类，对用户其实是不可见的，如果生成了Logger，Manager就会自动存在，Manager对象负责管理所有的Logger。

logger和manager的关系，总结了一下几条：

• Logger是输出log的对象，Manager类提供了管理多个Logger的功能。
• 一个程序中只能有一个manager对象，生成manager时，必定也会生成RootLogger，manager对象中的self.root指向了RootLogger
• manager对象中的self.loggerDict，这个字典保存了当前所有的logger对象（不包含rootlogger）
• 如果使用logging.getLogger的name为空，那么默认指向了name为root的RootLogger
• 如果使用logging.getLogger的name不为空，生成的logger会自动挂载到RootLogger下，除非指定其他的父logger
• 其他的logger通过name建立父子关系

父子关系实例

loger1=logging.getLogger('A')
loger2=logging.getLogger('A.B')
#loger2的父loger是loger1
loger2.parent
out>><logging.Logger object at 0xb7230d6c>
#loger1的父loger是rootlogger
loger1.parent
out>><logging.RootLogger object at 0xb7230b6c>

这些关系都在manager中进行管理

重要的代码：

class Manager(object):
    """
    There is [under normal circumstances] just one Manager instance, which
    holds the hierarchy of loggers.
    """
    def __init__(self, rootnode):
        """
        Initialize the manager with the root node of the logger hierarchy.
        """
        self.root = rootnode
        self.disable = 0
        self.emittedNoHandlerWarning = False
        self.loggerDict = {}
        self.loggerClass = None
        self.logRecordFactory = None

    def getLogger(self, name):
        """
        Get a logger with the specified name (channel name), creating it
        if it doesn't yet exist. This name is a dot-separated hierarchical
        name, such as "a", "a.b", "a.b.c" or similar.

        If a PlaceHolder existed for the specified name [i.e. the logger
        didn't exist but a child of it did], replace it with the created
        logger and fix up the parent/child references which pointed to the
        placeholder to now point to the logger.
        """
        rv = None
        if not isinstance(name, str):
            raise TypeError('A logger name must be a string')
        _acquireLock()
        try:
            if name in self.loggerDict:
                rv = self.loggerDict[name]
                if isinstance(rv, PlaceHolder):
                    ph = rv
                    #生成一个logger，将logger中的manager指向self
       
                    rv = (self.loggerClass or _loggerClass)(name)
                    rv.manager = self
           					# 维护所有logger的父子关系
                    self.loggerDict[name] = rv
                    self._fixupChildren(ph, rv)
                    self._fixupParents(rv)
            else:
                rv = (self.loggerClass or _loggerClass)(name)
                rv.manager = self
                self.loggerDict[name] = rv
                self._fixupParents(rv)
        finally:
            _releaseLock()
        return rv

4.4 LoggerAdapter —— 对标准logger的一个扩展

LogRecord这个大字典中提供的成员变量已经很多，但是，如果在输出log时候仍然希望能够夹带一些自己想要看到的更多信息，例如产生这个log的时候，调用某些函数去获得其他信息，那么就可以把这些添加到Logger中，LoggerAdapter这个类就起到这个作用。

LoggerAdapter这个类很有意思，如果不做什么改动，那么LoggerAdapter类和Logger并没有什么区别。LoggerAdapter只是对Logger类进行了一下包装。

LoggerAdapter的用法其实是在它的成员函数process()的注释中已经说明了：

def process(self, msg, kwargs):
    """
    Process the logging message and keyword arguments passed in to
    a logging call to insert contextual information. You can either
    manipulate the message itself, the keyword args or both. Return
    the message and kwargs modified (or not) to suit your needs.

    Normally, you'll only need to override this one method in a
    LoggerAdapter subclass for your specific needs.
    """
    kwargs["extra"] = self.extra
    return msg, kwargs

也就是说重写process函数，以下是一个例子：

import logging
import random
L=logging.getLogger('name')

#定义一个函数，生成0~1000的随机数
def func():
    return random.randint(1,1000)

class myLogger(logging.LoggerAdapter):
    #继承LoggerAdapter，重写process，生成随机数添加到msg前面
    def process(self,msg,kwargs):
        return '(%d),%s' % (self.extra['name'](),msg)  ,kwargs

#函数对象放入字典中传入  
LA=myLogger(L,{'name':func})

#now,do some logging
LA.debug('some_loging_messsage')

out>>DEBUG:name:(167),some_loging_messsage

5. logging中的config函数

5.1 def basicConfig(**kwargs)

basicConfig函数将对各种参数进行配置，如果不传入参数，则进行默认配置：

1. format配置
2. handler配置
3. level配置

参考文章：

python笔记_logging模块

Python之日志处理（logging模块）

使用 Python logging模块进行日志收集（翻译）