Python 日志模块 logging rotate 的坑儿

2016-05-25 本文已影响6176人混沌中的菜菜

本文的坑儿，主要是在日志滚动这一块，当然，如果你的应用一直在打日志，系统时间一直是正确的，那么 python(2.6.6) 自己的日志模块是 ok 的。

先说现象：
初始化日志按照时间滚动，TimedRotatingFileHandler(when='D', interval=1...)
在 2016-05-23 查看 cap-sync.log 日志的滚动情况，发现下面的诡异现象：

ls -l
head -n 1cap-sync.log.2016-05-19
tail -n 1cap-sync.log.2016-05-19
head -n 1cap-sync.log.2016-05-20
tail -n 1cap-sync.log.2016-05-20
head -n 1cap-sync.log
tail -n 1cap-sync.log
 
total30460
-rw-rw-r-- 1 admin admin     1440 May 23 10:56 cap-sync.log
-rw-rw-r-- 1 admin admin   531572 May 20 18:34 cap-sync.log.2016-05-19
-rw-rw-r-- 1 admin admin     1330 May 23 10:56 cap-sync.log.2016-05-20

2016-05-20 09:28:40,411 - CAP-Sync - INFO - Consume has failed record in JMQ:{"action":"add","appCode":"config","ips":["10.255.255.1"]}.Put this message into retry queue
2016-05-20 18:34:16,265 - CAP-Sync - INFO - Consume OK with JMQ: {"action":"remove","appCode":"big.new","ips":["10.255.255.2"]}.

2016-05-22 21:34:40,133 - CAP-Sync - INFO - Consume OK with JMQ:{"action":"remove","appCode":"zk","ips":["10.1255.255.2"]}.
2016-05-23 10:56:56,373 - CAP-Sync - INFO - Consume OK with JMQ:{"action":"add","appCode":"service","ips":["10.255.255.1"]}.

2016-05-22 21:34:40,148 - JMQ-api - INFO - produce JMQ success! Detail Info:{"action":"remove","appCode":"zk","ips":["10.255.255.2"]}
2016-05-23 10:56:56,384 - JMQ-api - INFO - produce JMQ success! Detail Info:{"action":"add","appCode":"service","ips":["10.255.255.1"]}

诡异点：

21、22号没有日志备份
19号的日志里面，都是20号的日志；
23号同时修改了 cap-sync.log.2016-05-20 以及 cap-sync.log 文件
cap-sync.log.2016-05-20 以及 cap-sync.log 文件里分别记录了应该记录在 cap-sync.log 里的日志

网上查到的已知 BUGs：

默认 python 库中的 logging.handlers.TimedRotatingFileHandler 会在 logger 初始化阶段不生成 suffix，这样一旦程序重启就会导致上次启动的日志被覆盖。
解决办法：在初始化 TimedRotatingFileHandler 之后，设置 suffix

handler.suffix = "%Y-%m-%d"```

这个类实现切换日志的时候，使用了当前时间 + interval 来计算下一次的切换时间，但可能当前时间相对于整点是有偏移的，比如应该在 10:00:00 切日志，但直到 10:00:05 才有日志写，也就是这个点才开始切日志，这样就带来 5s 的偏移，并且可能程序跑得越久，偏移越大。但看代码，对于按 MIDNIGHT 或 weekday 来切是有做校正的。
用 TimedRotatingFileHandler 的目的是让其自动在日志文件名后面加上日期时间，可以按秒、分、时、天、周或者其倍数来设置，BUG 出现的场景是：手动设置时间，并把时间往未来时间调（比如把2012-03-15调成2014-03-15），这时就出问题了，这时产生每条日志后会产生一个日志文件，这并不是我们想要的效果，如果把当前时间再往历史时间调（比如把2012-03-15调成2010-03-15），这时也会产生问题：所有产生的日志都会记录到一个没有日期后缀的文件，并不会按日期分类。如果时间是正确的并按正常的流程走并不会产生问题，所以想看看 logging 是怎么实现的，看了其源码：\lib\logging\handlers.py，果然不出所料，它的设计是有问题的，根本不考虑手动调时间或者时间可能不对需要同步的情况

根本原因：
Addhandler，会多次追加，也就是说在 a.py 里 import b 的时候，已经在 logger 实例里加了一个 handler，
然后 a.py 去初始化一个同名的 logger 时，又追加了一个同样的 handler。

所以产生的效果是：

没有 rotate 的情况下，一条日志会被打印N次（N 是全部代码里初始化 logger 的次数）
Rotate 的时候，会导致同时往昨天以及今天的日志文件里写日志
这个情形，没想明白，为什么会往昨天的日志文件继续写日志

解决方法：

确保只有一个 get_logger 的实例
按天 rotate，尽量用 midnight
在 global_logger.py 中，addhandler 之前先判断当前 handler 个数：

    if not len(logger.handlers):
        logger.addHandler(handler)

参考资料：
http://stackoverflow.com/questions/6333916/python-logging-ensure-a-handler-is-added-only-once

Python 日志模块 logging rotate 的坑儿

猜你喜欢

热点阅读