新创建的 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 动了手脚?
问题一:我的日志去哪了?
上例中,我明明想输出 “问题究竟在哪”,但是为什么这条日志没有在终端出现呢?事实上,使用 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 对我言听计从》
什么,想超前点播?不妨先看看 mmcv logging 的实现吧~
mmcv/mmcv at master · open-mmlab/mmcvgithub.com/open-mmlab/mmcv/tree/master/mmcv/正在上传…重新上传取消