Python 下的日志模块

发表于 更新于

以下代码均基于 Python3.8，其他版本可能有所出入

使用日志

开始使用一个日志，基本上都是用的 [logging.info](http://logging.info) 或是 [logger.info](http://logger.info) 形式的 API

以 [logging.info](http://logging.info) 为例，其源码为

1
2
3
4
5
6
7
8
9
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)

这里涉及到了两个东西：basicConfig 和 root，basicConfig 的作用是生成默认的配置，与网上其他简单地教程中手动调用 logging.basicConfig 方法但不传递任何参数效果是相同的，而 root 默认情况是来源于 root = RootLogger(WARNING) 一行代码，是在 logging 模块被初始化执行时候生成的一个根日志对象，并默认将等级设定为了 WARNING 级别。

至于 RootLogger 其实也很简单，就是在默认的 logger 的情况下设定了一个名字 root

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
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.
    """
    def __init__(self, level):
        """
        Initialize the logger with the name "root".
        """
        Logger.__init__(self, "root", level)

    def __reduce__(self):
				"""
				这个方法是用于 pickle 使用的，当返回一个两个元素的元组时第一个元
        素是 pickle 时调用的函数而第二个元素是传递给这个函数的参数。

        即相当于执行了一个 getLogger()，这个相当于 logging.getLogger()，
        返回值始终是当前运行时环境下的 root logger
				"""
        return getLogger, ()

综上，当调用 logging.info 时实际上是调用了 root.info，也就是我们着重关注的是 Logger.info 这一函数

Logger 对象

从 info 方法看起的话，

1
2
3
4
5
class Logger(Filterer):
    # ...
    def info(self, msg, *args, **kwargs):
        if self.isEnabledFor(INFO):
            self._log(INFO, msg, args, **kwargs)

这里面做了两件事情，一是判断目前 Logger 是否对相应等级（这里是 INFO）开启，如果开启则以 INFO 作为首参数向 logger._log 进行真正的日志写入。

除了 info，还有 debug、warning、error、critical 几个等级，实现均与 info 类似，只是传递了不同的等级参数；还有一个「万能工具」叫做 logger.log，可以自行传递一个数字作为等级，流程与上面类似

1
2
3
4
5
6
7
8
9
10
class Logger(Filterer):
    # ...    
    def log(self, level, msg, *args, **kwargs):
        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)

我们先看简单的，怎么判断是否是对 level 开启的

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
class Logger(Filterer):
    # ...    
    def isEnabledFor(self, level):
        """
        Is this logger enabled for level 'level'?
        """
        if self.disabled:
            return False

        try:
            return self._cache[level]
        except KeyError:
            _acquireLock()
            if self.manager.disable >= level:
                is_enabled = self._cache[level] = False
            else:
                is_enabled = self._cache[level] = level >= self.getEffectiveLevel()
            _releaseLock()

            return is_enabled
    def getEffectiveLevel(self):
        """
        Get the effective level for this logger.

        Loop through this logger and its parents in the logger hierarchy,
        looking for a non-zero logging level. Return the first one found.
        """
        logger = self
        while logger:
            if logger.level:
                return logger.level
            logger = logger.parent
        return NOTSET

代码很简单，一共有三步

  1. 首先看自己是否已经是禁用掉的，如果禁用了直接返回 False
  2. 再去缓存中看是否有启用的结果，如果有结果直接返回
  3. 看是否满足 manager.disable >= level ，如果满足直接返回 False，manager.disable 是属于全局的 Logger 的，如果全局的 disable 值大于等于写入的 level 直接返回 False 并加入缓存
  4. 上述不满足时还会再判断 level >= self.getEffectiveLevel() ，返回这一结果并加入缓存

好了上面又引入了几个新东西。。

一个是莫名其妙来的 self.manager，实际上这个的来源是在 root=RootLogger(WARNING) 这一句的时候出现的

1
2
3
root = RootLogger(WARNING)
Logger.root = root
Logger.manager = Manager(Logger.root)

这个语句会让所有的 Logger 都知道当前的 root 和 manager 是什么

而具体到 manager 的创建过程，这里保存了所有 Logger 都需要遵从的设定

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
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
	  # ...

默认情况下 disable 是 0，也就是只要你 level 设定为正数就不可能因为全局的设定而被忽略（当然手动修改这个 disable 就当我没说了）

而常见的几个 level 分别对应的值是

1
2
3
4
5
6
7
8
CRITICAL = 50
FATAL = CRITICAL
ERROR = 40
WARNING = 30
WARN = WARNING
INFO = 20
DEBUG = 10
NOTSET = 0

可以发现，除了「不设定」的 NOTSET 以外都不会被忽略，换句话说就是，这一步往往只是限定你必须设定一个 level 的

另一个新出现的getEffectiveLevel 会递归判断自己是否设定了 level，如果设定了（if logger.level 等同于 if logger.level != NOTSET ）就返回，否则返回父 logger 的；如果已经是 根 logger 了则停止并返回 NOTSET

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
class Logger(Filterer):
    # ...
    def getEffectiveLevel(self):
        """
        Get the effective level for this logger.

        Loop through this logger and its parents in the logger hierarchy,
        looking for a non-zero logging level. Return the first one found.
        """
        logger = self
        while logger:
            if logger.level:
                return logger.level
            logger = logger.parent
        return NOTSET

所以这个 isEnabledFor 流程就很明显了，看要写入日志的等级是否大于要求的最高等级（简单来说 ERROR > WARNING > INFO > DEBUG），只有大于才能写入成功；

另外可以看到，在更新缓存的时候是进行了获取和释放锁的操作的，这个锁是被整个 logging 模块所共享的线程锁，会在修改日志配置、写入日志等情景下使用，防止多线程的情况下出现错误。不过也因为仅仅是线程锁，所以在多进程的时候这里的锁就无效了，并发写日志到同一位置就可能出问题了，这个问题在后面会说到。

正式的内容刚刚开始，写日志的 _log 函数如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
class Logger(Filterer):
    def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False,
             stacklevel=1):
        """
        Low-level logging routine which creates a LogRecord and then calls
        all the handlers of this logger to handle the record.
        """
        sinfo = None
        if _srcfile:
            #IronPython doesn't track Python frames, so findCaller raises an
            #exception on some versions of IronPython. We trap it here so that
            #IronPython can use logging.
            try:
                fn, lno, func, sinfo = self.findCaller(stack_info, stacklevel)
            except ValueError: # pragma: no cover
                fn, lno, func = "(unknown file)", 0, "(unknown function)"
        else: # pragma: no cover
            fn, lno, func = "(unknown file)", 0, "(unknown function)"
        if exc_info:
            if isinstance(exc_info, BaseException):
                exc_info = (type(exc_info), exc_info, exc_info.__traceback__)
            elif not isinstance(exc_info, tuple):
                exc_info = sys.exc_info()
        record = self.makeRecord(self.name, level, fn, lno, msg, args,
                                 exc_info, func, extra, sinfo)
        self.handle(record)

这一步乍一看很乱，但其实就做了三件事情

  • 获取到 fn, lno, func, sinfo 四个变量、获取处理 exc_info 变量
  • self.makeRecord 生成 Record
  • self.handle(record) 处理 Record

对于第一件事请就不做展开看原理了，功能上是利用反射来获取到调用栈信息来报告文件名 fn、调用的函数所在文件中的行数lno 、调用的具体函数名 func 和调用栈信息文本 sinfo；exc_info 则是异常的信息，默认为 None，如果传递一个 exception 则打印其信息，如果传递一个元组则直接就用传递的元组不做处理，而如果传递一个其他类型的真值就会利用 sys.exc_info 获取到当前的异常信息。

第二件事情就是利用给定的参数生成一个 LogRecord 对象，这个对象是后续传递给 handle 处理的，包含了所有要记录的日志信息。这里需要注意的是，LogRecord 并没有 extra 参数，传递给 makeRecord 的 extra 参数仅仅被用来修改生成的 LogRecord 对象的 __dict__

而当 LogRecord 对象被构建完成，就会调用 self.handle(record) 来对这个日志真正的进行处理

1
2
3
4
class Logger(Filterer):
    def handle(self, record):
        if (not self.disabled) and self.filter(record):
            self.callHandlers(record)

在这一步里面，首先判断这个 logger 是不是被禁用了（not self.disabled），然后看是否要过滤掉（filter(record)）。过滤部分的来源其实是一直没有提到的 Logger 的父类 Filterer ，这个后面再说。先主要关注真正的业务逻辑，也就是 self.callHandlers(record)

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
class Logger(Filterer):
    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.
        """
        c = self
        found = 0
        while c:
            for hdlr in c.handlers:
                found = found + 1
                if record.levelno >= hdlr.level:
                    hdlr.handle(record)
            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

这里面的逻辑很好理解

  1. 找当前的 Logger 所注册的所有 Handler，依次调用其 handle(record) 方法
  2. 如果允许递归（c.propagate）递归向上找父 Logger，如果找到则重新执行 1-2 步
  3. 如果自始至终都没有找到任何的 Handler 可以执行，则使用 lastResort 这个 Handler 进行处理

这里面有一个 lastResord handler 会在没有注册任何 handler 时候被调用，其创建过程是

1
2
3
4
5
6
7
8
9
10
11
12
13
_defaultLastResort = _StderrHandler(WARNING)
lastResort = _defaultLastResort

class _StderrHandler(StreamHandler):
    def __init__(self, level=NOTSET):
        """
        Initialize the handler.
        """
        Handler.__init__(self, level)

    @property
    def stream(self):
        return sys.stderr

可以发现它所做的是将所有 WARNING 及以上等级的日志写入至标准错误

以上就是 Logger 整体的调用栈行为

Handler 对象

可以发现在 logger 会把具体的执行流程给到 handler，上面在 lastResort 中就有一个 StreamHandler，我们看一下整体所有的 Handler 的继承

这里只列举了在 logging 和 logging.handler 包下的几个常见的 Handler，一般只用到这些就足够了

我们从 Handler 开始看，上面调用的 .handle 方法就是定义在这里的

1
2
3
4
5
6
7
8
9
10
class Handler(Filterer):
    def handle(self, record):
        rv = self.filter(record)
        if rv:
            self.acquire()
            try:
                self.emit(record)
            finally:
                self.release()
        return rv

这里所做的事情是过滤、获取锁、触发、释放锁。

对于过滤发现它调用的也是 filter，这个 filter 同样来源于 Filterer 父类，这个类是被前面说到的 Logger 和这里的 Handler 所共同继承的，我们在这里依然不说，留到后面。

获取和释放锁的过程是为了保证一个 Handler 同时只能被一个线程所使用，这里用到的依然是线程锁，所以在多进程的时候依然需要注意进行处理，锁是属于 Handler 的，不同 Handler 拥有的是不同的锁。

最后调用的 emit 函数是用来被子类重写的，子类一般都是在这里完成的实现逻辑。

我们最常使用的输出到控制台是 StreamHandler ，输出到文件是 FileHandler，FileHandler 是基于 StreamHandler 的，因此我们先看 StreamHandler 做了什么。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
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
        self.stream = stream

    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.
            stream.write(msg + self.terminator)
            self.flush()
        except RecursionError:  # See issue 36272
            raise
        except Exception:
            self.handleError(record)
  1. 不指定输出到的流默认是标准错误
  2. 调用的 format 方法是由 Handler 类给出的，用于将 record 记录转换为文字
  3. 其他的一些刷新缓存创建锁的代码就省略了

format 实现如下，默认是用了一个 Formatter，负责将你的各种参数合并为一条文字

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
_defaultFormatter = Formatter()

class Handler(Filterer):
    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)

Filterer

Filterer 是 Logger 和 Handler 的共同父类，但实际上可以算是一个 Mixin 用于增强功能而不是类似于继承的父类。其核心是一个 filter 方法，接收一个 LogRecord 对象返回一个布尔值，返回 True 代表处理，返回 False 代表跳过

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
class Filterer(object):
    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.

        .. versionchanged:: 3.2

           Allow filters to be just callables.
        """
        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

可以传递声明 filter，只要有一个返回 False 那么最终结果就是 False

Formatter

Formatter 其实没什么可说的，就是需要实现一个 format 方法，接收一个 LogRecord 对象，返回一个字符串，具体实现无非就是一些文本替换，有兴趣的可以自己去看代码，这里就不赘述了

自定义自己的多进程日志模块

需求：每个进程的日志保存在不同的文件，大概格式是 {前缀}.{进程名}-{进程pid}.log ，同时利用类似于 TimedRoatatingFileHandler 的方式让每天的日志在不同的文件中