是谁偷偷动了我的 logger

OpenMMLab 官方账号

发布于 2022-04-09 08:39:32

65410

代码可运行

文章被收录于专栏：OpenMMLabOpenMMLab

运行总次数：0

代码可运行

新创建的 logger 为何无法正确 “发声”，不怀好意的日志究竟从何而来，精心配置的 logger 竟然然口口吐吐叠叠词词，到底是配置者的失误还是来自三方库的暗箱操作，欢迎走进 logging 详解的第一期：《是谁偷偷动了我的 logger》。

GOODGOOD，通过 mmcv 配置的 logger 日志格式整齐，还能将日志导出到文件，能够很好的备份实验数据，舒服～

诶，最近 torch 也更新了，赶快跟上的时代的步伐，给自己的训练任务升个级！

调试完成，实验启动！

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 - 触发多重日志！