python的logging 模块浅析

0x00 python logging的继承关系

使用python做日志输出时，首先我们需要一个创建一个Logger对象：import logging; logger = logging.getLogger()。然后，我们就可以用logger.info/debug/error(msg)来输出日志了。

如果只是单纯地打印日志，这样做和丑陋的print没有任何区别。我们期望log能有一定的格式，这时你就会用到logging.Formatter；我们还希望日志不仅在console中输出，还要向文件输出；这样你需要给我们的logger添加handler，一个handler指向标准输出流，一个handler指向文件handler。logging.handlers提供了一些这些常用的handler。

然后，你希望对这些不同的输出流进行精准的控制，比如：在console中只输出某些高级别的日志，而在文件日志中输出所有日志。在console中，使用一种输出formatter，在文件输出中使用另一种formatter。你不满足于python提供的DEBUG/INFO/WARNING/ERROR/CRITICAL的控制粒度，想要更精细地控制日志。你就需要理解日志是如何流转、继承地。

这是python官方提供的一张log输出图

也就是说，我们有可以从如下几个层面控制日志的输出：

1. Logger 输出级别控制
2. Logger 的filter控制
3. Handler 的级别控制
4. Handler 的filter控制

此外，我们要注意到日志的输出是流式的，只要有一个地方日志被过滤掉了，他就不能输出了。再设计多级别的日志系统时，尤其要注意这点。如果我们要设置过滤条件，要在上图所示的日志流中，逐渐提高level级别。

0x01 为日志增加默认属性

python日志支持的默认字段比较少：

其实Filter隐含了一个比较dirty的接口，让你能够修改logRecord的属性。让你能够给日志增加一个新的字段。代码如下：

class ContextFilter(logging.Filter):
    hostname = os.getenv('HOSTNAME')

    def filter(self, record):
        record.hostname = self.hostname
        return True

将ContextFilter添加到你的某个handler，然后给这个handler增加一个这样的formatter: [%(asctime)s] [%(levelname)s] [HOSTNAME: %(hostname)s] %(message)s；这个handler就可以输出主机名了。当然，这样做其实是有悖于fileter的本意的。不过我还没有找到更好的办法。

0x02 更细的日志粒度

python的日志粒度如下：

如果我们向定义一个比debug级别更低的日志怎么办呢？代码如下：

VERBOSE_LOG_LEVEL = 5
def VERBOSE(self, message, *args, **kwargs):
    if self.isEnabledFor(VERBOSE_LOG_LEVEL):
        self._log(VERBOSE_LOG_LEVEL, message, args, **kwargs)


logging.Logger.VERB = VERBOSE

这样我们就定义了一个级别为5的输出。这样做的好处是，比如有些特别琐碎的、系统级别的输出，你不希望框架使用者看到，而只是作为日志分析用。你可以定义一个非常低的日志级别。然后把绝大多数的handler的控制级别设置的都比5高，只留一个接口给日志收集者。这样，就可以大大提升框架使用者的体验。

0x03 一个小bug

偶然的原因复现了别人的一个bug.

触发错误的代码很简单：

import requests
import logging

logger = logging.getLogger()
logStdOut = logging.StreamHandler()
LOGFORMATCNSL=logging.Formatter("%(asctime)s %(message)s %(aVar)s %(bVar)s")
logStdOut.setFormatter(LOGFORMATCNSL)
logStdOut.setLevel(logging.DEBUG)
logger.setLevel(logging.NOTSET)
logger.addHandler(logStdOut)

def tryThis():
    logger.error("deneme", extra={"aVar": "aVal", "bVar": "bVal"})
    conn = requests.get("http://www.google.com")
    conn.close()

tryThis()

错误最终定位到了在urllib3/connectionpool.py下的日志打印命令

log.debug("%s://%s:%s \"%s %s %s\" %s %s", self.scheme, self.host, self.port,
                  method, url, http_version, httplib_response.status,
                  httplib_response.length)

通过debug模式，我们可以看到，在这里，RootLogger被赋予了一个formatter， '%(asctime)s %(message)s %(aVar)s %(bVar)s'。

RootLogger是什么？是一个python程序内全局唯一的，所有Logger对象的祖先。它是怎么产生的呢？

logger = logging.getLogger()，这个logger就是RootLogger。我们对logger的设定，自然会影响到所有的日志输出。

因此，直接修改RootLogger是危险的。而如果我们给getLogger传一个参数，它会生成一个非root的Logger。问题就解决了。

修正后的代码如下：

import requests
import logging

# code with out bug
logger = logging.getLogger("__abc__")
# code will trigger the keyError bug
# logger = logging.getLogger()

logStdOut = logging.StreamHandler()
print(isinstance(logger, logging.RootLogger))
LOGFORMATCNSL=logging.Formatter("%(asctime)s %(message)s %(aVar)s %(bVar)s")
logStdOut.setFormatter(LOGFORMATCNSL)
logStdOut.setLevel(logging.DEBUG)
logger.setLevel(logging.NOTSET)
logger.addHandler(logStdOut)


def tryThis():
    logger.error("deneme", extra={"aVar": "aVal", "bVar": "bVal"})
    conn = requests.get("http://www.baidu.com")
    conn.close()

tryThis()

尬聊