Python 日志模块 logging rotate 的坑儿

本文的坑儿,主要是在日志滚动这一块,当然,如果你的应用一直在打日志,系统时间一直是正确的,那么 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。

所以产生的效果是:

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

解决方法:

  1. 确保只有一个 get_logger 的实例
  2. 按天 rotate,尽量用 midnight
  3. 在 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

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 206,723评论 6 481
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 88,485评论 2 382
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 152,998评论 0 344
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 55,323评论 1 279
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 64,355评论 5 374
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 49,079评论 1 285
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,389评论 3 400
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,019评论 0 259
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 43,519评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,971评论 2 325
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,100评论 1 333
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,738评论 4 324
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,293评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,289评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,517评论 1 262
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,547评论 2 354
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,834评论 2 345

推荐阅读更多精彩内容