起步

最近在用 tornado + peewee + peewee-async 写自己的东西。有了早前工作上的重大教训，这次我一上手就着手打开 peewee 或者是 peewee-async 的 SQL 执行日志，遇到了点问题。最后问题解决了，但过程中产生的几个“为什么”想在这里记录一下。

环境准备

Python3.7, tornado6.1, peewee3.14.4, peewee-async0.7.1。

测试代码如下：

from abc import ABC

import tornado.ioloop
import tornado.web
import tornado.log
import peewee
import peewee_async

# ## init peewee async
db = peewee_async.PooledMySQLDatabase(
    "test",
    user="root", password="123456",
    host="guan.com", port=3306,
    max_connections=10,
)
db.set_allow_sync(True)
objects = peewee_async.Manager(db)

# ## Student Model
class Student(peewee.Model):
    id = peewee.PrimaryKeyField()
    name = peewee.CharField()

    class Meta:
        database = db

# ## http handler
class StudentHandler(tornado.web.RequestHandler, ABC):
    async def get(self):
        """
            查询学生

            cmd: http GET :8080
        """
        students = await objects.execute(Student.select())
        await self.finish(",".join(s.name for s in students))

    async def post(self):
        """
            创建一个学生

            cmd: http --form POST :8080 name=zhong
        """
        Student.create_table(True)  # auto create table

        name = self.get_body_argument("name")
        await objects.create(Student, name=name)
        await self.finish("创建成功")

if __name__ == "__main__":
    app = tornado.web.Application([
        (r"/", StudentHandler)
    ])
    app.listen(8080)
    tornado.ioloop.IOLoop.current().start()

为方便发起 http 请求，这里推荐使用命令行工具 httpie，安装之后可尝试对百度发起请求：

$ http GET www.baidu.com

打印 peewee 的 SQL 日志

诚如 peewee 文档中的 Logging queries 所说：

# Print all queries to stderr.
import logging
logger = logging.getLogger('peewee')
logger.addHandler(logging.StreamHandler())
logger.setLevel(logging.DEBUG)

将上述代码加到测试代码中，发起 http://127.0.0.1:8080 GET 请求（操作之前，请对 http://127.0.0.1:8080 发起 POST 请求）。日志是有了，但日志不对劲：

('SELECT table_name FROM information_schema.tables WHERE table_schema = DATABASE() AND table_type != %s ORDER BY table_name', ('VIEW',))
DEBUG:peewee:('SELECT table_name FROM information_schema.tables WHERE table_schema = DATABASE() AND table_type != %s ORDER BY table_name', ('VIEW',))
('INSERT INTO `student` (`name`) VALUES (%s)', (['zhong2'],), {})
DEBUG:peewee.async:('INSERT INTO `student` (`name`) VALUES (%s)', (['zhong2'],), {})
('SELECT `t1`.`id`, `t1`.`name` FROM `student` AS `t1`', ([],), {})
DEBUG:peewee.async:('SELECT `t1`.`id`, `t1`.`name` FROM `student` AS `t1`', ([],), {})

于是产生了几个“为什么”：

为什么加入 peewee - Logging queries 中的代码之后就能输出日志了？
为什么有重复的日志输出？（尽管打印格式不同）
为什么日志输出有的是 “DEBUG:peewee”，有的则是 “DEBUG:peewee.async”？
有更优雅的日志打印方案吗？

第一个为什么

为什么加入 peewee - Logging queries 中的代码之后就能输出日志了？

先说后两行。

logger.addHandler(logging.StreamHandler())
logger.setLevel(logging.DEBUG)

这两行代码大家应该不会有疑问。第一行是设置 logger 行为，如果不对 StreamHandler() 传入 steam，默认使用标准错误：sys.stderr；第二行设置日志等级。

所以“为什么就能输出日志”的关键落在了 logging.getLogger('peewee') 身上。

查看 logging.getLogger 源码：

# logging 源码
def getLogger(name=None):
    if name:
        return Logger.manager.getLogger(name)
    else:
        return root

class Manager(object):
    def __init__(self, rootnode):
        # ...
        self.loggerDict = {}
        # ...

    def getLogger(self, name):
        rv = None
        # ...
        try:
            if name in self.loggerDict:  # 如果存在 name 存在
                rv = self.loggerDict[name]  # 取出对应的 logger
                # ...
                    self._fixupParents(rv)
            else:
                # 否则传入 name, 创建 logger
                rv = (self.loggerClass or _loggerClass)(name)  
                rv.manager = self
                self.loggerDict[name] = rv  # 加入缓存
                self._fixupParents(rv)
        finally:
            _releaseLock()
        return rv

只看 python logging 的源码可能还有点迷糊，再看看 peewee 的代码就懂了。

# peewee 源码
try:  # Python 2.7+
    from logging import NullHandler
except ImportError:
    class NullHandler(logging.Handler):
        def emit(self, record):
            pass

logger = logging.getLogger('peewee')
logger.addHandler(NullHandler())

也就说，peewee 中本就有打印日志的行为，但由于默认设置的 handler 为 NullHandler，表示什么都别做。当我们通过 logging.getLogger('peewee') 拿到命名空间为 peewee 的 logger 后，添加了 StreamHandler()，于是就有了日志输出。

要是你看 peewee-async 包，你会发现它也是这样做的：

# peewee-async 源码
__log__ = logging.getLogger('peewee.async')
__log__.addHandler(logging.NullHandler())

所以还等什么，赶紧丢掉 if debug: logger.debug(...) 这种 low 操作，用 logger name 控制日志行为吧！

第二个为什么

为什么有重复的日志输出？（尽管打印格式不同）

仔细查看日志，可以发现执行的 sql 被重复打印了。但如果离开 tornado 框架，日志不会重复，那就是 tornado 在作怪。不过，就算龙卷风想作孽，总得 python 允许它作孽才行。查阅官方文档 logger objects 很惊喜地发现了 propagate 属性：

If this attribute evaluates to true, events logged to this logger will be passed to the handlers of higher level (ancestor) loggers, in addition to any handlers attached to this logger.

根据这段文字大概猜到了两点：1. logger 之间可以存在上下级关系 2. 事件默认向上传播，事件会被多次捕获。

所以一定存在 root logger <-- ... <-- peewee logger 这种关系。就不卖关子了，打印一下可知：

print(logger.parent)  # <RootLogger root (WARNING)>

重复日志只能是 root logger 打出来的，但我们并没有对 root logger 做过任何操作。范围锁定到很小了，只看 tornado 代码即可：

# tornado 源码
class IOLoop(Configurable):
    # ...
    def _setup_logging(self) -> None:
        """The IOLoop catches and logs exceptions, so it's
        important that log output be visible.  However, python's
        default behavior for non-root loggers (prior to python
        3.2) is to print an unhelpful "no handlers could be
        found" message rather than the actual log entry, so we
        must explicitly configure logging if we've made it this
        far without anything.

        This method should be called from start() in subclasses.
        """
        if not any(  # 如果没有设置任何 handlers
            [
                logging.getLogger().handlers,
                logging.getLogger("tornado").handlers,
                logging.getLogger("tornado.application").handlers,
            ]
        ):
            logging.basicConfig()  # 对 root logger 设置默认的 StreamHandler()

解决方案：禁止事件向上传播。

logger = logging.getLogger("peewee")
logger.propagate = False

第三个为什么

为什么日志输出有的是 “DEBUG:peewee”，有的则是 “DEBUG:peewee.async”？

第三个问题可想而知，说明一些 sql 是 peewee 执行的，一些是 peewee-async 所为。有趣的是，peewee.async logger 的 parent 是 peewee logger：

logger = logging.getLogger("peewee.async")
print(logger.parent)  # <Logger peewee (DEBUG)>

那么， peewee.async logger 是怎么做到“换父”的呢？起先我翻遍了 peewee-async 的代码没有看出端倪来，最后看到了 logging Manager.getLogger 里调用的 _fixupParents ：

# logging 源码
def _fixupParents(self, alogger):
    """
    Ensure that there are either loggers or placeholders all the way
    from the specified logger to the root of the logger hierarchy.
    """
    name = alogger.name
    i = name.rfind(".")  # 从右开始，找到第一个 “.” 出现的索引值
    rv = None
    while (i > 0) and not rv:
        substr = name[:i]  # 截取 {1}.{2} 中的 {1} 部分
        if substr not in self.loggerDict:  # 如果不在缓存中，放入缓存
            self.loggerDict[substr] = PlaceHolder(alogger)
        else:  # 如果在缓存中，取出来
            obj = self.loggerDict[substr]  
            if isinstance(obj, Logger):
                rv = obj  # 将找到的 logger 赋给 rv
            else:
                assert isinstance(obj, PlaceHolder)
                obj.append(alogger)
        i = name.rfind(".", 0, i - 1)  # 继续从右开始，找到第一个 “.” 出现的索引值
    if not rv:  # 如果 rv 不存在
        rv = self.root
    alogger.parent = rv

从代码可看出，logger 的上下级关系是由名字决定的，. 是层级分隔符。例如 x.y logger 是 x.y.z logger 的父亲，peewee logger 是 peewee.async logger 的父亲。

结合前面说到的“向上传播”，开启 peewee logger 的日志输出后，它会打印 peewee.async logger 的日志内容；作为最终节点的 root logger，它会打印 peewee logger 以及 peewee.async logger 的日志内容。所以能够看到 “DEBUG:peewee”、“DEBUG:peewee.async” 开头的日志。

更优雅的日志打印

从去年伊始，我已经不怎么直接使用 python 官方提供的 logger 了，而选择主打简单实用的 loguru。

打印自己的日志当然行，但如何接管三方库里的日志输出呢？以下是 loguru 文档中提到的解决方案：

# Want to intercept standard logging messages toward your Loguru sinks?
import logging
from loguru import logger

class InterceptHandler(logging.Handler):
    def emit(self, record):
        # Get corresponding Loguru level if it exists
        try:
            level = logger.level(record.levelname).name
        except ValueError:
            level = record.levelno

        # Find caller from where originated the logged message
        frame, depth = logging.currentframe(), 2
        while frame.f_code.co_filename == logging.__file__:
            frame = frame.f_back
            depth += 1

        logger.opt(depth=depth, exception=record.exc_info).log(
            level, record.getMessage()
        )

logging.basicConfig(handlers=[InterceptHandler()], level=0)

原理很简单，巧用 logger 的向上传播特性，在 root logger 中使用 loguru 统一输出日志。

接管标准日志后你会发现 loguru 打印了很多奇奇怪怪的内容，这是因为从 python 源码到使用的第三方包都可能注册了自己的 logger，而 root logger 会不假思索的全都打印出来。

查看已经存在的 logger：

import logging

print(logging.Logger.manager.loggerDict)

我们可以拿到已经存在的 logger，选择性关闭向上传播特性。

有关心情

Guan