眾所周知，python的自帶logging模塊是線程安全的，從內部源碼也可看到，很多配置或者寫入日志的時候，通過加鎖-釋放鎖(threading.RLock())來實現線程安全。
內部源碼參見logging.__int__(line 210)：
_lock = threading.RLock()
def _acquireLock():
"""
Acquire the module-level lock for serializing access to shared data.
This should be released with _releaseLock().
"""
if _lock:
_lock.acquire()
def _releaseLock():
"""
Release the module-level lock acquired by calling _acquireLock().
"""
if _lock:
_lock.release()
tips
單進程下，日志記錄正常。多進程下日志丟失問題，根據日志切分源碼，多進程同時切分日志時，會導致后面的進程刪除前面線程切分出來的日志，導致日志丟失。
如果進程共用一個日志文件, rotate只需要執行一次, 但實際是每個進程都會執行一次上面的過程, 第一個rotate之外的進程, 在rm的時候刪除的都是沒有過期的日志。
解決多進程寫同一日志安全問題，包括但不局限於如下幾點：
- 1.django內部的logging配置，使用 TimedRotatingFileHandler 的話，應該考慮日志輪轉只有一個進程操作，考慮加鎖-python自帶的fcntl的文件鎖機制，需要繼承TimedRotatingFileHandler然后重寫doRollover()方法，性能要求不高的可以考慮
- 2.共享隊列，通過將日志操作發送給queue，同步處理
- 3.cron定時切分+腳本實現(常用的通過uwsgi(uwsgi操作日志，優先級高於django的TimedRotatingFileHandler)定向輸出日出，結合腳本執行切分具體命令，再由cron定時執行)
接下來看看logging模塊內部的源碼文件
就3個文件，分別是：
__int__.py: 功能可以簡單理解為，一般化的logging配置，讀取設置filter/format/handler/logger，另外比較重要的功能是提供Logger的api接口，單個文件直接調用的話，直接通過Logger這個類實現實例調用，或者是handler常用的底層class，繼承關系為(父->子)：Handler(實現加鎖解鎖/flush/) -> StreamHandler(實現日志的實際的emit與flush操作) -> FileHandler()- config.py： 讀取設置參數，如果是在較為大型的應用中，例如django web應用，一般會在django的settings.py中配置LOGGING參數，此參數也包含filter/format/handler/logger四項配置
- handlers.py: 實現很多額外的不同類型的handler，比如基於大小的日志rotate的RotatingFileHanler，基於時間的TimedRotatingFileHandler，基於Socket，基於syslog，基於queue，基於http等等
重點看看class TimedRotatingFileHandler
從左到右，父類到子類的繼承關系：
*Handler -> StreamHandler -> FileHandler -> BaseRotatingHandler -> TimedRotatingFileHandler*
TimedRotatingFileHandler的方法：
- computeRollover(currentTime)： 初始化時調用，計算輪轉時間點
- shouldRollover(record)： 是否輪轉
- getFilesToDelete()： 獲取要刪除的文件，被doRollover()調用
- doRollover()： 輪轉日志
繼承方法：
handlers.py
- BaseRotatingHandler.emit(record): 先判斷是否需要輪轉文件，然后發送日志到文件，實際調用FileHandler.emit()，然后調用StreamHandler.emit(), record實際上就是一系列的format參數，如asctime, filename, module, msg等等
- BaseRotatingHandler.rotation_filename(default_name): 返回文件輪轉名
- BaseRotatingHandler.rotate(src, dst)：輪轉文件
__int__.py
- FileHandler.emit(record)
- StreamHandler.emit(record)
下面說說具體調用邏輯。
比如logger.<levelName>("hello world...")觸發了logging模塊時，
1.首先調用BaseRotatingHandler.emit()
---
def emit(self, record):
"""
Emit a record.
Output the record to the file, catering for rollover as described
in doRollover().
"""
try:
if self.shouldRollover(record): # 程序調用TimedRotatingFileHandler.shouldRollover(), 如果當前時間小於rolloverat的時間，就返回0，否則1
self.doRollover() # 上面檢查為1，應該輪轉，因為時間已經大於rolloverat的時間
logging.FileHandler.emit(self, record) # 執行記錄發送，如上面所述，執行StreamHandler.emit()方法，寫入日志
except Exception:
self.handleError(record)
---
2.調用TimedRotatingFileHandler.doRollover(), 只有輪轉時才會觸發
---
def doRollover(self):
"""
do a rollover; in this case, a date/time stamp is appended to the filename
when the rollover happens. However, you want the file to be named for the
start of the interval, not the current time. If there is a backup count,
then we have to get a list of matching filenames, sort them and remove
the one with the oldest suffix.
"""
if self.stream: # stream非空，進入
self.stream.close() # 關閉流
self.stream = None # 重新復制None
# get the time that this sequence started at and make it a TimeTuple
currentTime = int(time.time()) # e.g. 1638257483
dstNow = time.localtime(currentTime)[-1] # 0
t = self.rolloverAt - self.interval # 1638239215
if self.utc: # pass
timeTuple = time.gmtime(t)
else: # +08:00, 東八區
timeTuple = time.localtime(t)
dstThen = timeTuple[-1] # 0
if dstNow != dstThen: # pass
if dstNow:
addend = 3600
else:
addend = -3600
timeTuple = time.localtime(t + addend)
dfn = self.rotation_filename(self.baseFilename + "." + # 調用BaseRotatinghandler.rotation_filename(), 返回dfn="path/xxx.log.2021-11-30_10-26"(10-26為os.stat(file)的mtime)
time.strftime(self.suffix, timeTuple))
if os.path.exists(dfn): # 文件存在則rm, 本例不存在，所以不走這塊
os.remove(dfn)
self.rotate(self.baseFilename, dfn) # 調用BaseRotatinghandler.rotate(src, dst)，實現文件的輪轉， 源文件存在則重命名
if self.backupCount > 0:
for s in self.getFilesToDelete(): # 獲取需要刪除的文件
os.remove(s) # 返回非空時，遍歷刪除冗余文件
if not self.delay: # delay為false, 進入
self.stream = self._open() # 重置非空
newRolloverAt = self.computeRollover(currentTime) # 重新計算輪轉時間
while newRolloverAt <= currentTime:
newRolloverAt = newRolloverAt + self.interval
#If DST changes and midnight or weekly rollover, adjust for this.
if (self.when == 'MIDNIGHT' or self.when.startswith('W')) and not self.utc: # 非utc時間且(午夜更新或者每周x更新)
dstAtRollover = time.localtime(newRolloverAt)[-1]
if dstNow != dstAtRollover:
if not dstNow: # DST kicks in before next rollover, so we need to deduct an hour
addend = -3600
else: # DST bows out before next rollover, so we need to add an hour
addend = 3600
newRolloverAt += addend
self.rolloverAt = newRolloverAt # 更新輪轉時間點
---
3.BaseRotatinghandler.rotation_filename()
---
def rotation_filename(self, default_name):
"""
Modify the filename of a log file when rotating.
This is provided so that a custom filename can be provided.
The default implementation calls the 'namer' attribute of the
handler, if it's callable, passing the default name to
it. If the attribute isn't callable (the default is None), the name
is returned unchanged.
:param default_name: The default name for the log file.
"""
if not callable(self.namer): # 通常走這里，返回傳入的name
result = default_name
else:
result = self.namer(default_name)
return result
---
4.BaseRotatinghandler.rotate(src, dst)
---
def rotate(self, source, dest):
"""
When rotating, rotate the current log.
The default implementation calls the 'rotator' attribute of the
handler, if it's callable, passing the source and dest arguments to
it. If the attribute isn't callable (the default is None), the source
is simply renamed to the destination.
:param source: The source filename. This is normally the base
filename, e.g. 'test.log'
:param dest: The destination filename. This is normally
what the source is rotated to, e.g. 'test.log.1'.
"""
if not callable(self.rotator): # self.rotator->None，執行這里
# Issue 18940: A file may not have been created if delay is True.
if os.path.exists(source): # 源文件存在，則重命名
os.rename(source, dest)
else:
self.rotator(source, dest)
---
5.TimedRotatingFileHandler.getFilesToDelete()
---
def getFilesToDelete(self):
"""
Determine the files to delete when rolling over.
More specific than the earlier method, which just used glob.glob().
"""
dirName, baseName = os.path.split(self.baseFilename) # 如path/xxx.log.2021-11-30_10-26,分離目錄及文件名
fileNames = os.listdir(dirName) # 獲取當下目錄的文件數組
result = [] # 接下來的for循環中，如果文件數組的文件名符合前后綴的比較，以absPath加入到result數組中
prefix = baseName + "."
plen = len(prefix)
for fileName in fileNames:
if fileName[:plen] == prefix:
suffix = fileName[plen:]
if self.extMatch.match(suffix):
result.append(os.path.join(dirName, fileName))
if len(result) < self.backupCount: # 如果數量小於備份數，認為不用刪除， 重置[]
result = []
else: # 數量冗余，排序后返回需要刪除的文件切片
result.sort()
result = result[:len(result) - self.backupCount]
return result
---
到這里，一條日志的完整處理流程就結束了。
django啟動時，在加載LOGGING的config時，加載到此模塊，首先執行此模塊的初始化：
依次從上往下壓棧，
1.BaseRotatingHandler.__int__(self, filename, 'a', encoding, delay)
2.logging.FileHandler.__init__(self, filename, mode, encoding, delay)
3.StreamHandler.__init__(self, self._open())
4.Handler.__init__(self)
最終通過BaseRotatingHandler首先一系列的初始化，初始化后，獲得以下屬性：
- baseFilename
- delay
- mode
- name
- ratator # 執行輪轉時用，默認None
- stream
...
接着通過自身的屬性初始化獲取了：
- when: 輪轉時間點, 如midnight
- backCount： 備份數
- utc： 是否utc時間, false
- atTime： bool, fasle
- interval： 輪轉間隔-秒, 86400
- suffix: 年-月-日
- excMatch： 匹配模式，刪除冗余備份時用
- rolloverAt： 很重要，輪轉時間點，比如現在2021-11-30 14:54:00，該值應是2021-12-01 00:00:00
關於rolloverAt這個屬性，
- 如果輪轉時間不是按照星期或者midnight模式的話，舉個例子，按照60min一次，此時，rolloverAt=文件的最后一次修改時間 + interval(60min)
- 如果按照星期或者midnight的話，如midnight，按照當前的時間，當天剩余時間 r = 一天的秒數86400-當前的時間換算成秒，最終rolloverAt=文件的最后一次修改時間 + r
總的來說，在django起來的時候，對於TimeRotating部分，只會初始化其相關參數
1.django應用啟動流程分析
1.1 運行項目目錄下的manage.py
通過給定的參數進行啟動，主要是
- 指定文件名-manage.py,
- 運行命令，如runserver
- 啟動主機ip:port
1.2 執行初始化settings
加載設置各種settings.py中涉及的參數，典型的如：
- CACHES
- INSTALLED_APPS
- LOGGING
- MIDDLEWARE
- TIME_ZONE
1.3 加載設置目錄下的初始化
如項目可能用到celery, 將celery.py中的的配置加載
2.django的LOGGING初始化
加載LOGGING中的四項設置參數：
- filters-過濾，不同粒度
- formatters(重要的)-輸出日志格式
- handlers(重要的)-日志的rotate
- loggers-哪些需要記錄日志
django啟動時配置logging的順序：
# django.utils.log
1.django setup時會加載settings.py中的LOGGING參數，然后調用logging.config.dictConfig，內部調用logging.config.dictConfigClass.configure()
# logging.config.dictConfigClass.configure
2.通過傳入的settings.py中設置的LOGGING的map配置，依次配置
- 2.1 formatter -> 格式化
- 2.2 filter -> 過濾器
- 2.3 handler -> 發送給哪個文件記錄
- 遍歷handlers進行配置
- 2.4 logger -> api，供應用程序調用
# logging.config.dictConfigClass.configure
3.該模塊實質上就是用來解析django中的settings的LOGGING的配置用的
2.1 主要說說logging部分的handlers
初始化時會遍歷LOGGINGh中的各個handler，針對具體的handler class，進行對應的初始化，比如 TimedRotatingFileHandler
1.初始化init
- rotate時間 when
- backcount, 備份數
- filename-日志name
- rolloverAt-計算輪轉時間(TimedRotatingFileHandler.computeRollover())
2.是否輪轉，根據時間差返回1/0，需要輪轉返回1，否則返回0
3.打開日志文件
參考：