新创建的 logger 为何无法正确 “发声”，不怀好意的日志究竟从何而来，精心配置的 logger 竟然然口口吐吐叠叠词词，到底是配置者的失误还是来自三方库的暗箱操作，欢迎走进 logging 详解的第一期：《是谁偷偷动了我的 logger》。
调试完成，实验启动！
2022-01-28 15:01:45,436 - mmdet - INFO - Epoch [1][0/7330] lr: 1.000e-02, eta: 8:28:55, time: 0.248, data_time: 0.008, memory: 3510, loss_cls: 0.9523, loss_bbox: 0.6255, loss: 1.5778 Epoch [1][0/7330] lr: 1.000e-02, eta: 8:28:55, time: 0.248, data_time: 0.008, memory: 3510, loss_cls: 0.9523, loss_bbox: 0.6255, loss: 1.5778 Epoch [1][0/7330] lr: 1.000e-02, eta: 8:28:55, time: 0.248, data_time: 0.008, memory: 3510, loss_cls: 0.9523, loss_bbox: 0.6255, loss: 1.5778 Epoch [1][0/7330] lr: 1.000e-02, eta: 8:28:55, time: 0.248, data_time: 0.008, memory: 3510, loss_cls: 0.9523, loss_bbox: 0.6255, loss: 1.5778 ...
纳尼，日志怎么影分身了，几张卡就有几次重复的日志，不应该啊，这难道就是卡多的烦恼？我 mmcv 版本也没更新，只是更新了 torch，按理说 logger 都是一样的配方，为啥日志乱了呢？
为了解决多重日志的 bug，我追根溯源的对 python 的 logging 模块进行了地毯式的 debug。在我第 10086 次调试过程中，出现了诡异的现象：
>>> # import “三方”库 >>> logger = logging.getLogger("misery debug") >>> logger.setLevel(logging.INFO) >>> logger.info("问题究竟在哪") misery debug 现在的年轻人难道希望问题很好定位，bug 很好修，程序一跑就 ok？不会吧？
我的日志 "问题究竟在哪" 为什么没有显示？这句 "misery debug 现在的年轻人难道希望问题很好定位，bug 很好修，程序一跑就 ok？不会吧？" 又是从哪来的？到底是谁对我的 logger 动了手脚？
问题一：我的 logger 去哪了✦
上例中，我明明想输出 “问题究竟在哪”，但是为什么这条日志没有在终端出现呢？事实上，使用 logging .getLogger 接口获取的 logger，只是一个胚胎，本身不具备任何输出日志的能力。logger 是通过自身携带的 handler 来输出日志的，例如 StreamHandler（向终端输出日志）和 FileHandler（向文件输出日志）。所以我们需要为创建的 logger 配置 handler，从而能够实现输出日志的功能。
>>> logger = logging.getLogger("misery debug") >>> logger.setLevel(logging.INFO) >>> logger.handlers.addHandler(logging.StreamHandler()) >>> logger.info("问题究竟在哪") 问题究竟在哪 misery debug 现在的年轻人难道希望问题很好定位，bug 很好修，程序一跑就 ok，不会吧？
在为 logger 配置上 StreamHandler 后，日志就能正常输出了。
问题二：是谁在默默低语✦
misery debug 现在的年轻人难道希望问题很好定位，bug 很好修，程序一跑就 ok，不会吧？
这句嘲讽的打印和 mmcv 日志多重打印其实是一回事，而 logging 库的继承关系则是这一系列问题的症结所在。
众所可能不周知， logging 库为了简化配置 logger 的流程，允许我们通过派生“子实例”来获取日志格式和父实例一样的 logger。为了便于介绍日志格式的继承关系，下例中我们直接使用 mmcv.get_logger 函数来获取 logger（get_logger 接口能够获取有统一日志格式的 logger）。
>>> parent_logger = mmcv.get_logger('parent') >>> child_logger = parent_logger.getChild('child') >>> child_logger.info("I'm child") 2022-03-01 21:58:18,438 - parent.child - INFO - I'm child
logging.Logger.getChild() 方法能够非常简单的获取具有相同日志格式的子实例，但是这也是多重日志的根源。
鲁迅曾经说过，人类拥有共同的祖先，logger 也不例外，那就是 logging.root 。所有通过 logging.getLogger 方法创建的实例，都拥有共同的祖先：logging.root。
>>> logger = logging.getLogger('roommate') >>> logger = logger.getChild('roommate') >>> logger = logger.getChild('roommate') >>> logger = logger.getChild('roommate') >>> while logger.parent: >>> print(logger.parent.name) >>> logger = logger.parent roommate.roommate.roommate roommate.roommate roommate root
这样就会引入一个问题，如果三方库配置了 logging.root ，按照继承逻辑是否会影响到我们的日志呢，答案是会的。我仔细检查了我导入的模块（自导自演），终于找到了 devil_whisper.py。
import logging handler = logging.StreamHandler() format = logging.Formatter("%(name)s 现在的年轻人难道希望问题很好定位，bug 很好修，程序一跑就 ok，不会吧？") handler.setFormatter(format) handler.setLevel(logging.INFO) logging.root.addHandler(handler)
由于 logging.getLogger("misery debug") 获取的 logger 继承自 logging.root，因此就会输出 misery debug 现在的年轻人难道希望问题很好定位，bug 很好修，程序一跑就 ok，不会吧？
mmcv 出现多重日志的原因也是如此。尽管 mmcv 的 mmcv.get_logger 会将 logging.root 的 handler 的日志等级设置成 ERROR，从而过滤所有 ERROR 等级以下的日志，但是如果三方库在 mmcv.get_logger 之后再配置 logging.root，就会出现多重日志的现象。
# https://github.com/open-mmlab/mmcv/blob/master/mmcv/utils/logging.py >>> def get_logger(name, log_file=None, log_level=logging.INFO, file_mode='w'): >>> ... >>> for handler in logger.root.handlers: >>> if type(handler) is logging.StreamHandler: >>> handler.setLevel(logging.ERROR) >>> ... >>> return logger >>> logging.root.addHandler(logging.StreamHandler()) >>> logger = get_logger('mmcv') # 将 Handler 的日志等级设置为 ERROR. >>> logger.info('不会触发多重日志！') 2022-03-01 22:16:42,682 - mmcv - INFO - 不会触发多重日志！ >>> logging.root.addHandler(logging.StreamHandler()) # root 新增了 handler. >>> logger.info('触发多重日志！') 2022-03-01 22:16:42,682 - mmcv - INFO - 触发多重日志！ 触发多重日志！
既然继承是多重日志的万恶之源，我们就需要理解 logging.Logger 的继承逻辑，这边以流程图的形式展示 handler 的继承规则。
Handler 的继承规则
不难发现，logging 模块通过 propagate 属性实现了 handler 的 “继承”。当 propagate 为 True 时，子实例会向上搜索并调用父实例的 Handler 从而触发多重打印。我们只需要另 propagate 为 False，能走出万恶的继承循环了。
>>> logging.root.addHandler(logging.StreamHandler()) >>> logger = mmcv.get_logger('mmcv') >>> logger.propagate = False >>> logger.info('不会触发多重日志！') 2022-03-01 22:31:03,429 - mmcv - INFO - 不会触发多重日志！ >>> logging.root.addHandler(logging.StreamHandler()) >>> logger.info('触发多重日志！') 2022-03-01 22:31:03,429 - mmcv - INFO - 触发多重日志！
可以看到两句话都只被打印了一遍，问题成功解决。
虽然找到了多重日志的根源，但这只是 logging 模块的冰山一角。如何配置会 “察言观色” 的 logger，能够按照日志等级输出不同格式的日志，如何缕清 logger 父子实例复杂的继承关系？尽情期待第二期：《三句话，让 logger 对我言听计从》～
文章来源：【OpenMMLab】
2022-03-15 18:12
