本文的坑兒依啰，主要是在日志滾動(dòng)這一塊，當(dāng)然案训，如果你的應(yīng)用一直在打日志买置，系統(tǒng)時(shí)間一直是正確的，那么 python(2.6.6) 自己的日志模塊是 ok 的强霎。
先說現(xiàn)象：
初始化日志按照時(shí)間滾動(dòng)忿项，TimedRotatingFileHandler(when='D', interval=1...)
在 2016-05-23 查看 cap-sync.log 日志的滾動(dòng)情況，發(fā)現(xiàn)下面的詭異現(xiàn)象：
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"]}
詭異點(diǎn)：
- 21城舞、22號(hào)沒有日志備份
- 19號(hào)的日志里面轩触，都是20號(hào)的日志；
- 23號(hào)同時(shí)修改了 cap-sync.log.2016-05-20 以及 cap-sync.log 文件
- cap-sync.log.2016-05-20 以及 cap-sync.log 文件里分別記錄了應(yīng)該記錄在 cap-sync.log 里的日志
網(wǎng)上查到的已知 BUGs：
- 默認(rèn) python 庫中的 logging.handlers.TimedRotatingFileHandler 會(huì)在 logger 初始化階段不生成 suffix家夺，這樣一旦程序重啟就會(huì)導(dǎo)致上次啟動(dòng)的日志被覆蓋脱柱。
解決辦法： 在初始化 TimedRotatingFileHandler 之后，設(shè)置 suffix
handler.suffix = "%Y-%m-%d"```
- 這個(gè)類實(shí)現(xiàn)切換日志的時(shí)候秦踪，使用了當(dāng)前時(shí)間 + interval 來計(jì)算下一次的切換時(shí)間褐捻，但可能當(dāng)前時(shí)間相對(duì)于整點(diǎn)是有偏移的，比如應(yīng)該在 10:00:00 切日志椅邓，但直到 10:00:05 才有日志寫柠逞，也就是這個(gè)點(diǎn)才開始切日志，這樣就帶來 5s 的偏移景馁，并且可能程序跑得越久板壮，偏移越大。但看代碼合住，對(duì)于按 MIDNIGHT 或 weekday 來切是有做校正的绰精。
- 用 TimedRotatingFileHandler 的目的是讓其自動(dòng)在日志文件名后面加上日期時(shí)間，可以按秒透葛、分笨使、時(shí)、天僚害、周或者其倍數(shù)來設(shè)置硫椰，BUG 出現(xiàn)的場(chǎng)景是：手動(dòng)設(shè)置時(shí)間，并把時(shí)間往未來時(shí)間調(diào)（比如把2012-03-15調(diào)成2014-03-15），這時(shí)就出問題了靶草，這時(shí)產(chǎn)生每條日志后會(huì)產(chǎn)生一個(gè)日志文件蹄胰，這并不是我們想要的效果，如果把當(dāng)前時(shí)間再往歷史時(shí)間調(diào)（比如把2012-03-15調(diào)成2010-03-15）奕翔，這時(shí)也會(huì)產(chǎn)生問題：所有產(chǎn)生的日志都會(huì)記錄到一個(gè)沒有日期后綴的文件裕寨，并不會(huì)按日期分類。如果時(shí)間是正確的并按正常的流程走并不會(huì)產(chǎn)生問題派继，所以想看看 logging 是怎么實(shí)現(xiàn)的宾袜，看了其源碼：\lib\logging\handlers.py，果然不出所料互艾，它的設(shè)計(jì)是有問題的试和，根本不考慮手動(dòng)調(diào)時(shí)間或者時(shí)間可能不對(duì)需要同步的情況
根本原因：
Addhandler讯泣，會(huì)多次追加纫普，也就是說在 a.py 里 import b 的時(shí)候，已經(jīng)在 logger 實(shí)例里加了一個(gè) handler好渠，
然后 a.py 去初始化一個(gè)同名的 logger 時(shí)昨稼，又追加了一個(gè)同樣的 handler。
所以產(chǎn)生的效果是：
- 沒有 rotate 的情況下拳锚，一條日志會(huì)被打印N次（N 是全部代碼里初始化 logger 的次數(shù)）
- Rotate 的時(shí)候假栓，會(huì)導(dǎo)致同時(shí)往昨天以及今天的日志文件里寫日志
這個(gè)情形，沒想明白霍掺，為什么會(huì)往昨天的日志文件繼續(xù)寫日志
解決方法：
- 確保只有一個(gè) get_logger 的實(shí)例
- 按天 rotate匾荆，盡量用 midnight
- 在 global_logger.py 中，addhandler 之前先判斷當(dāng)前 handler 個(gè)數(shù)：
if not len(logger.handlers):
logger.addHandler(handler)
參考資料：
http://stackoverflow.com/questions/6333916/python-logging-ensure-a-handler-is-added-only-once
