一、問題描述
項(xiàng)目中态辛，使用RotatingFileHandler根據(jù)日志文件大小來切分日志麸澜。設(shè)置文件的MaxBytes為1GB， backupCount大小為5奏黑。
經(jīng)查看痰憎，發(fā)現(xiàn)日志文件的大小均小于10MB，且每個(gè)回滾日志文件的寫入時(shí)間也都比較接近攀涵。
二、分析
日志文件過小洽沟，猜測是代碼有問題以故，或者是文件內(nèi)容有丟失；日志寫入時(shí)間接近猜測是同時(shí)寫入的問題裆操。
經(jīng)檢查怒详，代碼沒有問題，排除此原因踪区±ニ福考慮當(dāng)前使用gunicorn的多進(jìn)程啟動(dòng)程序，多半是多個(gè)進(jìn)程同時(shí)寫入當(dāng)個(gè)文件造成日志文件丟失缎岗。
logging模塊是線程安全的静尼，但并不是進(jìn)程安全的。
如何解決此問題呢？首先先過一遍Python的logging模塊在處理日志回滾的具體實(shí)現(xiàn)方法鼠渺。
2.1 logging模塊實(shí)現(xiàn)日志回滾
logging中RotatingFileHandler類和TimedRotatingFileHandler類分別實(shí)現(xiàn)按照日志文件大小和日志文件時(shí)間來切分文件鸭巴，均繼承自BaseRotatingHandler類。
BaseRotatingHandler類中實(shí)現(xiàn)了文件切分的觸發(fā)和執(zhí)行拦盹，具體過程如下：
1def emit(self, record):
2 """
3 Emit a record.
4 Output the record to the file, catering for rollover as described
5 in doRollover().
6 """
7 try:
8 if self.shouldRollover(record):
9 self.doRollover()
10 logging.FileHandler.emit(self, record)
11 except Exception:
12 self.handleError(record)
復(fù)制代碼
具體的執(zhí)行過程shouldRollover(record)和doRollover()函數(shù)則在RotatingFileHandler類和TimedRotatingFileHandler類中實(shí)現(xiàn)鹃祖。
以RotatingFileHandler類為例，doRollover()函數(shù)流程如下：
1def doRollover(self):
2 if self.stream:
3 self.stream.close()
4 self.stream = None
5 if self.backupCount > 0:
6 for i in range(self.backupCount - 1, 0, -1): # 從backupCount普舆，依次到1
7 sfn = self.rotation_filename("%s.%d" % (self.baseFilename, i))
8 dfn = self.rotation_filename("%s.%d" % (self.baseFilename,
9 i + 1))
10 if os.path.exists(sfn):
11 if os.path.exists(dfn):
12 os.remove(dfn)
13 os.rename(sfn, dfn) # 實(shí)現(xiàn)將xx.log.i->xx.log.i+1
14 dfn = self.rotation_filename(self.baseFilename + ".1")
15 # ---------start-----------
16 if os.path.exists(dfn): # 判斷如果xx.log.1存在恬口，則刪除xx.log.1
17 os.remove(dfn)
18 self.rotate(self.baseFilename, dfn) # 將xx.log->xx.log.1
19 # ----------end------------
20 if not self.delay:
21 self.stream = self._open() # 執(zhí)行新的xx.log
復(fù)制代碼
分析如上過程，整個(gè)步驟是：
- 當(dāng)前正在處理的日志文件名為
self.baseFilename沼侣，該值self.baseFilename = os.path.abspath(filename)是設(shè)置的日志文件的絕對路徑祖能，假設(shè)baseFilename為error.log。 - 當(dāng)進(jìn)行文件回滾的時(shí)候华临，會(huì)依次將
error.log.i重命名為error.log.i+1芯杀。 - 判斷
error.log.1是否存在，若存在雅潭，則刪除揭厚，將當(dāng)前日志文件error.log重命名為error.log.1。 -
self.stream重新指向新建error.log文件扶供。
當(dāng)程序啟動(dòng)多進(jìn)程時(shí)筛圆，每個(gè)進(jìn)程都會(huì)執(zhí)行doRollover過程，若有多個(gè)進(jìn)程進(jìn)入臨界區(qū)椿浓，則會(huì)導(dǎo)致dfn被刪除多次等多種混亂操作太援。
2.2 多進(jìn)程日志安全輸出到同一文件方案
相應(yīng)的解決方法：
- 將日志發(fā)送到同一個(gè)進(jìn)程中，由該進(jìn)程負(fù)責(zé)輸出到文件中（使用
Queue和QueueHandler將所有日志事件發(fā)送至一個(gè)進(jìn)程中） - 對日志輸出加鎖扳碍，每個(gè)進(jìn)程在執(zhí)行日志輸出時(shí)先獲得鎖（用多處理模塊中的
Lock類來序列化對進(jìn)程的文件訪問） - 讓所有進(jìn)程都將日志記錄至一個(gè)
SocketHandler提岔，然后用一個(gè)實(shí)現(xiàn)了套接字服務(wù)器的單獨(dú)進(jìn)程一邊從套接字中讀取一邊將日志記錄至文件（Python手冊中提供）
三、解決方案
3.1 使用ConcurrentRotatingFileHandler包
該方法就屬于加鎖方案。
ConcurrentLogHandler 可以在多進(jìn)程環(huán)境下安全的將日志寫入到同一個(gè)文件案怯，并且可以在日志文件達(dá)到特定大小時(shí)役衡，分割日志文件（支持按文件大小分割）。但ConcurrentLogHandler 不支持按時(shí)間分割日志文件的方式赛惩。
ConcurrentLogHandler 模塊使用文件鎖定，以便多個(gè)進(jìn)程同時(shí)記錄到單個(gè)文件趁餐，而不會(huì)破壞日志事件喷兼。該模塊提供與RotatingFileHandler類似的文件循環(huán)方案。
該模塊嘗試不惜一切代價(jià)保存記錄后雷，這意味著日志文件將大于指定的最大大屑竟摺（如果磁盤空間不足吠各，則堅(jiān)持使用RotatingFileHandler，因?yàn)樗菄?yán)格遵守最大文件大行邱）走孽，如果有多個(gè)腳本的實(shí)例同時(shí)運(yùn)行并寫入同一個(gè)日志文件，那么所有腳本都應(yīng)該使用ConcurrentLogHandler琳状，不應(yīng)該混合和匹配這這個(gè)類磕瓷。
并發(fā)訪問通過使用文件鎖來處理，該文件鎖應(yīng)確保日志消息不會(huì)被丟棄或破壞念逞。這意味著將為寫入磁盤的每個(gè)日志消息獲取并釋放文件鎖困食。（在Windows上，您可能還會(huì)遇到臨時(shí)情況翎承，必須為每個(gè)日志消息打開和關(guān)閉日志文件硕盹。）這可能會(huì)影響性能。在我的測試中叨咖，性能綽綽有余瘩例，但是如果您需要大容量或低延遲的解決方案，建議您將其放在其他地方甸各。
ConcurrentRotatingFileLogHandler類是python標(biāo)準(zhǔn)日志處理程序RotatingFileHandler的直接替代垛贤。
這個(gè)包捆綁了portalocker來處理文件鎖定。由于使用了portalocker模塊趣倾，該模塊當(dāng)前僅支持“nt”和“posix”平臺(tái)聘惦。
安裝：
1pip install ConcurrentLogHandler復(fù)制代碼
該模塊支持
Python2.6及以后版本。當(dāng)前最新版本是0.9.1
ConcurrentLogHandler的使用方法與其他handler類一致儒恋，如與RotatingFileHandler的使用方法一樣善绎。
初始化函數(shù)及參數(shù)：
1class ConcurrentRotatingFileHandler(BaseRotatingHandler):
2 """
3 Handler for logging to a set of files, which switches from one file to the
4 next when the current file reaches a certain size. Multiple processes can
5 write to the log file concurrently, but this may mean that the file will
6 exceed the given size.
7 """
8 def __init__(self, filename, mode='a', maxBytes=0, backupCount=0,
9 encoding=None, debug=True, delay=0):
復(fù)制代碼
參數(shù)含義同Python內(nèi)置RotatingFileHandler類相同，具體可參考上一篇博文诫尽。同樣繼承自BaseRotatingHandler類禀酱。
簡單的示例：
1import logging
2from cloghandler import ConcurrentRotatingFileHandler
3
4logger = logging.getLogger()
5rotateHandler = ConcurrentRotatingFileHandler('./logs/my_logfile.log', "a", 1024*1024, 5)
6logger.addHandler(rotateHandler)
7logger.setLevel(logging.DEBUG)
8
9logger.info('This is a info message.')
復(fù)制代碼
為了適應(yīng)沒有ConcurrentRotatingFileHandler包的情況，增加回退使用RotatingFileHandler的代碼：
1try:
2 from cloghandler import ConcurrentRotatingFileHandler as RFHandler
3except ImportError:
4 from warning import warn
5 warn('ConcurrentRotatingFileHandler package not installed, Using builtin log handler')
6 from logging.handlers import RotatingFileHandler as RFHandler
復(fù)制代碼
運(yùn)行后可以發(fā)現(xiàn)牧嫉，會(huì)自動(dòng)創(chuàng)建一個(gè).lock文件剂跟，通過鎖的方式來安全的寫日志文件。
備注： 該庫自2013年以后就沒有再更新驹止，若有問題，可使用
3.2小節(jié)中的concurrent-log-handler軟件包观蜗。
在非單獨(dú)使用python腳本的時(shí)候臊恋，注意使用方式：
1# 不建議使用方式
2from cloghandler import ConcurrentRotatingFileHandler
3
4.......
5'handlers':{
6 "error_file": {
7 "class": "ConcurrentRotatingFileHandler",
8 "maxBytes": 100*1024*1024,# 日志的大小
9 "backupCount": 3,
10# 建議寫完整
11import cloghandler
12'handlers':{
13 "error_file": {
14 "class": "cloghandler.ConcurrentRotatingFileHandler",
15 "maxBytes": 100*1024*1024,# 日志的大小
16 "backupCount": 3,
復(fù)制代碼
否則，會(huì)出現(xiàn)如下錯(cuò)誤：
1Error: Unable to configure handler 'access_file': Cannot resolve 'ConcurrentRotatingFileHandler': No module named 'ConcurrentRotatingFileHandler'
復(fù)制代碼
3.2 concurrent-log-handler包
該模塊同樣也為python的標(biāo)準(zhǔn)日志記錄軟件提供了額外的日志處理程序墓捻。即回將日志事件寫入日志文件抖仅，當(dāng)文件達(dá)到一定大小時(shí)坊夫，該日志文件將輪流輪轉(zhuǎn)，多個(gè)進(jìn)程可以安全地寫入同一日志文件撤卢，還可以將其進(jìn)行壓縮（開啟）环凿。Windows和POSIX系統(tǒng)均受支持。
它可以看做是舊版本cloghandler的直接替代品放吩，主需要將cloghandler更改為concurrent_log_handler智听。
其特征及說明與cloghandler一致，具體可見3.1小節(jié)渡紫。
安裝：
1pip install concurrent-log-handler
復(fù)制代碼
若是從源碼安裝到推，則執(zhí)行如下命令：
1python setup.py install
復(fù)制代碼
使用示例：
1import logging
2from concurrent_log_handler import ConcurrentRotatingFileHandler
3
4logger = logging.getLogger()
5rotateHandler = ConcurrentRotatingFileHandler('./logs/mylogfile.log', 'a', 512*1024, 5)
6logger.addHandler(rotateHandler)
7logger.setLevel(logging.DEBUG)
8
9logger.info('This is a info message.')
復(fù)制代碼
同樣的，若要分發(fā)代碼惕澎，不確定是否都已安裝concurrent_log_handler軟件包時(shí)莉测，使Python可以輕松的回退到內(nèi)置的RotatingFileHandler。下面是示例：
1import logging
2try:
3 from concurrent_log_handler import ConcurrentRotatingFileHandler as RFHandler
4except ImportError:
5 # 下面兩行可選
6 from warnings import warn
7 warn('concurrent_log_handler package not installed. Using builtin log handler')
8 from logging.handlers import RotatingFileHandler as RFHandler
9
10logger = logging.getLogger()
11rotateHandler = RFHandler('./logs/mylogfile.log', 'a', 1024*1024, 5)
12logger.addHandler(rotateHandler)
復(fù)制代碼
同樣的唧喉，建議直接導(dǎo)入
concurrent_log_handler捣卤，使用concurrent_log_handler.ConcurrentRotatingFileHandler方式。
3.3 對日志輸出加鎖
TimedRotatingFileHandler類doRollover函數(shù)的主要部分如下：
1def doRollover(self):
2 ....
3 dfn = self.rotation_filename(self.baseFilename + "." +
4 time.strftime(self.suffix, timeTuple))
5 # -------begin-------
6 if os.path.exists(dfn): # 判斷如果存在dfn八孝，則刪除
7 os.remove(dfn)
8 self.rotate(self.baseFilename, dfn) # 將當(dāng)前日志文件重命名為dfn
9 # --------end--------
10 if self.backupCount > 0:
11 for s in self.getFilesToDelete():
12 os.remove(s)
13 if not self.delay:
14 self.stream = self._open()
15 ....
復(fù)制代碼
修改思路：
判斷dfn文件是否已經(jīng)存在董朝，如果存在，表示已經(jīng)被rename過了唆阿；如果不存在益涧，則只允許一個(gè)進(jìn)程去rename，其他進(jìn)程需等待驯鳖。
新建一個(gè)類繼承自TimeRotatingFileHandler闲询，修改doRollover函數(shù)，只需處理上面代碼的注釋部分即可浅辙。如下：
1class MPTimeRotatingFileHandler(TimeRotatingFileHandler):
2 def doRollover(self):
3 ....
4 dfn = self.rotation_filename(self.baseFilename + "." +
5 time.strftime(self.suffix, timeTuple))
6 # ----modify start----
7 if not os.path.exists(dfn):
8 f = open(self.baseFilename, 'a')
9 fcntl.lockf(f.fileno(), fcntl.LOCK_EX)
10 if os.path.exists(self.baseFilename): # 判斷baseFilename是否存在
11 self.rotate(self.baseFilename, dfn)
12 # ----modify end-----
13 if self.backupCount > 0:
14 for s in self.getFilesToDelete():
15 os.remove(s)
16 ....
復(fù)制代碼
3.4 重寫FileHandler類
logging.handlers.py中各類的繼承關(guān)系如下圖所示：
<figcaption>image-20200106151225654</figcaption>
TimeRotatingFileHandler類就是繼承自該類扭弧，在FileHandler類中增加一些處理。
具體可參考以下博文：
在
Python官方手冊中记舆，提供了多進(jìn)程中日志記錄至單個(gè)文件的方法鸽捻。
logging是線程安全的，將單個(gè)進(jìn)程中的多個(gè)線程日志記錄至單個(gè)文件也是支持的泽腮。但將多個(gè)進(jìn)程中的日志記錄至單個(gè)文件中則不支持御蒲，因?yàn)樵?code>Python中并沒有在多個(gè)進(jìn)程中實(shí)現(xiàn)對單個(gè)文件訪問的序列化的標(biāo)準(zhǔn)方案。
將多個(gè)進(jìn)程中日志記錄至單個(gè)文件中诊赊，有以下幾個(gè)方案：
- 讓所有進(jìn)程都將日志記錄至一個(gè)
SocketHandler厚满，然后用一個(gè)實(shí)現(xiàn)了套接字服務(wù)器的單獨(dú)進(jìn)程一邊從套接字中讀取一邊將日志記錄至文件。 - 使用
Queue和 QueueHandler 將所有的日志事件發(fā)送至你的多進(jìn)程應(yīng)用的一個(gè)進(jìn)程中碧磅。
3.5 單獨(dú)進(jìn)程負(fù)責(zé)日志事件
一個(gè)單獨(dú)監(jiān)聽進(jìn)程負(fù)責(zé)監(jiān)聽其他進(jìn)程的日志事件碘箍，并根據(jù)自己的配置記錄遵馆。
示例：
1import logging
2import logging.handlers
3import multiprocessing
4
5from random import choice, random
6import time
7
8def listener_configurer():
9 root = logging.getLogger()
10 h = logging.handlers.RotatingFileHandler('test.log', 'a', 300,10) # rotate file設(shè)置的很小，以便于查看結(jié)果
11 f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')
12 h.setFormatter(f)
13 root.addHandler(h)
14
15def listenser_process(queue, configurer):
16 configurer()
17 while True:
18 try:
19 record = queue.get()
20 if record is None:
21 break
22 logger = logging.getLogger(record.name)
23 logger.handle(record)
24 except Exception:
25 import sys, traceback
26 print('Whoops! Problem:', file=sys.stderr)
27 trackback.print_exc(file=sys.stderr)
28
29LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,
30 logging.ERROR, logging.CRITICAL]
31
32LOGGERS = ['a.b.c', 'd.e.f']
33
34MESSAGES = [
35 'Random message #1',
36 'Random message #2',
37 'Random message #3',
38]
39
40def worker_configurer(queue):
41 h = logging.handlers.QueueHandler(queue)
42 root = logging.getLogger()
43 root.addHandler(h)
44 root.setLevel(logging.DEBUG)
45
46# 該循環(huán)僅記錄10個(gè)事件丰榴，這些事件具有隨機(jī)的介入延遲货邓，然后終止
47def worker_process(queue, configurer):
48 configurer(queue)
49 name = multiprocessing.current_process().name
50 print('Worker started:%s'%name)
51 for i in range(10):
52 time.sleep(random())
53 logger = logging.getLogger(choice(LOGGERS))
54 level = choice(LEVELS)
55 message = choice(MESSAGES)
56 logger.log(level, message)
57# 創(chuàng)建隊(duì)列，創(chuàng)建并啟動(dòng)監(jiān)聽器四濒，創(chuàng)建十個(gè)工作進(jìn)程并啟動(dòng)它們换况，等待它們完成，然后將None發(fā)送到隊(duì)列以通知監(jiān)聽器完成
58def main():
59 queue = multiprocessing.Queue(-1)
60 listener = multiprocessing.Process(target=listener_process,
61 args=(queue, listener_configurer))
62 listener.start()
63 workers = []
64 for i in range(10):
65 worker = multiprocessing.Process(target=worker_process,
66 args=(queue, listener_configurer))
67 workers.append(worker)
68 worker.start()
69 for w in workers:
70 w.join()
71 queue.put_nowait(None)
72 listener.join()
73
74if __name__ == '__main__':
75 main()
復(fù)制代碼
使用主進(jìn)程中一個(gè)單獨(dú)的線程記錄日志
下面這段代碼展示了如何使用特定的日志記錄配置峻黍，例如foo記錄器使用了特殊的處理程序复隆，將foo子系統(tǒng)中所有的事件記錄至一個(gè)文件mplog-foo.log。在主進(jìn)程（即使是在工作進(jìn)程中產(chǎn)生的日志事件）的日志記錄機(jī)制中將直接使用恰當(dāng)?shù)呐渲谩?/p>
1import logging
2import logging.config
3import logging.handlers
4from multiprocessing import Process, Queue
5import random
6import threading
7import time
8
9def logger_thread(q):
10 while True:
11 record = q.get()
12 if record is None:
13 break
14 logger = logging.getLogger(record.name)
15 logger.handle(record)
16
17def worker_process(q):
18 qh = logging.handlers.QueueHandler(q)
19 root = logging.getLogger()
20 root.setLevel(logging.DEBUG)
21 root.addHandler(qh)
22 levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
23 logging.CRITICAL]
24 loggers = ['foo', 'foo.bar', 'foo.bar.baz', 'spam', 'spam.ham', 'spam.ham.eggs']
25
26 for i in range(100):
27 lv1=l = random.choice(levles)
28 logger = logging.getLogger(random.choice(loggers))
29 logger.log(lvl, 'Message no. %d', i)
30
31for __name__ == '__main__':
32 q = Queue()
33 d = {
34 'version': 1,
35 'formatters': {
36 'detailed': {
37 'class': 'logging.Formatter',
38 'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
39 }
40 },
41 'handlers': {
42 'console': {
43 'class': 'logging.StreamHandler',
44 'level': 'INFO',
45 },
46 'file': {
47 'class': 'logging.FileHandler',
48 'filename': 'mplog.log',
49 'mode': 'w',
50 'formatter': 'detailed',
51 },
52 'foofile': {
53 'class': 'logging.FileHandler',
54 'filename': 'mplog-foo.log',
55 'mode': 'w',
56 'formatter': 'detailed',
57 },
58 'errors': {
59 'class': 'logging.FileHandler',
60 'filename': 'mplog-errors.log',
61 'mode': 'w',
62 'level': 'ERROR',
63 'formatter': 'detailed',
64 },
65 },
66 'loggers': {
67 'foo': {
68 'handlers': ['foofile']
69 }
70 },
71 'root': {
72 'level': 'DEBUG',
73 'handlers': ['console', 'file', 'errors']
74 },
75 }
76 workers = []
77 for i in range(5):
78 wp = Process(target=worker_process, name='worker %d'%(i+1), args=(q,))
79 workers.append(wp)
80 wp.start()
81 logging.config.dictConfig(d)
82 lp = threading.Thread(target=logger_thread, args=(q,))
83 lp.start()
84
85 for wp in workers:
86 wp.join()
87 q.put(None)
88 lp.join()
復(fù)制代碼
3.6 logging.SocketHandler的方案
該方案具體的使用方法姆涩，下方博文給出了說明挽拂，具體實(shí)現(xiàn)參考如下博客：
