深入理解python logging日誌模組
- 零到壹度原創
- 2018-04-03 15:02:061946瀏覽
這篇文章主要介紹了深入理解python logging日誌模組,小編覺得挺不錯的，更主要是討論在多進程環境下如何使用logging 來輸出日誌， 如何安全地切分日誌檔案。 現在分享給大家，也給大家做個參考。一起跟著小編過來看看吧
1. logging日誌模組介紹
python的logging模組提供了靈活的標準模組，使得任何Python程式都可以使用這個第三方模組來實作日誌記錄。 python logging 官方文件
logging框架中主要由四個部分組成：
Loggers: 可供程式直接呼叫的介面
#Handlers: 決定將日誌記錄指派至正確的目的地
Filters: 提供更細粒度的日誌是否輸出的判斷
Formatters: 制定最終記錄列印的格式佈局
2. logging的組成
loggers
loggers 就是程式可以直接呼叫的一個日誌接口，可以直接向logger寫入日誌資訊。 logger並不是直接實例化使用的，而是透過logging.getLogger(name)來取得對象，事實上logger物件是單例模式，logging是多執行緒安全的，也就是無論程式中哪裡需要打日誌取得到的logger物件都是同一個。但不幸的是logger並不支援多進程，這個在後面的章節再解釋，並給出一些解決方案。
【注意】loggers物件是有父子關係的，當沒有父logger物件時它的父物件是root，當擁有父對象時父子關係會被修正。舉例logging.getLogger("abc.xyz")會建立兩個logger對象，一個是abc父對象，一個是xyz子對象，同時abc沒有父對象所以它的父對像是root 。但實際上abc是一個佔位物件（虛的日誌物件），可以沒有handler來處理日誌。但是root不是佔位對象，如果某一個日誌對像打日誌時，它的父對象會同時收到日誌，所以有些用戶發現創建了一個logger對象時會打兩遍日誌，就是因為他創建的logger打了一遍日誌，同時root物件也打了一次日誌。
每個logger都有一個日誌的等級。 logging中定義瞭如下層級
| 等級 | 數值 |
|---|---|
| NOTSET | 0 |
| 調試 | 10 |
| #訊息 | 20 |
| ##警告 | 30 |
| 錯誤 | 40 |
| 50 |
當一個logger收到日誌訊息後先判斷是否符合level，如果決定要處理就將訊息傳遞給Handlers進行處理。
Handlers
Handlers 將logger發出來的訊息準確地分配，送往正確的地方。舉個栗子，送往控制台或檔案或both或其他地方(流程管道之類的)。它決定了每個日誌的行為，是之後需要配置的重點區域。
每個Handler同樣有一個日誌級別，一個logger可以擁有多個handler也就是說logger可以根據不同的日誌等級將日誌傳遞給不同的handler。當然也可以相同的等級傳遞給多個handlers這就根據需求來靈活的設定了。
Filters
Filters 提供了更細粒度的判斷，來決定日誌是否需要列印。原則上handler取得一個日誌就必定會根據等級被統一處理，但是如果handler擁有一個Filter可以對日誌進行額外的處理和判斷。例如Filter能夠對來自特定來源的日誌進行攔截or修改甚至修改其日誌等級（修改後再進行等級判斷）。
logger和handler都可以安裝filter甚至可以安裝多個filter串連起來。
Formatters
Formatters 指定了最終某筆記錄列印的格式佈局。 Formatter會將傳遞來的訊息拼接成一條具體的字串，預設情況下Format只會將訊息%(message)s直接列印出來。 Format中有一些自帶的LogRecord屬性可以使用，如下表格:
| Attribute | #Format | Description |
|---|---|---|
| #%(asctime)s | 將日誌的時間建構成可讀的形式，預設為'2016-02-08 12:00:00,123'精確到毫秒 | |
| %(filename)s | 包含path的檔案名稱 | |
| %(funcName )s | 由哪個function發出的log | |
| %(levelname)s | 日誌的最終等級（被filter修改後的） | |
| %(message)s | 日誌資訊 | # |
| lineno | %(lineno)d | 目前日誌的行號 |
| pathname | %(pathname )s | 完整路徑 |
| process | #%(process)s | 目前進程 |
一個Handler只能擁有一個Formatter 因此如果要實作多種格式的輸出只能用多個Handler來實作。
3. logging 設定
簡易設定
首先在loggers 章節裡說明了一點，我們擁有一個缺省的日誌物件root，這個root日誌物件的好處是我們直接可以使用logging來進行設定和打日誌。例如：
logging.basicConfig(level=logging.INFO,filename='logger.log')
logging.info("info message")所以這裡的簡易配置所指的就是root日誌對象，隨拿隨用。每個logger都是單例物件所以配置過一遍之後程式內任何地方呼叫都可以。我們只需要呼叫basicConfig就可以對root日誌物件進行簡易的配置，事實上這種方式相當有效易用。它使得呼叫任何logger時保證至少一定會有一個Handler能夠處理日誌。
簡易配置大致可以這麼設定：
logging.basicConfig(level=logging.INFO,
format='%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s',
datefmt='[%Y-%m_%d %H:%M:%S]',
filename='../log/my.log',
filemode='a')程式碼配置
另一種更細緻地設定方式是在程式碼中配置，但這種設定方式是使用的最少的方式，畢竟誰也不希望把設定寫死到程式碼裡面去。但這裡也稍微介紹一下，雖然用的不多，在必要的時候也可以用一把。 (以後補上)
設定檔設定
python中logging的設定檔是基於ConfigParser的功能。也就是說設定檔的格式也是按照這種方式來寫。先奉上一個比較一般的設定檔再細說
############################################## [loggers] keys=root, log02 [logger_root] level=INFO handlers=handler01 [logger_log02] level=DEBUG handler=handler02 qualname=log02 ############################################## [handlers] keys=handler01,handler02 [handler_handler01] class=FileHandler level=INFO formatter=form01 args=('../log/cv_parser_gm_server.log',"a") [handler_handler02] class=StreamHandler level=NOTSET formatter=form01 args=(sys.stdout,) ############################################## [formatters] keys=form01,form02 [formatter_form01] format=%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(process)d %(message)s datefmt=[%Y-%m-%d %H:%M:%S] [formatter_form02] format=(message)s ##############################################
相信看一遍以後，也找出規律了，我將幾個大塊用#分了出來。每一個logger或handler或formatter都有一個key名字。以logger為例，首先需要在[loggers]配置中加上key名字代表了這個logger。然後用[loggers_xxxx]其中xxxx為key名來具體配置這個logger，在log02中我配置了level和一個handler名，當然你可以配置多個hander。根據這個handler名再去 [handlers]裡面去找具體handler的配置，以此類推。
然後在程式碼中，這樣載入設定檔即可
logging.config.fileConfig(log_conf_file)
在handler中有一个class配置，可能有些读者并不是很懂。其实这个是logging里面原先就写好的一些handler类，你可以在这里直接调用。class指向的类相当于具体处理的Handler的执行者。在logging的文档中可以知道这里所有的Handler类都是线程安全的，大家可以放心使用。那么问题就来了，如果多进程怎么办呢。在下一章我主要就是重写Handler类，来实现在多进程环境下使用logging。 我们自己重写或者全部新建一个Handler类，然后将class配置指向自己的Handler类就可以加载自己重写的Handler了。
4. logging遇到多进程（important）
这部分其实是我写这篇文章的初衷。python中由于某种历史原因，多线程的性能基本可以无视。所以一般情况下python要实现并行操作或者并行计算的时候都是使用多进程。但是 python 中logging 并不支持多进程，所以会遇到不少麻烦。
本次就以 TimedRotatingFileHandler 这个类的问题作为例子。这个Handler本来的作用是：按天切割日志文件。（当天的文件是xxxx.log 昨天的文件是xxxx.log.2016-06-01）。这样的好处是，一来可以按天来查找日志，二来可以让日志文件不至于非常大, 过期日志也可以按天删除。
但是问题来了，如果是用多进程来输出日志，则只有一个进程会切换，其他进程会在原来的文件中继续打，还有可能某些进程切换的时候早就有别的进程在新的日志文件里打入东西了，那么他会无情删掉之，再建立新的日志文件。反正将会很乱很乱，完全没法开心的玩耍。
所以这里就想了几个办法来解决多进程logging问题
原因
在解决之前，我们先看看为什么会导致这样的原因。
先将 TimedRotatingFileHandler 的源代码贴上来，这部分是切换时所作的操作：
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:
self.stream.close()
self.stream = None
# get the time that this sequence started at and make it a TimeTuple
currentTime = int(time.time())
dstNow = time.localtime(currentTime)[-1]
t = self.rolloverAt - self.interval
if self.utc:
timeTuple = time.gmtime(t)
else:
timeTuple = time.localtime(t)
dstThen = timeTuple[-1]
if dstNow != dstThen:
if dstNow:
addend = 3600
else:
addend = -3600
timeTuple = time.localtime(t + addend)
dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
if os.path.exists(dfn):
os.remove(dfn)
# Issue 18940: A file may not have been created if delay is True.
if os.path.exists(self.baseFilename):
os.rename(self.baseFilename, dfn)
if self.backupCount > 0:
for s in self.getFilesToDelete():
os.remove(s)
if not self.delay:
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:
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
我们观察 if os.path.exists(dfn) 这一行开始，这里的逻辑是如果 dfn 这个文件存在，则要先删除掉它，然后将 baseFilename 这个文件重命名为 dfn 文件。然后再重新打开 baseFilename这个文件开始写入东西。那么这里的逻辑就很清楚了
假设当前日志文件名为 current.log 切分后的文件名为 current.log.2016-06-01
判断 current.log.2016-06-01 是否存在，如果存在就删除
将当前的日志文件名 改名为current.log.2016-06-01
重新打开新文件（我观察到源代码中默认是”a” 模式打开，之前据说是”w”）
于是在多进程的情况下，一个进程切换了，其他进程的句柄还在 current.log.2016-06-01 还会继续往里面写东西。又或者一个进程执行切换了，会把之前别的进程重命名的 current.log.2016-06-01 文件直接删除。又或者还有一个情况，当一个进程在写东西，另一个进程已经在切换了，会造成不可预估的情况发生。还有一种情况两个进程同时在切文件，第一个进程正在执行第3步，第二进程刚执行完第2步，然后第一个进程 完成了重命名但还没有新建一个新的 current.log 第二个进程开始重命名，此时第二个进程将会因为找不到 current 发生错误。如果第一个进程已经成功创建了 current.log 第二个进程会将这个空文件另存为 current.log.2016-06-01。那么不仅删除了日志文件，而且，进程一认为已经完成过切分了不会再切，而事实上他的句柄指向的是current.log.2016-06-01。
好了这里看上去很复杂，实际上就是因为对于文件操作时，没有对多进程进行一些约束，而导致的问题。
那么如何优雅地解决这个问题呢。我提出了两种方案，当然我会在下面提出更多可行的方案供大家尝试。
解决方案1
先前我们发现 TimedRotatingFileHandler 中逻辑的缺陷。我们只需要稍微修改一下逻辑即可：
判断切分后的文件 current.log.2016-06-01 是否存在，如果不存在则进行重命名。（如果存在说明有其他进程切过了，我不用切了，换一下句柄即可）
以”a”模式 打开 current.log
发现修改后就这么简单~
talking is cheap show me the code:不要以为代码那么长，其实修改部分就是 “##” 注释的地方而已，其他都是照抄源代码。这个类继承了 TimedRotatingFileHandler 重写了这个切分的过程。这个解决方案十分优雅，改换的地方非常少，也十分有效。但有网友提出，这里有一处地方依然不完美，就是rename的那一步，如果就是这么巧，同时两个或者多个进程进入了 if 语句，先后开始 rename 那么依然会发生删除掉日志的情况。确实这种情况确实会发生，由于切分文件一天才一次，正好切分的时候同时有两个Handler在操作，又正好同时走到这里，也是蛮巧的，但是为了完美，可以加上一个文件锁，if 之后加锁，得到锁之后再判断一次，再进行rename这种方式就完美了。代码就不贴了，涉及到锁代码，影响美观。
class SafeRotatingFileHandler(TimedRotatingFileHandler): def __init__(self, filename, when='h', interval=1, backupCount=0, encoding=None, delay=False, utc=False): TimedRotatingFileHandler.__init__(self, filename, when, interval, backupCount, encoding, delay, utc) """ Override doRollover lines commanded by "##" is changed by cc """ 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. Override, 1. if dfn not exist then do rename 2. _open with "a" model """ if self.stream: self.stream.close() self.stream = None # get the time that this sequence started at and make it a TimeTuple currentTime = int(time.time()) dstNow = time.localtime(currentTime)[-1] t = self.rolloverAt - self.interval if self.utc: timeTuple = time.gmtime(t) else: timeTuple = time.localtime(t) dstThen = timeTuple[-1] if dstNow != dstThen: if dstNow: addend = 3600 else: addend = -3600 timeTuple = time.localtime(t + addend) dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple) ## if os.path.exists(dfn): ## os.remove(dfn) # Issue 18940: A file may not have been created if delay is True. ## if os.path.exists(self.baseFilename): if not os.path.exists(dfn) and os.path.exists(self.baseFilename): os.rename(self.baseFilename, dfn) if self.backupCount > 0: for s in self.getFilesToDelete(): os.remove(s) if not self.delay: self.mode = "a" 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: 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
解决方案2
我认为最简单有效的解决方案。重写FileHandler类（这个类是所有写入文件的Handler都需要继承的TimedRotatingFileHandler 就是继承的这个类；我们增加一些简单的判断和操作就可以。
我们的逻辑是这样的：
判断当前时间戳是否与指向的文件名是同一个时间
-
如果不是，则切换 指向的文件即可
结束，是不是很简单的逻辑。
talking is cheap show me the code
check_baseFilename 就是执行逻辑1判断；build_baseFilename 就是执行逻辑2换句柄。就这么简单完成了。
这种方案与之前不同的是，当前文件就是 current.log.2016-06-01 ，到了明天当前文件就是current.log.2016-06-02 没有重命名的情况，也没有删除的情况。十分简洁优雅。也能解决多进程的logging问题。
class SafeFileHandler(FileHandler): def __init__(self, filename, mode, encoding=None, delay=0): """ Use the specified filename for streamed logging """ if codecs is None: encoding = None FileHandler.__init__(self, filename, mode, encoding, delay) self.mode = mode self.encoding = encoding self.suffix = "%Y-%m-%d" self.suffix_time = "" def emit(self, record): """ Emit a record. Always check time """ try: if self.check_baseFilename(record): self.build_baseFilename() FileHandler.emit(self, record) except (KeyboardInterrupt, SystemExit): raise except: self.handleError(record) def check_baseFilename(self, record): """ Determine if builder should occur. record is not used, as we are just comparing times, but it is needed so the method signatures are the same """ timeTuple = time.localtime() if self.suffix_time != time.strftime(self.suffix, timeTuple) or not os.path.exists(self.baseFilename+'.'+self.suffix_time): return 1 else: return 0 def build_baseFilename(self): """ do builder; in this case, old time stamp is removed from filename and a new time stamp is append to the filename """ if self.stream: self.stream.close() self.stream = None # remove old suffix if self.suffix_time != "": index = self.baseFilename.find("."+self.suffix_time) if index == -1: index = self.baseFilename.rfind(".") self.baseFilename = self.baseFilename[:index] # add new suffix currentTimeTuple = time.localtime() self.suffix_time = time.strftime(self.suffix, currentTimeTuple) self.baseFilename = self.baseFilename + "." + self.suffix_time self.mode = 'a' if not self.delay: self.stream = self._open()
解决方案其他
当然还有其他的解决方案，例如由一个logging进程统一打日志，其他进程将所有的日志内容打入logging进程管道由它来打理。还有将日志打入网络socket当中也是同样的道理。
5. 参考资料
python logging 官方文档
林中小灯的切分方案，方案一就是从这儿来的
以上是深入理解python logging日誌模組的詳細內容。更多資訊請關注PHP中文網其他相關文章！